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/85.runsolver.aptitude aptitude -s -y --without-recommends install po-debiandoc kreversi decompyle libiw27 libneon24-dev 

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.44 1.17 1.04 2/55 24124
/proc/meminfo: memFree=914092/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=3152 CPUtime=0
/proc/24124/stat : 24124 (runsolver) R 24123 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29123736 3227648 32 18446744073709551615 134512640 134586868 4291301600 4291299648 4151809072 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24124/statm: 788 32 0 19 0 73 0

[startup+0.128824 s]
/proc/loadavg: 1.44 1.17 1.04 2/55 24124
/proc/meminfo: memFree=914092/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=7872 CPUtime=0
/proc/24124/stat : 24124 (aptitude) D 24123 24124 17863 34816 17863 4202496 123 0 5 0 0 0 0 0 20 0 1 0 29123736 8060928 46 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270724232 139853243130327 0 0 0 0 0 0 0 17 0 0 0 11 0 0
/proc/24124/statm: 1968 46 34 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 7872

[startup+0.200399 s]
/proc/loadavg: 1.44 1.17 1.04 2/55 24124
/proc/meminfo: memFree=914092/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=17468 CPUtime=0
/proc/24124/stat : 24124 (aptitude) D 24123 24124 17863 34816 17863 4202496 132 0 10 0 0 0 0 0 20 0 1 0 29123736 17887232 58 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270723496 139853243135366 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/24124/statm: 4367 58 40 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 17468

[startup+0.300394 s]
/proc/loadavg: 1.44 1.17 1.04 2/55 24124
/proc/meminfo: memFree=914092/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=36128 CPUtime=0
/proc/24124/stat : 24124 (aptitude) D 24123 24124 17863 34816 17863 4202496 161 0 21 0 0 0 0 0 20 0 1 0 29123736 36995072 92 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270723112 139853243135366 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/24124/statm: 9032 92 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.700339 s]
/proc/loadavg: 1.44 1.17 1.04 2/55 24124
/proc/meminfo: memFree=914092/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=54968 CPUtime=0
/proc/24124/stat : 24124 (aptitude) D 24123 24124 17863 34816 17863 4202496 967 0 72 0 0 0 0 0 20 0 1 0 29123736 56287232 930 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270723208 139853203508528 0 134217728 4096 0 0 0 0 17 0 0 0 67 0 0
/proc/24124/statm: 13742 930 775 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+1.5003 s]
/proc/loadavg: 1.41 1.17 1.04 1/56 24128
/proc/meminfo: memFree=900816/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=100508 CPUtime=0.02
/proc/24124/stat : 24124 (aptitude) D 24123 24124 17863 34816 17863 4202496 2942 1706 153 4 0 2 0 0 20 0 1 0 29123736 102920192 2896 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718160 139853240326042 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/24124/statm: 25127 2896 1721 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+3.10034 s]
/proc/loadavg: 1.41 1.17 1.04 1/56 24128
/proc/meminfo: memFree=897468/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=111108 CPUtime=0.31
/proc/24124/stat : 24124 (aptitude) D 24123 24124 17863 34816 17863 4202496 13005 1706 336 4 25 6 0 0 20 0 1 0 29123736 113774592 13134 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718040 139853214034160 0 134217728 4096 0 0 0 0 17 0 0 0 270 0 0
/proc/24124/statm: 27777 13134 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 111108
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.37 1.16 1.04 2/57 24129
/proc/meminfo: memFree=782512/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=133788 CPUtime=2.84
/proc/24124/stat : 24124 (aptitude) R 24123 24124 17863 34816 17863 4202496 20236 2203 347 5 263 21 0 0 20 0 2 0 29123736 136998912 16937 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270713392 139853202786440 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 335 0 0
/proc/24124/statm: 33447 16937 9644 1052 0 9442 0
[pid=24124/tid=24129] ppid=24123 vsize=133788 CPUtime=0
/proc/24124/task/24129/stat : 24129 (aptitude) S 24123 24124 17863 34816 17863 4202560 6 2203 0 5 0 0 0 0 20 0 2 0 29124141 136998912 16937 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136103424 139853214020308 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 133788
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.34 1.16 1.04 2/57 24130
/proc/meminfo: memFree=717908/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=264708 CPUtime=9.21
/proc/24124/stat : 24124 (aptitude) S 24123 24124 17863 34816 17863 4202496 37694 2203 347 5 894 27 0 0 20 0 2 0 29123736 271060992 33503 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718448 139853214021195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 335 0 0
/proc/24124/statm: 66177 33503 9700 1052 0 42172 0
[pid=24124/tid=24129] ppid=24123 vsize=264708 CPUtime=6.07
/proc/24124/task/24129/stat : 24129 (aptitude) R 24123 24124 17863 34816 17863 4202560 17457 2203 0 5 601 6 0 0 20 0 2 0 29124141 271060992 33503 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136094744 139853203428579 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.21
Current children cumulated vsize (KiB) 264708
heavy processes:

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

[startup+12.8074 s]
/proc/loadavg: 1.34 1.16 1.04 2/57 24130
/proc/meminfo: memFree=715552/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=265500 CPUtime=9.31
/proc/24124/stat : 24124 (aptitude) S 24123 24124 17863 34816 17863 4202496 37909 2203 347 5 904 27 0 0 20 0 2 0 29123736 271872000 33718 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718448 139853214021195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 335 0 0
/proc/24124/statm: 66375 33718 9700 1052 0 42370 0
[pid=24124/tid=24129] ppid=24123 vsize=265500 CPUtime=6.17
/proc/24124/task/24129/stat : 24129 (aptitude) R 24123 24124 17863 34816 17863 4202560 17672 2203 0 5 611 6 0 0 20 0 2 0 29124141 271872000 33718 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136096952 139853247922458 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.31
Current children cumulated vsize (KiB) 265500

[startup+16.0002 s]
/proc/loadavg: 1.34 1.16 1.04 2/57 24130
/proc/meminfo: memFree=686784/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=296632 CPUtime=12.49
/proc/24124/stat : 24124 (aptitude) S 24123 24124 17863 34816 17863 4202496 45754 2203 347 5 1216 33 0 0 20 0 2 0 29123736 303751168 41505 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718448 139853214021195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 335 0 0
/proc/24124/statm: 74158 41505 9700 1052 0 50153 0
[pid=24124/tid=24129] ppid=24123 vsize=296632 CPUtime=9.35
/proc/24124/task/24129/stat : 24129 (aptitude) R 24123 24124 17863 34816 17863 4202560 25517 2203 0 5 923 12 0 0 20 0 2 0 29124141 303751168 41505 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136094744 139853247900824 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 296632

[startup+19.2002 s]
/proc/loadavg: 1.32 1.16 1.04 2/57 24130
/proc/meminfo: memFree=666448/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=316488 CPUtime=15.68
/proc/24124/stat : 24124 (aptitude) S 24123 24124 17863 34816 17863 4202496 50687 2203 347 5 1532 36 0 0 20 0 2 0 29123736 324083712 46438 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718448 139853214021195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 335 0 0
/proc/24124/statm: 79122 46438 9700 1052 0 55117 0
[pid=24124/tid=24129] ppid=24123 vsize=316488 CPUtime=12.53
/proc/24124/task/24129/stat : 24129 (aptitude) R 24123 24124 17863 34816 17863 4202560 30450 2203 0 5 1239 14 0 0 20 0 2 0 29124141 324083712 46438 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136096856 139853247505114 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 15.68
Current children cumulated vsize (KiB) 316488

[startup+20.8002 s]
/proc/loadavg: 1.32 1.16 1.04 2/57 24130
/proc/meminfo: memFree=660124/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=327328 CPUtime=17.27
/proc/24124/stat : 24124 (aptitude) S 24123 24124 17863 34816 17863 4202496 53402 2203 347 5 1689 38 0 0 20 0 2 0 29123736 335183872 49148 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718448 139853214021195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 335 0 0
/proc/24124/statm: 81832 49148 9700 1052 0 57827 0
[pid=24124/tid=24129] ppid=24123 vsize=327328 CPUtime=14.12
/proc/24124/task/24129/stat : 24129 (aptitude) R 24123 24124 17863 34816 17863 4202560 33165 2203 0 5 1395 17 0 0 20 0 2 0 29124141 335183872 49148 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136097032 139853247983525 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.27
Current children cumulated vsize (KiB) 327328

[startup+21.6002 s]
/proc/loadavg: 1.29 1.16 1.04 2/57 24130
/proc/meminfo: memFree=652064/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=330440 CPUtime=18.02
/proc/24124/stat : 24124 (aptitude) R 24123 24124 17863 34816 17863 4202496 54404 2203 352 5 1764 38 0 0 20 0 2 0 29123736 338370560 50097 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270716824 139853202767442 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 340 0 0
/proc/24124/statm: 82610 50097 9749 1052 0 58598 0
[pid=24124/tid=24129] ppid=24123 vsize=330440 CPUtime=14.57
/proc/24124/task/24129/stat : 24129 (aptitude) S 24123 24124 17863 34816 17863 4202560 33938 2203 0 5 1440 17 0 0 20 0 2 0 29124141 338370560 50097 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136103424 139853214020308 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.02
Current children cumulated vsize (KiB) 330440

[startup+22.0002 s]
/proc/loadavg: 1.29 1.16 1.04 2/57 24131
/proc/meminfo: memFree=648212/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=330440 CPUtime=18.42
/proc/24124/stat : 24124 (aptitude) R 24123 24124 17863 34816 17863 4202496 57025 2702 352 5 1798 43 0 1 20 0 2 0 29123736 338370560 50159 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718008 139853202786440 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 340 0 0
/proc/24124/statm: 82610 50159 9750 1052 0 58598 0
[pid=24124/tid=24129] ppid=24123 vsize=330440 CPUtime=14.58
/proc/24124/task/24129/stat : 24129 (aptitude) S 24123 24124 17863 34816 17863 4202560 33938 2702 0 5 1440 17 0 1 20 0 2 0 29124141 338370560 50159 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136103424 139853214020308 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.42
Current children cumulated vsize (KiB) 330440

[startup+22.1032 s]
/proc/loadavg: 1.29 1.16 1.04 2/57 24131
/proc/meminfo: memFree=648212/1022884 swapFree=0/0
[pid=24124] ppid=24123 vsize=330440 CPUtime=18.51
/proc/24124/stat : 24124 (aptitude) R 24123 24124 17863 34816 17863 4202496 57224 2702 352 5 1804 46 0 1 20 0 2 0 29123736 338370560 50021 18446744073709551615 139853245276160 139853249583512 140734270726688 140734270718664 139853246986140 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 340 0 0
/proc/24124/statm: 82610 50021 9750 1052 0 58598 0
[pid=24124/tid=24129] ppid=24123 vsize=330440 CPUtime=14.58
/proc/24124/task/24129/stat : 24129 (aptitude) S 24123 24124 17863 34816 17863 4202560 33938 2702 0 5 1440 17 0 1 20 0 2 0 29124141 338370560 50021 18446744073709551615 139853245276160 139853249583512 140734270726688 139853136103424 139853214020308 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.51
Current children cumulated vsize (KiB) 330440

Child status: 0
Real time (s): 22.1804
CPU time (s): 18.6172
CPU user time (s): 18.0851
CPU system time (s): 0.532033
CPU usage (%): 83.9353
Max. virtual memory (cumulated for all children) (KiB): 330440

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.0851
system time used= 0.532033
maximum resident set size= 201140
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 60424
page faults= 359
swaps= 0
block input operations= 206312
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1986
involuntary context switches= 371

runsolver used 0.056003 second user time and 0.060003 second system time

The end