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/151.runsolver.aptitude aptitude -s -y --without-recommends remove gnome-applets-data cervisia libgimpprint1 groff-base ifupdown 

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.04 1.06 2/55 26938
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=54860 CPUtime=0
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 587 0 0 0 0 0 0 0 20 0 1 0 29934257 56176640 487 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141524632 140462318622598 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 13715 487 398 1052 0 73 0

[startup+0.137622 s]
/proc/loadavg: 1.02 1.04 1.06 2/55 26938
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=103288 CPUtime=0.12
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 11253 1708 0 0 10 2 0 0 20 0 1 0 29934257 105766912 11054 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141516688 140462315661171 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 25822 11054 9842 1052 0 1159 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 103288

[startup+0.200275 s]
/proc/loadavg: 1.02 1.04 1.06 2/55 26938
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=103288 CPUtime=0.18
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 11299 1708 0 0 16 2 0 0 20 0 1 0 29934257 105766912 11100 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141516688 140462278401781 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 25822 11100 9888 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.30027 s]
/proc/loadavg: 1.02 1.04 1.06 2/55 26938
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=103288 CPUtime=0.28
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 11308 1708 0 0 26 2 0 0 20 0 1 0 29934257 105766912 11109 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141516688 140462315505488 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 25822 11109 9897 1052 0 1159 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103288

[startup+0.700198 s]
/proc/loadavg: 1.02 1.04 1.06 2/55 26938
/proc/meminfo: memFree=830996/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=123068 CPUtime=0.68
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 17689 1708 0 0 62 6 0 0 20 0 1 0 29934257 126021632 15965 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141514856 140462315720852 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26938/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.02 1.04 1.06 2/57 26943
/proc/meminfo: memFree=801972/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=135856 CPUtime=1.48
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 20627 1708 0 0 140 8 0 0 20 0 2 0 29934257 139116544 17544 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141515720 140462278972663 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 33964 17544 10227 1052 0 9301 0
[pid=26938/tid=26943] ppid=26937 vsize=135856 CPUtime=0
/proc/26938/task/26943/stat : 26943 (aptitude) S 26937 26938 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29934335 139116544 17544 18446744073709551615 140462320820224 140462325127576 140736141525424 140462208497664 140462289564372 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.10024 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26943
/proc/meminfo: memFree=800980/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=148392 CPUtime=3.07
/proc/26938/stat : 26938 (aptitude) S 26937 26938 17863 34816 17863 4202496 23864 1708 0 0 299 8 0 0 20 0 2 0 29934257 151953408 20780 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141517184 140462289565259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 37098 20780 10320 1052 0 12435 0
[pid=26938/tid=26943] ppid=26937 vsize=148392 CPUtime=0.26
/proc/26938/task/26943/stat : 26943 (aptitude) R 26937 26938 17863 34816 17863 4202560 3080 1708 0 0 26 0 0 0 20 0 2 0 29934335 151953408 20780 18446744073709551615 140462320820224 140462325127576 140736141525424 140462208489352 140462287129579 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) 148392

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

[startup+3.20031 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26943
/proc/meminfo: memFree=800980/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=150636 CPUtime=3.17
/proc/26938/stat : 26938 (aptitude) S 26937 26938 17863 34816 17863 4202496 24409 1708 0 0 308 9 0 0 20 0 2 0 29934257 154251264 21325 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141517184 140462289565259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 37659 21325 10320 1052 0 12996 0
[pid=26938/tid=26943] ppid=26937 vsize=150636 CPUtime=0.37
/proc/26938/task/26943/stat : 26943 (aptitude) R 26937 26938 17863 34816 17863 4202560 3625 1708 0 0 36 1 0 0 20 0 2 0 29934335 154251264 21325 18446744073709551615 140462320820224 140462325127576 140736141525424 140462208489336 140462323021595 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) 150636

[startup+3.60024 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26943
/proc/meminfo: memFree=785976/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=156048 CPUtime=3.57
/proc/26938/stat : 26938 (aptitude) S 26937 26938 17863 34816 17863 4202496 25770 1708 0 0 348 9 0 0 20 0 2 0 29934257 159793152 22686 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141517184 140462289565259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 39012 22686 10321 1052 0 14349 0
[pid=26938/tid=26943] ppid=26937 vsize=156048 CPUtime=0.76
/proc/26938/task/26943/stat : 26943 (aptitude) R 26937 26938 17863 34816 17863 4202560 4985 1708 0 0 75 1 0 0 20 0 2 0 29934335 159793152 22686 18446744073709551615 140462320820224 140462325127576 140736141525424 140462208489352 140462323508246 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) 156048

[startup+3.80025 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26943
/proc/meminfo: memFree=785976/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=158452 CPUtime=3.77
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 26418 1708 0 0 368 9 0 0 20 0 2 0 29934257 162254848 23332 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141513288 140462278311367 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 39613 23332 10370 1052 0 14943 0
[pid=26938/tid=26943] ppid=26937 vsize=158452 CPUtime=0.8
/proc/26938/task/26943/stat : 26943 (aptitude) S 26937 26938 17863 34816 17863 4202560 5572 1708 0 0 79 1 0 0 20 0 2 0 29934335 162254848 23332 18446744073709551615 140462320820224 140462325127576 140736141525424 140462208497664 140462289564372 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.77
Current children cumulated vsize (KiB) 158452

[startup+3.90025 s]
/proc/loadavg: 1.02 1.04 1.06 2/57 26943
/proc/meminfo: memFree=785976/1022884 swapFree=0/0
[pid=26938] ppid=26937 vsize=107832 CPUtime=3.87
/proc/26938/stat : 26938 (aptitude) R 26937 26938 17863 34816 17863 4202496 26429 1708 0 0 377 10 0 0 20 0 1 0 29934257 110419968 10701 18446744073709551615 140462320820224 140462325127576 140736141525424 140736141522736 140462277955247 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26938/statm: 26958 10701 1468 1052 0 11214 0
Current children cumulated CPU time (s) 3.87
Current children cumulated vsize (KiB) 107832

Child status: 0
Real time (s): 3.91032
CPU time (s): 3.89624
CPU user time (s): 3.78024
CPU system time (s): 0.116007
CPU usage (%): 99.64
Max. virtual memory (cumulated for all children) (KiB): 158452

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.78024
system time used= 0.116007
maximum resident set size= 93344
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 28195
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= 57
involuntary context switches= 111

runsolver used 0.004 second user time and 0.020001 second system time

The end