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/92.runsolver.aptitude aptitude -s -y --without-recommends install libnet0-dev bnfc libgnome-ruby1.6 libstonith-dev pentanet-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.18 1.14 1.05 2/55 24187
/proc/meminfo: memFree=870436/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=3152 CPUtime=0
/proc/24187/stat : 24187 (runsolver) R 24186 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29141240 3227648 32 18446744073709551615 134512640 134586868 4289268848 4289266896 4151243824 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.137631 s]
/proc/loadavg: 1.18 1.14 1.05 2/55 24187
/proc/meminfo: memFree=870436/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=100508 CPUtime=0.12
/proc/24187/stat : 24187 (aptitude) R 24186 24187 17863 34816 17863 4202496 10579 1709 0 0 11 1 0 0 20 0 1 0 29141240 102920192 10379 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305328 140704323404133 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 25127 10379 9205 1052 0 1122 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 100508

[startup+0.200287 s]
/proc/loadavg: 1.18 1.14 1.05 2/55 24187
/proc/meminfo: memFree=870436/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=100508 CPUtime=0.18
/proc/24187/stat : 24187 (aptitude) R 24186 24187 17863 34816 17863 4202496 10606 1709 0 0 17 1 0 0 20 0 1 0 29141240 102920192 10406 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305328 140704323960996 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 25127 10406 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300273 s]
/proc/loadavg: 1.18 1.14 1.05 2/55 24187
/proc/meminfo: memFree=870436/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=111108 CPUtime=0.29
/proc/24187/stat : 24187 (aptitude) R 24186 24187 17863 34816 17863 4202496 12390 1709 0 0 27 2 0 0 20 0 1 0 29141240 113774592 12182 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305656 140704330692179 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 27777 12182 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 111108

[startup+0.700209 s]
/proc/loadavg: 1.18 1.14 1.05 2/55 24187
/proc/meminfo: memFree=870436/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=123288 CPUtime=0.68
/proc/24187/stat : 24187 (aptitude) R 24186 24187 17863 34816 17863 4202496 17028 1709 0 0 61 7 0 0 20 0 2 0 29141240 126246912 14302 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779309848 140704323404791 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 30822 14302 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50023 s]
/proc/loadavg: 1.16 1.14 1.05 2/57 24192
/proc/meminfo: memFree=842272/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=132412 CPUtime=1.48
/proc/24187/stat : 24187 (aptitude) R 24186 24187 17863 34816 17863 4202496 19440 1709 0 0 140 8 0 0 20 0 2 0 29141240 135589888 16710 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779304416 140704331156983 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 33103 16710 9585 1052 0 9098 0
[pid=24187/tid=24192] ppid=24186 vsize=132412 CPUtime=0
/proc/24187/task/24192/stat : 24192 (aptitude) S 24186 24187 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29141305 135589888 16710 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219387904 140704297304788 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) 132412

[startup+3.10025 s]
/proc/loadavg: 1.16 1.14 1.05 2/57 24193
/proc/meminfo: memFree=840900/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=133916 CPUtime=3.07
/proc/24187/stat : 24187 (aptitude) R 24186 24187 17863 34816 17863 4202496 20627 2208 0 0 294 12 1 0 20 0 2 0 29141240 137129984 16954 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779300880 140704286071161 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 33479 16954 9644 1052 0 9474 0
[pid=24187/tid=24192] ppid=24186 vsize=133916 CPUtime=0.01
/proc/24187/task/24192/stat : 24192 (aptitude) S 24186 24187 17863 34816 17863 4202560 6 2208 0 0 0 0 1 0 20 0 2 0 29141305 137129984 16954 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219387904 140704297304788 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) 133916

[startup+6.30024 s]
/proc/loadavg: 1.16 1.14 1.05 2/57 24193
/proc/meminfo: memFree=802096/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=246312 CPUtime=6.26
/proc/24187/stat : 24187 (aptitude) S 24186 24187 17863 34816 17863 4202496 33186 2208 0 0 606 19 1 0 20 0 2 0 29141240 252223488 28924 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305824 140704297305675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 61578 28924 9700 1052 0 37573 0
[pid=24187/tid=24192] ppid=24186 vsize=246312 CPUtime=3.15
/proc/24187/task/24192/stat : 24192 (aptitude) R 24186 24187 17863 34816 17863 4202560 12558 2208 0 0 308 6 1 0 20 0 2 0 29141305 252223488 28924 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219377336 140704286071111 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 246312

[startup+12.7003 s]
/proc/loadavg: 1.14 1.14 1.05 2/57 24193
/proc/meminfo: memFree=709716/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=334424 CPUtime=12.63
/proc/24187/stat : 24187 (aptitude) S 24186 24187 17863 34816 17863 4202496 55702 2208 0 0 1236 26 1 0 20 0 2 0 29141240 342450176 50928 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305824 140704297305675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 83606 50928 9700 1052 0 59601 0
[pid=24187/tid=24192] ppid=24186 vsize=334424 CPUtime=9.52
/proc/24187/task/24192/stat : 24192 (aptitude) R 24186 24187 17863 34816 17863 4202560 35074 2208 0 0 938 13 1 0 20 0 2 0 29141305 342450176 50928 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219379224 140704331985497 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 334424

[startup+25.5003 s]
/proc/loadavg: 1.11 1.13 1.04 2/57 24193
/proc/meminfo: memFree=569844/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=471856 CPUtime=25.38
/proc/24187/stat : 24187 (aptitude) S 24186 24187 17863 34816 17863 4202496 90346 2208 0 0 2496 41 1 0 20 0 2 0 29141240 483180544 85265 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305824 140704297305675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 117964 85265 9715 1052 0 93959 0
[pid=24187/tid=24192] ppid=24186 vsize=471856 CPUtime=22.26
/proc/24187/task/24192/stat : 24192 (aptitude) R 24186 24187 17863 34816 17863 4202560 69711 2208 0 0 2197 28 1 0 20 0 2 0 29141305 483180544 85265 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219379528 140704331435561 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.38
Current children cumulated vsize (KiB) 471856

[startup+51.1003 s]
/proc/loadavg: 1.07 1.12 1.04 2/57 24193
/proc/meminfo: memFree=291960/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=752688 CPUtime=50.84
/proc/24187/stat : 24187 (aptitude) S 24186 24187 17863 34816 17863 4202496 160405 2208 0 0 5009 74 1 0 20 0 2 0 29141240 770752512 155324 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305824 140704297305675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 188172 155324 9716 1052 0 164167 0
[pid=24187/tid=24192] ppid=24186 vsize=752688 CPUtime=47.73
/proc/24187/task/24192/stat : 24192 (aptitude) R 24186 24187 17863 34816 17863 4202560 139770 2208 0 0 4710 62 1 0 20 0 2 0 29141305 770752512 155324 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219379352 140704331206938 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 50.84
Current children cumulated vsize (KiB) 752688

[startup+102.3 s]
/proc/loadavg: 1.18 1.13 1.05 2/57 24201
/proc/meminfo: memFree=9044/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=1108548 CPUtime=99.75
/proc/24187/stat : 24187 (aptitude) S 24186 24187 17863 34816 17863 4202496 249764 2208 240 0 9850 124 1 0 20 0 2 0 29141240 1135153152 239650 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305824 140704297305675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 277137 239650 9015 1052 0 253132 0
[pid=24187/tid=24192] ppid=24186 vsize=1108548 CPUtime=96.63
/proc/24187/task/24192/stat : 24192 (aptitude) R 24186 24187 17863 34816 17863 4202560 229121 2208 236 0 9551 111 1 0 20 0 2 0 29141305 1135153152 239650 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219381336 140704286061378 0 134217728 4096 0 0 0 0 -1 0 0 0 178 0 0
Current children cumulated CPU time (s) 99.75
Current children cumulated vsize (KiB) 1108548



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+111 s]
/proc/loadavg: 1.23 1.14 1.05 2/57 24201
/proc/meminfo: memFree=8144/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=1151184 CPUtime=105.92
/proc/24187/stat : 24187 (aptitude) S 24186 24187 17863 34816 17863 4202496 261103 2208 624 0 10457 134 1 0 20 0 2 0 29141240 1178812416 246025 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305824 140704297305675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 287796 246025 9491 1052 0 263791 0
[pid=24187/tid=24192] ppid=24186 vsize=1151184 CPUtime=102.8
/proc/24187/task/24192/stat : 24192 (aptitude) R 24186 24187 17863 34816 17863 4202560 240460 2208 620 0 10158 121 1 0 20 0 2 0 29141305 1178812416 246025 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219379224 140704286071117 0 134217728 4096 0 0 0 0 -1 0 0 0 419 0 0
Current children cumulated CPU time (s) 105.92
Current children cumulated vsize (KiB) 1151184

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

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

[startup+111 s]
/proc/loadavg: 1.23 1.14 1.05 2/57 24201
/proc/meminfo: memFree=8144/1022884 swapFree=0/0
[pid=24187] ppid=24186 vsize=1151184 CPUtime=105.92
/proc/24187/stat : 24187 (aptitude) S 24186 24187 17863 34816 17863 4202496 261103 2208 624 0 10457 134 1 0 20 0 2 0 29141240 1178812416 246025 18446744073709551615 140704328560640 140704332867992 140733779314064 140733779305824 140704297305675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24187/statm: 287796 246025 9491 1052 0 263791 0
[pid=24187/tid=24192] ppid=24186 vsize=1151184 CPUtime=102.8
/proc/24187/task/24192/stat : 24192 (aptitude) R 24186 24187 17863 34816 17863 4202560 240460 2208 620 0 10158 121 1 0 20 0 2 0 29141305 1178812416 246025 18446744073709551615 140704328560640 140704332867992 140733779314064 140704219379224 140704286071117 0 134217728 4096 0 0 0 0 -1 0 0 0 419 0 0
Current children cumulated CPU time (s) 105.92
Current children cumulated vsize (KiB) 1151184

Child ended because it received signal 15 (SIGTERM)
Real time (s): 111.13
CPU time (s): 106.043
CPU user time (s): 104.631
CPU system time (s): 1.41209
CPU usage (%): 95.4218
Max. virtual memory (cumulated for all children) (KiB): 1151184

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 104.631
system time used= 1.41209
maximum resident set size= 985400
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263361
page faults= 627
swaps= 0
block input operations= 24448
block output operations= 72
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 963
involuntary context switches= 2658

runsolver used 0.128008 second user time and 0.384024 second system time

The end