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/146.runsolver.aptitude aptitude -s -y --without-recommends remove libgdbm3 kturtle kfilereplace libkpimexchange1 whiptail 

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.08 1.03 1.01 2/55 22530
/proc/meminfo: memFree=903472/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=54860 CPUtime=0
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 585 0 0 0 0 0 0 0 20 0 1 0 28699310 56176640 485 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283065096 139786490847453 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 13715 485 398 1052 0 73 0

[startup+0.201687 s]
/proc/loadavg: 1.08 1.03 1.01 2/55 22530
/proc/meminfo: memFree=903472/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=89152 CPUtime=0.18
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 7869 1706 0 0 17 1 0 0 20 0 1 0 28699310 91291648 7661 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283055664 139786487895249 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 22288 7661 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.30028 s]
/proc/loadavg: 1.08 1.03 1.01 2/55 22530
/proc/meminfo: memFree=903472/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=101864 CPUtime=0.28
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 11708 1706 0 0 26 2 0 0 20 0 1 0 28699310 104308736 10755 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283055320 139786487947425 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 25466 10755 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.400267 s]
/proc/loadavg: 1.08 1.03 1.01 2/55 22530
/proc/meminfo: memFree=903472/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=101864 CPUtime=0.38
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 11708 1706 0 0 35 3 0 0 20 0 1 0 28699310 104308736 10755 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283055320 139786461802864 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 25466 10755 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.38
Current children cumulated vsize (KiB) 101864

[startup+0.700203 s]
/proc/loadavg: 1.08 1.03 1.01 2/55 22530
/proc/meminfo: memFree=903472/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=113868 CPUtime=0.68
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 13631 1706 0 0 64 4 0 0 20 0 2 0 28699310 116600832 12003 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283057160 139786459352044 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 28467 12003 6965 1052 0 7037 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 113868

[startup+1.50024 s]
/proc/loadavg: 1.08 1.03 1.01 2/57 22535
/proc/meminfo: memFree=882756/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=115240 CPUtime=1.48
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 13834 1706 0 0 144 4 0 0 20 0 2 0 28699310 118005760 12205 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283052592 139786496091880 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 28810 12205 7034 1052 0 7380 0
[pid=22530/tid=22535] ppid=22529 vsize=115240 CPUtime=0
/proc/22530/task/22535/stat : 22535 (aptitude) S 22529 22530 17863 34816 17863 4202560 4 1706 0 0 0 0 0 0 20 0 2 0 28699355 118005760 12205 18446744073709551615 139786493046784 139786497354136 140737283065888 139786396452864 139786461790932 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) 115240

[startup+3.10024 s]
/proc/loadavg: 1.07 1.02 1.00 2/57 22535
/proc/meminfo: memFree=862296/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=224176 CPUtime=3.08
/proc/22530/stat : 22530 (aptitude) S 22529 22530 17863 34816 17863 4202496 24957 1706 0 0 300 8 0 0 20 0 2 0 28699310 229556224 23327 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283057648 139786461791819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 56044 23327 7088 1052 0 34614 0
[pid=22530/tid=22535] ppid=22529 vsize=224176 CPUtime=1.37
/proc/22530/task/22535/stat : 22535 (aptitude) R 22529 22530 17863 34816 17863 4202560 11121 1706 0 0 133 4 0 0 20 0 2 0 28699355 229556224 23327 18446744073709551615 139786493046784 139786497354136 140737283065888 139786396446344 139786495631614 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 224176

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

[startup+3.30024 s]
/proc/loadavg: 1.07 1.02 1.00 2/57 22535
/proc/meminfo: memFree=862296/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=228932 CPUtime=3.27
/proc/22530/stat : 22530 (aptitude) S 22529 22530 17863 34816 17863 4202496 26157 1706 0 0 319 8 0 0 20 0 2 0 28699310 234426368 24527 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283057648 139786461791819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 57233 24527 7089 1052 0 35803 0
[pid=22530/tid=22535] ppid=22529 vsize=228932 CPUtime=1.56
/proc/22530/task/22535/stat : 22535 (aptitude) R 22529 22530 17863 34816 17863 4202560 12321 1706 0 0 152 4 0 0 20 0 2 0 28699355 234426368 24527 18446744073709551615 139786493046784 139786497354136 140737283065888 139786396446472 139786450557336 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) 228932

[startup+3.70024 s]
/proc/loadavg: 1.07 1.02 1.00 2/57 22535
/proc/meminfo: memFree=832536/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=233844 CPUtime=3.66
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 27632 1706 0 0 358 8 0 0 20 0 2 0 28699310 239456256 25951 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283056024 139786495649056 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 58461 25951 7139 1052 0 37024 0
[pid=22530/tid=22535] ppid=22529 vsize=233844 CPUtime=1.92
/proc/22530/task/22535/stat : 22535 (aptitude) S 22529 22530 17863 34816 17863 4202560 13564 1706 0 0 188 4 0 0 20 0 2 0 28699355 239456256 25951 18446744073709551615 139786493046784 139786497354136 140737283065888 139786396452864 139786461790932 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) 233844

[startup+3.90025 s]
/proc/loadavg: 1.07 1.02 1.00 2/57 22535
/proc/meminfo: memFree=832536/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=233876 CPUtime=3.86
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 27655 1706 0 0 378 8 0 0 20 0 2 0 28699310 239489024 25974 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283053752 139786495172072 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 58469 25974 7140 1052 0 37032 0
[pid=22530/tid=22535] ppid=22529 vsize=233876 CPUtime=1.92
/proc/22530/task/22535/stat : 22535 (aptitude) S 22529 22530 17863 34816 17863 4202560 13564 1706 0 0 188 4 0 0 20 0 2 0 28699355 239489024 25974 18446744073709551615 139786493046784 139786497354136 140737283065888 139786396452864 139786461790932 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.86
Current children cumulated vsize (KiB) 233876

[startup+4.00026 s]
/proc/loadavg: 1.07 1.02 1.00 2/57 22535
/proc/meminfo: memFree=832536/1022884 swapFree=0/0
[pid=22530] ppid=22529 vsize=233876 CPUtime=3.96
/proc/22530/stat : 22530 (aptitude) R 22529 22530 17863 34816 17863 4202496 27712 1706 0 0 388 8 0 0 20 0 2 0 28699310 239489024 25964 18446744073709551615 139786493046784 139786497354136 140737283065888 140737283057992 139786450538155 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22530/statm: 58469 25964 7148 1052 0 37032 0
[pid=22530/tid=22535] ppid=22529 vsize=233876 CPUtime=1.92
/proc/22530/task/22535/stat : 22535 (aptitude) S 22529 22530 17863 34816 17863 4202560 13564 1706 0 0 188 4 0 0 20 0 2 0 28699355 239489024 25964 18446744073709551615 139786493046784 139786497354136 140737283065888 139786396452864 139786461790932 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.96
Current children cumulated vsize (KiB) 233876

Child status: 0
Real time (s): 4.07481
CPU time (s): 4.06025
CPU user time (s): 3.94025
CPU system time (s): 0.120007
CPU usage (%): 99.6428
Max. virtual memory (cumulated for all children) (KiB): 233876

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.94025
system time used= 0.120007
maximum resident set size= 104028
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29486
page faults= 0
swaps= 0
block input operations= 0
block output operations= 64
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 60
involuntary context switches= 114

runsolver used 0.012 second user time and 0.012 second system time

The end