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/42.runsolver.aptitude aptitude -s -y --without-recommends install gstreamer0.8-jack g77-2.95-doc upx-ucl libginac1.3 ted-gtk 

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 1.05 1.01 2/55 23282
/proc/meminfo: memFree=869420/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=3152 CPUtime=0
/proc/23282/stat : 23282 (runsolver) R 23281 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28887939 3227648 33 18446744073709551615 134512640 134586868 4286797168 4286795216 4151530544 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.142865 s]
/proc/loadavg: 1.06 1.05 1.01 2/55 23282
/proc/meminfo: memFree=869420/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=100508 CPUtime=0.13
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 10578 1711 0 0 9 4 0 0 20 0 1 0 28887939 102920192 10379 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849270592 140648362516792 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 25127 10379 9204 1052 0 1122 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 100508

[startup+0.200279 s]
/proc/loadavg: 1.06 1.05 1.01 2/55 23282
/proc/meminfo: memFree=869420/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=100508 CPUtime=0.18
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 10606 1711 0 0 14 4 0 0 20 0 1 0 28887939 102920192 10407 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849270592 140648367945392 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300272 s]
/proc/loadavg: 1.06 1.05 1.01 2/55 23282
/proc/meminfo: memFree=869420/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=104484 CPUtime=0.28
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 11036 1711 0 0 24 4 0 0 20 0 1 0 28887939 106991616 10829 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849270984 140648369264750 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 26121 10829 9300 1052 0 2116 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 104484

[startup+0.700199 s]
/proc/loadavg: 1.06 1.05 1.01 2/55 23282
/proc/meminfo: memFree=869420/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=123288 CPUtime=0.68
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 17029 1711 0 0 61 7 0 0 20 0 2 0 28887939 126246912 14303 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849274920 140648361969634 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23287
/proc/meminfo: memFree=841388/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=131952 CPUtime=1.48
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 19318 1711 0 0 140 8 0 0 20 0 2 0 28887939 135118848 16587 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849269624 140648370171007 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 32988 16587 9585 1052 0 8983 0
[pid=23282/tid=23287] ppid=23281 vsize=131952 CPUtime=0
/proc/23282/task/23287/stat : 23287 (aptitude) S 23281 23282 17863 34816 17863 4202560 4 1711 0 0 0 0 0 0 20 0 2 0 28888006 135118848 16587 18446744073709551615 140648367116288 140648371423640 140736849279328 140648257943552 140648335860436 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) 131952

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

[startup+1.60032 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23287
/proc/meminfo: memFree=841388/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=131952 CPUtime=1.58
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 19326 1711 0 0 150 8 0 0 20 0 2 0 28887939 135118848 16595 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849269624 140648333049445 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 32988 16595 9586 1052 0 8983 0
[pid=23282/tid=23287] ppid=23281 vsize=131952 CPUtime=0
/proc/23282/task/23287/stat : 23287 (aptitude) S 23281 23282 17863 34816 17863 4202560 4 1711 0 0 0 0 0 0 20 0 2 0 28888006 135118848 16595 18446744073709551615 140648367116288 140648371423640 140736849279328 140648257943552 140648335860436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.58
Current children cumulated vsize (KiB) 131952

[startup+2.40024 s]
/proc/loadavg: 1.05 1.05 1.00 2/57 23288
/proc/meminfo: memFree=840388/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=133580 CPUtime=2.37
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 20269 2210 0 0 228 8 0 1 20 0 2 0 28887939 136785920 16746 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849266032 140648333049424 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 33395 16746 9637 1052 0 9390 0
[pid=23282/tid=23287] ppid=23281 vsize=133580 CPUtime=0.01
/proc/23282/task/23287/stat : 23287 (aptitude) S 23281 23282 17863 34816 17863 4202560 6 2210 0 0 0 0 0 1 20 0 2 0 28888006 136785920 16746 18446744073709551615 140648367116288 140648371423640 140736849279328 140648257943552 140648335860436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.37
Current children cumulated vsize (KiB) 133580

[startup+2.80025 s]
/proc/loadavg: 1.05 1.05 1.00 2/57 23288
/proc/meminfo: memFree=840388/1022884 swapFree=0/0
[pid=23282] ppid=23281 vsize=133608 CPUtime=2.77
/proc/23282/stat : 23282 (aptitude) R 23281 23282 17863 34816 17863 4202496 22620 2210 0 0 267 9 0 1 20 0 2 0 28887939 136814592 16850 18446744073709551615 140648367116288 140648371423640 140736849279328 140736849269088 140648324819254 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23282/statm: 33402 16850 9738 1052 0 9390 0
[pid=23282/tid=23287] ppid=23281 vsize=133608 CPUtime=0.01
/proc/23282/task/23287/stat : 23287 (aptitude) S 23281 23282 17863 34816 17863 4202560 59 2210 0 0 0 0 0 1 20 0 2 0 28888006 136814592 16850 18446744073709551615 140648367116288 140648371423640 140736849279328 140648257943552 140648335860436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.77
Current children cumulated vsize (KiB) 133608

Child status: 0
Real time (s): 2.83549
CPU time (s): 2.81618
CPU user time (s): 2.68817
CPU system time (s): 0.128008
CPU usage (%): 99.319
Max. virtual memory (cumulated for all children) (KiB): 133608

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 2.68817
system time used= 0.128008
maximum resident set size= 67412
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25561
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 63
involuntary context switches= 94

runsolver used 0 second user time and 0.020001 second system time

The end