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/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

[startup+0 s]
/proc/loadavg: 1.08 1.09 1.06 2/55 26066
/proc/meminfo: memFree=952320/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=3152 CPUtime=0
/proc/26066/stat : 26066 (runsolver) R 26065 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29688025 3227648 32 18446744073709551615 134512640 134586868 4294876944 4294874992 4151759920 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26066/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.159441 s]
/proc/loadavg: 1.08 1.09 1.06 2/55 26066
/proc/meminfo: memFree=952320/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=12328 CPUtime=0
/proc/26066/stat : 26066 (aptitude) D 26065 26066 17863 34816 17863 4202496 130 0 4 0 0 0 0 0 20 0 1 0 29688025 12623872 51 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499563880 140176636278307 0 0 0 0 0 0 0 17 0 0 0 14 0 0
/proc/26066/statm: 3082 51 36 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.200404 s]
/proc/loadavg: 1.08 1.09 1.06 2/55 26066
/proc/meminfo: memFree=952320/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=19848 CPUtime=0
/proc/26066/stat : 26066 (aptitude) D 26065 26066 17863 34816 17863 4202496 142 0 7 0 0 0 0 0 20 0 1 0 29688025 20324352 64 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499563784 140176636277456 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/26066/statm: 4962 64 43 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 19848

[startup+0.300376 s]
/proc/loadavg: 1.08 1.09 1.06 2/55 26066
/proc/meminfo: memFree=952320/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=40832 CPUtime=0
/proc/26066/stat : 26066 (aptitude) D 26065 26066 17863 34816 17863 4202496 178 0 15 0 0 0 0 0 20 0 1 0 29688025 41811968 101 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499563400 140176636278307 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/26066/statm: 10208 101 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.700317 s]
/proc/loadavg: 1.08 1.09 1.06 2/55 26066
/proc/meminfo: memFree=952320/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=103288 CPUtime=0.02
/proc/26066/stat : 26066 (aptitude) D 26065 26066 17863 34816 17863 4202496 2794 1704 32 4 1 1 0 0 20 0 1 0 29688025 105766912 2628 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558448 140176633468826 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/26066/statm: 25822 2628 1416 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.50039 s]
/proc/loadavg: 1.08 1.09 1.06 1/56 26070
/proc/meminfo: memFree=944996/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=103432 CPUtime=0.3
/proc/26066/stat : 26066 (aptitude) D 26065 26066 17863 34816 17863 4202496 11237 1704 119 4 28 2 0 0 20 0 1 0 29688025 105914368 11157 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558488 140176607175024 0 134217728 4096 0 0 0 0 17 0 0 0 113 0 0
/proc/26066/statm: 25858 11157 9902 1052 0 1195 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 103432

[startup+3.10021 s]
/proc/loadavg: 1.08 1.09 1.06 2/56 26070
/proc/meminfo: memFree=865016/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=126624 CPUtime=1.11
/proc/26066/stat : 26066 (aptitude) R 26065 26066 17863 34816 17863 4202496 18098 1704 119 4 96 15 0 0 20 0 2 0 29688025 129662976 15138 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499562760 140176633262292 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 194 0 0
/proc/26066/statm: 31656 15138 10141 1052 0 6993 0
Current children cumulated CPU time (s) 1.11
Current children cumulated vsize (KiB) 126624
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.08 1.09 1.06 2/57 26072
/proc/meminfo: memFree=805488/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=220128 CPUtime=4.25
/proc/26066/stat : 26066 (aptitude) S 26065 26066 17863 34816 17863 4202496 26408 2202 119 5 403 22 0 0 20 0 2 0 29688025 225411072 22372 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558736 140176607163979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 196 0 0
/proc/26066/statm: 55032 22372 10359 1052 0 30369 0
[pid=26066/tid=26071] ppid=26065 vsize=220128 CPUtime=0.77
/proc/26066/task/26071/stat : 26071 (aptitude) R 26065 26066 17863 34816 17863 4202560 4538 2202 0 5 76 1 0 0 20 0 2 0 29688305 225411072 22372 18446744073709551615 140176638418944 140176642726296 140736499566976 140176526089960 140176641052000 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.25
Current children cumulated vsize (KiB) 220128
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.07 1.09 1.06 2/57 26072
/proc/meminfo: memFree=727616/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=284172 CPUtime=10.61
/proc/26066/stat : 26066 (aptitude) S 26065 26066 17863 34816 17863 4202496 42933 2202 119 5 1035 26 0 0 20 0 2 0 29688025 290992128 38384 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558736 140176607163979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 196 0 0
/proc/26066/statm: 71043 38384 10359 1052 0 46380 0
[pid=26066/tid=26071] ppid=26065 vsize=284172 CPUtime=7.14
/proc/26066/task/26071/stat : 26071 (aptitude) R 26065 26066 17863 34816 17863 4202560 21063 2202 0 5 708 6 0 0 20 0 2 0 29688305 290992128 38384 18446744073709551615 140176638418944 140176642726296 140736499566976 140176526089912 140176641154695 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.61
Current children cumulated vsize (KiB) 284172

[startup+25.5003 s]
/proc/loadavg: 1.05 1.09 1.06 2/57 26072
/proc/meminfo: memFree=644908/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=363648 CPUtime=23.33
/proc/26066/stat : 26066 (aptitude) S 26065 26066 17863 34816 17863 4202496 63585 2202 119 5 2299 34 0 0 20 0 2 0 29688025 372375552 58238 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558736 140176607163979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 196 0 0
/proc/26066/statm: 90912 58238 10360 1052 0 66249 0
[pid=26066/tid=26071] ppid=26065 vsize=363648 CPUtime=19.86
/proc/26066/task/26071/stat : 26071 (aptitude) R 26065 26066 17863 34816 17863 4202560 41715 2202 0 5 1972 14 0 0 20 0 2 0 29688305 372375552 58238 18446744073709551615 140176638418944 140176642726296 140736499566976 140176526087704 140176641120208 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 23.33
Current children cumulated vsize (KiB) 363648

[startup+51.1003 s]
/proc/loadavg: 1.03 1.08 1.06 2/57 26072
/proc/meminfo: memFree=504292/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=506120 CPUtime=48.82
/proc/26066/stat : 26066 (aptitude) S 26065 26066 17863 34816 17863 4202496 99315 2202 119 5 4831 51 0 0 20 0 2 0 29688025 518266880 93830 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558736 140176607163979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 196 0 0
/proc/26066/statm: 126530 93830 10360 1052 0 101867 0
[pid=26066/tid=26071] ppid=26065 vsize=506120 CPUtime=45.33
/proc/26066/task/26071/stat : 26071 (aptitude) R 26065 26066 17863 34816 17863 4202560 77445 2202 0 5 4503 30 0 0 20 0 2 0 29688305 518266880 93830 18446744073709551615 140176638418944 140176642726296 140736499566976 140176526089912 140176641065610 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 48.82
Current children cumulated vsize (KiB) 506120

[startup+102.354 s]
/proc/loadavg: 1.01 1.06 1.05 2/57 26072
/proc/meminfo: memFree=14068/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=1001316 CPUtime=99.62
/proc/26066/stat : 26066 (aptitude) S 26065 26066 17863 34816 17863 4202496 223014 2202 119 5 9854 108 0 0 20 0 2 0 29688025 1025347584 217494 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558736 140176607163979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 196 0 0
/proc/26066/statm: 250329 217494 10375 1052 0 225666 0
[pid=26066/tid=26071] ppid=26065 vsize=1001316 CPUtime=96.14
/proc/26066/task/26071/stat : 26071 (aptitude) R 26065 26066 17863 34816 17863 4202560 201138 2202 0 5 9526 88 0 0 20 0 2 0 29688305 1025347584 217494 18446744073709551615 140176638418944 140176642726296 140736499566976 140176526089816 140176633323728 0 134217728 4096 0 0 0 0 -1 0 0 0 22 0 0
Current children cumulated CPU time (s) 99.62
Current children cumulated vsize (KiB) 1001316



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+118.8 s]
/proc/loadavg: 1.35 1.14 1.08 2/57 26072
/proc/meminfo: memFree=9140/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=1151864 CPUtime=115.39
/proc/26066/stat : 26066 (aptitude) S 26065 26066 17863 34816 17863 4202496 260701 2202 142 5 11409 130 0 0 20 0 2 0 29688025 1179508736 244829 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558736 140176607163979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 196 0 0
/proc/26066/statm: 287966 244829 9186 1052 0 263303 0
[pid=26066/tid=26071] ppid=26065 vsize=1151864 CPUtime=111.9
/proc/26066/task/26071/stat : 26071 (aptitude) R 26065 26066 17863 34816 17863 4202560 238825 2202 23 5 11080 110 0 0 20 0 2 0 29688305 1179508736 244829 18446744073709551615 140176638418944 140176642726296 140736499566976 140176526087752 140176595929415 0 134217728 4096 0 0 0 0 -1 0 0 0 44 0 0
Current children cumulated CPU time (s) 115.39
Current children cumulated vsize (KiB) 1151864

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

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

[startup+118.8 s]
/proc/loadavg: 1.35 1.14 1.08 2/57 26072
/proc/meminfo: memFree=9140/1022884 swapFree=0/0
[pid=26066] ppid=26065 vsize=1151864 CPUtime=115.39
/proc/26066/stat : 26066 (aptitude) S 26065 26066 17863 34816 17863 4202496 260701 2202 142 5 11409 130 0 0 20 0 2 0 29688025 1179508736 244829 18446744073709551615 140176638418944 140176642726296 140736499566976 140736499558736 140176607163979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 196 0 0
/proc/26066/statm: 287966 244829 9186 1052 0 263303 0
[pid=26066/tid=26071] ppid=26065 vsize=1151864 CPUtime=111.9
/proc/26066/task/26071/stat : 26071 (aptitude) R 26065 26066 17863 34816 17863 4202560 238825 2202 23 5 11080 110 0 0 20 0 2 0 29688305 1179508736 244829 18446744073709551615 140176638418944 140176642726296 140736499566976 140176526087752 140176595929415 0 134217728 4096 0 0 0 0 -1 0 0 0 44 0 0
Current children cumulated CPU time (s) 115.39
Current children cumulated vsize (KiB) 1151864

Child ended because it received signal 15 (SIGTERM)
Real time (s): 118.921
CPU time (s): 115.515
CPU user time (s): 114.151
CPU system time (s): 1.36408
CPU usage (%): 97.1358
Max. virtual memory (cumulated for all children) (KiB): 1151864

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 114.151
system time used= 1.36408
maximum resident set size= 980760
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262995
page faults= 147
swaps= 0
block input operations= 232840
block output operations= 96
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2426
involuntary context switches= 2650

runsolver used 0.212013 second user time and 0.340021 second system time

The end