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/99.runsolver.aptitude aptitude -s -y --without-recommends install filter njplot kgpg screem python2.2-musicbrainz 

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.09 1.04 2/55 24258
/proc/meminfo: memFree=869680/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=3152 CPUtime=0
/proc/24258/stat : 24258 (runsolver) R 24257 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29195503 3227648 32 18446744073709551615 134512640 134586868 4289147008 4289145056 4151665712 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.139753 s]
/proc/loadavg: 1.14 1.09 1.04 2/55 24258
/proc/meminfo: memFree=869680/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=100508 CPUtime=0.12
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 10579 1708 0 0 10 2 0 0 20 0 1 0 29195503 102920192 10380 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490521232 140163361092955 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 25127 10380 9205 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.14 1.09 1.04 2/55 24258
/proc/meminfo: memFree=869680/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=100508 CPUtime=0.18
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 10606 1708 0 0 16 2 0 0 20 0 1 0 29195503 102920192 10407 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490521232 140163323439783 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300264 s]
/proc/loadavg: 1.14 1.09 1.04 2/55 24258
/proc/meminfo: memFree=869680/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=104484 CPUtime=0.28
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 11107 1708 0 0 26 2 0 0 20 0 1 0 29195503 106991616 10900 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490521624 140163368400981 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 26121 10900 9300 1052 0 2116 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 104484

[startup+0.700234 s]
/proc/loadavg: 1.14 1.09 1.04 2/55 24258
/proc/meminfo: memFree=869680/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=123288 CPUtime=0.68
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 17028 1708 0 0 61 7 0 0 20 0 2 0 29195503 126246912 14303 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490525752 140163367081520 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/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.14 1.09 1.04 2/57 24263
/proc/meminfo: memFree=841524/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=132396 CPUtime=1.48
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 19436 1708 0 0 141 7 0 0 20 0 2 0 29195503 135573504 16707 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490520320 140163323762824 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 33099 16707 9585 1052 0 9094 0
[pid=24258/tid=24263] ppid=24257 vsize=132396 CPUtime=0
/proc/24258/task/24263/stat : 24263 (aptitude) S 24257 24258 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29195569 135573504 16707 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257079808 140163334996692 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) 132396

[startup+3.10024 s]
/proc/loadavg: 1.14 1.09 1.04 2/57 24264
/proc/meminfo: memFree=840276/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=133808 CPUtime=3.07
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 20601 2211 0 0 295 12 0 0 20 0 2 0 29195503 137019392 16955 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490516784 140163361080364 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 33452 16955 9644 1052 0 9447 0
[pid=24258/tid=24263] ppid=24257 vsize=133808 CPUtime=0
/proc/24258/task/24263/stat : 24263 (aptitude) S 24257 24258 17863 34816 17863 4202560 6 2211 0 0 0 0 0 0 20 0 2 0 29195569 137019392 16955 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257079808 140163334996692 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) 133808

[startup+6.30024 s]
/proc/loadavg: 1.13 1.09 1.04 2/57 24264
/proc/meminfo: memFree=796388/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=246076 CPUtime=6.25
/proc/24258/stat : 24258 (aptitude) S 24257 24258 17863 34816 17863 4202496 33347 2211 0 0 607 18 0 0 20 0 2 0 29195503 251981824 28868 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490521728 140163334997579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 61519 28868 9700 1052 0 37514 0
[pid=24258/tid=24263] ppid=24257 vsize=246076 CPUtime=3.16
/proc/24258/task/24263/stat : 24263 (aptitude) R 24257 24258 17863 34816 17863 4202560 12745 2211 0 0 310 6 0 0 20 0 2 0 29195569 251981824 28868 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257073240 140163367880865 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) 246076

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

[startup+6.40032 s]
/proc/loadavg: 1.13 1.09 1.04 2/57 24264
/proc/meminfo: memFree=796388/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=247264 CPUtime=6.35
/proc/24258/stat : 24258 (aptitude) S 24257 24258 17863 34816 17863 4202496 33616 2211 0 0 617 18 0 0 20 0 2 0 29195503 253198336 29133 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490521728 140163334997579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 61816 29133 9700 1052 0 37811 0
[pid=24258/tid=24263] ppid=24257 vsize=247264 CPUtime=3.26
/proc/24258/task/24263/stat : 24263 (aptitude) R 24257 24258 17863 34816 17863 4202560 13014 2211 0 0 320 6 0 0 20 0 2 0 29195569 253198336 29133 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257073336 140163368837374 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.35
Current children cumulated vsize (KiB) 247264

[startup+8.00023 s]
/proc/loadavg: 1.13 1.09 1.04 2/57 24264
/proc/meminfo: memFree=779400/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=260992 CPUtime=7.94
/proc/24258/stat : 24258 (aptitude) S 24257 24258 17863 34816 17863 4202496 37150 2211 0 0 775 19 0 0 20 0 2 0 29195503 267255808 32587 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490521728 140163334997579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 65248 32587 9700 1052 0 41243 0
[pid=24258/tid=24263] ppid=24257 vsize=260992 CPUtime=4.84
/proc/24258/task/24263/stat : 24263 (aptitude) R 24257 24258 17863 34816 17863 4202560 16548 2211 0 0 477 7 0 0 20 0 2 0 29195569 267255808 32587 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257073336 140163332561921 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.94
Current children cumulated vsize (KiB) 260992

[startup+9.60024 s]
/proc/loadavg: 1.12 1.09 1.04 2/57 24264
/proc/meminfo: memFree=771092/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=281332 CPUtime=9.54
/proc/24258/stat : 24258 (aptitude) S 24257 24258 17863 34816 17863 4202496 42233 2211 0 0 934 20 0 0 20 0 2 0 29195503 288083968 37668 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490521728 140163334997579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 70333 37668 9700 1052 0 46328 0
[pid=24258/tid=24263] ppid=24257 vsize=281332 CPUtime=6.43
/proc/24258/task/24263/stat : 24263 (aptitude) R 24257 24258 17863 34816 17863 4202560 21631 2211 0 0 636 7 0 0 20 0 2 0 29195569 288083968 37668 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257071128 140163361076345 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.54
Current children cumulated vsize (KiB) 281332

[startup+10.4002 s]
/proc/loadavg: 1.12 1.09 1.04 2/57 24264
/proc/meminfo: memFree=755716/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=284028 CPUtime=10.34
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 43897 2211 1 0 1014 20 0 0 20 0 2 0 29195503 290844672 38489 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490517832 140163368377501 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 71007 38489 9750 1052 0 46995 0
[pid=24258/tid=24263] ppid=24257 vsize=284028 CPUtime=6.91
/proc/24258/task/24263/stat : 24263 (aptitude) S 24257 24258 17863 34816 17863 4202560 22274 2211 1 0 684 7 0 0 20 0 2 0 29195569 290844672 38489 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257079808 140163334996692 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.34
Current children cumulated vsize (KiB) 284028

[startup+10.8011 s]
/proc/loadavg: 1.12 1.09 1.04 2/57 24264
/proc/meminfo: memFree=755716/1022884 swapFree=0/0
[pid=24258] ppid=24257 vsize=284028 CPUtime=10.73
/proc/24258/stat : 24258 (aptitude) R 24257 24258 17863 34816 17863 4202496 46307 2710 1 0 1042 30 0 1 20 0 2 0 29195503 290844672 34355 18446744073709551615 140163366252544 140163370559896 140733490529968 140733490526232 140163324118506 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24258/statm: 71007 34355 9750 1052 0 46995 0
[pid=24258/tid=24263] ppid=24257 vsize=284028 CPUtime=6.92
/proc/24258/task/24263/stat : 24263 (aptitude) S 24257 24258 17863 34816 17863 4202560 22274 2710 1 0 684 7 0 1 20 0 2 0 29195569 290844672 34355 18446744073709551615 140163366252544 140163370559896 140733490529968 140163257079808 140163334996692 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.73
Current children cumulated vsize (KiB) 284028

Child status: 0
Real time (s): 10.8357
CPU time (s): 10.7927
CPU user time (s): 10.4407
CPU system time (s): 0.352022
CPU usage (%): 99.6025
Max. virtual memory (cumulated for all children) (KiB): 284028

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.4407
system time used= 0.352022
maximum resident set size= 154776
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 49174
page faults= 1
swaps= 0
block input operations= 8
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 77
involuntary context switches= 235

runsolver used 0 second user time and 0.052003 second system time

The end