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/159.runsolver.aptitude aptitude -s -y --without-recommends remove libmng-dev libksba8 libboost-python1.32.0 kpersonalizer kdevelop3-data 

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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.15 1.07 1.06 2/55 26995
/proc/meminfo: memFree=834460/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=54860 CPUtime=0
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 584 0 0 0 0 0 0 0 20 0 1 0 29952765 56176640 483 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980910152 139990158034832 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 13715 483 395 1052 0 73 0

[startup+0.167376 s]
/proc/loadavg: 1.15 1.07 1.06 2/55 26995
/proc/meminfo: memFree=834460/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=103288 CPUtime=0.14
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 11289 1707 0 0 12 2 0 0 20 0 1 0 29952765 105766912 11090 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980902208 139990155633046 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 25822 11090 9878 1052 0 1159 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 103288

[startup+0.200341 s]
/proc/loadavg: 1.15 1.07 1.06 2/55 26995
/proc/meminfo: memFree=834460/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=103288 CPUtime=0.19
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 11299 1707 0 0 16 3 0 0 20 0 1 0 29952765 105766912 11100 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980902208 139990155073099 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 25822 11100 9888 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300266 s]
/proc/loadavg: 1.15 1.07 1.06 2/55 26995
/proc/meminfo: memFree=834460/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=103288 CPUtime=0.29
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 11308 1707 0 0 26 3 0 0 20 0 1 0 29952765 105766912 11109 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980902208 139990117772790 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 25822 11109 9897 1052 0 1159 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103288

[startup+0.700202 s]
/proc/loadavg: 1.15 1.07 1.06 2/55 26995
/proc/meminfo: memFree=834460/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=123068 CPUtime=0.68
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 17688 1707 0 0 62 6 0 0 20 0 1 0 29952765 126021632 15965 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980900376 139990117772831 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.15 1.07 1.06 2/57 27000
/proc/meminfo: memFree=805436/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=135852 CPUtime=1.47
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 20627 1707 0 0 140 7 0 0 20 0 2 0 29952765 139112448 17544 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980899272 139990128973358 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 33963 17544 10227 1052 0 9300 0
[pid=26995/tid=27000] ppid=26994 vsize=135852 CPUtime=0
/proc/26995/task/27000/stat : 27000 (aptitude) S 26994 26995 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 29952843 139112448 17544 18446744073709551615 139990160232448 139990164539800 140735980910944 139990047909888 139990128976596 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.14 1.07 1.06 2/57 27000
/proc/meminfo: memFree=804568/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=145104 CPUtime=3.07
/proc/26995/stat : 26995 (aptitude) S 26994 26995 17863 34816 17863 4202496 23040 1707 0 0 298 9 0 0 20 0 2 0 29952765 148586496 19955 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980902704 139990128977483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 36276 19955 10320 1052 0 11613 0
[pid=26995/tid=27000] ppid=26994 vsize=145104 CPUtime=0.26
/proc/26995/task/27000/stat : 27000 (aptitude) R 26994 26995 17863 34816 17863 4202560 2254 1707 0 0 25 1 0 0 20 0 2 0 29952843 148586496 19955 18446744073709551615 139990160232448 139990164539800 140735980910944 139990047899064 139990117732789 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) 145104

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

[startup+3.20031 s]
/proc/loadavg: 1.14 1.07 1.06 2/57 27000
/proc/meminfo: memFree=804568/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=149328 CPUtime=3.17
/proc/26995/stat : 26995 (aptitude) S 26994 26995 17863 34816 17863 4202496 24089 1707 0 0 308 9 0 0 20 0 2 0 29952765 152911872 21004 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980902704 139990128977483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 37332 21004 10320 1052 0 12669 0
[pid=26995/tid=27000] ppid=26994 vsize=149328 CPUtime=0.36
/proc/26995/task/27000/stat : 27000 (aptitude) R 26994 26995 17863 34816 17863 4202560 3303 1707 0 0 35 1 0 0 20 0 2 0 29952843 152911872 21004 18446744073709551615 139990160232448 139990164539800 140735980910944 139990047900616 139990161867440 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.17
Current children cumulated vsize (KiB) 149328

[startup+4.00024 s]
/proc/loadavg: 1.14 1.07 1.06 2/57 27000
/proc/meminfo: memFree=790432/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=157512 CPUtime=3.97
/proc/26995/stat : 26995 (aptitude) S 26994 26995 17863 34816 17863 4202496 26131 1707 0 0 388 9 0 0 20 0 2 0 29952765 161292288 23046 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980902704 139990128977483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 39378 23046 10321 1052 0 14715 0
[pid=26995/tid=27000] ppid=26994 vsize=157512 CPUtime=1.15
/proc/26995/task/27000/stat : 27000 (aptitude) R 26994 26995 17863 34816 17863 4202560 5344 1707 0 0 114 1 0 0 20 0 2 0 29952843 161292288 23046 18446744073709551615 139990160232448 139990164539800 140735980910944 139990047903320 139990162865504 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.97
Current children cumulated vsize (KiB) 157512

[startup+4.40023 s]
/proc/loadavg: 1.14 1.07 1.06 2/57 27000
/proc/meminfo: memFree=780388/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=160416 CPUtime=4.37
/proc/26995/stat : 26995 (aptitude) S 26994 26995 17863 34816 17863 4202496 26881 1707 0 0 428 9 0 0 20 0 2 0 29952765 164265984 23796 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980902704 139990128977483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 40104 23796 10321 1052 0 15441 0
[pid=26995/tid=27000] ppid=26994 vsize=160416 CPUtime=1.56
/proc/26995/task/27000/stat : 27000 (aptitude) R 26994 26995 17863 34816 17863 4202560 6094 1707 0 0 155 1 0 0 20 0 2 0 29952843 164265984 23796 18446744073709551615 139990160232448 139990164539800 140735980910944 139990047901208 139990163007789 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.37
Current children cumulated vsize (KiB) 160416

[startup+4.80024 s]
/proc/loadavg: 1.14 1.07 1.06 2/57 27000
/proc/meminfo: memFree=780388/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=163480 CPUtime=4.76
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 27665 1707 0 0 466 10 0 0 20 0 2 0 29952765 167403520 24578 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980900776 139990155049076 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 40870 24578 10370 1052 0 16200 0
[pid=26995/tid=27000] ppid=26994 vsize=163480 CPUtime=1.86
/proc/26995/task/27000/stat : 27000 (aptitude) S 26994 26995 17863 34816 17863 4202560 6823 1707 0 0 184 2 0 0 20 0 2 0 29952843 167403520 24578 18446744073709551615 139990160232448 139990164539800 140735980910944 139990047909888 139990128976596 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.76
Current children cumulated vsize (KiB) 163480

[startup+4.90025 s]
/proc/loadavg: 1.14 1.07 1.06 2/57 27000
/proc/meminfo: memFree=780388/1022884 swapFree=0/0
[pid=26995] ppid=26994 vsize=163480 CPUtime=4.86
/proc/26995/stat : 26995 (aptitude) R 26994 26995 17863 34816 17863 4202496 27665 1707 0 0 476 10 0 0 20 0 2 0 29952765 167403520 24578 18446744073709551615 139990160232448 139990164539800 140735980910944 140735980898808 139990161061473 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26995/statm: 40870 24578 10370 1052 0 16200 0
[pid=26995/tid=27000] ppid=26994 vsize=163480 CPUtime=1.86
/proc/26995/task/27000/stat : 27000 (aptitude) S 26994 26995 17863 34816 17863 4202560 6823 1707 0 0 184 2 0 0 20 0 2 0 29952843 167403520 24578 18446744073709551615 139990160232448 139990164539800 140735980910944 139990047909888 139990128976596 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.86
Current children cumulated vsize (KiB) 163480

Child status: 0
Real time (s): 4.98105
CPU time (s): 4.96031
CPU user time (s): 4.8323
CPU system time (s): 0.128008
CPU usage (%): 99.5836
Max. virtual memory (cumulated for all children) (KiB): 163480

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.8323
system time used= 0.128008
maximum resident set size= 98328
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29440
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= 58
involuntary context switches= 134

runsolver used 0.012 second user time and 0.016001 second system time

The end