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/84.runsolver.aptitude aptitude -s -y --without-recommends install libcrypt-gpg-perl gtoaster cl-ptester libapache-mod-python2.3 opensc 

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.15 1.07 1.01 2/55 23891
/proc/meminfo: memFree=964332/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=3152 CPUtime=0
/proc/23891/stat : 23891 (runsolver) R 23890 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29107693 3227648 33 18446744073709551615 134512640 134586868 4289446688 4289444736 4151206960 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23891/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.196993 s]
/proc/loadavg: 1.15 1.07 1.01 2/55 23891
/proc/meminfo: memFree=964332/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=38696 CPUtime=0
/proc/23891/stat : 23891 (aptitude) D 23890 23891 17863 34816 17863 4202496 173 0 15 0 0 0 0 0 20 0 1 0 29107693 39624704 96 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512678152 139967932949238 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/23891/statm: 9674 96 61 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 38696

[startup+0.200383 s]
/proc/loadavg: 1.15 1.07 1.01 2/55 23891
/proc/meminfo: memFree=964332/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=38696 CPUtime=0
/proc/23891/stat : 23891 (aptitude) D 23890 23891 17863 34816 17863 4202496 173 0 15 0 0 0 0 0 20 0 1 0 29107693 39624704 96 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512678152 139967932949238 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/23891/statm: 9674 96 61 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 38696

[startup+0.300368 s]
/proc/loadavg: 1.15 1.07 1.01 2/55 23891
/proc/meminfo: memFree=964332/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=54968 CPUtime=0
/proc/23891/stat : 23891 (aptitude) D 23890 23891 17863 34816 17863 4202496 1028 0 25 0 0 0 0 0 20 0 1 0 29107693 56287232 943 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512676984 139967903846768 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/23891/statm: 13742 943 789 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700309 s]
/proc/loadavg: 1.15 1.07 1.01 2/55 23891
/proc/meminfo: memFree=964332/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=100508 CPUtime=0.01
/proc/23891/stat : 23891 (aptitude) D 23890 23891 17863 34816 17863 4202496 2755 1704 61 4 0 1 0 0 20 0 1 0 29107693 102920192 2616 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673296 139967930140570 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/23891/statm: 25127 2616 1442 1052 0 1122 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 100508

[startup+1.50032 s]
/proc/loadavg: 1.14 1.07 1.01 1/56 23895
/proc/meminfo: memFree=955768/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=100508 CPUtime=0.03
/proc/23891/stat : 23891 (aptitude) D 23890 23891 17863 34816 17863 4202496 5657 1704 195 4 1 2 0 0 20 0 1 0 29107693 102920192 5652 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673296 139967930140570 0 134217728 4096 0 0 0 0 17 0 0 0 141 0 0
/proc/23891/statm: 25127 5652 4478 1052 0 1122 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 100508

[startup+3.1002 s]
/proc/loadavg: 1.14 1.07 1.01 2/56 23895
/proc/meminfo: memFree=954032/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=119772 CPUtime=0.63
/proc/23891/stat : 23891 (aptitude) D 23890 23891 17863 34816 17863 4202496 16224 1704 285 4 50 13 0 0 20 0 1 0 29107693 122646528 14785 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512671256 139967903846768 0 134217728 4096 0 0 0 0 17 0 0 0 242 0 0
/proc/23891/statm: 29943 14785 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.63
Current children cumulated vsize (KiB) 119772
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.14 1.07 1.01 2/57 23897
/proc/meminfo: memFree=841432/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=210200 CPUtime=3.63
/proc/23891/stat : 23891 (aptitude) S 23890 23891 17863 34816 17863 4202496 23329 2200 285 6 342 21 0 0 20 0 2 0 29107693 215244800 19880 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673584 139967903835723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 259 0 0
/proc/23891/statm: 52550 19880 9698 1052 0 28545 0
[pid=23891/tid=23896] ppid=23890 vsize=210200 CPUtime=0.51
/proc/23891/task/23896/stat : 23896 (aptitude) R 23890 23891 17863 34816 17863 4202560 2981 2200 0 6 50 1 0 0 20 0 2 0 29108024 215244800 19880 18446744073709551615 139967935090688 139967939398040 140734512681824 139967825911976 139967903831598 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.63
Current children cumulated vsize (KiB) 210200
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.11 1.07 1.01 2/57 23897
/proc/meminfo: memFree=766660/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=276120 CPUtime=10
/proc/23891/stat : 23891 (aptitude) S 23890 23891 17863 34816 17863 4202496 40592 2200 285 6 974 26 0 0 20 0 2 0 29107693 282746880 36377 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673584 139967903835723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 259 0 0
/proc/23891/statm: 69030 36377 9700 1052 0 45025 0
[pid=23891/tid=23896] ppid=23890 vsize=276120 CPUtime=6.88
/proc/23891/task/23896/stat : 23896 (aptitude) R 23890 23891 17863 34816 17863 4202560 20244 2200 0 6 682 6 0 0 20 0 2 0 29108024 282746880 36377 18446744073709551615 139967935090688 139967939398040 140734512681824 139967825909272 139967903831598 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10
Current children cumulated vsize (KiB) 276120
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.10 1.07 1.01 2/57 23897
/proc/meminfo: memFree=691764/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=349352 CPUtime=22.73
/proc/23891/stat : 23891 (aptitude) S 23890 23891 17863 34816 17863 4202496 58945 2200 285 6 2238 35 0 0 20 0 2 0 29107693 357736448 54670 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673584 139967903835723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 259 0 0
/proc/23891/statm: 87338 54670 9700 1052 0 63333 0
[pid=23891/tid=23896] ppid=23890 vsize=349352 CPUtime=19.61
/proc/23891/task/23896/stat : 23896 (aptitude) R 23890 23891 17863 34816 17863 4202560 38597 2200 0 6 1946 15 0 0 20 0 2 0 29108024 357736448 54670 18446744073709551615 139967935090688 139967939398040 140734512681824 139967825911432 139967901399737 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.73
Current children cumulated vsize (KiB) 349352

[startup+51.1003 s]
/proc/loadavg: 1.06 1.06 1.00 2/57 23897
/proc/meminfo: memFree=516056/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=526952 CPUtime=48.22
/proc/23891/stat : 23891 (aptitude) S 23890 23891 17863 34816 17863 4202496 103744 2200 285 6 4766 56 0 0 20 0 2 0 29107693 539598848 99000 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673584 139967903835723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 259 0 0
/proc/23891/statm: 131738 99000 9714 1052 0 107733 0
[pid=23891/tid=23896] ppid=23890 vsize=526952 CPUtime=45.1
/proc/23891/task/23896/stat : 23896 (aptitude) R 23890 23891 17863 34816 17863 4202560 83389 2200 0 6 4474 36 0 0 20 0 2 0 29108024 539598848 99000 18446744073709551615 139967935090688 139967939398040 140734512681824 139967825911432 139967930491442 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.22
Current children cumulated vsize (KiB) 526952

[startup+102.3 s]
/proc/loadavg: 1.10 1.06 1.01 2/57 23901
/proc/meminfo: memFree=162684/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=847416 CPUtime=99.11
/proc/23891/stat : 23891 (aptitude) S 23890 23891 17863 34816 17863 4202496 183759 2200 285 6 9814 97 0 0 20 0 2 0 29107693 867753984 178994 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673584 139967903835723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 259 0 0
/proc/23891/statm: 211854 178994 9714 1052 0 187849 0
[pid=23891/tid=23896] ppid=23890 vsize=847416 CPUtime=95.97
/proc/23891/task/23896/stat : 23896 (aptitude) R 23890 23891 17863 34816 17863 4202560 163404 2200 0 6 9521 76 0 0 20 0 2 0 29108024 867753984 178994 18446744073709551615 139967935090688 139967939398040 140734512681824 139967825909272 139967901395948 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 99.11
Current children cumulated vsize (KiB) 847416



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+158 s]
/proc/loadavg: 1.44 1.17 1.04 2/57 24121
/proc/meminfo: memFree=8924/1022884 swapFree=0/0
[pid=23891] ppid=23890 vsize=1151988 CPUtime=146.25
/proc/23891/stat : 23891 (aptitude) S 23890 23891 17863 34816 17863 4202496 260976 2200 816 6 14471 154 0 0 20 0 2 0 29107693 1179635712 232067 18446744073709551615 139967935090688 139967939398040 140734512681824 140734512673584 139967903835723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 259 0 0
/proc/23891/statm: 287997 232067 7581 1052 0 263992 0
[pid=23891/tid=23896] ppid=23890 vsize=1151988 CPUtime=143.12
/proc/23891/task/23896/stat : 23896 (aptitude) R 23890 23891 17863 34816 17863 4202560 240613 2200 527 6 14178 134 0 0 20 0 2 0 29108024 1179635712 232067 18446744073709551615 139967935090688 139967939398040 140734512681824 139967825909272 139967892600968 0 134217728 4096 0 0 0 0 -1 0 0 0 451 0 0
Current children cumulated CPU time (s) 146.25
Current children cumulated vsize (KiB) 1151988

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): 158.277
CPU time (s): 146.429
CPU user time (s): 144.809
CPU system time (s): 1.6201
CPU usage (%): 92.5144
Max. virtual memory (cumulated for all children) (KiB): 1151988

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 144.809
system time used= 1.6201
maximum resident set size= 930472
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263350
page faults= 822
swaps= 0
block input operations= 215016
block output operations= 128
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2768
involuntary context switches= 7792

runsolver used 0.236014 second user time and 0.508031 second system time

The end