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/logs/21.runsolver.aptitude aptitude -s -y --without-recommends install liquidwar-data python2.3-weblib kaffe-pthreads plplot-bin python-gtk2-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

[startup+0 s]
/proc/loadavg: 1.02 1.05 0.85 2/55 21002
/proc/meminfo: memFree=912980/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=3152 CPUtime=0
/proc/21002/stat : 21002 (runsolver) R 21001 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28342271 3227648 32 18446744073709551615 134512640 134586868 4286690880 4286688928 4152026160 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.15929 s]
/proc/loadavg: 1.02 1.05 0.85 2/55 21002
/proc/meminfo: memFree=912980/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=89152 CPUtime=0.15
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 7777 1710 0 0 14 1 0 0 20 0 1 0 28342271 91291648 7574 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163141648 139986298228255 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 22288 7574 6663 1052 0 858 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 89152

[startup+0.200284 s]
/proc/loadavg: 1.02 1.05 0.85 2/55 21002
/proc/meminfo: memFree=912980/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=89152 CPUtime=0.19
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 7873 1710 0 0 18 1 0 0 20 0 1 0 28342271 91291648 7662 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163140160 139986336087764 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300273 s]
/proc/loadavg: 1.02 1.05 0.85 2/55 21002
/proc/meminfo: memFree=912980/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=101864 CPUtime=0.28
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 11712 1710 0 0 27 1 0 0 20 0 1 0 28342271 104308736 10756 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163139816 139986309443952 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.700202 s]
/proc/loadavg: 1.02 1.05 0.85 2/55 21002
/proc/meminfo: memFree=912980/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=110244 CPUtime=0.68
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 12559 1710 0 0 65 3 0 0 20 0 2 0 28342271 112889856 10930 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142424 139986343395909 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 27561 10930 6961 1052 0 6131 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 110244

[startup+1.50023 s]
/proc/loadavg: 1.02 1.05 0.85 2/57 21007
/proc/meminfo: memFree=892016/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=115436 CPUtime=1.47
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 14222 2207 0 0 141 6 0 0 20 0 2 0 28342271 118206464 12383 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142408 139986343773082 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 28859 12383 7073 1052 0 7429 0
[pid=21002/tid=21007] ppid=21001 vsize=115436 CPUtime=0
/proc/21002/task/21007/stat : 21007 (aptitude) S 21001 21002 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 28342315 118206464 12383 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244093952 139986309432020 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 115436

[startup+3.10024 s]
/proc/loadavg: 1.02 1.05 0.85 2/57 21008
/proc/meminfo: memFree=885444/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=136688 CPUtime=3.07
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 20873 2207 0 0 297 10 0 0 20 0 2 0 28342271 139968512 17901 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 34172 17901 7129 1052 0 12742 0
[pid=21002/tid=21007] ppid=21001 vsize=136688 CPUtime=1.03
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 6189 2207 0 0 99 4 0 0 20 0 2 0 28342315 139968512 17901 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244085272 139986343349388 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) 136688

[startup+6.30024 s]
/proc/loadavg: 1.02 1.05 0.85 2/57 21008
/proc/meminfo: memFree=837952/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=244872 CPUtime=6.26
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 31603 2207 0 0 610 16 0 0 20 0 2 0 28342271 250748928 28535 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 61218 28535 7129 1052 0 39788 0
[pid=21002/tid=21007] ppid=21001 vsize=244872 CPUtime=4.21
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 16918 2207 0 0 412 9 0 0 20 0 2 0 28342315 250748928 28535 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244085272 139986298183615 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) 244872

[startup+12.7002 s]
/proc/loadavg: 1.02 1.05 0.85 2/57 21008
/proc/meminfo: memFree=776820/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=298304 CPUtime=12.63
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 44973 2207 0 0 1240 23 0 0 20 0 2 0 28342271 305463296 41889 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 74576 41889 7129 1052 0 53146 0
[pid=21002/tid=21007] ppid=21001 vsize=298304 CPUtime=10.58
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 30288 2207 0 0 1042 16 0 0 20 0 2 0 28342315 305463296 41889 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244085272 139986335515708 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 298304

[startup+25.5003 s]
/proc/loadavg: 1.01 1.05 0.85 2/57 21008
/proc/meminfo: memFree=707380/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=365296 CPUtime=25.37
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 61843 2207 0 0 2505 32 0 0 20 0 2 0 28342271 374063104 58620 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 91324 58620 7129 1052 0 69894 0
[pid=21002/tid=21007] ppid=21001 vsize=365296 CPUtime=23.32
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 47158 2207 0 0 2307 25 0 0 20 0 2 0 28342315 374063104 58620 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244087480 139986343258512 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 365296

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

[startup+25.6004 s]
/proc/loadavg: 1.01 1.05 0.85 2/57 21008
/proc/meminfo: memFree=707380/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=365828 CPUtime=25.47
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 61973 2207 0 0 2515 32 0 0 20 0 2 0 28342271 374607872 58750 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 91457 58750 7129 1052 0 70027 0
[pid=21002/tid=21007] ppid=21001 vsize=365828 CPUtime=23.41
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 47288 2207 0 0 2316 25 0 0 20 0 2 0 28342315 374607872 58750 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244085272 139986343395558 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 365828

[startup+32.0033 s]
/proc/loadavg: 1.01 1.05 0.85 2/59 21010
/proc/meminfo: memFree=669760/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=396568 CPUtime=31.82
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 69684 2207 0 0 3146 36 0 0 20 0 2 0 28342271 406085632 66437 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 99142 66437 7129 1052 0 77712 0
[pid=21002/tid=21007] ppid=21001 vsize=396568 CPUtime=29.78
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 54999 2207 0 0 2948 30 0 0 20 0 2 0 28342315 406085632 66437 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244085272 139986298198343 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 31.82
Current children cumulated vsize (KiB) 396568

[startup+38.4002 s]
/proc/loadavg: 1.01 1.04 0.85 2/57 21026
/proc/meminfo: memFree=641228/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=426216 CPUtime=38.14
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 77119 2207 0 0 3773 41 0 0 20 0 2 0 28342271 436445184 73863 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 106554 73863 7143 1052 0 85124 0
[pid=21002/tid=21007] ppid=21001 vsize=426216 CPUtime=36.09
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 62427 2207 0 0 3575 34 0 0 20 0 2 0 28342315 436445184 73863 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244085224 139986343334242 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.14
Current children cumulated vsize (KiB) 426216

[startup+40.0002 s]
/proc/loadavg: 1.01 1.04 0.86 2/57 21026
/proc/meminfo: memFree=631804/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=433236 CPUtime=39.73
/proc/21002/stat : 21002 (aptitude) S 21001 21002 17863 34816 17863 4202496 78876 2207 0 0 3929 44 0 0 20 0 2 0 28342271 443633664 75620 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142144 139986309432907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 108309 75620 7143 1052 0 86879 0
[pid=21002/tid=21007] ppid=21001 vsize=433236 CPUtime=37.69
/proc/21002/task/21007/stat : 21007 (aptitude) R 21001 21002 17863 34816 17863 4202560 64184 2207 0 0 3731 38 0 0 20 0 2 0 28342315 443633664 75620 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244085272 139986343430458 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 39.73
Current children cumulated vsize (KiB) 433236

[startup+41.6002 s]
/proc/loadavg: 1.01 1.04 0.86 2/57 21026
/proc/meminfo: memFree=626844/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=440808 CPUtime=41.33
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 81110 2207 0 0 4088 45 0 0 20 0 2 0 28342271 451387392 77736 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163140520 139986343290144 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 110202 77736 7191 1052 0 88765 0
[pid=21002/tid=21007] ppid=21001 vsize=440808 CPUtime=39.09
/proc/21002/task/21007/stat : 21007 (aptitude) S 21001 21002 17863 34816 17863 4202560 66092 2207 0 0 3871 38 0 0 20 0 2 0 28342315 451387392 77736 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244093952 139986309432020 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.33
Current children cumulated vsize (KiB) 440808

[startup+42.0002 s]
/proc/loadavg: 1.01 1.04 0.86 2/57 21026
/proc/meminfo: memFree=621264/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=440880 CPUtime=41.72
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 81139 2207 0 0 4127 45 0 0 20 0 2 0 28342271 451461120 77765 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163140520 139986298179154 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 110220 77765 7191 1052 0 88783 0
[pid=21002/tid=21007] ppid=21001 vsize=440880 CPUtime=39.09
/proc/21002/task/21007/stat : 21007 (aptitude) S 21001 21002 17863 34816 17863 4202560 66092 2207 0 0 3871 38 0 0 20 0 2 0 28342315 451461120 77765 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244093952 139986309432020 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.72
Current children cumulated vsize (KiB) 440880

[startup+42.4002 s]
/proc/loadavg: 1.01 1.04 0.86 2/57 21026
/proc/meminfo: memFree=621264/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=440880 CPUtime=42.13
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 83079 2207 0 0 4167 46 0 0 20 0 2 0 28342271 451461120 77763 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163142200 139986335579722 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 110220 77763 7192 1052 0 88783 0
[pid=21002/tid=21007] ppid=21001 vsize=440880 CPUtime=39.09
/proc/21002/task/21007/stat : 21007 (aptitude) S 21001 21002 17863 34816 17863 4202560 66092 2207 0 0 3871 38 0 0 20 0 2 0 28342315 451461120 77763 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244093952 139986309432020 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 42.13
Current children cumulated vsize (KiB) 440880

[startup+42.5002 s]
/proc/loadavg: 1.01 1.04 0.86 2/57 21026
/proc/meminfo: memFree=621264/1022884 swapFree=0/0
[pid=21002] ppid=21001 vsize=440880 CPUtime=42.22
/proc/21002/stat : 21002 (aptitude) R 21001 21002 17863 34816 17863 4202496 83185 2706 0 0 4169 52 0 1 20 0 2 0 28342271 451461120 77792 18446744073709551615 139986340687872 139986344995224 140737163150384 140737163141544 139986298531909 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21002/statm: 110220 77792 7192 1052 0 88783 0
[pid=21002/tid=21007] ppid=21001 vsize=440880 CPUtime=39.1
/proc/21002/task/21007/stat : 21007 (aptitude) S 21001 21002 17863 34816 17863 4202560 66092 2706 0 0 3871 38 0 1 20 0 2 0 28342315 451461120 77792 18446744073709551615 139986340687872 139986344995224 140737163150384 139986244093952 139986309432020 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 42.22
Current children cumulated vsize (KiB) 440880

Child status: 0
Real time (s): 42.5972
CPU time (s): 42.3426
CPU user time (s): 41.7226
CPU system time (s): 0.620038
CPU usage (%): 99.4025
Max. virtual memory (cumulated for all children) (KiB): 440880

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 41.7226
system time used= 0.620038
maximum resident set size= 311384
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 86607
page faults= 0
swaps= 0
block input operations= 0
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 145
involuntary context switches= 1087

runsolver used 0 second user time and 0.196012 second system time

The end