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/130.runsolver.aptitude aptitude -s -y --without-recommends remove apt diff xutils kdemultimedia kbugbuster 

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.02 1.05 1.06 2/55 26791
/proc/meminfo: memFree=832268/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=54860 CPUtime=0
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 593 0 0 0 0 0 0 0 20 0 1 0 29921498 56176640 492 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769080680 140026486174839 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 13715 492 403 1052 0 73 0

[startup+0.170636 s]
/proc/loadavg: 1.02 1.05 1.06 2/55 26791
/proc/meminfo: memFree=832268/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=103288 CPUtime=0.15
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 11290 1710 0 0 12 3 0 0 20 0 1 0 29921498 105766912 11090 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769072736 140026483719741 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 25822 11090 9879 1052 0 1159 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 103288

[startup+0.200301 s]
/proc/loadavg: 1.02 1.05 1.06 2/55 26791
/proc/meminfo: memFree=832268/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=103288 CPUtime=0.19
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 11300 1710 0 0 16 3 0 0 20 0 1 0 29921498 105766912 11100 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769072736 140026483720733 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 25822 11100 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300267 s]
/proc/loadavg: 1.02 1.05 1.06 2/55 26791
/proc/meminfo: memFree=832268/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=103288 CPUtime=0.29
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 11308 1710 0 0 26 3 0 0 20 0 1 0 29921498 105766912 11108 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769072736 140026483163919 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 25822 11108 9897 1052 0 1159 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103288

[startup+0.700198 s]
/proc/loadavg: 1.02 1.05 1.06 2/55 26791
/proc/meminfo: memFree=832268/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=123068 CPUtime=0.68
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 17688 1710 0 0 62 6 0 0 20 0 1 0 29921498 126021632 15964 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769070904 140026445860354 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 30767 15964 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.02 1.05 1.06 2/57 26796
/proc/meminfo: memFree=803244/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=135856 CPUtime=1.48
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 20627 1710 0 0 140 8 0 0 20 0 2 0 29921498 139116544 17543 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769069800 140026445830280 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 33964 17543 10227 1052 0 9301 0
[pid=26791/tid=26796] ppid=26790 vsize=135856 CPUtime=0
/proc/26791/task/26796/stat : 26796 (aptitude) S 26790 26791 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29921576 139116544 17543 18446744073709551615 140026488320000 140026492627352 140736769081472 140026375997440 140026457064148 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) 135856

[startup+3.10025 s]
/proc/loadavg: 1.02 1.05 1.06 2/57 26796
/proc/meminfo: memFree=802252/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=140872 CPUtime=3.07
/proc/26791/stat : 26791 (aptitude) S 26790 26791 17863 34816 17863 4202496 21968 1710 0 0 299 8 0 0 20 0 2 0 29921498 144252928 18883 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769073232 140026457065035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 35218 18883 10319 1052 0 10555 0
[pid=26791/tid=26796] ppid=26790 vsize=140872 CPUtime=0.27
/proc/26791/task/26796/stat : 26796 (aptitude) R 26790 26791 17863 34816 17863 4202560 1183 1710 0 0 27 0 0 0 20 0 2 0 29921576 144252928 18883 18446744073709551615 140026488320000 140026492627352 140736769081472 140026375988328 140026483720057 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) 140872

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

[startup+3.20031 s]
/proc/loadavg: 1.02 1.05 1.06 2/57 26796
/proc/meminfo: memFree=802252/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=140872 CPUtime=3.17
/proc/26791/stat : 26791 (aptitude) S 26790 26791 17863 34816 17863 4202496 21976 1710 0 0 309 8 0 0 20 0 2 0 29921498 144252928 18891 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769073232 140026457065035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 35218 18891 10319 1052 0 10555 0
[pid=26791/tid=26796] ppid=26790 vsize=140872 CPUtime=0.37
/proc/26791/task/26796/stat : 26796 (aptitude) R 26790 26791 17863 34816 17863 4202560 1191 1710 0 0 37 0 0 0 20 0 2 0 29921576 144252928 18891 18446744073709551615 140026488320000 140026492627352 140736769081472 140026375988328 140026454629440 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) 140872

[startup+3.60025 s]
/proc/loadavg: 1.02 1.05 1.06 2/57 26796
/proc/meminfo: memFree=796548/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=142748 CPUtime=3.57
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 22505 1710 0 0 348 9 0 0 20 0 2 0 29921498 146173952 19418 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769069336 140026490154662 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 35687 19418 10370 1052 0 11017 0
[pid=26791/tid=26796] ppid=26790 vsize=142748 CPUtime=0.69
/proc/26791/task/26796/stat : 26796 (aptitude) S 26790 26791 17863 34816 17863 4202560 1665 1710 0 0 69 0 0 0 20 0 2 0 29921576 146173952 19418 18446744073709551615 140026488320000 140026492627352 140736769081472 140026375997440 140026457064148 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.57
Current children cumulated vsize (KiB) 142748

[startup+3.70024 s]
/proc/loadavg: 1.02 1.05 1.06 2/57 26796
/proc/meminfo: memFree=796548/1022884 swapFree=0/0
[pid=26791] ppid=26790 vsize=142748 CPUtime=3.67
/proc/26791/stat : 26791 (aptitude) R 26790 26791 17863 34816 17863 4202496 22505 1710 0 0 358 9 0 0 20 0 2 0 29921498 146173952 19418 18446744073709551615 140026488320000 140026492627352 140736769081472 140736769069336 140026489149088 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26791/statm: 35687 19418 10370 1052 0 11017 0
[pid=26791/tid=26796] ppid=26790 vsize=142748 CPUtime=0.69
/proc/26791/task/26796/stat : 26796 (aptitude) S 26790 26791 17863 34816 17863 4202560 1665 1710 0 0 69 0 0 0 20 0 2 0 29921576 146173952 19418 18446744073709551615 140026488320000 140026492627352 140736769081472 140026375997440 140026457064148 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.67
Current children cumulated vsize (KiB) 142748

Child status: 255
Real time (s): 3.73953
CPU time (s): 3.72423
CPU user time (s): 3.61223
CPU system time (s): 0.112007
CPU usage (%): 99.5908
Max. virtual memory (cumulated for all children) (KiB): 142748

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.61223
system time used= 0.112007
maximum resident set size= 77740
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 24296
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= 105

runsolver used 0.012 second user time and 0.012 second system time

The end