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/logs/96.runsolver.aptitude aptitude -s -y --without-recommends install koffice-i18n-fi gforge-db-postgresql libdshconfig1-dev misdn-kernel-headers yarssr 

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.04 1.09 1.04 2/55 24231
/proc/meminfo: memFree=865748/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=3152 CPUtime=0
/proc/24231/stat : 24231 (runsolver) R 24230 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29169404 3227648 33 18446744073709551615 134512640 134586868 4293567536 4293565584 4151624752 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.192664 s]
/proc/loadavg: 1.04 1.09 1.04 2/55 24231
/proc/meminfo: memFree=865748/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=100508 CPUtime=0.18
/proc/24231/stat : 24231 (aptitude) R 24230 24231 17863 34816 17863 4202496 10606 1708 0 0 16 2 0 0 20 0 1 0 29169404 102920192 10406 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200733568 139905301640539 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 25127 10406 9231 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.200284 s]
/proc/loadavg: 1.04 1.09 1.04 2/55 24231
/proc/meminfo: memFree=865748/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=100508 CPUtime=0.19
/proc/24231/stat : 24231 (aptitude) R 24230 24231 17863 34816 17863 4202496 10607 1708 0 0 17 2 0 0 20 0 1 0 29169404 102920192 10407 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200733568 139905302199869 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 100508

[startup+0.300269 s]
/proc/loadavg: 1.04 1.09 1.04 2/55 24231
/proc/meminfo: memFree=865748/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=111108 CPUtime=0.28
/proc/24231/stat : 24231 (aptitude) R 24230 24231 17863 34816 17863 4202496 12372 1708 0 0 26 2 0 0 20 0 1 0 29169404 113774592 12164 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200733896 139905308931675 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 27777 12164 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700205 s]
/proc/loadavg: 1.04 1.09 1.04 2/55 24231
/proc/meminfo: memFree=865748/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=123288 CPUtime=0.68
/proc/24231/stat : 24231 (aptitude) R 24230 24231 17863 34816 17863 4202496 17030 1708 0 0 62 6 0 0 20 0 2 0 29169404 126246912 14303 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200738088 139905301643457 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.04 1.09 1.04 2/57 24236
/proc/meminfo: memFree=837468/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=132436 CPUtime=1.48
/proc/24231/stat : 24231 (aptitude) R 24230 24231 17863 34816 17863 4202496 19448 1708 0 0 141 7 0 0 20 0 2 0 29169404 135614464 16716 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200732656 139905310228253 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 33109 16716 9585 1052 0 9104 0
[pid=24231/tid=24236] ppid=24230 vsize=132436 CPUtime=0
/proc/24231/task/24236/stat : 24236 (aptitude) S 24230 24231 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29169469 135614464 16716 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197627392 139905275544276 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) 132436

[startup+3.10025 s]
/proc/loadavg: 1.04 1.09 1.04 2/57 24237
/proc/meminfo: memFree=836344/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=133848 CPUtime=3.07
/proc/24231/stat : 24231 (aptitude) R 24230 24231 17863 34816 17863 4202496 20639 2206 0 0 295 12 0 0 20 0 2 0 29169404 137060352 16959 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200729120 139905264310649 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 33462 16959 9644 1052 0 9457 0
[pid=24231/tid=24236] ppid=24230 vsize=133848 CPUtime=0
/proc/24231/task/24236/stat : 24236 (aptitude) S 24230 24231 17863 34816 17863 4202560 6 2206 0 0 0 0 0 0 20 0 2 0 29169469 137060352 16959 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197627392 139905275544276 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 133848

[startup+6.30024 s]
/proc/loadavg: 1.04 1.09 1.04 2/57 24237
/proc/meminfo: memFree=792084/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=246152 CPUtime=6.25
/proc/24231/stat : 24231 (aptitude) S 24230 24231 17863 34816 17863 4202496 33294 2206 0 0 609 16 0 0 20 0 2 0 29169404 252059648 28865 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200734064 139905275545163 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 61538 28865 9700 1052 0 37533 0
[pid=24231/tid=24236] ppid=24230 vsize=246152 CPUtime=3.14
/proc/24231/task/24236/stat : 24236 (aptitude) R 24230 24231 17863 34816 17863 4202560 12654 2206 0 0 310 4 0 0 20 0 2 0 29169469 252059648 28865 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197618712 139905309542664 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) 246152

[startup+12.7003 s]
/proc/loadavg: 1.03 1.08 1.04 2/57 24237
/proc/meminfo: memFree=744592/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=303120 CPUtime=12.62
/proc/24231/stat : 24231 (aptitude) S 24230 24231 17863 34816 17863 4202496 48093 2206 0 0 1242 20 0 0 20 0 2 0 29169404 310394880 43111 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200734064 139905275545163 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 75780 43111 9700 1052 0 51775 0
[pid=24231/tid=24236] ppid=24230 vsize=303120 CPUtime=9.5
/proc/24231/task/24236/stat : 24236 (aptitude) R 24230 24231 17863 34816 17863 4202560 27453 2206 0 0 943 7 0 0 20 0 2 0 29169469 310394880 43111 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197620872 139905309410358 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) 303120

[startup+25.5002 s]
/proc/loadavg: 1.02 1.08 1.04 2/57 24237
/proc/meminfo: memFree=635720/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=399484 CPUtime=25.36
/proc/24231/stat : 24231 (aptitude) S 24230 24231 17863 34816 17863 4202496 72224 2206 0 0 2506 30 0 0 20 0 2 0 29169404 409071616 67178 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200734064 139905275545163 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 99871 67178 9700 1052 0 75866 0
[pid=24231/tid=24236] ppid=24230 vsize=399484 CPUtime=22.24
/proc/24231/task/24236/stat : 24236 (aptitude) R 24230 24231 17863 34816 17863 4202560 51584 2206 0 0 2206 18 0 0 20 0 2 0 29169469 409071616 67178 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197621640 139905264295753 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) 399484

[startup+51.1003 s]
/proc/loadavg: 1.02 1.07 1.04 2/57 24237
/proc/meminfo: memFree=406692/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=633364 CPUtime=50.84
/proc/24231/stat : 24231 (aptitude) S 24230 24231 17863 34816 17863 4202496 130726 2206 0 0 5025 59 0 0 20 0 2 0 29169404 648564736 125605 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200734064 139905275545163 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24231/statm: 158341 125605 9716 1052 0 134336 0
[pid=24231/tid=24236] ppid=24230 vsize=633364 CPUtime=47.72
/proc/24231/task/24236/stat : 24236 (aptitude) R 24230 24231 17863 34816 17863 4202560 110079 2206 0 0 4726 46 0 0 20 0 2 0 29169469 648564736 125605 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197621528 139905264300917 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) 633364



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+96.6002 s]
/proc/loadavg: 1.15 1.09 1.04 2/57 24237
/proc/meminfo: memFree=9060/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=1151748 CPUtime=93.49
/proc/24231/stat : 24231 (aptitude) S 24230 24231 17863 34816 17863 4202496 260585 2206 248 0 9217 132 0 0 20 0 2 0 29169404 1179389952 245680 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200734064 139905275545163 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 3 0 0
/proc/24231/statm: 287937 245680 8731 1052 0 263932 0
[pid=24231/tid=24236] ppid=24230 vsize=1151748 CPUtime=90.36
/proc/24231/task/24236/stat : 24236 (aptitude) R 24230 24231 17863 34816 17863 4202560 239926 2206 243 0 8917 119 0 0 20 0 2 0 29169469 1179389952 245680 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197619112 139905309446440 0 134217728 4096 0 0 0 0 -1 0 0 0 235 0 0
Current children cumulated CPU time (s) 93.49
Current children cumulated vsize (KiB) 1151748

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

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

[startup+96.6002 s]
/proc/loadavg: 1.15 1.09 1.04 2/57 24237
/proc/meminfo: memFree=9060/1022884 swapFree=0/0
[pid=24231] ppid=24230 vsize=1151748 CPUtime=93.49
/proc/24231/stat : 24231 (aptitude) S 24230 24231 17863 34816 17863 4202496 260585 2206 248 0 9217 132 0 0 20 0 2 0 29169404 1179389952 245680 18446744073709551615 139905306800128 139905311107480 140737200742304 140737200734064 139905275545163 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 3 0 0
/proc/24231/statm: 287937 245680 8731 1052 0 263932 0
[pid=24231/tid=24236] ppid=24230 vsize=1151748 CPUtime=90.36
/proc/24231/task/24236/stat : 24236 (aptitude) R 24230 24231 17863 34816 17863 4202560 239926 2206 243 0 8917 119 0 0 20 0 2 0 29169469 1179389952 245680 18446744073709551615 139905306800128 139905311107480 140737200742304 139905197619112 139905309446440 0 134217728 4096 0 0 0 0 -1 0 0 0 235 0 0
Current children cumulated CPU time (s) 93.49
Current children cumulated vsize (KiB) 1151748

Child ended because it received signal 15 (SIGTERM)
Real time (s): 96.7285
CPU time (s): 93.6139
CPU user time (s): 92.2178
CPU system time (s): 1.39609
CPU usage (%): 96.78
Max. virtual memory (cumulated for all children) (KiB): 1151748

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 92.2178
system time used= 1.39609
maximum resident set size= 983148
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262892
page faults= 248
swaps= 0
block input operations= 11528
block output operations= 64
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 542
involuntary context switches= 2176

runsolver used 0.184011 second user time and 0.272017 second system time

The end