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: runsolver -W 300 -M 1124 -w /home/cbse/results/sarge-etch-lenny-squeeze-sid/logs/21.runsolver.aptitude aptitude -s -y --without-recommends install liquidwar-data python2.3-weblib kaffe-pthreads plplot-bin python-gtk2-dev 

Enforcing wall clock limit (soft limit, will send signal-name then SIGKILL): 300 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

[startup+0 s]
/proc/loadavg: 1.05 1.08 1.03 2/55 25158
/proc/meminfo: memFree=832744/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=3152 CPUtime=0
/proc/25158/stat : 25158 (runsolver) R 25157 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29358001 3227648 32 18446744073709551615 134512640 134586868 4286770944 4286768992 4152218672 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.170758 s]
/proc/loadavg: 1.05 1.08 1.03 2/55 25158
/proc/meminfo: memFree=832744/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=103288 CPUtime=0.15
/proc/25158/stat : 25158 (aptitude) R 25157 25158 17863 34816 17863 4202496 11289 1710 0 0 14 1 0 0 20 0 1 0 29358001 105766912 11091 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920807920 139683970033413 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 25822 11091 9879 1052 0 1159 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 103288

[startup+0.200341 s]
/proc/loadavg: 1.05 1.08 1.03 2/55 25158
/proc/meminfo: memFree=832744/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=103288 CPUtime=0.19
/proc/25158/stat : 25158 (aptitude) R 25157 25158 17863 34816 17863 4202496 11299 1710 0 0 17 2 0 0 20 0 1 0 29358001 105766912 11101 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920807920 139683970588664 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300333 s]
/proc/loadavg: 1.05 1.08 1.03 2/55 25158
/proc/meminfo: memFree=832744/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=103432 CPUtime=0.29
/proc/25158/stat : 25158 (aptitude) R 25157 25158 17863 34816 17863 4202496 11426 1710 0 0 27 2 0 0 20 0 1 0 29358001 105914368 11220 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920806432 139683970041845 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103432

[startup+0.700206 s]
/proc/loadavg: 1.05 1.08 1.03 2/55 25158
/proc/meminfo: memFree=832744/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=123068 CPUtime=0.68
/proc/25158/stat : 25158 (aptitude) R 25157 25158 17863 34816 17863 4202496 17687 1710 0 0 62 6 0 0 20 0 1 0 29358001 126021632 15965 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920806088 139683970088856 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50031 s]
/proc/loadavg: 1.05 1.08 1.03 2/57 25163
/proc/meminfo: memFree=812772/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=136072 CPUtime=1.48
/proc/25158/stat : 25158 (aptitude) R 25157 25158 17863 34816 17863 4202496 20646 1710 0 0 141 7 0 0 20 0 2 0 29358001 139337728 17565 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920807928 139683932770175 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 34018 17565 10207 1052 0 9355 0
[pid=25158/tid=25163] ppid=25157 vsize=136072 CPUtime=0
/proc/25158/task/25163/stat : 25163 (aptitude) S 25157 25158 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29358078 139337728 17565 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862865920 139683943932628 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 136072

[startup+3.10031 s]
/proc/loadavg: 1.05 1.08 1.03 2/57 25163
/proc/meminfo: memFree=802480/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=137844 CPUtime=3.06
/proc/25158/stat : 25158 (aptitude) R 25157 25158 17863 34816 17863 4202496 22021 2208 0 0 294 12 0 0 20 0 2 0 29358001 141152256 17953 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920803360 139683970016300 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 34461 17953 10303 1052 0 9798 0
[pid=25158/tid=25163] ppid=25157 vsize=137844 CPUtime=0
/proc/25158/task/25163/stat : 25163 (aptitude) S 25157 25158 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 29358078 141152256 17953 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862865920 139683943932628 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 137844

[startup+6.3003 s]
/proc/loadavg: 1.05 1.08 1.03 2/57 25164
/proc/meminfo: memFree=758584/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=258948 CPUtime=6.25
/proc/25158/stat : 25158 (aptitude) S 25157 25158 17863 34816 17863 4202496 37002 2208 0 0 607 18 0 0 20 0 2 0 29358001 265162752 32059 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920808416 139683943933515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 64737 32059 10359 1052 0 40074 0
[pid=25158/tid=25163] ppid=25157 vsize=258948 CPUtime=2.83
/proc/25158/task/25163/stat : 25163 (aptitude) R 25157 25158 17863 34816 17863 4202560 14981 2208 0 0 278 5 0 0 20 0 2 0 29358078 265162752 32059 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862857192 139683941096480 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 258948

[startup+12.7003 s]
/proc/loadavg: 1.04 1.08 1.03 2/57 25164
/proc/meminfo: memFree=673520/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=334936 CPUtime=12.62
/proc/25158/stat : 25158 (aptitude) S 25157 25158 17863 34816 17863 4202496 56642 2208 0 0 1238 24 0 0 20 0 2 0 29358001 342974464 51061 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920808416 139683943933515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 83734 51061 10359 1052 0 59071 0
[pid=25158/tid=25163] ppid=25157 vsize=334936 CPUtime=9.21
/proc/25158/task/25163/stat : 25163 (aptitude) R 25157 25158 17863 34816 17863 4202560 34621 2208 0 0 910 11 0 0 20 0 2 0 29358078 342974464 51061 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862859448 139683977834786 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 334936

[startup+25.5003 s]
/proc/loadavg: 1.03 1.08 1.03 2/57 25164
/proc/meminfo: memFree=551380/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=454180 CPUtime=25.36
/proc/25158/stat : 25158 (aptitude) S 25157 25158 17863 34816 17863 4202496 86496 2208 0 0 2498 38 0 0 20 0 2 0 29358001 465080320 80849 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920808416 139683943933515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 113545 80849 10360 1052 0 88882 0
[pid=25158/tid=25163] ppid=25157 vsize=454180 CPUtime=21.94
/proc/25158/task/25163/stat : 25163 (aptitude) R 25157 25158 17863 34816 17863 4202560 64475 2208 0 0 2169 25 0 0 20 0 2 0 29358078 465080320 80849 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862857288 139683977389851 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 454180

[startup+51.1003 s]
/proc/loadavg: 1.02 1.07 1.02 2/57 25164
/proc/meminfo: memFree=337356/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=670828 CPUtime=50.84
/proc/25158/stat : 25158 (aptitude) S 25157 25158 17863 34816 17863 4202496 140648 2208 0 0 5026 58 0 0 20 0 2 0 29358001 686927872 134999 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920808416 139683943933515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 167707 134999 10375 1052 0 143044 0
[pid=25158/tid=25163] ppid=25157 vsize=670828 CPUtime=47.43
/proc/25158/task/25163/stat : 25163 (aptitude) R 25157 25158 17863 34816 17863 4202560 118620 2208 0 0 4697 46 0 0 20 0 2 0 29358078 686927872 134999 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862859496 139683978037050 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.84
Current children cumulated vsize (KiB) 670828

[startup+102.3 s]
/proc/loadavg: 1.23 1.10 1.03 2/57 25164
/proc/meminfo: memFree=8164/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=1081172 CPUtime=98.49
/proc/25158/stat : 25158 (aptitude) S 25157 25158 17863 34816 17863 4202496 244313 2208 393 0 9735 114 0 0 20 0 2 0 29358001 1107120128 234583 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920808416 139683943933515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 270293 234583 10316 1052 0 245630 0
[pid=25158/tid=25163] ppid=25157 vsize=1081172 CPUtime=95.07
/proc/25158/task/25163/stat : 25163 (aptitude) R 25157 25158 17863 34816 17863 4202560 222277 2208 389 0 9406 101 0 0 20 0 2 0 29358078 1107120128 234583 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862857240 139683941497450 0 134217728 4096 0 0 0 0 -1 0 0 0 314 0 0
Current children cumulated CPU time (s) 98.49
Current children cumulated vsize (KiB) 1081172



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+111.4 s]
/proc/loadavg: 1.19 1.10 1.03 2/57 25164
/proc/meminfo: memFree=8532/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=1151000 CPUtime=107.24
/proc/25158/stat : 25158 (aptitude) S 25157 25158 17863 34816 17863 4202496 261802 2208 412 0 10598 126 0 0 20 0 2 0 29358001 1178624000 246120 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920808416 139683943933515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 287750 246120 10318 1052 0 263087 0
[pid=25158/tid=25163] ppid=25157 vsize=1151000 CPUtime=103.82
/proc/25158/task/25163/stat : 25163 (aptitude) R 25157 25158 17863 34816 17863 4202560 239766 2208 408 0 10269 113 0 0 20 0 2 0 29358078 1178624000 246120 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862857368 139683932692020 0 134217728 4096 0 0 0 0 -1 0 0 0 333 0 0
Current children cumulated CPU time (s) 107.24
Current children cumulated vsize (KiB) 1151000

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

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

[startup+111.4 s]
/proc/loadavg: 1.19 1.10 1.03 2/57 25164
/proc/meminfo: memFree=8532/1022884 swapFree=0/0
[pid=25158] ppid=25157 vsize=1151000 CPUtime=107.24
/proc/25158/stat : 25158 (aptitude) S 25157 25158 17863 34816 17863 4202496 261802 2208 412 0 10598 126 0 0 20 0 2 0 29358001 1178624000 246120 18446744073709551615 139683975188480 139683979495832 140736920816656 140736920808416 139683943933515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25158/statm: 287750 246120 10318 1052 0 263087 0
[pid=25158/tid=25163] ppid=25157 vsize=1151000 CPUtime=103.82
/proc/25158/task/25163/stat : 25163 (aptitude) R 25157 25158 17863 34816 17863 4202560 239766 2208 408 0 10269 113 0 0 20 0 2 0 29358078 1178624000 246120 18446744073709551615 139683975188480 139683979495832 140736920816656 139683862857368 139683932692020 0 134217728 4096 0 0 0 0 -1 0 0 0 333 0 0
Current children cumulated CPU time (s) 107.24
Current children cumulated vsize (KiB) 1151000

Child ended because it received signal 15 (SIGTERM)
Real time (s): 111.53
CPU time (s): 107.395
CPU user time (s): 106.039
CPU system time (s): 1.35608
CPU usage (%): 96.2923
Max. virtual memory (cumulated for all children) (KiB): 1151000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 106.039
system time used= 1.35608
maximum resident set size= 984804
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 264091
page faults= 412
swaps= 0
block input operations= 14408
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 770
involuntary context switches= 2481

runsolver used 0.184011 second user time and 0.33202 second system time

The end