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/38.runsolver.aptitude aptitude -s -y --without-recommends install gnome-pilot kernel-internals-guide libexpat1 libcoyotl2 python2.4-xmms 

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.14 1.06 0.93 2/55 21397
/proc/meminfo: memFree=822680/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=3152 CPUtime=0
/proc/21397/stat : 21397 (runsolver) R 21396 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28396494 3227648 32 18446744073709551615 134512640 134586868 4292052912 4292050960 4151440432 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.181018 s]
/proc/loadavg: 1.14 1.06 0.93 2/55 21397
/proc/meminfo: memFree=822680/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=89152 CPUtime=0.17
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 7776 1709 0 0 16 1 0 0 20 0 1 0 28396494 91291648 7576 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643618576 139954646449643 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 22288 7576 6665 1052 0 858 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 89152

[startup+0.200284 s]
/proc/loadavg: 1.14 1.06 0.93 2/55 21397
/proc/meminfo: memFree=822680/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=89152 CPUtime=0.19
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 7778 1709 0 0 18 1 0 0 20 0 1 0 28396494 91291648 7578 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643615704 139954657667312 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 22288 7578 6667 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300263 s]
/proc/loadavg: 1.14 1.06 0.93 2/55 21397
/proc/meminfo: memFree=822680/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=100164 CPUtime=0.29
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 11280 1709 0 0 26 3 0 0 20 0 1 0 28396494 102567936 10327 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643616824 139954691848294 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 25041 10327 6742 1052 0 3611 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 100164

[startup+0.700199 s]
/proc/loadavg: 1.14 1.06 0.93 2/55 21397
/proc/meminfo: memFree=822680/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=110228 CPUtime=0.68
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 12617 1709 0 0 63 5 0 0 20 0 2 0 28396494 112873472 10989 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619352 139954691617377 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 27557 10989 6961 1052 0 6127 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 110228

[startup+1.50024 s]
/proc/loadavg: 1.14 1.06 0.93 2/57 21402
/proc/meminfo: memFree=801840/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=115400 CPUtime=1.47
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 14572 2212 0 0 139 8 0 0 20 0 2 0 28396494 118169600 12359 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619336 139954691148007 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 28850 12359 7073 1052 0 7420 0
[pid=21397/tid=21402] ppid=21396 vsize=115400 CPUtime=0
/proc/21397/task/21402/stat : 21402 (aptitude) S 21396 21397 17863 34816 17863 4202560 6 2212 0 0 0 0 0 0 20 0 2 0 28396539 118169600 12359 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592315392 139954657653460 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) 115400

[startup+3.10024 s]
/proc/loadavg: 1.13 1.06 0.93 2/57 21403
/proc/meminfo: memFree=794896/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=136528 CPUtime=3.07
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 20829 2212 0 0 297 10 0 0 20 0 2 0 28396494 139804672 17866 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 34132 17866 7129 1052 0 12702 0
[pid=21397/tid=21402] ppid=21396 vsize=136528 CPUtime=1.04
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 6178 2212 0 0 102 2 0 0 20 0 2 0 28396539 139804672 17866 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592307064 139954691757919 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) 136528

[startup+6.30024 s]
/proc/loadavg: 1.13 1.06 0.93 2/57 21403
/proc/meminfo: memFree=746412/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=180484 CPUtime=6.25
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 31811 2212 0 0 612 13 0 0 20 0 2 0 28396494 184815616 28840 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 45121 28840 7129 1052 0 23691 0
[pid=21397/tid=21402] ppid=21396 vsize=180484 CPUtime=4.22
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 17160 2212 0 0 417 5 0 0 20 0 2 0 28396539 184815616 28840 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592308824 139954691738179 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 180484

[startup+12.7002 s]
/proc/loadavg: 1.11 1.06 0.93 2/57 21403
/proc/meminfo: memFree=685652/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=298948 CPUtime=12.62
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 45042 2212 0 0 1245 17 0 0 20 0 2 0 28396494 306122752 42045 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 74737 42045 7129 1052 0 53307 0
[pid=21397/tid=21402] ppid=21396 vsize=298948 CPUtime=10.58
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 30390 2212 0 0 1050 8 0 0 20 0 2 0 28396539 306122752 42045 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592308920 139954691616704 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) 298948

[startup+25.5003 s]
/proc/loadavg: 1.09 1.06 0.93 2/57 21403
/proc/meminfo: memFree=617328/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=364968 CPUtime=25.36
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 61723 2212 0 0 2512 24 0 0 20 0 2 0 28396494 373727232 58534 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 91242 58534 7129 1052 0 69812 0
[pid=21397/tid=21402] ppid=21396 vsize=364968 CPUtime=23.33
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 47071 2212 0 0 2318 15 0 0 20 0 2 0 28396539 373727232 58534 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592308920 139954646419783 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) 364968

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

[startup+25.6003 s]
/proc/loadavg: 1.09 1.06 0.93 2/57 21403
/proc/meminfo: memFree=617328/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=365500 CPUtime=25.46
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 61869 2212 0 0 2522 24 0 0 20 0 2 0 28396494 374272000 58680 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 91375 58680 7129 1052 0 69945 0
[pid=21397/tid=21402] ppid=21396 vsize=365500 CPUtime=23.43
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 47217 2212 0 0 2328 15 0 0 20 0 2 0 28396539 374272000 58680 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592308872 139954691646679 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 365500

[startup+38.4002 s]
/proc/loadavg: 1.07 1.05 0.93 2/57 21403
/proc/meminfo: memFree=563636/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=421788 CPUtime=38.21
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 76009 2212 0 0 3789 32 0 0 20 0 2 0 28396494 431910912 72782 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 105447 72782 7143 1052 0 84017 0
[pid=21397/tid=21402] ppid=21396 vsize=421788 CPUtime=36.17
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 61350 2212 0 0 3593 24 0 0 20 0 2 0 28396539 431910912 72782 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592308920 139954691138409 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.21
Current children cumulated vsize (KiB) 421788

[startup+41.6002 s]
/proc/loadavg: 1.07 1.05 0.93 2/57 21403
/proc/meminfo: memFree=550120/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=434648 CPUtime=41.39
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 79216 2212 0 0 4105 34 0 0 20 0 2 0 28396494 445079552 75989 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 108662 75989 7143 1052 0 87232 0
[pid=21397/tid=21402] ppid=21396 vsize=434648 CPUtime=39.36
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 64557 2212 0 0 3910 26 0 0 20 0 2 0 28396539 445079552 75989 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592308872 139954691471412 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.39
Current children cumulated vsize (KiB) 434648

[startup+44.8002 s]
/proc/loadavg: 1.07 1.05 0.93 2/57 21403
/proc/meminfo: memFree=535860/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=448720 CPUtime=44.57
/proc/21397/stat : 21397 (aptitude) S 21396 21397 17863 34816 17863 4202496 82727 2212 0 0 4421 36 0 0 20 0 2 0 28396494 459489280 79492 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643619072 139954657654347 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 112180 79492 7143 1052 0 90750 0
[pid=21397/tid=21402] ppid=21396 vsize=448720 CPUtime=42.55
/proc/21397/task/21402/stat : 21402 (aptitude) R 21396 21397 17863 34816 17863 4202560 68068 2212 0 0 4227 28 0 0 20 0 2 0 28396539 459489280 79492 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592306712 139954646449661 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 44.57
Current children cumulated vsize (KiB) 448720

[startup+46.4003 s]
/proc/loadavg: 1.07 1.05 0.93 2/57 21403
/proc/meminfo: memFree=525320/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=454436 CPUtime=46.16
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 84503 2212 0 0 4579 37 0 0 20 0 2 0 28396494 465342464 81143 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643617448 139954655218667 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 113609 81143 7191 1052 0 92172 0
[pid=21397/tid=21402] ppid=21396 vsize=454436 CPUtime=43.73
/proc/21397/task/21402/stat : 21402 (aptitude) S 21396 21397 17863 34816 17863 4202560 69506 2212 0 0 4345 28 0 0 20 0 2 0 28396539 465342464 81143 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592315392 139954657653460 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.16
Current children cumulated vsize (KiB) 454436

[startup+46.8002 s]
/proc/loadavg: 1.07 1.05 0.93 2/57 21403
/proc/meminfo: memFree=525320/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=454512 CPUtime=46.56
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 85023 2212 0 0 4619 37 0 0 20 0 2 0 28396494 465420288 81174 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643617400 139954646096539 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 113628 81174 7192 1052 0 92191 0
[pid=21397/tid=21402] ppid=21396 vsize=454512 CPUtime=43.73
/proc/21397/task/21402/stat : 21402 (aptitude) S 21396 21397 17863 34816 17863 4202560 69506 2212 0 0 4345 28 0 0 20 0 2 0 28396539 465420288 81174 18446744073709551615 139954688909312 139954693216664 140736643627312 139954592315392 139954657653460 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.56
Current children cumulated vsize (KiB) 454512

[startup+47.2003 s]
/proc/loadavg: 1.07 1.05 0.93 2/57 21403
/proc/meminfo: memFree=525320/1022884 swapFree=0/0
[pid=21397] ppid=21396 vsize=281024 CPUtime=46.98
/proc/21397/stat : 21397 (aptitude) R 21396 21397 17863 34816 17863 4202496 87309 2712 0 0 4645 51 1 1 20 0 1 0 28396494 287768576 13156 18446744073709551615 139954688909312 139954693216664 140736643627312 140736643626872 139954646775274 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21397/statm: 70256 13156 1521 1052 0 54512 0
Current children cumulated CPU time (s) 46.98
Current children cumulated vsize (KiB) 281024

Child status: 0
Real time (s): 47.213
CPU time (s): 47.0029
CPU user time (s): 46.4629
CPU system time (s): 0.540033
CPU usage (%): 99.5551
Max. virtual memory (cumulated for all children) (KiB): 454512

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 46.4629
system time used= 0.540033
maximum resident set size= 325040
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 90088
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= 153
involuntary context switches= 841

runsolver used 0.080005 second user time and 0.144009 second system time

The end