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-sid/logs/104.runsolver.aptitude aptitude -s -y --without-recommends remove libatk1.0-dev libkpimidentities1 kdebase-bin libvte4 openoffice.org-debian-files 

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.04 1.07 1.08 2/55 26607
/proc/meminfo: memFree=832856/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=3152 CPUtime=0
/proc/26607/stat : 26607 (runsolver) R 26606 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29890910 3227648 32 18446744073709551615 134512640 134586868 4292021216 4292019264 4152079408 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.202046 s]
/proc/loadavg: 1.04 1.07 1.08 2/55 26607
/proc/meminfo: memFree=832856/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=103288 CPUtime=0.18
/proc/26607/stat : 26607 (aptitude) R 26606 26607 17863 34816 17863 4202496 11301 1709 0 0 16 2 0 0 20 0 1 0 29890910 105766912 11100 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161598544 140084170180072 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 25822 11100 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300289 s]
/proc/loadavg: 1.04 1.07 1.08 2/55 26607
/proc/meminfo: memFree=832856/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=103432 CPUtime=0.28
/proc/26607/stat : 26607 (aptitude) R 26606 26607 17863 34816 17863 4202496 11428 1709 0 0 26 2 0 0 20 0 1 0 29890910 105914368 11219 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161597056 140084170192866 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 25858 11219 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.400272 s]
/proc/loadavg: 1.04 1.07 1.08 2/55 26607
/proc/meminfo: memFree=832856/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=114256 CPUtime=0.39
/proc/26607/stat : 26607 (aptitude) R 26606 26607 17863 34816 17863 4202496 14146 1709 0 0 35 4 0 0 20 0 1 0 29890910 116998144 13936 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161596424 140084177464450 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 28564 13936 9967 1052 0 3901 0
Current children cumulated CPU time (s) 0.39
Current children cumulated vsize (KiB) 114256

[startup+0.700202 s]
/proc/loadavg: 1.04 1.07 1.08 2/55 26607
/proc/meminfo: memFree=832856/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=123068 CPUtime=0.68
/proc/26607/stat : 26607 (aptitude) R 26606 26607 17863 34816 17863 4202496 17689 1709 0 0 63 5 0 0 20 0 1 0 29890910 126021632 15964 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161596712 140084170239891 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 30767 15964 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50025 s]
/proc/loadavg: 1.04 1.07 1.08 2/57 26612
/proc/meminfo: memFree=803584/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=135852 CPUtime=1.47
/proc/26607/stat : 26607 (aptitude) R 26606 26607 17863 34816 17863 4202496 20627 1709 0 0 141 6 0 0 20 0 2 0 29890910 139112448 17543 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161594392 140084178047120 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 33963 17543 10227 1052 0 9300 0
[pid=26607/tid=26612] ppid=26606 vsize=135852 CPUtime=0
/proc/26607/task/26612/stat : 26612 (aptitude) S 26606 26607 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29890987 139112448 17543 18446744073709551615 140084175339520 140084179646872 140735161607280 140084063016960 140084144083668 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) 135852

[startup+3.10024 s]
/proc/loadavg: 1.04 1.07 1.08 2/57 26612
/proc/meminfo: memFree=802840/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=148660 CPUtime=3.07
/proc/26607/stat : 26607 (aptitude) S 26606 26607 17863 34816 17863 4202496 23938 1709 0 0 300 7 0 0 20 0 2 0 29890910 152227840 20853 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161599040 140084144084555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 37165 20853 10320 1052 0 12502 0
[pid=26607/tid=26612] ppid=26606 vsize=148660 CPUtime=0.27
/proc/26607/task/26612/stat : 26612 (aptitude) R 26606 26607 17863 34816 17863 4202560 3153 1709 0 0 27 0 0 0 20 0 2 0 29890987 152227840 20853 18446744073709551615 140084175339520 140084179646872 140735161607280 140084063007208 140084177859162 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) 148660

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

[startup+3.30025 s]
/proc/loadavg: 1.04 1.07 1.08 2/57 26612
/proc/meminfo: memFree=802840/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=149848 CPUtime=3.27
/proc/26607/stat : 26607 (aptitude) S 26606 26607 17863 34816 17863 4202496 24211 1709 0 0 319 8 0 0 20 0 2 0 29890910 153444352 21126 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161599040 140084144084555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 37462 21126 10320 1052 0 12799 0
[pid=26607/tid=26612] ppid=26606 vsize=149848 CPUtime=0.47
/proc/26607/task/26612/stat : 26612 (aptitude) R 26606 26607 17863 34816 17863 4202560 3426 1709 0 0 46 1 0 0 20 0 2 0 29890987 153444352 21126 18446744073709551615 140084175339520 140084179646872 140735161607280 140084063010392 140084177550426 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.27
Current children cumulated vsize (KiB) 149848

[startup+3.70026 s]
/proc/loadavg: 1.04 1.07 1.08 2/57 26612
/proc/meminfo: memFree=788580/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=151724 CPUtime=3.66
/proc/26607/stat : 26607 (aptitude) R 26606 26607 17863 34816 17863 4202496 24755 1709 0 0 358 8 0 0 20 0 2 0 29890910 155365376 21668 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161595144 140084177546015 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 37931 21668 10370 1052 0 13261 0
[pid=26607/tid=26612] ppid=26606 vsize=151724 CPUtime=0.77
/proc/26607/task/26612/stat : 26612 (aptitude) S 26606 26607 17863 34816 17863 4202560 3904 1709 0 0 75 2 0 0 20 0 2 0 29890987 155365376 21668 18446744073709551615 140084175339520 140084179646872 140735161607280 140084063016960 140084144083668 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.66
Current children cumulated vsize (KiB) 151724

[startup+3.80025 s]
/proc/loadavg: 1.04 1.07 1.08 2/57 26612
/proc/meminfo: memFree=788580/1022884 swapFree=0/0
[pid=26607] ppid=26606 vsize=151724 CPUtime=3.76
/proc/26607/stat : 26607 (aptitude) R 26606 26607 17863 34816 17863 4202496 24755 1709 0 0 368 8 0 0 20 0 2 0 29890910 155365376 21668 18446744073709551615 140084175339520 140084179646872 140735161607280 140735161595144 140084177544318 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26607/statm: 37931 21668 10370 1052 0 13261 0
[pid=26607/tid=26612] ppid=26606 vsize=151724 CPUtime=0.77
/proc/26607/task/26612/stat : 26612 (aptitude) S 26606 26607 17863 34816 17863 4202560 3904 1709 0 0 75 2 0 0 20 0 2 0 29890987 155365376 21668 18446744073709551615 140084175339520 140084179646872 140735161607280 140084063016960 140084144083668 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.76
Current children cumulated vsize (KiB) 151724

Child status: 0
Real time (s): 3.84345
CPU time (s): 3.82824
CPU user time (s): 3.71223
CPU system time (s): 0.116007
CPU usage (%): 99.6042
Max. virtual memory (cumulated for all children) (KiB): 151724

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.71223
system time used= 0.116007
maximum resident set size= 86688
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 26533
page faults= 0
swaps= 0
block input operations= 0
block output operations= 8
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 55
involuntary context switches= 106

runsolver used 0.012 second user time and 0.012 second system time

The end