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/37.runsolver.aptitude aptitude -s -y --without-recommends install python-uncertainities libcfitsio2 contact-lookup-applet python-imaging-doc xfce4 

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.03 1.04 1.00 2/55 23234
/proc/meminfo: memFree=868476/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=3152 CPUtime=0
/proc/23234/stat : 23234 (runsolver) R 23233 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28870108 3227648 32 18446744073709551615 134512640 134586868 4286806800 4286804848 4151612464 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.14097 s]
/proc/loadavg: 1.03 1.04 1.00 2/55 23234
/proc/meminfo: memFree=868476/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=100508 CPUtime=0.12
/proc/23234/stat : 23234 (aptitude) R 23233 23234 17863 34816 17863 4202496 10580 1708 0 0 10 2 0 0 20 0 1 0 28870108 102920192 10382 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402802768 140403974262977 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 25127 10382 9207 1052 0 1122 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 100508

[startup+0.200284 s]
/proc/loadavg: 1.03 1.04 1.00 2/55 23234
/proc/meminfo: memFree=868476/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=100508 CPUtime=0.18
/proc/23234/stat : 23234 (aptitude) R 23233 23234 17863 34816 17863 4202496 10605 1708 0 0 16 2 0 0 20 0 1 0 28870108 102920192 10407 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402802768 140403974260566 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.30027 s]
/proc/loadavg: 1.03 1.04 1.00 2/55 23234
/proc/meminfo: memFree=868476/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=111108 CPUtime=0.28
/proc/23234/stat : 23234 (aptitude) R 23233 23234 17863 34816 17863 4202496 12457 1708 0 0 26 2 0 0 20 0 1 0 28870108 113774592 12251 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803096 140403981551212 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 27777 12251 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.7002 s]
/proc/loadavg: 1.03 1.04 1.00 2/55 23234
/proc/meminfo: memFree=868476/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=123288 CPUtime=0.68
/proc/23234/stat : 23234 (aptitude) R 23233 23234 17863 34816 17863 4202496 17028 1708 0 0 63 5 0 0 20 0 2 0 28870108 126246912 14303 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402807288 140403974262623 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50023 s]
/proc/loadavg: 1.03 1.04 1.00 2/57 23239
/proc/meminfo: memFree=840196/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=132416 CPUtime=1.48
/proc/23234/stat : 23234 (aptitude) R 23233 23234 17863 34816 17863 4202496 19442 1708 0 0 142 6 0 0 20 0 2 0 28870108 135593984 16712 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402801856 140403936915376 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 33104 16712 9585 1052 0 9099 0
[pid=23234/tid=23239] ppid=23233 vsize=132416 CPUtime=0
/proc/23234/task/23239/stat : 23239 (aptitude) S 23233 23234 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 28870173 135593984 16712 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870246912 140403948163796 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) 132416

[startup+3.10024 s]
/proc/loadavg: 1.03 1.04 1.00 2/57 23240
/proc/meminfo: memFree=839072/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=133828 CPUtime=3.07
/proc/23234/stat : 23234 (aptitude) R 23233 23234 17863 34816 17863 4202496 20622 2207 0 0 295 12 0 0 20 0 2 0 28870108 137039872 16956 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402798320 140403981995813 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 33457 16956 9644 1052 0 9452 0
[pid=23234/tid=23239] ppid=23233 vsize=133828 CPUtime=0
/proc/23234/task/23239/stat : 23239 (aptitude) S 23233 23234 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 28870173 137039872 16956 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870246912 140403948163796 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 133828

[startup+6.30025 s]
/proc/loadavg: 1.02 1.04 1.00 2/57 23240
/proc/meminfo: memFree=794068/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=247424 CPUtime=6.26
/proc/23234/stat : 23234 (aptitude) S 23233 23234 17863 34816 17863 4202496 33610 2207 0 0 606 20 0 0 20 0 2 0 28870108 253362176 29191 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803264 140403948164683 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 61856 29191 9700 1052 0 37851 0
[pid=23234/tid=23239] ppid=23233 vsize=247424 CPUtime=3.13
/proc/23234/task/23239/stat : 23239 (aptitude) R 23233 23234 17863 34816 17863 4202560 12987 2207 0 0 306 7 0 0 20 0 2 0 28870173 253362176 29191 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870238232 140403936930169 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) 247424

[startup+12.7003 s]
/proc/loadavg: 1.02 1.04 1.00 2/57 23240
/proc/meminfo: memFree=744716/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=297620 CPUtime=12.62
/proc/23234/stat : 23234 (aptitude) S 23233 23234 17863 34816 17863 4202496 46681 2207 0 0 1237 25 0 0 20 0 2 0 28870108 304762880 41726 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803264 140403948164683 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 74405 41726 9700 1052 0 50400 0
[pid=23234/tid=23239] ppid=23233 vsize=297620 CPUtime=9.5
/proc/23234/task/23239/stat : 23239 (aptitude) R 23233 23234 17863 34816 17863 4202560 26058 2207 0 0 938 12 0 0 20 0 2 0 28870173 304762880 41726 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870238184 140403936930169 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 297620

[startup+25.5003 s]
/proc/loadavg: 1.02 1.04 1.00 2/57 23240
/proc/meminfo: memFree=649360/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=389176 CPUtime=25.36
/proc/23234/stat : 23234 (aptitude) S 23233 23234 17863 34816 17863 4202496 69605 2207 0 0 2502 34 0 0 20 0 2 0 28870108 398516224 64571 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803264 140403948164683 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 97294 64571 9700 1052 0 73289 0
[pid=23234/tid=23239] ppid=23233 vsize=389176 CPUtime=22.24
/proc/23234/task/23239/stat : 23239 (aptitude) R 23233 23234 17863 34816 17863 4202560 48982 2207 0 0 2202 22 0 0 20 0 2 0 28870173 398516224 64571 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870238360 140403974118161 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 389176

[startup+51.1003 s]
/proc/loadavg: 1.01 1.03 1.00 2/57 23240
/proc/meminfo: memFree=460136/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=581672 CPUtime=50.85
/proc/23234/stat : 23234 (aptitude) S 23233 23234 17863 34816 17863 4202496 117790 2207 0 0 5029 56 0 0 20 0 2 0 28870108 595632128 112683 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803264 140403948164683 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 145418 112683 9716 1052 0 121413 0
[pid=23234/tid=23239] ppid=23233 vsize=581672 CPUtime=47.72
/proc/23234/task/23239/stat : 23239 (aptitude) R 23233 23234 17863 34816 17863 4202560 97161 2207 0 0 4729 43 0 0 20 0 2 0 28870173 595632128 112683 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870238600 140403982126735 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 581672

[startup+102.3 s]
/proc/loadavg: 1.13 1.05 1.01 2/57 23243
/proc/meminfo: memFree=8248/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=1062912 CPUtime=100.29
/proc/23234/stat : 23234 (aptitude) S 23233 23234 17863 34816 17863 4202496 238140 2207 118 0 9913 116 0 0 20 0 2 0 28870108 1088421888 230413 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803264 140403948164683 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 265728 230413 9626 1052 0 241723 0
[pid=23234/tid=23239] ppid=23233 vsize=1062912 CPUtime=97.17
/proc/23234/task/23239/stat : 23239 (aptitude) R 23233 23234 17863 34816 17863 4202560 217511 2207 118 0 9613 104 0 0 20 0 2 0 28870173 1088421888 230413 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870238632 140403982127143 0 134217728 4096 0 0 0 0 -1 0 0 0 140 0 0
Current children cumulated CPU time (s) 100.29
Current children cumulated vsize (KiB) 1062912



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+112.5 s]
/proc/loadavg: 1.18 1.07 1.01 2/57 23243
/proc/meminfo: memFree=10164/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=1151352 CPUtime=109.55
/proc/23234/stat : 23234 (aptitude) S 23233 23234 17863 34816 17863 4202496 260359 2207 213 0 10819 136 0 0 20 0 2 0 28870108 1178984448 246024 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803264 140403948164683 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 287838 246024 9680 1052 0 263833 0
[pid=23234/tid=23239] ppid=23233 vsize=1151352 CPUtime=106.43
/proc/23234/task/23239/stat : 23239 (aptitude) R 23233 23234 17863 34816 17863 4202560 239720 2207 211 0 10519 124 0 0 20 0 2 0 28870173 1178984448 246024 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870238232 140403936930119 0 134217728 4096 0 0 0 0 -1 0 0 0 208 0 0
Current children cumulated CPU time (s) 109.55
Current children cumulated vsize (KiB) 1151352

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

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

[startup+112.5 s]
/proc/loadavg: 1.18 1.07 1.01 2/57 23243
/proc/meminfo: memFree=10164/1022884 swapFree=0/0
[pid=23234] ppid=23233 vsize=1151352 CPUtime=109.55
/proc/23234/stat : 23234 (aptitude) S 23233 23234 17863 34816 17863 4202496 260359 2207 213 0 10819 136 0 0 20 0 2 0 28870108 1178984448 246024 18446744073709551615 140403979419648 140403983727000 140736402811504 140736402803264 140403948164683 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23234/statm: 287838 246024 9680 1052 0 263833 0
[pid=23234/tid=23239] ppid=23233 vsize=1151352 CPUtime=106.43
/proc/23234/task/23239/stat : 23239 (aptitude) R 23233 23234 17863 34816 17863 4202560 239720 2207 211 0 10519 124 0 0 20 0 2 0 28870173 1178984448 246024 18446744073709551615 140403979419648 140403983727000 140736402811504 140403870238232 140403936930119 0 134217728 4096 0 0 0 0 -1 0 0 0 208 0 0
Current children cumulated CPU time (s) 109.55
Current children cumulated vsize (KiB) 1151352

Child ended because it received signal 15 (SIGTERM)
Real time (s): 112.599
CPU time (s): 109.663
CPU user time (s): 108.219
CPU system time (s): 1.44409
CPU usage (%): 97.3927
Max. virtual memory (cumulated for all children) (KiB): 1151352

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 108.219
system time used= 1.44409
maximum resident set size= 985952
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262597
page faults= 213
swaps= 0
block input operations= 6328
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 537
involuntary context switches= 2613

runsolver used 0.184011 second user time and 0.340021 second system time

The end