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/3.runsolver.aptitude aptitude -s -y --without-recommends install wpp hibernate xtrlock gql-shell nettle-bin 

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.06 0.96 0.64 2/55 20831
/proc/meminfo: memFree=972996/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=3152 CPUtime=0
/proc/20831/stat : 20831 (runsolver) R 20830 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28263931 3227648 32 18446744073709551615 134512640 134586868 4286778704 4286776752 4152210480 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/20831/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.168813 s]
/proc/loadavg: 1.06 0.96 0.64 2/55 20831
/proc/meminfo: memFree=972996/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=28716 CPUtime=0
/proc/20831/stat : 20831 (aptitude) D 20830 20831 17863 34816 17863 4202496 154 0 11 0 0 0 0 0 20 0 1 0 28263931 29405184 77 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788612504 140280870897187 0 0 0 0 0 0 0 17 0 0 0 16 0 0
/proc/20831/statm: 7179 77 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.200412 s]
/proc/loadavg: 1.06 0.96 0.64 2/55 20831
/proc/meminfo: memFree=972996/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=33024 CPUtime=0
/proc/20831/stat : 20831 (aptitude) D 20830 20831 17863 34816 17863 4202496 161 0 13 0 0 0 0 0 20 0 1 0 28263931 33816576 85 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788612312 140280870897187 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/20831/statm: 8256 85 55 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 33024

[startup+0.300399 s]
/proc/loadavg: 1.06 0.96 0.64 2/55 20831
/proc/meminfo: memFree=972996/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=50688 CPUtime=0
/proc/20831/stat : 20831 (aptitude) R 20830 20831 17863 34816 17863 4202496 191 0 20 0 0 0 0 0 20 0 1 0 28263931 51904512 116 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788611800 140280870896410 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/20831/statm: 12672 116 69 1052 0 67 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 50688

[startup+0.700231 s]
/proc/loadavg: 1.06 0.96 0.64 2/55 20831
/proc/meminfo: memFree=972996/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=89152 CPUtime=0.07
/proc/20831/stat : 20831 (aptitude) R 20830 20831 17863 34816 17863 4202496 7532 1704 87 4 5 2 0 0 20 0 1 0 28263931 91291648 7419 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788607152 140280867878483 0 134217728 4096 0 0 0 0 17 0 0 0 58 0 0
/proc/20831/statm: 22288 7419 6508 1052 0 858 0
Current children cumulated CPU time (s) 0.07
Current children cumulated vsize (KiB) 89152

[startup+1.50022 s]
/proc/loadavg: 1.06 0.96 0.64 2/56 20835
/proc/meminfo: memFree=935408/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=108136 CPUtime=0.54
/proc/20831/stat : 20831 (aptitude) R 20830 20831 17863 34816 17863 4202496 12078 1704 87 4 46 8 0 0 20 0 2 0 28263931 110731264 10538 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788609512 140280875162781 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 91 0 0
/proc/20831/statm: 27034 10538 6925 1052 0 5604 0
Current children cumulated CPU time (s) 0.54
Current children cumulated vsize (KiB) 108136

[startup+3.10026 s]
/proc/loadavg: 1.06 0.96 0.64 2/57 20836
/proc/meminfo: memFree=890884/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=121860 CPUtime=2.11
/proc/20831/stat : 20831 (aptitude) S 20830 20831 17863 34816 17863 4202496 17266 2200 87 6 200 11 0 0 20 0 2 0 28263931 124784640 14171 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788607648 140280841782859 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 91 0 0
/proc/20831/statm: 30465 14171 7122 1052 0 9035 0
[pid=20831/tid=20836] ppid=20830 vsize=121860 CPUtime=0.28
/proc/20831/task/20836/stat : 20836 (aptitude) R 20830 20831 17863 34816 17863 4202560 2845 2200 0 6 27 1 0 0 20 0 2 0 28264074 124784640 14171 18446744073709551615 140280873037824 140280877345176 140734788615888 140280776435432 140280841773489 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.11
Current children cumulated vsize (KiB) 121860
heavy processes:

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

[startup+3.20368 s]
/proc/loadavg: 1.06 0.96 0.64 3/57 20837
/proc/meminfo: memFree=883320/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=121992 CPUtime=2.15
/proc/20831/stat : 20831 (aptitude) D 20830 20831 17863 34816 17863 4202496 17322 2200 93 6 204 11 0 0 20 0 2 0 28263931 124919808 14230 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788603896 140280830883072 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 94 0 0
/proc/20831/statm: 30498 14230 7138 1052 0 9068 0
[pid=20831/tid=20836] ppid=20830 vsize=121992 CPUtime=0.33
/proc/20831/task/20836/stat : 20836 (aptitude) S 20830 20831 17863 34816 17863 4202560 2884 2200 1 6 32 1 0 0 20 0 2 0 28264074 124919808 14230 18446744073709551615 140280873037824 140280877345176 140734788615888 140280776443904 140280841781972 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 2.15
Current children cumulated vsize (KiB) 121992

[startup+3.40322 s]
/proc/loadavg: 1.06 0.96 0.64 2/57 20837
/proc/meminfo: memFree=881956/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=122152 CPUtime=2.32
/proc/20831/stat : 20831 (aptitude) R 20830 20831 17863 34816 17863 4202496 19154 2200 100 6 220 12 0 0 20 0 2 0 28263931 125083648 14289 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788605648 140280830740790 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 98 0 0
/proc/20831/statm: 30538 14289 7171 1052 0 9101 0
[pid=20831/tid=20836] ppid=20830 vsize=122152 CPUtime=0.33
/proc/20831/task/20836/stat : 20836 (aptitude) S 20830 20831 17863 34816 17863 4202560 2884 2200 1 6 32 1 0 0 20 0 2 0 28264074 125083648 14289 18446744073709551615 140280873037824 140280877345176 140734788615888 140280776443904 140280841781972 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 2.32
Current children cumulated vsize (KiB) 122152

[startup+3.50029 s]
/proc/loadavg: 1.06 0.96 0.64 2/57 20837
/proc/meminfo: memFree=881956/1022884 swapFree=0/0
[pid=20831] ppid=20830 vsize=87084 CPUtime=2.34
/proc/20831/stat : 20831 (aptitude) D 20830 20831 17863 34816 17863 4202496 19294 2699 105 6 221 12 0 1 20 0 1 0 28263931 89174016 5543 18446744073709551615 140280873037824 140280877345176 140734788615888 140734788613200 140280873763184 0 134217728 4096 0 0 0 0 17 0 0 0 105 0 0
/proc/20831/statm: 21771 5543 1499 1052 0 6027 0
Current children cumulated CPU time (s) 2.34
Current children cumulated vsize (KiB) 87084

Child status: 0
Real time (s): 3.54275
CPU time (s): 2.36815
CPU user time (s): 2.22414
CPU system time (s): 0.144009
CPU usage (%): 66.8448
Max. virtual memory (cumulated for all children) (KiB): 122152

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 2.22414
system time used= 0.144009
maximum resident set size= 57168
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 22053
page faults= 123
swaps= 0
block input operations= 126576
block output operations= 8
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1378
involuntary context switches= 89

runsolver used 0.016001 second user time and 0.012 second system time

The end