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/54.runsolver.aptitude aptitude -s -y --without-recommends install gtk2-engines-industrial scripts4ticker heroes-sound-tracks xfonts-intl-chinese-big ksimus-boolean 

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.30 1.12 1.06 2/55 25688
/proc/meminfo: memFree=960384/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=3152 CPUtime=0
/proc/25688/stat : 25688 (runsolver) R 25687 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29584897 3227648 33 18446744073709551615 134512640 134586868 4291908928 4291906976 4151653424 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25688/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.187229 s]
/proc/loadavg: 1.30 1.12 1.06 2/55 25688
/proc/meminfo: memFree=960384/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=17468 CPUtime=0
/proc/25688/stat : 25688 (aptitude) D 25687 25688 17863 34816 17863 4202496 135 0 7 0 0 0 0 0 20 0 1 0 29584897 17887232 57 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390740696 140700031407494 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/25688/statm: 4367 57 40 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 17468

[startup+0.200399 s]
/proc/loadavg: 1.30 1.12 1.06 2/55 25688
/proc/meminfo: memFree=960384/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=28716 CPUtime=0
/proc/25688/stat : 25688 (aptitude) D 25687 25688 17863 34816 17863 4202496 155 0 11 0 0 0 0 0 20 0 1 0 29584897 29405184 77 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390740504 140700031407651 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/25688/statm: 7179 77 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.300375 s]
/proc/loadavg: 1.30 1.12 1.06 2/55 25688
/proc/meminfo: memFree=960384/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=48572 CPUtime=0
/proc/25688/stat : 25688 (aptitude) D 25687 25688 17863 34816 17863 4202496 187 0 19 0 0 0 0 0 20 0 1 0 29584897 49737728 111 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390739704 140700031406814 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/25688/statm: 12143 111 68 1052 0 66 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 48572

[startup+0.700284 s]
/proc/loadavg: 1.30 1.12 1.06 2/55 25688
/proc/meminfo: memFree=960384/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=100384 CPUtime=0.01
/proc/25688/stat : 25688 (aptitude) D 25687 25688 17863 34816 17863 4202496 1636 1703 34 4 1 0 0 0 20 0 1 0 29584897 102793216 1473 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390738144 140699991236453 0 134217728 4096 0 0 0 0 17 0 0 0 60 0 0
/proc/25688/statm: 25096 1473 988 1052 0 433 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 100384

[startup+1.50028 s]
/proc/loadavg: 1.30 1.12 1.06 1/56 25692
/proc/meminfo: memFree=951820/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=103288 CPUtime=0.01
/proc/25688/stat : 25688 (aptitude) D 25687 25688 17863 34816 17863 4202496 3198 1703 151 4 1 0 0 0 20 0 1 0 29584897 105766912 3149 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735360 140700028406243 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/25688/statm: 25822 3149 1938 1052 0 1159 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 103288

[startup+3.10032 s]
/proc/loadavg: 1.30 1.12 1.06 1/56 25692
/proc/meminfo: memFree=948472/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=123068 CPUtime=0.48
/proc/25688/stat : 25688 (aptitude) D 25687 25688 17863 34816 17863 4202496 17346 1703 319 4 44 4 0 0 20 0 1 0 29584897 126021632 15940 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390733320 140700002304368 0 134217728 4096 0 0 0 0 17 0 0 0 252 0 0
/proc/25688/statm: 30767 15940 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.48
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.28 1.12 1.06 2/57 25693
/proc/meminfo: memFree=805732/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=137844 CPUtime=2.9
/proc/25688/stat : 25688 (aptitude) R 25687 25688 17863 34816 17863 4202496 21700 2198 319 6 265 24 1 0 20 0 2 0 29584897 141152256 17953 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390730592 140699991058759 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 34461 17953 10303 1052 0 9798 0
[pid=25688/tid=25693] ppid=25687 vsize=137844 CPUtime=0.01
/proc/25688/task/25693/stat : 25693 (aptitude) S 25687 25688 17863 34816 17863 4202560 6 2198 0 6 0 0 1 0 20 0 2 0 29585315 141152256 17953 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921225728 140700002292436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 137844
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.25 1.11 1.06 2/57 25694
/proc/meminfo: memFree=756372/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=255292 CPUtime=9.26
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 35303 2198 319 6 895 30 1 0 20 0 2 0 29584897 261419008 31152 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 63823 31152 10359 1052 0 39160 0
[pid=25688/tid=25693] ppid=25687 vsize=255292 CPUtime=5.79
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 13602 2198 0 6 572 6 1 0 20 0 2 0 29585315 261419008 31152 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921219256 140699991058759 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.26
Current children cumulated vsize (KiB) 255292
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.20 1.11 1.06 2/57 25694
/proc/meminfo: memFree=653948/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=354804 CPUtime=21.99
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 60427 2198 319 6 2158 40 1 0 20 0 2 0 29584897 363319296 56008 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 88701 56008 10359 1052 0 64038 0
[pid=25688/tid=25693] ppid=25687 vsize=354804 CPUtime=18.53
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 38726 2198 0 6 1835 17 1 0 20 0 2 0 29585315 363319296 56008 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921219256 140699991058765 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 21.99
Current children cumulated vsize (KiB) 354804

[startup+51.1003 s]
/proc/loadavg: 1.13 1.10 1.05 2/57 25702
/proc/meminfo: memFree=492336/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=514000 CPUtime=47.45
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 100246 2198 319 6 4675 69 1 0 20 0 2 0 29584897 526336000 95776 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 128500 95776 10374 1052 0 103837 0
[pid=25688/tid=25693] ppid=25687 vsize=514000 CPUtime=43.99
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 78538 2198 0 6 4352 46 1 0 20 0 2 0 29585315 526336000 95776 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921217048 140700028948058 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.45
Current children cumulated vsize (KiB) 514000

[startup+102.3 s]
/proc/loadavg: 1.05 1.08 1.05 2/57 25702
/proc/meminfo: memFree=174400/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=828996 CPUtime=98.42
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 179179 2198 319 6 9737 104 1 0 20 0 2 0 29584897 848891904 174402 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 207249 174402 10374 1052 0 182586 0
[pid=25688/tid=25693] ppid=25687 vsize=828996 CPUtime=94.94
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 157471 2198 0 6 9412 81 1 0 20 0 2 0 29585315 848891904 174402 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921217048 140700036145337 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 98.42
Current children cumulated vsize (KiB) 828996

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

[startup+102.403 s]
/proc/loadavg: 1.05 1.08 1.05 2/57 25702
/proc/meminfo: memFree=174400/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=829524 CPUtime=98.52
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 179326 2198 319 6 9747 104 1 0 20 0 2 0 29584897 849432576 174549 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 207381 174549 10374 1052 0 182718 0
[pid=25688/tid=25693] ppid=25687 vsize=829524 CPUtime=95.04
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 157618 2198 0 6 9422 81 1 0 20 0 2 0 29585315 849432576 174549 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921217048 140700036439443 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 98.52
Current children cumulated vsize (KiB) 829524

[startup+115.2 s]
/proc/loadavg: 1.04 1.08 1.05 2/57 25702
/proc/meminfo: memFree=107688/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=899632 CPUtime=111.25
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 196862 2198 319 6 11012 112 1 0 20 0 2 0 29584897 921223168 192070 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 224908 192070 10374 1052 0 200245 0
[pid=25688/tid=25693] ppid=25687 vsize=899632 CPUtime=107.79
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 175154 2198 0 6 10688 90 1 0 20 0 2 0 29585315 921223168 192070 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921217048 140700036145337 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 111.25
Current children cumulated vsize (KiB) 899632

[startup+128 s]
/proc/loadavg: 1.04 1.07 1.05 2/57 25702
/proc/meminfo: memFree=32792/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=972616 CPUtime=124
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 215158 2198 319 6 12279 120 1 0 20 0 2 0 29584897 995958784 210341 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 243154 210341 10374 1052 0 218491 0
[pid=25688/tid=25693] ppid=25687 vsize=972616 CPUtime=120.52
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 193450 2198 0 6 11954 97 1 0 20 0 2 0 29585315 995958784 210341 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921217048 140699991058759 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 124
Current children cumulated vsize (KiB) 972616

[startup+131.2 s]
/proc/loadavg: 1.03 1.07 1.05 2/57 25702
/proc/meminfo: memFree=11892/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=993248 CPUtime=127.18
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 220323 2198 319 6 12594 123 1 0 20 0 2 0 29584897 1017085952 215506 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390735648 140700002293323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 330 0 0
/proc/25688/statm: 248312 215506 10374 1052 0 223649 0
[pid=25688/tid=25693] ppid=25687 vsize=993248 CPUtime=123.7
/proc/25688/task/25693/stat : 25693 (aptitude) R 25687 25688 17863 34816 17863 4202560 198615 2198 0 6 12269 100 1 0 20 0 2 0 29585315 1017085952 215506 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921219384 140699991058759 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 127.18
Current children cumulated vsize (KiB) 993248

[startup+134.7 s]
/proc/loadavg: 1.03 1.07 1.05 2/57 25702
/proc/meminfo: memFree=9816/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=1002736 CPUtime=129.92
/proc/25688/stat : 25688 (aptitude) R 25687 25688 17863 34816 17863 4202496 222945 2198 340 6 12867 124 1 0 20 0 2 0 29584897 1026801664 218036 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390734024 140700036174830 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 340 0 0
/proc/25688/statm: 250684 218036 10422 1052 0 226014 0
[pid=25688/tid=25693] ppid=25687 vsize=1002736 CPUtime=125.29
/proc/25688/task/25693/stat : 25693 (aptitude) S 25687 25688 17863 34816 17863 4202560 201024 2198 8 6 12427 101 1 0 20 0 2 0 29585315 1026801664 218036 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921225728 140700002292436 0 134217728 4096 0 0 0 0 -1 0 0 0 61 0 0
Current children cumulated CPU time (s) 129.92
Current children cumulated vsize (KiB) 1002736

[startup+135.5 s]
/proc/loadavg: 1.03 1.07 1.05 2/57 25702
/proc/meminfo: memFree=9816/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=1002796 CPUtime=130.72
/proc/25688/stat : 25688 (aptitude) R 25687 25688 17863 34816 17863 4202496 222972 2198 340 6 12947 124 1 0 20 0 2 0 29584897 1026863104 218063 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390734024 140699991039659 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 340 0 0
/proc/25688/statm: 250699 218063 10422 1052 0 226029 0
[pid=25688/tid=25693] ppid=25687 vsize=1002796 CPUtime=125.29
/proc/25688/task/25693/stat : 25693 (aptitude) S 25687 25688 17863 34816 17863 4202560 201024 2198 8 6 12427 101 1 0 20 0 2 0 29585315 1026863104 218063 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921225728 140700002292436 0 134217728 4096 0 0 0 0 -1 0 0 0 61 0 0
Current children cumulated CPU time (s) 130.72
Current children cumulated vsize (KiB) 1002796

[startup+136.3 s]
/proc/loadavg: 1.03 1.07 1.05 2/57 25702
/proc/meminfo: memFree=9816/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=1002796 CPUtime=131.49
/proc/25688/stat : 25688 (aptitude) S 25687 25688 17863 34816 17863 4202496 225669 2198 340 6 13008 140 1 0 20 0 2 0 29584897 1026863104 218110 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390733664 140699991417299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 340 0 0
/proc/25688/statm: 250699 218110 10423 1052 0 226029 0
[pid=25688/tid=25693] ppid=25687 vsize=1002796 CPUtime=125.29
/proc/25688/task/25693/stat : 25693 (aptitude) S 25687 25688 17863 34816 17863 4202560 201024 2198 8 6 12427 101 1 0 20 0 2 0 29585315 1026863104 218110 18446744073709551615 140700033548288 140700037855640 140734390743888 140699921225728 140700002292436 0 134217728 4096 0 0 0 0 -1 0 0 0 61 0 0
Current children cumulated CPU time (s) 131.49
Current children cumulated vsize (KiB) 1002796

[startup+136.7 s]
/proc/loadavg: 1.03 1.07 1.05 1/56 25703
/proc/meminfo: memFree=357876/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=620280 CPUtime=131.77
/proc/25688/stat : 25688 (aptitude) D 25687 25688 17863 34816 17863 4202496 226432 2687 346 16 13017 157 1 2 20 0 1 0 29584897 635166720 122548 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390743032 140699991398935 0 134217728 4096 0 0 0 0 17 0 0 0 346 0 0
/proc/25688/statm: 155070 122548 1522 1052 0 139326 0
Current children cumulated CPU time (s) 131.77
Current children cumulated vsize (KiB) 620280

[startup+136.804 s]
/proc/loadavg: 1.03 1.07 1.05 1/56 25703
/proc/meminfo: memFree=357876/1022884 swapFree=0/0
[pid=25688] ppid=25687 vsize=620280 CPUtime=131.86
/proc/25688/stat : 25688 (aptitude) R 25687 25688 17863 34816 17863 4202496 226435 2687 346 16 13017 166 1 2 20 0 1 0 29584897 635166720 23220 18446744073709551615 140700033548288 140700037855640 140734390743888 140734390743448 140699991414250 0 134217728 4096 0 0 0 0 17 0 0 0 347 0 0
/proc/25688/statm: 155070 23220 1522 1052 0 139326 0
Current children cumulated CPU time (s) 131.86
Current children cumulated vsize (KiB) 620280

Child status: 0
Real time (s): 136.895
CPU time (s): 131.896
CPU user time (s): 130.184
CPU system time (s): 1.71211
CPU usage (%): 96.3487
Max. virtual memory (cumulated for all children) (KiB): 1002796

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 130.184
system time used= 1.71211
maximum resident set size= 873056
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 229177
page faults= 374
swaps= 0
block input operations= 254304
block output operations= 208
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2818
involuntary context switches= 2425

runsolver used 0.188011 second user time and 0.452028 second system time

The end