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/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: 0.99 1.04 1.02 2/55 24632
/proc/meminfo: memFree=862752/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=3152 CPUtime=0
/proc/24632/stat : 24632 (runsolver) R 24631 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29241018 3227648 33 18446744073709551615 134512640 134586868 4287522880 4287520928 4151911472 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 788 33 0 19 0 73 0

[startup+0.146103 s]
/proc/loadavg: 0.99 1.04 1.02 2/55 24632
/proc/meminfo: memFree=862752/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=100508 CPUtime=0.13
/proc/24632/stat : 24632 (aptitude) R 24631 24632 17863 34816 17863 4202496 10588 1706 0 0 13 0 0 0 20 0 1 0 29241018 102920192 10388 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819852592 140246187895068 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 25127 10388 9214 1052 0 1122 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 100508

[startup+0.200281 s]
/proc/loadavg: 0.99 1.04 1.02 2/55 24632
/proc/meminfo: memFree=862752/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=100508 CPUtime=0.18
/proc/24632/stat : 24632 (aptitude) R 24631 24632 17863 34816 17863 4202496 10606 1706 0 0 18 0 0 0 20 0 1 0 29241018 102920192 10406 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819852592 140246151206233 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 25127 10406 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300266 s]
/proc/loadavg: 0.99 1.04 1.02 2/55 24632
/proc/meminfo: memFree=862752/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=111108 CPUtime=0.29
/proc/24632/stat : 24632 (aptitude) R 24631 24632 17863 34816 17863 4202496 12453 1706 0 0 28 1 0 0 20 0 1 0 29241018 113774592 12245 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819852920 140246195185260 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 27777 12245 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 111108

[startup+0.700201 s]
/proc/loadavg: 0.99 1.04 1.02 2/55 24632
/proc/meminfo: memFree=862752/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=123288 CPUtime=0.68
/proc/24632/stat : 24632 (aptitude) R 24631 24632 17863 34816 17863 4202496 17024 1706 0 0 63 5 0 0 20 0 2 0 29241018 126246912 14298 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819854952 140246195178653 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 30822 14298 9478 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 0.99 1.04 1.02 2/57 24637
/proc/meminfo: memFree=834852/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=131940 CPUtime=1.47
/proc/24632/stat : 24632 (aptitude) R 24631 24632 17863 34816 17863 4202496 19296 1706 0 0 142 5 0 0 20 0 2 0 29241018 135106560 16566 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819849240 140246150564217 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 32985 16566 9569 1052 0 8980 0
[pid=24632/tid=24637] ppid=24631 vsize=131940 CPUtime=0
/proc/24632/task/24637/stat : 24637 (aptitude) S 24631 24632 17863 34816 17863 4202560 4 1706 0 0 0 0 0 0 20 0 2 0 29241083 135106560 16566 18446744073709551615 140246193053696 140246197361048 140736819861328 140246083880960 140246161797844 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) 131940

[startup+3.10023 s]
/proc/loadavg: 0.99 1.04 1.02 2/57 24637
/proc/meminfo: memFree=834108/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=146364 CPUtime=3.07
/proc/24632/stat : 24632 (aptitude) S 24631 24632 17863 34816 17863 4202496 22994 1706 0 0 301 6 0 0 20 0 2 0 29241018 149876736 20263 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819853088 140246161798731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 36591 20263 9662 1052 0 12586 0
[pid=24632/tid=24637] ppid=24631 vsize=146364 CPUtime=0.54
/proc/24632/task/24637/stat : 24637 (aptitude) R 24631 24632 17863 34816 17863 4202560 3556 1706 0 0 54 0 0 0 20 0 2 0 29241083 149876736 20263 18446744073709551615 140246193053696 140246197361048 140736819861328 140246083871672 140246195638526 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) 146364

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

[startup+3.20031 s]
/proc/loadavg: 0.99 1.04 1.02 2/57 24637
/proc/meminfo: memFree=834108/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=148476 CPUtime=3.17
/proc/24632/stat : 24632 (aptitude) S 24631 24632 17863 34816 17863 4202496 23527 1706 0 0 311 6 0 0 20 0 2 0 29241018 152039424 20796 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819853088 140246161798731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 37119 20796 9662 1052 0 13114 0
[pid=24632/tid=24637] ppid=24631 vsize=148476 CPUtime=0.64
/proc/24632/task/24637/stat : 24637 (aptitude) R 24631 24632 17863 34816 17863 4202560 4089 1706 0 0 64 0 0 0 20 0 2 0 29241083 152039424 20796 18446744073709551615 140246193053696 140246197361048 140736819861328 140246083869176 140246195796288 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) 148476

[startup+3.60024 s]
/proc/loadavg: 0.99 1.04 1.02 2/57 24637
/proc/meminfo: memFree=816500/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=152700 CPUtime=3.57
/proc/24632/stat : 24632 (aptitude) S 24631 24632 17863 34816 17863 4202496 24572 1706 0 0 351 6 0 0 20 0 2 0 29241018 156364800 21841 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819853088 140246161798731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 38175 21841 9662 1052 0 14170 0
[pid=24632/tid=24637] ppid=24631 vsize=152700 CPUtime=1.03
/proc/24632/task/24637/stat : 24637 (aptitude) R 24631 24632 17863 34816 17863 4202560 5134 1706 0 0 103 0 0 0 20 0 2 0 29241083 156364800 21841 18446744073709551615 140246193053696 140246197361048 140736819861328 140246083871576 140246150553985 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) 152700

[startup+3.80024 s]
/proc/loadavg: 0.99 1.04 1.02 2/57 24637
/proc/meminfo: memFree=816500/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=159756 CPUtime=3.77
/proc/24632/stat : 24632 (aptitude) R 24631 24632 17863 34816 17863 4202496 26390 1706 0 0 370 7 0 0 20 0 2 0 29241018 163590144 23657 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819851160 140246187908332 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 39939 23657 9711 1052 0 15927 0
[pid=24632/tid=24637] ppid=24631 vsize=159756 CPUtime=1.14
/proc/24632/task/24637/stat : 24637 (aptitude) S 24631 24632 17863 34816 17863 4202560 6891 1706 0 0 113 1 0 0 20 0 2 0 29241083 163590144 23657 18446744073709551615 140246193053696 140246197361048 140736819861328 140246083880960 140246161797844 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) 159756

[startup+3.90025 s]
/proc/loadavg: 0.99 1.04 1.02 2/57 24637
/proc/meminfo: memFree=816500/1022884 swapFree=0/0
[pid=24632] ppid=24631 vsize=159756 CPUtime=3.87
/proc/24632/stat : 24632 (aptitude) R 24631 24632 17863 34816 17863 4202496 26390 1706 0 0 380 7 0 0 20 0 2 0 29241018 163590144 23657 18446744073709551615 140246193053696 140246197361048 140736819861328 140736819849192 140246194774932 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/24632/statm: 39939 23657 9711 1052 0 15927 0
[pid=24632/tid=24637] ppid=24631 vsize=159756 CPUtime=1.14
/proc/24632/task/24637/stat : 24637 (aptitude) S 24631 24632 17863 34816 17863 4202560 6891 1706 0 0 113 1 0 0 20 0 2 0 29241083 163590144 23657 18446744073709551615 140246193053696 140246197361048 140736819861328 140246083880960 140246161797844 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.87
Current children cumulated vsize (KiB) 159756

Child status: 0
Real time (s): 3.97384
CPU time (s): 3.96025
CPU user time (s): 3.86424
CPU system time (s): 0.096006
CPU usage (%): 99.658
Max. virtual memory (cumulated for all children) (KiB): 159756

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.86424
system time used= 0.096006
maximum resident set size= 94644
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 28165
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= 56
involuntary context switches= 114

runsolver used 0.008 second user time and 0.016001 second system time

The end