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/1.runsolver.aptitude aptitude -s -y --without-recommends install libgnome2-gconf-perl libroy1-prof python-simpy libchipcard20 libeb7-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: 0.81 0.98 0.99 2/55 24746
/proc/meminfo: memFree=792504/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=3152 CPUtime=0
/proc/24746/stat : 24746 (runsolver) R 24745 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29263113 3227648 32 18446744073709551615 134512640 134586868 4292559232 4292557280 4151604272 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.205144 s]
/proc/loadavg: 0.81 0.98 0.99 2/55 24746
/proc/meminfo: memFree=792504/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=103288 CPUtime=0.18
/proc/24746/stat : 24746 (aptitude) R 24745 24746 17863 34816 17863 4202496 11302 1709 0 0 16 2 0 0 20 0 1 0 29263113 105766912 11103 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636990752 140192090913260 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 25822 11103 9891 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.30035 s]
/proc/loadavg: 0.81 0.98 0.99 2/55 24746
/proc/meminfo: memFree=792504/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=103432 CPUtime=0.28
/proc/24746/stat : 24746 (aptitude) R 24745 24746 17863 34816 17863 4202496 11427 1709 0 0 26 2 0 0 20 0 1 0 29263113 105914368 11220 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636989264 140192091043810 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.400267 s]
/proc/loadavg: 0.81 0.98 0.99 2/55 24746
/proc/meminfo: memFree=792504/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=114256 CPUtime=0.38
/proc/24746/stat : 24746 (aptitude) R 24745 24746 17863 34816 17863 4202496 14145 1709 0 0 35 3 0 0 20 0 1 0 29263113 116998144 13937 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636988632 140192098315764 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 28564 13937 9967 1052 0 3901 0
Current children cumulated CPU time (s) 0.38
Current children cumulated vsize (KiB) 114256

[startup+0.700202 s]
/proc/loadavg: 0.81 0.98 0.99 2/55 24746
/proc/meminfo: memFree=792504/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=123068 CPUtime=0.68
/proc/24746/stat : 24746 (aptitude) R 24745 24746 17863 34816 17863 4202496 17688 1709 0 0 63 5 0 0 20 0 1 0 29263113 126021632 15965 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636988920 140192091091088 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 0.81 0.98 0.99 2/57 24751
/proc/meminfo: memFree=772268/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=136064 CPUtime=1.47
/proc/24746/stat : 24746 (aptitude) R 24745 24746 17863 34816 17863 4202496 20642 1709 1 0 141 6 0 0 20 0 2 0 29263113 139329536 17563 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636990760 140192053700704 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 34016 17563 10207 1052 0 9353 0
[pid=24746/tid=24751] ppid=24745 vsize=136064 CPUtime=0
/proc/24746/task/24751/stat : 24751 (aptitude) S 24745 24746 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29263190 139329536 17563 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983867904 140192064934612 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 136064

[startup+3.10024 s]
/proc/loadavg: 0.81 0.98 0.99 2/57 24751
/proc/meminfo: memFree=762100/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=137816 CPUtime=3.08
/proc/24746/stat : 24746 (aptitude) R 24745 24746 17863 34816 17863 4202496 21984 2212 1 0 298 9 0 1 20 0 2 0 29263113 141123584 17928 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636986192 140192099248554 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 34454 17928 10303 1052 0 9791 0
[pid=24746/tid=24751] ppid=24745 vsize=137816 CPUtime=0.01
/proc/24746/task/24751/stat : 24751 (aptitude) S 24745 24746 17863 34816 17863 4202560 6 2212 0 0 0 0 0 1 20 0 2 0 29263190 141123584 17928 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983867904 140192064934612 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 137816

[startup+6.30024 s]
/proc/loadavg: 0.82 0.98 0.99 2/57 24752
/proc/meminfo: memFree=719568/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=251400 CPUtime=6.26
/proc/24746/stat : 24746 (aptitude) S 24745 24746 17863 34816 17863 4202496 34799 2212 1 0 612 13 0 1 20 0 2 0 29263113 257433600 30189 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636991248 140192064935499 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 62850 30189 10359 1052 0 38187 0
[pid=24746/tid=24751] ppid=24745 vsize=251400 CPUtime=2.86
/proc/24746/task/24751/stat : 24751 (aptitude) R 24745 24746 17863 34816 17863 4202560 12814 2212 0 0 281 4 0 1 20 0 2 0 29263190 257433600 30189 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983861480 140192053700744 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) 251400

[startup+12.7002 s]
/proc/loadavg: 0.84 0.98 0.99 2/57 24752
/proc/meminfo: memFree=669596/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=296912 CPUtime=12.63
/proc/24746/stat : 24746 (aptitude) S 24745 24746 17863 34816 17863 4202496 46353 2212 1 0 1244 18 0 1 20 0 2 0 29263113 304037888 41557 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636991248 140192064935499 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 74228 41557 10360 1052 0 49565 0
[pid=24746/tid=24751] ppid=24745 vsize=296912 CPUtime=9.23
/proc/24746/task/24751/stat : 24751 (aptitude) R 24745 24746 17863 34816 17863 4202560 24368 2212 0 0 914 8 0 1 20 0 2 0 29263190 304037888 41557 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983860832 140192098775294 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) 296912

[startup+25.5032 s]
/proc/loadavg: 0.87 0.98 0.99 2/57 24752
/proc/meminfo: memFree=598668/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=365540 CPUtime=25.37
/proc/24746/stat : 24746 (aptitude) S 24745 24746 17863 34816 17863 4202496 63739 2212 1 0 2512 24 0 1 20 0 2 0 29263113 374312960 58720 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636991248 140192064935499 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 91385 58720 10360 1052 0 66722 0
[pid=24746/tid=24751] ppid=24745 vsize=365540 CPUtime=21.96
/proc/24746/task/24751/stat : 24751 (aptitude) R 24745 24746 17863 34816 17863 4202560 41754 2212 0 0 2181 14 0 1 20 0 2 0 29263190 374312960 58720 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983862152 140192091014265 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 365540

[startup+51.1003 s]
/proc/loadavg: 0.91 0.98 0.99 2/57 24752
/proc/meminfo: memFree=449364/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=516608 CPUtime=50.83
/proc/24746/stat : 24746 (aptitude) S 24745 24746 17863 34816 17863 4202496 102090 2212 1 0 5034 48 0 1 20 0 2 0 29263113 529006592 96480 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636991248 140192064935499 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 129152 96480 10360 1052 0 104489 0
[pid=24746/tid=24751] ppid=24745 vsize=516608 CPUtime=47.43
/proc/24746/task/24751/stat : 24751 (aptitude) R 24745 24746 17863 34816 17863 4202560 80105 2212 0 0 4703 39 0 1 20 0 2 0 29263190 529006592 96480 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983861560 140192098775294 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 50.83
Current children cumulated vsize (KiB) 516608

[startup+102.3 s]
/proc/loadavg: 1.04 1.00 1.00 2/57 24752
/proc/meminfo: memFree=8084/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=1009720 CPUtime=101.64
/proc/24746/stat : 24746 (aptitude) S 24745 24746 17863 34816 17863 4202496 225249 2212 1 0 10051 112 0 1 20 0 2 0 29263113 1033953280 219611 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636991248 140192064935499 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 252430 219611 10375 1052 0 227767 0
[pid=24746/tid=24751] ppid=24745 vsize=1009720 CPUtime=98.23
/proc/24746/task/24751/stat : 24751 (aptitude) R 24745 24746 17863 34816 17863 4202560 203258 2212 0 0 9720 102 0 1 20 0 2 0 29263190 1033953280 219611 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983859272 140192098935251 0 134217728 4096 0 0 0 0 -1 0 0 0 12 0 0
Current children cumulated CPU time (s) 101.64
Current children cumulated vsize (KiB) 1009720



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+116.803 s]
/proc/loadavg: 1.25 1.05 1.01 2/57 24752
/proc/meminfo: memFree=9108/1022884 swapFree=0/0
[pid=24746] ppid=24745 vsize=1151500 CPUtime=115.61
/proc/24746/stat : 24746 (aptitude) S 24745 24746 17863 34816 17863 4202496 260747 2212 7 0 11425 135 0 1 20 0 2 0 29263113 1179136000 247477 18446744073709551615 140192096190464 140192100497816 140736636999488 140736636991248 140192064935499 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24746/statm: 287875 247477 10297 1052 0 263212 0
[pid=24746/tid=24751] ppid=24745 vsize=1151500 CPUtime=112.2
/proc/24746/task/24751/stat : 24751 (aptitude) R 24745 24746 17863 34816 17863 4202560 238756 2212 6 0 11093 126 0 1 20 0 2 0 29263190 1179136000 247477 18446744073709551615 140192096190464 140192100497816 140736636999488 140191983859720 140192091590600 0 134217728 4096 0 0 0 0 -1 0 0 0 34 0 0
Current children cumulated CPU time (s) 115.61
Current children cumulated vsize (KiB) 1151500

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

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

Child ended because it received signal 15 (SIGTERM)
Real time (s): 116.92
CPU time (s): 115.707
CPU user time (s): 114.295
CPU system time (s): 1.41209
CPU usage (%): 98.9626
Max. virtual memory (cumulated for all children) (KiB): 1151500

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 114.295
system time used= 1.41209
maximum resident set size= 991792
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263031
page faults= 8
swaps= 0
block input operations= 480
block output operations= 80
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 310
involuntary context switches= 2620

runsolver used 0.176011 second user time and 0.368023 second system time

The end