runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/randa9ba44.cudf.easy.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/easy//randa9ba44.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/randa9ba44.cudf.easy.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.53 1.34 1.23 4/46 30043
/proc/meminfo: memFree=791548/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2584 CPUtime=0.02
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 565 1855 0 0 0 0 0 2 24 0 1 0 876526137 2646016 283 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 646 283 240 194 0 32 0
[pid=30043] ppid=30033 vsize=3024 CPUtime=0.01
/proc/30043/stat : 30043 (cudftodeb.nativ) R 30033 30033 2059 34821 2220 4202496 474 0 0 0 1 0 0 0 25 0 1 0 876526140 3096576 401 1283457024 134512640 135004320 4288328736 18446744073709551615 134951589 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30043/statm: 756 401 224 121 0 148 0

[startup+0.188008 s]
/proc/loadavg: 1.53 1.34 1.23 4/46 30043
/proc/meminfo: memFree=791548/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2584 CPUtime=0.02
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 565 1855 0 0 0 0 0 2 24 0 1 0 876526137 2646016 283 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 646 283 240 194 0 32 0
[pid=30043] ppid=30033 vsize=6496 CPUtime=0.16
/proc/30043/stat : 30043 (cudftodeb.nativ) R 30033 30033 2059 34821 2220 4202496 1286 0 0 0 16 0 0 0 25 0 1 0 876526140 6651904 1213 1283457024 134512640 135004320 4288328736 18446744073709551615 134948002 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30043/statm: 1624 1213 225 121 0 1016 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 9080

[startup+0.20801 s]
/proc/loadavg: 1.53 1.34 1.23 4/46 30043
/proc/meminfo: memFree=791548/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2584 CPUtime=0.02
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 565 1855 0 0 0 0 0 2 24 0 1 0 876526137 2646016 283 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 646 283 240 194 0 32 0
[pid=30043] ppid=30033 vsize=6744 CPUtime=0.18
/proc/30043/stat : 30043 (cudftodeb.nativ) R 30033 30033 2059 34821 2220 4202496 1395 0 0 0 18 0 0 0 25 0 1 0 876526140 6905856 1322 1283457024 134512640 135004320 4288328736 18446744073709551615 134961336 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30043/statm: 1686 1322 225 121 0 1078 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 9328

[startup+0.308037 s]
/proc/loadavg: 1.53 1.34 1.23 4/46 30043
/proc/meminfo: memFree=791548/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2584 CPUtime=0.02
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 565 1855 0 0 0 0 0 2 24 0 1 0 876526137 2646016 283 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 646 283 240 194 0 32 0
[pid=30043] ppid=30033 vsize=8976 CPUtime=0.28
/proc/30043/stat : 30043 (cudftodeb.nativ) R 30033 30033 2059 34821 2220 4202496 1917 0 0 0 28 0 0 0 25 0 1 0 876526140 9191424 1844 1283457024 134512640 135004320 4288328736 18446744073709551615 134986478 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30043/statm: 2244 1844 225 121 0 1636 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 11560

[startup+0.708151 s]
/proc/loadavg: 1.53 1.34 1.23 4/46 30043
/proc/meminfo: memFree=791548/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2584 CPUtime=0.02
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 565 1855 0 0 0 0 0 2 24 0 1 0 876526137 2646016 283 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 646 283 240 194 0 32 0
[pid=30043] ppid=30033 vsize=17816 CPUtime=0.68
/proc/30043/stat : 30043 (cudftodeb.nativ) R 30033 30033 2059 34821 2220 4202496 4081 0 0 0 68 0 0 0 25 0 1 0 876526140 18243584 4008 1283457024 134512640 135004320 4288328736 18446744073709551615 134951650 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30043/statm: 4454 4008 225 121 0 3846 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 20400

[startup+1.50835 s]
/proc/loadavg: 1.53 1.34 1.23 2/47 30044
/proc/meminfo: memFree=768820/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2584 CPUtime=0.02
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 565 1855 0 0 0 0 0 2 24 0 1 0 876526137 2646016 283 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 646 283 240 194 0 32 0
[pid=30043] ppid=30033 vsize=34928 CPUtime=1.48
/proc/30043/stat : 30043 (cudftodeb.nativ) R 30033 30033 2059 34821 2220 4202496 8316 0 0 0 148 0 0 0 25 0 1 0 876526140 35766272 8243 1283457024 134512640 135004320 4288328736 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30043/statm: 8732 8243 225 121 0 8124 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 37512

[startup+3.10875 s]
/proc/loadavg: 1.49 1.33 1.23 2/47 30044
/proc/meminfo: memFree=743276/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2584 CPUtime=0.02
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 565 1855 0 0 0 0 0 2 24 0 1 0 876526137 2646016 283 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 646 283 240 194 0 32 0
[pid=30043] ppid=30033 vsize=31480 CPUtime=3.08
/proc/30043/stat : 30043 (cudftodeb.nativ) R 30033 30033 2059 34821 2220 4202496 12312 0 0 0 306 2 0 0 25 0 1 0 876526140 32235520 7420 1283457024 134512640 135004320 4288328736 18446744073709551615 4158654038 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30043/statm: 7870 7420 237 121 0 7262 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 34064

[startup+6.30667 s]
/proc/loadavg: 1.49 1.33 1.23 2/48 30057
/proc/meminfo: memFree=735636/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2592 CPUtime=3.45
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 692 18003 0 1 0 0 337 8 17 0 1 0 876526137 2654208 294 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 648 294 249 194 0 34 0
[pid=30054] ppid=30033 vsize=49900 CPUtime=1.72
/proc/30054/stat : 30054 (aptitude) R 30033 30033 2059 34821 2220 4202496 11092 650 177 0 162 10 0 0 20 0 2 0 876526532 51097600 6877 1283457024 134512640 137933492 4288376816 18446744073709551615 135855000 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/30054/statm: 12475 6877 4263 836 0 6684 0
[pid=30054/tid=30056] ppid=30033 vsize=49900 CPUtime=0
/proc/30054/task/30056/stat : 30056 (aptitude) S 30033 30033 2059 34821 2220 4202560 91 650 0 0 0 0 0 0 15 0 2 0 876526681 51097600 6877 1283457024 134512640 137933492 4288376816 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680194816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 5.17
Current children cumulated vsize (KiB) 52492

Solver just ended. Dumping a history of the last processes samples

[startup+6.40668 s]
/proc/loadavg: 1.49 1.33 1.23 2/48 30057
/proc/meminfo: memFree=735636/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2592 CPUtime=3.45
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 692 18003 0 1 0 0 337 8 17 0 1 0 876526137 2654208 294 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 648 294 249 194 0 34 0
[pid=30054] ppid=30033 vsize=50936 CPUtime=1.82
/proc/30054/stat : 30054 (aptitude) R 30033 30033 2059 34821 2220 4202496 12157 1059 177 0 171 10 0 1 22 0 2 0 876526532 52158464 7139 1283457024 134512640 137933492 4288376816 18446744073709551615 4159197460 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/30054/statm: 12734 7139 4266 836 0 6943 0
[pid=30054/tid=30056] ppid=30033 vsize=50936 CPUtime=0.01
/proc/30054/task/30056/stat : 30056 (aptitude) S 30033 30033 2059 34821 2220 4202560 91 1059 0 0 0 0 0 1 15 0 2 0 876526681 52158464 7139 1283457024 134512640 137933492 4288376816 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680194816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 5.27
Current children cumulated vsize (KiB) 53528

[startup+7.20685 s]
/proc/loadavg: 1.45 1.33 1.22 2/47 30060
/proc/meminfo: memFree=742960/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2592 CPUtime=5.36
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 719 31356 0 178 0 0 516 20 18 0 1 0 876526137 2654208 294 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 648 294 249 194 0 34 0
[pid=30060] ppid=30033 vsize=18516 CPUtime=0.72
/proc/30060/stat : 30060 (aptsolutions.na) R 30033 30033 2059 34821 2220 4202496 4263 0 0 0 70 2 0 0 22 0 1 0 876526786 18960384 4150 1283457024 134512640 134971616 4291987328 18446744073709551615 134915762 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30060/statm: 4629 4150 204 113 0 4031 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 21108

[startup+7.60693 s]
/proc/loadavg: 1.45 1.33 1.22 2/47 30060
/proc/meminfo: memFree=742960/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2592 CPUtime=5.36
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 719 31356 0 178 0 0 516 20 18 0 1 0 876526137 2654208 294 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 648 294 249 194 0 34 0
[pid=30060] ppid=30033 vsize=27196 CPUtime=1.12
/proc/30060/stat : 30060 (aptsolutions.na) R 30033 30033 2059 34821 2220 4202496 6433 0 0 0 110 2 0 0 25 0 1 0 876526786 27848704 6320 1283457024 134512640 134971616 4291987328 18446744073709551615 134953676 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30060/statm: 6799 6320 204 113 0 6201 0
Current children cumulated CPU time (s) 6.48
Current children cumulated vsize (KiB) 29788

[startup+8.00702 s]
/proc/loadavg: 1.45 1.33 1.22 2/47 30060
/proc/meminfo: memFree=719152/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2592 CPUtime=5.36
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 719 31356 0 178 0 0 516 20 18 0 1 0 876526137 2654208 294 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 648 294 249 194 0 34 0
[pid=30060] ppid=30033 vsize=37580 CPUtime=1.51
/proc/30060/stat : 30060 (aptsolutions.na) R 30033 30033 2059 34821 2220 4202496 8981 0 0 0 149 2 0 0 25 0 1 0 876526786 38481920 8866 1283457024 134512640 134971616 4291987328 18446744073709551615 134911428 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30060/statm: 9395 8866 209 113 0 8797 0
Current children cumulated CPU time (s) 6.87
Current children cumulated vsize (KiB) 40172

[startup+8.10704 s]
/proc/loadavg: 1.45 1.33 1.22 2/47 30060
/proc/meminfo: memFree=719152/1048576 swapFree=2078744/2097144
[pid=30033] ppid=30032 vsize=2592 CPUtime=5.36
/proc/30033/stat : 30033 (aptitude-parano) S 30032 30033 2059 34821 2220 4202496 719 31356 0 178 0 0 516 20 18 0 1 0 876526137 2654208 294 1283457024 134512640 135304128 4294091088 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 648 294 249 194 0 34 0
[pid=30060] ppid=30033 vsize=44540 CPUtime=1.61
/proc/30060/stat : 30060 (aptsolutions.na) R 30033 30033 2059 34821 2220 4202496 10639 0 0 0 159 2 0 0 25 0 1 0 876526786 45608960 10524 1283457024 134512640 134971616 4291987328 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/30060/statm: 11135 10524 209 113 0 10537 0
Current children cumulated CPU time (s) 6.97
Current children cumulated vsize (KiB) 47132

Child status: 0
Real time (s): 8.14071
CPU time (s): 7.01644
CPU user time (s): 6.77642
CPU system time (s): 0.240015
CPU usage (%): 86.1895
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.77642
system time used= 0.240015
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43490
page faults= 178
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 243
involuntary context switches= 259

runsolver used 0 second user time and 0 second system time

The end