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/rand815.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand815.sarge-etch-lenny.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand815.sarge-etch-lenny.cudf.sarge-etch-lenny.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.12 1.19 1.18 1/45 21922
/proc/meminfo: memFree=824540/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=3024 CPUtime=0
/proc/21922/stat : 21922 (runsolver) D 21921 21922 2059 34821 2220 4202560 73 0 0 0 0 0 0 0 25 0 1 0 876059746 3096576 94 1283457024 134512640 134586868 4290159744 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/21922/statm: 756 94 62 19 0 54 0

[startup+0.149951 s]
/proc/loadavg: 1.12 1.19 1.18 1/45 21922
/proc/meminfo: memFree=824540/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2588 CPUtime=0.02
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 571 1866 0 0 0 0 0 2 25 0 1 0 876059746 2650112 285 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.209967 s]
/proc/loadavg: 1.12 1.19 1.18 1/45 21922
/proc/meminfo: memFree=824540/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2588 CPUtime=0.02
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 571 1866 0 0 0 0 0 2 25 0 1 0 876059746 2650112 285 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.309983 s]
/proc/loadavg: 1.12 1.19 1.18 1/45 21922
/proc/meminfo: memFree=824540/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2588 CPUtime=0.02
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 571 1866 0 0 0 0 0 2 25 0 1 0 876059746 2650112 285 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.71006 s]
/proc/loadavg: 1.12 1.19 1.18 1/45 21922
/proc/meminfo: memFree=824540/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2588 CPUtime=0.02
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 571 1866 0 0 0 0 0 2 25 0 1 0 876059746 2650112 285 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+1.51021 s]
/proc/loadavg: 1.19 1.20 1.18 2/47 21933
/proc/meminfo: memFree=790588/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2588 CPUtime=0.02
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 571 1866 0 0 0 0 0 2 25 0 1 0 876059746 2650112 285 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 647 285 240 194 0 33 0
[pid=21933] ppid=21922 vsize=31204 CPUtime=1.42
/proc/21933/stat : 21933 (cudftodeb.nativ) R 21922 21922 2059 34821 2220 4202496 7390 0 8 0 140 2 0 0 25 0 1 0 876059751 31952896 7324 1283457024 134512640 135004320 4294230176 18446744073709551615 134829624 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21933/statm: 7801 7324 225 121 0 7193 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 33792

[startup+3.11067 s]
/proc/loadavg: 1.19 1.20 1.18 2/47 21933
/proc/meminfo: memFree=769384/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2588 CPUtime=0.02
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 571 1866 0 0 0 0 0 2 25 0 1 0 876059746 2650112 285 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 647 285 240 194 0 33 0
[pid=21933] ppid=21922 vsize=65632 CPUtime=3.01
/proc/21933/stat : 21933 (cudftodeb.nativ) R 21922 21922 2059 34821 2220 4202496 15823 0 8 0 294 7 0 0 25 0 1 0 876059751 67207168 15755 1283457024 134512640 135004320 4294230176 18446744073709551615 4159313437 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21933/statm: 16408 15755 237 121 0 15800 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 68220

[startup+6.30775 s]
/proc/loadavg: 1.18 1.20 1.18 2/47 21933
/proc/meminfo: memFree=756240/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=5.5
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 657 24441 0 8 0 0 532 18 18 0 1 0 876059746 2658304 288 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 288 241 194 0 35 0
Current children cumulated CPU time (s) 5.5
Current children cumulated vsize (KiB) 2596

[startup+12.713 s]
/proc/loadavg: 1.16 1.19 1.18 3/48 21947
/proc/meminfo: memFree=703464/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=5.73
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 707 26842 0 9 0 0 553 20 18 0 1 0 876059746 2658304 296 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 296 249 194 0 35 0
[pid=21943] ppid=21922 vsize=76856 CPUtime=4.62
/proc/21943/stat : 21943 (aptitude) R 21922 21922 2059 34821 2220 4202496 19512 651 326 0 450 12 0 0 20 0 2 0 876060410 78700544 13478 1283457024 134512640 137933492 4293068048 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/21943/statm: 19214 13478 5659 836 0 11896 0
[pid=21943/tid=21945] ppid=21922 vsize=76856 CPUtime=2
/proc/21943/task/21945/stat : 21945 (aptitude) R 21922 21922 2059 34821 2220 4202560 5663 651 0 0 200 0 0 0 18 0 2 0 876060664 78700544 13478 1283457024 134512640 137933492 4293068048 18446744073709551615 4153171237 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.35
Current children cumulated vsize (KiB) 79452

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

[startup+12.8131 s]
/proc/loadavg: 1.16 1.19 1.18 3/48 21947
/proc/meminfo: memFree=703464/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=5.73
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 707 26842 0 9 0 0 553 20 18 0 1 0 876059746 2658304 296 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 296 249 194 0 35 0
[pid=21943] ppid=21922 vsize=76988 CPUtime=4.72
/proc/21943/stat : 21943 (aptitude) R 21922 21922 2059 34821 2220 4202496 19555 651 326 0 460 12 0 0 20 0 2 0 876060410 78835712 13521 1283457024 134512640 137933492 4293068048 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/21943/statm: 19247 13521 5659 836 0 11929 0
[pid=21943/tid=21945] ppid=21922 vsize=76988 CPUtime=2.1
/proc/21943/task/21945/stat : 21945 (aptitude) R 21922 21922 2059 34821 2220 4202560 5706 651 0 0 210 0 0 0 18 0 2 0 876060664 78835712 13521 1283457024 134512640 137933492 4293068048 18446744073709551615 4155102977 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.45
Current children cumulated vsize (KiB) 79584

[startup+16.0137 s]
/proc/loadavg: 1.15 1.19 1.18 2/48 21947
/proc/meminfo: memFree=693296/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=5.73
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 707 26842 0 9 0 0 553 20 18 0 1 0 876059746 2658304 296 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 296 249 194 0 35 0
[pid=21943] ppid=21922 vsize=92004 CPUtime=7.92
/proc/21943/stat : 21943 (aptitude) S 21922 21922 2059 34821 2220 4202496 23037 651 326 0 778 14 0 0 15 0 2 0 876060410 94212096 17003 1283457024 134512640 137933492 4293068048 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/21943/statm: 23001 17003 5660 836 0 15683 0
[pid=21943/tid=21945] ppid=21922 vsize=92004 CPUtime=5.3
/proc/21943/task/21945/stat : 21945 (aptitude) R 21922 21922 2059 34821 2220 4202560 9186 651 0 0 528 2 0 0 25 0 2 0 876060664 94212096 17003 1283457024 134512640 137933492 4293068048 18446744073709551615 136299293 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 13.65
Current children cumulated vsize (KiB) 94600

[startup+17.6075 s]
/proc/loadavg: 1.15 1.19 1.18 3/48 21948
/proc/meminfo: memFree=681212/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=5.73
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 707 26842 0 9 0 0 553 20 18 0 1 0 876059746 2658304 296 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 296 249 194 0 35 0
[pid=21943] ppid=21922 vsize=97788 CPUtime=9.45
/proc/21943/stat : 21943 (aptitude) R 21922 21922 2059 34821 2220 4202496 25993 1063 329 0 927 18 0 0 16 0 2 0 876060410 100134912 18646 1283457024 134512640 137933492 4293068048 18446744073709551615 4159124105 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/21943/statm: 24447 18646 5711 836 0 17122 0
[pid=21943/tid=21945] ppid=21922 vsize=97788 CPUtime=6.31
/proc/21943/task/21945/stat : 21945 (aptitude) R 21922 21922 2059 34821 2220 4202560 10338 1063 1 0 629 2 0 0 25 0 2 0 876060664 100134912 18646 1283457024 134512640 137933492 4293068048 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 15.18
Current children cumulated vsize (KiB) 100384

[startup+19.2088 s]
/proc/loadavg: 1.15 1.19 1.18 2/47 21949
/proc/meminfo: memFree=715352/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=15.4
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 732 54054 0 343 0 0 1502 38 18 0 1 0 876059746 2658304 296 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 296 249 194 0 35 0
[pid=21949] ppid=21922 vsize=29916 CPUtime=1.29
/proc/21949/stat : 21949 (aptsolutions.na) R 21922 21922 2059 34821 2220 4202496 7069 0 8 0 128 1 0 0 22 0 1 0 876061533 30633984 6962 1283457024 134512640 134971616 4294076768 18446744073709551615 134946339 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21949/statm: 7479 6962 204 113 0 6881 0
Current children cumulated CPU time (s) 16.69
Current children cumulated vsize (KiB) 32512

[startup+20.009 s]
/proc/loadavg: 1.15 1.19 1.18 2/47 21949
/proc/meminfo: memFree=693156/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=15.4
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 732 54054 0 343 0 0 1502 38 18 0 1 0 876059746 2658304 296 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 296 249 194 0 35 0
[pid=21949] ppid=21922 vsize=45488 CPUtime=2.09
/proc/21949/stat : 21949 (aptsolutions.na) R 21922 21922 2059 34821 2220 4202496 10882 0 8 0 208 1 0 0 25 0 1 0 876061533 46579712 10773 1283457024 134512640 134971616 4294076768 18446744073709551615 4158707229 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21949/statm: 11372 10773 204 113 0 10774 0
Current children cumulated CPU time (s) 17.49
Current children cumulated vsize (KiB) 48084

[startup+20.2092 s]
/proc/loadavg: 1.15 1.19 1.18 2/47 21949
/proc/meminfo: memFree=693156/1048576 swapFree=2078744/2097144
[pid=21922] ppid=21921 vsize=2596 CPUtime=15.4
/proc/21922/stat : 21922 (aptitude-parano) S 21921 21922 2059 34821 2220 4202496 732 54054 0 343 0 0 1502 38 18 0 1 0 876059746 2658304 296 1283457024 134512640 135304128 4290917904 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21922/statm: 649 296 249 194 0 35 0
[pid=21949] ppid=21922 vsize=50832 CPUtime=2.29
/proc/21949/stat : 21949 (aptsolutions.na) R 21922 21922 2059 34821 2220 4202496 12261 0 8 0 228 1 0 0 25 0 1 0 876061533 52051968 12152 1283457024 134512640 134971616 4294076768 18446744073709551615 134837628 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21949/statm: 12708 12152 209 113 0 12110 0
Current children cumulated CPU time (s) 17.69
Current children cumulated vsize (KiB) 53428

Child status: 0
Real time (s): 20.2507
CPU time (s): 17.7491
CPU user time (s): 17.3411
CPU system time (s): 0.408025
CPU usage (%): 87.647
Max. virtual memory (cumulated for all children) (KiB): 111008

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 17.3411
system time used= 0.408025
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67698
page faults= 351
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 471
involuntary context switches= 422

runsolver used 0 second user time and 0 second system time

The end