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/136.runsolver.aptitude aptitude -s -y --without-recommends remove gtkhtml3.2 slang1 secpolicy libnews-nntpclient-perl python2.3-numeric 

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.00 1.01 1.00 2/55 22460
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=3152 CPUtime=0
/proc/22460/stat : 22460 (runsolver) R 22459 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28695616 3227648 32 18446744073709551615 134512640 134586868 4291923344 4291921392 4151395376 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.142081 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22460
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=89152 CPUtime=0.13
/proc/22460/stat : 22460 (aptitude) R 22459 22460 17863 34816 17863 4202496 7772 1710 0 0 11 2 0 0 20 0 1 0 28695616 91291648 7573 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341034704 140049433880011 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 22288 7573 6662 1052 0 858 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 89152

[startup+0.200279 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22460
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=89152 CPUtime=0.19
/proc/22460/stat : 22460 (aptitude) R 22459 22460 17863 34816 17863 4202496 7869 1710 0 0 17 2 0 0 20 0 1 0 28695616 91291648 7662 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341033216 140049396621200 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300267 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22460
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=101864 CPUtime=0.29
/proc/22460/stat : 22460 (aptitude) R 22459 22460 17863 34816 17863 4202496 11708 1710 0 0 26 3 0 0 20 0 1 0 28695616 104308736 10756 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341032872 140049396579871 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700199 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22460
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=113868 CPUtime=0.68
/proc/22460/stat : 22460 (aptitude) R 22459 22460 17863 34816 17863 4202496 13632 1710 0 0 64 4 0 0 20 0 2 0 28695616 116600832 12004 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341034712 140049396549959 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 28467 12004 6965 1052 0 7037 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 113868

[startup+1.50023 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22465
/proc/meminfo: memFree=883632/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=115236 CPUtime=1.47
/proc/22460/stat : 22460 (aptitude) R 22459 22460 17863 34816 17863 4202496 13836 1710 0 0 143 4 0 0 20 0 2 0 28695616 118001664 12206 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341030144 140049397191927 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 28809 12206 7034 1052 0 7379 0
[pid=22460/tid=22465] ppid=22459 vsize=115236 CPUtime=0
/proc/22460/task/22465/stat : 22465 (aptitude) S 22459 22460 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 28695661 118001664 12206 18446744073709551615 140049439039488 140049443346840 140733341043440 140049342445568 140049407783636 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) 115236

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

[startup+1.60032 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22465
/proc/meminfo: memFree=883632/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=115236 CPUtime=1.57
/proc/22460/stat : 22460 (aptitude) R 22459 22460 17863 34816 17863 4202496 13836 1710 0 0 153 4 0 0 20 0 2 0 28695616 118001664 12206 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341030144 140049407775153 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 28809 12206 7034 1052 0 7379 0
[pid=22460/tid=22465] ppid=22459 vsize=115236 CPUtime=0
/proc/22460/task/22465/stat : 22465 (aptitude) S 22459 22460 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 28695661 118001664 12206 18446744073709551615 140049439039488 140049443346840 140733341043440 140049342445568 140049407783636 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.57
Current children cumulated vsize (KiB) 115236

[startup+2.40023 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22465
/proc/meminfo: memFree=871108/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=128436 CPUtime=2.37
/proc/22460/stat : 22460 (aptitude) S 22459 22460 17863 34816 17863 4202496 17405 1710 0 0 231 6 0 0 20 0 2 0 28695616 131518464 15774 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341035200 140049407784523 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 32109 15774 7090 1052 0 10679 0
[pid=22460/tid=22465] ppid=22459 vsize=128436 CPUtime=0.67
/proc/22460/task/22465/stat : 22465 (aptitude) R 22459 22460 17863 34816 17863 4202560 3568 1710 0 0 66 1 0 0 20 0 2 0 28695661 131518464 15774 18446744073709551615 140049439039488 140049443346840 140733341043440 140049342439144 140049434439217 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) 128436

[startup+2.80025 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22465
/proc/meminfo: memFree=871108/1022884 swapFree=0/0
[pid=22460] ppid=22459 vsize=131104 CPUtime=2.77
/proc/22460/stat : 22460 (aptitude) R 22459 22460 17863 34816 17863 4202496 18148 1710 0 0 270 7 0 0 20 0 2 0 28695616 134250496 16515 18446744073709551615 140049439039488 140049443346840 140733341043440 140733341031304 140049441247253 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22460/statm: 32776 16515 7140 1052 0 11339 0
[pid=22460/tid=22465] ppid=22459 vsize=131104 CPUtime=0.93
/proc/22460/task/22465/stat : 22465 (aptitude) S 22459 22460 17863 34816 17863 4202560 4256 1710 0 0 91 2 0 0 20 0 2 0 28695661 134250496 16515 18446744073709551615 140049439039488 140049443346840 140733341043440 140049342445568 140049407783636 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) 131104

Child status: 0
Real time (s): 2.83299
CPU time (s): 2.82418
CPU user time (s): 2.73217
CPU system time (s): 0.092005
CPU usage (%): 99.6888
Max. virtual memory (cumulated for all children) (KiB): 131104

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 2.73217
system time used= 0.092005
maximum resident set size= 66076
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 19926
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= 55
involuntary context switches= 97

runsolver used 0 second user time and 0.016001 second system time

The end