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/logs/60.runsolver.aptitude aptitude -s -y --without-recommends install eximon kid3 libwine-capi cpipe grcm 

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.00 1.00 0.94 2/55 21602
/proc/meminfo: memFree=854780/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=3152 CPUtime=0
/proc/21602/stat : 21602 (runsolver) R 21601 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28485464 3227648 32 18446744073709551615 134512640 134586868 4293471664 4293469712 4151219248 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.202221 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21602
/proc/meminfo: memFree=854780/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=89152 CPUtime=0.19
/proc/21602/stat : 21602 (aptitude) R 21601 21602 17863 34816 17863 4202496 7869 1709 0 0 17 2 0 0 20 0 1 0 28485464 91291648 7662 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619367456 139672156625234 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300287 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21602
/proc/meminfo: memFree=854780/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=101864 CPUtime=0.29
/proc/21602/stat : 21602 (aptitude) R 21601 21602 17863 34816 17863 4202496 11708 1709 0 0 26 3 0 0 20 0 1 0 28485464 104308736 10756 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619367112 139672119311895 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.400259 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21602
/proc/meminfo: memFree=854780/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=101864 CPUtime=0.39
/proc/21602/stat : 21602 (aptitude) R 21601 21602 17863 34816 17863 4202496 11708 1709 0 0 35 4 0 0 20 0 1 0 28485464 104308736 10756 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619367112 139672119311860 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.39
Current children cumulated vsize (KiB) 101864

[startup+0.7002 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21602
/proc/meminfo: memFree=854780/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=108268 CPUtime=0.69
/proc/21602/stat : 21602 (aptitude) R 21601 21602 17863 34816 17863 4202496 12196 1709 0 0 65 4 0 0 20 0 2 0 28485464 110866432 10570 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619373176 139672127704673 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 27067 10570 6925 1052 0 5637 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 108268

[startup+1.50024 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21607
/proc/meminfo: memFree=833816/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=115480 CPUtime=1.48
/proc/21602/stat : 21602 (aptitude) R 21601 21602 17863 34816 17863 4202496 14128 2208 0 0 142 5 1 0 20 0 2 0 28485464 118251520 12361 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619368392 139672156504522 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 28870 12361 7057 1052 0 7440 0
[pid=21602/tid=21607] ppid=21601 vsize=115480 CPUtime=0.01
/proc/21602/task/21607/stat : 21607 (aptitude) S 21601 21602 17863 34816 17863 4202560 4 2208 0 0 0 0 1 0 20 0 2 0 28485509 118251520 12361 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065177600 139672130515668 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) 115480

[startup+3.10024 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21608
/proc/meminfo: memFree=825632/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=197912 CPUtime=3.08
/proc/21602/stat : 21602 (aptitude) S 21601 21602 17863 34816 17863 4202496 19361 2208 0 0 297 10 1 0 20 0 2 0 28485464 202661888 16815 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619369440 139672130516555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 49478 16815 7129 1052 0 28048 0
[pid=21602/tid=21607] ppid=21601 vsize=197912 CPUtime=1.01
/proc/21602/task/21607/stat : 21607 (aptitude) R 21601 21602 17863 34816 17863 4202560 4670 2208 0 0 97 3 1 0 20 0 2 0 28485509 202661888 16815 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065171256 139672119271948 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) 197912

[startup+6.3003 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21608
/proc/meminfo: memFree=796988/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=224048 CPUtime=6.26
/proc/21602/stat : 21602 (aptitude) S 21601 21602 17863 34816 17863 4202496 26001 2208 0 0 612 13 1 0 20 0 2 0 28485464 229425152 23334 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619369440 139672130516555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 56012 23334 7129 1052 0 34582 0
[pid=21602/tid=21607] ppid=21601 vsize=224048 CPUtime=4.2
/proc/21602/task/21607/stat : 21607 (aptitude) R 21601 21602 17863 34816 17863 4202560 11310 2208 0 0 413 6 1 0 20 0 2 0 28485509 229425152 23334 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065168968 139672164417914 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) 224048

[startup+12.7002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21608
/proc/meminfo: memFree=740320/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=277400 CPUtime=12.64
/proc/21602/stat : 21602 (aptitude) S 21601 21602 17863 34816 17863 4202496 39657 2208 0 0 1241 22 1 0 20 0 2 0 28485464 284057600 36657 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619369440 139672130516555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 69350 36657 7129 1052 0 47920 0
[pid=21602/tid=21607] ppid=21601 vsize=277400 CPUtime=10.57
/proc/21602/task/21607/stat : 21607 (aptitude) R 21601 21602 17863 34816 17863 4202560 24966 2208 0 0 1041 15 1 0 20 0 2 0 28485509 284057600 36657 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065168920 139672164368221 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 277400

[startup+25.5032 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21608
/proc/meminfo: memFree=645708/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=368504 CPUtime=25.37
/proc/21602/stat : 21602 (aptitude) S 21601 21602 17863 34816 17863 4202496 62434 2208 0 0 2501 35 1 0 20 0 2 0 28485464 377348096 59434 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619369440 139672130516555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 92126 59434 7129 1052 0 70696 0
[pid=21602/tid=21607] ppid=21601 vsize=368504 CPUtime=23.31
/proc/21602/task/21607/stat : 21607 (aptitude) R 21601 21602 17863 34816 17863 4202560 47743 2208 0 0 2302 28 1 0 20 0 2 0 28485509 377348096 59434 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065168920 139672119271763 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) 368504

[startup+51.1002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21608
/proc/meminfo: memFree=468512/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=547372 CPUtime=50.86
/proc/21602/stat : 21602 (aptitude) S 21601 21602 17863 34816 17863 4202496 107094 2208 0 0 5029 56 1 0 20 0 2 0 28485464 560508928 104094 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619369440 139672130516555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 136843 104094 7129 1052 0 115413 0
[pid=21602/tid=21607] ppid=21601 vsize=547372 CPUtime=48.79
/proc/21602/task/21607/stat : 21607 (aptitude) R 21601 21602 17863 34816 17863 4202560 92403 2208 0 0 4829 49 1 0 20 0 2 0 28485509 560508928 104094 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065171128 139672164601375 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.86
Current children cumulated vsize (KiB) 547372

[startup+102.3 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21608
/proc/meminfo: memFree=146732/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=872704 CPUtime=101.82
/proc/21602/stat : 21602 (aptitude) S 21601 21602 17863 34816 17863 4202496 188358 2208 0 0 10083 98 1 0 20 0 2 0 28485464 893648896 185356 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619369440 139672130516555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 218176 185356 7143 1052 0 196746 0
[pid=21602/tid=21607] ppid=21601 vsize=872704 CPUtime=99.76
/proc/21602/task/21607/stat : 21607 (aptitude) R 21601 21602 17863 34816 17863 4202560 173660 2208 0 0 9883 92 1 0 20 0 2 0 28485509 893648896 185356 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065168872 139672164438131 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 101.82
Current children cumulated vsize (KiB) 872704



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+147.8 s]
/proc/loadavg: 1.26 1.06 0.96 2/57 21608
/proc/meminfo: memFree=9868/1022884 swapFree=0/0
[pid=21602] ppid=21601 vsize=1151192 CPUtime=146.11
/proc/21602/stat : 21602 (aptitude) S 21601 21602 17863 34816 17863 4202496 258063 2208 72 0 14477 133 1 0 20 0 2 0 28485464 1178820608 247494 18446744073709551615 139672161771520 139672166078872 140735619377680 140735619369440 139672130516555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21602/statm: 287798 247494 5884 1052 0 266368 0
[pid=21602/tid=21607] ppid=21601 vsize=1151192 CPUtime=144.03
/proc/21602/task/21607/stat : 21607 (aptitude) R 21601 21602 17863 34816 17863 4202560 243365 2208 72 0 14276 126 1 0 20 0 2 0 28485509 1178820608 247494 18446744073709551615 139672161771520 139672166078872 140735619377680 139672065168920 139672163982429 0 134217728 4096 0 0 0 0 -1 0 0 0 53 0 0
Current children cumulated CPU time (s) 146.11
Current children cumulated vsize (KiB) 1151192

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): 147.946
CPU time (s): 146.237
CPU user time (s): 144.825
CPU system time (s): 1.41209
CPU usage (%): 98.845
Max. virtual memory (cumulated for all children) (KiB): 1151192

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 144.825
system time used= 1.41209
maximum resident set size= 991320
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 260310
page faults= 72
swaps= 0
block input operations= 2936
block output operations= 48
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 433
involuntary context switches= 3210

runsolver used 0.384024 second user time and 0.292018 second system time

The end