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/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.18 1.07 1.01 2/55 23246
/proc/meminfo: memFree=959708/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=3152 CPUtime=0
/proc/23246/stat : 23246 (runsolver) R 23245 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28881587 3227648 32 18446744073709551615 134512640 134586868 4287903232 4287901280 4151596080 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23246/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.153062 s]
/proc/loadavg: 1.18 1.07 1.01 2/55 23246
/proc/meminfo: memFree=959708/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=12328 CPUtime=0
/proc/23246/stat : 23246 (aptitude) D 23245 23246 17863 34816 17863 4202496 129 0 5 0 0 0 0 0 20 0 1 0 28881587 12623872 50 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805128632 140118496597539 0 0 0 0 0 0 0 17 0 0 0 14 0 0
/proc/23246/statm: 3082 50 36 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.200224 s]
/proc/loadavg: 1.18 1.07 1.01 2/55 23246
/proc/meminfo: memFree=959708/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=25980 CPUtime=0
/proc/23246/stat : 23246 (aptitude) D 23245 23246 17863 34816 17863 4202496 150 0 10 0 0 0 0 0 20 0 1 0 28881587 26603520 72 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805128392 140118496596758 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23246/statm: 6495 72 48 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 25980

[startup+0.300226 s]
/proc/loadavg: 1.18 1.07 1.01 2/55 23246
/proc/meminfo: memFree=959708/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=44448 CPUtime=0
/proc/23246/stat : 23246 (aptitude) D 23245 23246 17863 34816 17863 4202496 180 0 17 0 0 0 0 0 20 0 1 0 28881587 45514752 104 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805127912 140118496597382 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/23246/statm: 11112 104 65 1052 0 61 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 44448

[startup+0.700282 s]
/proc/loadavg: 1.18 1.07 1.01 2/55 23246
/proc/meminfo: memFree=959708/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=100508 CPUtime=0.02
/proc/23246/stat : 23246 (aptitude) D 23245 23246 17863 34816 17863 4202496 3785 1705 38 4 0 1 1 0 20 0 1 0 28881587 102920192 3623 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805123200 140118493787992 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/23246/statm: 25127 3623 2449 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+1.50021 s]
/proc/loadavg: 1.17 1.07 1.01 2/56 23250
/proc/meminfo: memFree=952004/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=119772 CPUtime=0.51
/proc/23246/stat : 23246 (aptitude) R 23245 23246 17863 34816 17863 4202496 16443 1705 59 4 44 6 1 0 20 0 1 0 28881587 122646528 14778 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805121160 140118467494256 0 134217728 4096 0 0 0 0 17 0 0 0 93 0 0
/proc/23246/statm: 29943 14778 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.51
Current children cumulated vsize (KiB) 119772

[startup+3.10024 s]
/proc/loadavg: 1.17 1.07 1.01 2/57 23251
/proc/meminfo: memFree=850688/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=132516 CPUtime=1.67
/proc/23246/stat : 23246 (aptitude) R 23245 23246 17863 34816 17863 4202496 19394 1705 59 4 155 11 1 0 20 0 2 0 28881587 135696384 16722 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805118888 140118493566004 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 137 0 0
/proc/23246/statm: 33129 16722 9585 1052 0 9124 0
[pid=23246/tid=23251] ppid=23245 vsize=132516 CPUtime=0.01
/proc/23246/task/23251/stat : 23251 (aptitude) S 23245 23246 17863 34816 17863 4202560 4 1705 0 4 0 0 1 0 20 0 2 0 28881796 135696384 16722 18446744073709551615 140118498738176 140118503045528 140734805131728 140118389565440 140118467482324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.67
Current children cumulated vsize (KiB) 132516
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.15 1.07 1.01 2/57 23252
/proc/meminfo: memFree=820804/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=233620 CPUtime=4.8
/proc/23246/stat : 23246 (aptitude) S 23245 23246 17863 34816 17863 4202496 29591 2201 59 6 460 19 1 0 20 0 2 0 28881587 239226880 25729 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805123488 140118467483211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/23246/statm: 58405 25729 9700 1052 0 34400 0
[pid=23246/tid=23251] ppid=23245 vsize=233620 CPUtime=1.68
/proc/23246/task/23251/stat : 23251 (aptitude) R 23245 23246 17863 34816 17863 4202560 9036 2201 0 6 164 3 1 0 20 0 2 0 28881796 239226880 25729 18446744073709551615 140118498738176 140118503045528 140734805131728 140118389556760 140118501480712 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.8
Current children cumulated vsize (KiB) 233620
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.14 1.06 1.01 2/57 23252
/proc/meminfo: memFree=764012/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=276972 CPUtime=11.17
/proc/23246/stat : 23246 (aptitude) R 23245 23246 17863 34816 17863 4202496 42102 2201 59 6 1089 27 1 0 20 0 2 0 28881587 283619328 36729 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805119592 140118502053752 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/23246/statm: 69243 36729 9749 1052 0 45231 0
[pid=23246/tid=23251] ppid=23245 vsize=276972 CPUtime=7.75
/proc/23246/task/23251/stat : 23251 (aptitude) S 23245 23246 17863 34816 17863 4202560 20528 2201 0 6 763 11 1 0 20 0 2 0 28881796 283619328 36729 18446744073709551615 140118498738176 140118503045528 140734805131728 140118389565440 140118467482324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.17
Current children cumulated vsize (KiB) 276972

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

[startup+12.8003 s]
/proc/loadavg: 1.14 1.06 1.01 2/57 23252
/proc/meminfo: memFree=764012/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=276972 CPUtime=11.28
/proc/23246/stat : 23246 (aptitude) R 23245 23246 17863 34816 17863 4202496 43759 2201 59 6 1099 28 1 0 20 0 2 0 28881587 283619328 36693 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805123928 140118500944771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/23246/statm: 69243 36693 9749 1052 0 45231 0
[pid=23246/tid=23251] ppid=23245 vsize=276972 CPUtime=7.75
/proc/23246/task/23251/stat : 23251 (aptitude) S 23245 23246 17863 34816 17863 4202560 20528 2201 0 6 763 11 1 0 20 0 2 0 28881796 283619328 36693 18446744073709551615 140118498738176 140118503045528 140734805131728 140118389565440 140118467482324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.28
Current children cumulated vsize (KiB) 276972

[startup+13.0002 s]
/proc/loadavg: 1.14 1.06 1.01 2/57 23252
/proc/meminfo: memFree=764012/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=276972 CPUtime=11.48
/proc/23246/stat : 23246 (aptitude) R 23245 23246 17863 34816 17863 4202496 44042 2700 59 6 1114 32 2 0 20 0 2 0 28881587 283619328 36838 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805122888 140118456582213 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/23246/statm: 69243 36838 9749 1052 0 45231 0
[pid=23246/tid=23251] ppid=23245 vsize=276972 CPUtime=7.76
/proc/23246/task/23251/stat : 23251 (aptitude) S 23245 23246 17863 34816 17863 4202560 20528 2700 0 6 763 11 2 0 20 0 2 0 28881796 283619328 36838 18446744073709551615 140118498738176 140118503045528 140734805131728 140118389565440 140118467482324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.48
Current children cumulated vsize (KiB) 276972

[startup+13.1002 s]
/proc/loadavg: 1.14 1.06 1.01 2/57 23252
/proc/meminfo: memFree=764012/1022884 swapFree=0/0
[pid=23246] ppid=23245 vsize=276972 CPUtime=11.57
/proc/23246/stat : 23246 (aptitude) R 23245 23246 17863 34816 17863 4202496 44412 2700 59 6 1121 34 2 0 20 0 2 0 28881587 283619328 36693 18446744073709551615 140118498738176 140118503045528 140734805131728 140734805123704 140118456229342 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/23246/statm: 69243 36693 9749 1052 0 45231 0
[pid=23246/tid=23251] ppid=23245 vsize=276972 CPUtime=7.76
/proc/23246/task/23251/stat : 23251 (aptitude) S 23245 23246 17863 34816 17863 4202560 20528 2700 0 6 763 11 2 0 20 0 2 0 28881796 283619328 36693 18446744073709551615 140118498738176 140118503045528 140734805131728 140118389565440 140118467482324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.57
Current children cumulated vsize (KiB) 276972

Child status: 0
Real time (s): 13.1384
CPU time (s): 11.6247
CPU user time (s): 11.2367
CPU system time (s): 0.388024
CPU usage (%): 88.4792
Max. virtual memory (cumulated for all children) (KiB): 276972

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.2367
system time used= 0.388024
maximum resident set size= 147672
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 47370
page faults= 65
swaps= 0
block input operations= 179464
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1692
involuntary context switches= 251

runsolver used 0.036002 second user time and 0.036002 second system time

The end