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/70.runsolver.aptitude aptitude -s -y --without-recommends install libformsgl1 dh-make bigloo-doc libauthen-sasl-cyrus-perl clamav 

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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.38 1.13 1.03 2/55 23765
/proc/meminfo: memFree=952532/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=3152 CPUtime=0
/proc/23765/stat : 23765 (runsolver) D 23764 23765 17863 34816 17863 4202560 80 0 0 0 0 0 0 0 20 0 1 0 29034501 3227648 101 18446744073709551615 134512640 134586868 4287497504 4287495472 4151665712 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23765/statm: 788 101 69 19 0 73 0

[startup+0.116751 s]
/proc/loadavg: 1.38 1.13 1.03 2/55 23765
/proc/meminfo: memFree=952532/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=7872 CPUtime=0
/proc/23765/stat : 23765 (aptitude) D 23764 23765 17863 34816 17863 4202496 126 0 3 0 0 0 0 0 20 0 1 0 29034501 8060928 46 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209673048 140089260458455 0 0 0 0 0 0 0 17 0 0 0 10 0 0
/proc/23765/statm: 1968 46 34 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 7872

[startup+0.200406 s]
/proc/loadavg: 1.38 1.13 1.03 2/55 23765
/proc/meminfo: memFree=952532/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=25980 CPUtime=0
/proc/23765/stat : 23765 (aptitude) D 23764 23765 17863 34816 17863 4202496 152 0 9 0 0 0 0 0 20 0 1 0 29034501 26603520 73 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209672168 140089260462870 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23765/statm: 6495 73 48 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 25980

[startup+0.300361 s]
/proc/loadavg: 1.38 1.13 1.03 2/55 23765
/proc/meminfo: memFree=952532/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=44448 CPUtime=0
/proc/23765/stat : 23765 (aptitude) D 23764 23765 17863 34816 17863 4202496 182 0 16 0 0 0 0 0 20 0 1 0 29034501 45514752 105 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209671688 140089260463494 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/23765/statm: 11112 105 65 1052 0 61 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 44448

[startup+0.700328 s]
/proc/loadavg: 1.38 1.13 1.03 2/55 23765
/proc/meminfo: memFree=952532/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=100508 CPUtime=0.02
/proc/23765/stat : 23765 (aptitude) D 23764 23765 17863 34816 17863 4202496 2576 1702 30 4 1 1 0 0 20 0 1 0 29034501 102920192 2406 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209666976 140089257654170 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/23765/statm: 25127 2406 1231 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+1.50021 s]
/proc/loadavg: 1.38 1.13 1.03 2/56 23769
/proc/meminfo: memFree=945580/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=100652 CPUtime=0.29
/proc/23765/stat : 23765 (aptitude) R 23764 23765 17863 34816 17863 4202496 10626 1702 97 4 26 3 0 0 20 0 1 0 29034501 103067648 10515 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209665280 140089257453675 0 134217728 4096 0 0 0 0 17 0 0 0 115 0 0
/proc/23765/statm: 25163 10515 9297 1052 0 1158 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 100652

[startup+3.10022 s]
/proc/loadavg: 1.35 1.13 1.03 2/56 23769
/proc/meminfo: memFree=877628/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=132144 CPUtime=1.18
/proc/23765/stat : 23765 (aptitude) R 23764 23765 17863 34816 17863 4202496 19212 1702 97 4 106 12 0 0 20 0 2 0 29034501 135315456 16581 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209666776 140089264806228 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 186 0 0
/proc/23765/statm: 33036 16581 9548 1052 0 9031 0
Current children cumulated CPU time (s) 1.18
Current children cumulated vsize (KiB) 132144
heavy processes:

[startup+6.30023 s]
/proc/loadavg: 1.35 1.13 1.03 2/57 23771
/proc/meminfo: memFree=831988/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=159308 CPUtime=4.33
/proc/23765/stat : 23765 (aptitude) S 23764 23765 17863 34816 17863 4202496 27350 2200 97 5 412 20 1 0 20 0 2 0 29034501 163131392 23560 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209667264 140089231349323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/23765/statm: 39827 23560 9700 1052 0 15822 0
[pid=23765/tid=23770] ppid=23764 vsize=159308 CPUtime=1.18
/proc/23765/task/23770/stat : 23770 (aptitude) R 23764 23765 17863 34816 17863 4202560 6855 2200 0 5 116 1 1 0 20 0 2 0 29034760 163131392 23560 18446744073709551615 140089262604288 140089266911640 140733209675504 140089153425080 140089265250939 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.33
Current children cumulated vsize (KiB) 159308
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.32 1.13 1.03 2/57 23771
/proc/meminfo: memFree=769368/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=277024 CPUtime=10.7
/proc/23765/stat : 23765 (aptitude) S 23764 23765 17863 34816 17863 4202496 41073 2200 97 5 1042 27 1 0 20 0 2 0 29034501 283672576 36592 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209667264 140089231349323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/23765/statm: 69256 36592 9700 1052 0 45251 0
[pid=23765/tid=23770] ppid=23764 vsize=277024 CPUtime=7.54
/proc/23765/task/23770/stat : 23770 (aptitude) R 23764 23765 17863 34816 17863 4202560 20577 2200 0 5 745 8 1 0 20 0 2 0 29034760 283672576 36592 18446744073709551615 140089262604288 140089266911640 140733209675504 140089153425080 140089219791532 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.7
Current children cumulated vsize (KiB) 277024

[startup+25.5003 s]
/proc/loadavg: 1.25 1.12 1.03 2/57 23771
/proc/meminfo: memFree=658884/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=384428 CPUtime=23.44
/proc/23765/stat : 23765 (aptitude) S 23764 23765 17863 34816 17863 4202496 68339 2200 97 5 2302 41 1 0 20 0 2 0 29034501 393654272 63411 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209667264 140089231349323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/23765/statm: 96107 63411 9700 1052 0 72102 0
[pid=23765/tid=23770] ppid=23764 vsize=384428 CPUtime=20.28
/proc/23765/task/23770/stat : 23770 (aptitude) R 23764 23765 17863 34816 17863 4202560 47843 2200 0 5 2004 23 1 0 20 0 2 0 29034760 393654272 63411 18446744073709551615 140089262604288 140089266911640 140733209675504 140089153425208 140089265250819 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.44
Current children cumulated vsize (KiB) 384428

[startup+51.1003 s]
/proc/loadavg: 1.16 1.11 1.02 2/57 23771
/proc/meminfo: memFree=450440/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=595716 CPUtime=48.92
/proc/23765/stat : 23765 (aptitude) S 23764 23765 17863 34816 17863 4202496 121193 2200 97 5 4825 66 1 0 20 0 2 0 29034501 610013184 116180 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209667264 140089231349323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/23765/statm: 148929 116180 9716 1052 0 124924 0
[pid=23765/tid=23770] ppid=23764 vsize=595716 CPUtime=45.76
/proc/23765/task/23770/stat : 23770 (aptitude) R 23764 23765 17863 34816 17863 4202560 100691 2200 0 5 4527 48 1 0 20 0 2 0 29034760 610013184 116180 18446744073709551615 140089262604288 140089266911640 140733209675504 140089153425912 140089220104517 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.92
Current children cumulated vsize (KiB) 595716

[startup+102.3 s]
/proc/loadavg: 1.15 1.11 1.02 2/57 23771
/proc/meminfo: memFree=8952/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=1107816 CPUtime=99.36
/proc/23765/stat : 23765 (aptitude) S 23764 23765 17863 34816 17863 4202496 249262 2200 107 5 9804 131 1 0 20 0 2 0 29034501 1134403584 241347 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209667264 140089231349323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/23765/statm: 276954 241347 9716 1052 0 252949 0
[pid=23765/tid=23770] ppid=23764 vsize=1107816 CPUtime=96.19
/proc/23765/task/23770/stat : 23770 (aptitude) R 23764 23765 17863 34816 17863 4202560 228760 2200 10 5 9506 112 1 0 20 0 2 0 29034760 1134403584 241347 18446744073709551615 140089262604288 140089266911640 140733209675504 140089153422920 140089264234103 0 134217728 4096 0 0 0 0 -1 0 0 0 34 0 0
Current children cumulated CPU time (s) 99.36
Current children cumulated vsize (KiB) 1107816



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+107.1 s]
/proc/loadavg: 1.14 1.11 1.02 2/57 23771
/proc/meminfo: memFree=9328/1022884 swapFree=0/0
[pid=23765] ppid=23764 vsize=1151112 CPUtime=103.52
/proc/23765/stat : 23765 (aptitude) S 23764 23765 17863 34816 17863 4202496 260137 2200 171 5 10214 137 1 0 20 0 2 0 29034501 1178738688 244740 18446744073709551615 140089262604288 140089266911640 140733209675504 140733209667264 140089231349323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 188 0 0
/proc/23765/statm: 287778 244740 9384 1052 0 263773 0
[pid=23765/tid=23770] ppid=23764 vsize=1151112 CPUtime=100.35
/proc/23765/task/23770/stat : 23770 (aptitude) R 23764 23765 17863 34816 17863 4202560 239623 2200 69 5 9916 118 1 0 20 0 2 0 29034760 1178738688 244740 18446744073709551615 140089262604288 140089266911640 140733209675504 140089153424984 140089265311704 0 134217728 4096 0 0 0 0 -1 0 0 0 75 0 0
Current children cumulated CPU time (s) 103.52
Current children cumulated vsize (KiB) 1151112

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): 107.213
CPU time (s): 103.63
CPU user time (s): 102.182
CPU system time (s): 1.44809
CPU usage (%): 96.6581
Max. virtual memory (cumulated for all children) (KiB): 1151112

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 102.182
system time used= 1.44809
maximum resident set size= 981468
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262406
page faults= 177
swaps= 0
block input operations= 165656
block output operations= 72
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1871
involuntary context switches= 2393

runsolver used 0.17201 second user time and 0.336021 second system time

The end