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/logs/44.runsolver.aptitude aptitude -s -y --without-recommends install teapop-pgsql python2.3-ldaptor visualboyadvance prcs-visualtree libkadm5clnt4-heimdal 

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

[startup+0 s]
/proc/loadavg: 0.98 0.56 0.23 2/55 19612
/proc/meminfo: memFree=246924/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=3152 CPUtime=0
/proc/19612/stat : 19612 (runsolver) R 19611 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28186653 3227648 32 18446744073709551615 134512640 134586868 4294581792 4294579840 4151432240 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.173224 s]
/proc/loadavg: 0.98 0.56 0.23 2/55 19612
/proc/meminfo: memFree=246924/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=86100 CPUtime=0.16
/proc/19612/stat : 19612 (aptitude) R 19611 19612 17863 34816 17863 4202496 7116 1709 0 0 14 2 0 0 20 0 1 0 28186653 88166400 6906 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353771112 140348303220261 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 21525 6906 4717 1052 0 2116 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 86100

[startup+0.200278 s]
/proc/loadavg: 0.98 0.56 0.23 2/55 19612
/proc/meminfo: memFree=246924/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=90632 CPUtime=0.19
/proc/19612/stat : 19612 (aptitude) R 19611 19612 17863 34816 17863 4202496 8612 1709 0 0 17 2 0 0 20 0 1 0 28186653 92807168 7657 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353771400 140348295995532 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 22658 7657 4725 1052 0 3249 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 90632

[startup+0.300257 s]
/proc/loadavg: 0.98 0.56 0.23 2/55 19612
/proc/meminfo: memFree=246924/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=96684 CPUtime=0.28
/proc/19612/stat : 19612 (aptitude) R 19611 19612 17863 34816 17863 4202496 9024 1709 0 0 26 2 0 0 20 0 2 0 28186653 99004416 7657 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353777752 140348295919072 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 24171 7657 4890 1052 0 4762 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 96684

[startup+0.700194 s]
/proc/loadavg: 0.98 0.56 0.23 2/55 19612
/proc/meminfo: memFree=246924/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=100672 CPUtime=0.68
/proc/19612/stat : 19612 (aptitude) R 19611 19612 17863 34816 17863 4202496 10142 1709 0 0 66 2 0 0 20 0 2 0 28186653 103088128 8770 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353769128 140348258590530 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 25168 8770 4994 1052 0 5759 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 100672

[startup+1.50023 s]
/proc/loadavg: 0.98 0.56 0.23 2/57 19618
/proc/meminfo: memFree=231036/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=110176 CPUtime=1.49
/proc/19612/stat : 19612 (aptitude) S 19611 19612 17863 34816 17863 4202496 13609 2208 0 0 144 4 1 0 20 0 2 0 28186653 112820224 11246 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353773728 140348269839947 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 27544 11246 5100 1052 0 8135 0
[pid=19612/tid=19617] ppid=19611 vsize=110176 CPUtime=0.33
/proc/19612/task/19617/stat : 19617 (aptitude) R 19611 19612 17863 34816 17863 4202560 2890 2208 0 0 32 0 1 0 20 0 2 0 28186681 112820224 11246 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217665048 140348303741316 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 110176

[startup+3.10024 s]
/proc/loadavg: 0.98 0.56 0.23 2/57 19618
/proc/meminfo: memFree=207352/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=200564 CPUtime=3.08
/proc/19612/stat : 19612 (aptitude) S 19611 19612 17863 34816 17863 4202496 19848 2208 0 0 299 8 1 0 20 0 2 0 28186653 205377536 17466 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353773728 140348269839947 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 50141 17466 5101 1052 0 30732 0
[pid=19612/tid=19617] ppid=19611 vsize=200564 CPUtime=1.92
/proc/19612/task/19617/stat : 19617 (aptitude) R 19611 19612 17863 34816 17863 4202560 9127 2208 0 0 186 5 1 0 20 0 2 0 28186681 205377536 17466 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217665048 140348303728179 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) 200564

[startup+6.30026 s]
/proc/loadavg: 0.98 0.57 0.23 2/57 19618
/proc/meminfo: memFree=181188/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=221728 CPUtime=6.26
/proc/19612/stat : 19612 (aptitude) S 19611 19612 17863 34816 17863 4202496 25198 2208 0 0 614 11 1 0 20 0 2 0 28186653 227049472 22743 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353773728 140348269839947 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 55432 22743 5102 1052 0 36023 0
[pid=19612/tid=19617] ppid=19611 vsize=221728 CPUtime=5.11
/proc/19612/task/19617/stat : 19617 (aptitude) R 19611 19612 17863 34816 17863 4202560 14477 2208 0 0 502 8 1 0 20 0 2 0 28186681 227049472 22743 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217667208 140348303951960 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 221728

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

[startup+6.40031 s]
/proc/loadavg: 0.98 0.57 0.23 2/57 19618
/proc/meminfo: memFree=181188/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=222256 CPUtime=6.37
/proc/19612/stat : 19612 (aptitude) S 19611 19612 17863 34816 17863 4202496 25373 2208 0 0 624 12 1 0 20 0 2 0 28186653 227590144 22906 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353773728 140348269839947 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 55564 22906 5102 1052 0 36155 0
[pid=19612/tid=19617] ppid=19611 vsize=222256 CPUtime=5.2
/proc/19612/task/19617/stat : 19617 (aptitude) R 19611 19612 17863 34816 17863 4202560 14652 2208 0 0 511 8 1 0 20 0 2 0 28186681 227590144 22906 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217665000 140348303923779 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.37
Current children cumulated vsize (KiB) 222256

[startup+8.00025 s]
/proc/loadavg: 0.98 0.57 0.23 2/57 19618
/proc/meminfo: memFree=169408/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=229420 CPUtime=7.96
/proc/19612/stat : 19612 (aptitude) S 19611 19612 17863 34816 17863 4202496 27137 2208 0 0 783 12 1 0 20 0 2 0 28186653 234926080 24670 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353773728 140348269839947 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 57355 24670 5102 1052 0 37946 0
[pid=19612/tid=19617] ppid=19611 vsize=229420 CPUtime=6.79
/proc/19612/task/19617/stat : 19617 (aptitude) R 19611 19612 17863 34816 17863 4202560 16416 2208 0 0 670 8 1 0 20 0 2 0 28186681 234926080 24670 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217667256 140348269830577 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.96
Current children cumulated vsize (KiB) 229420

[startup+8.80024 s]
/proc/loadavg: 0.98 0.57 0.23 2/57 19618
/proc/meminfo: memFree=163084/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=234464 CPUtime=8.75
/proc/19612/stat : 19612 (aptitude) S 19611 19612 17863 34816 17863 4202496 28409 2208 0 0 862 12 1 0 20 0 2 0 28186653 240091136 25940 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353773728 140348269839947 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 58616 25940 5103 1052 0 39207 0
[pid=19612/tid=19617] ppid=19611 vsize=234464 CPUtime=7.6
/proc/19612/task/19617/stat : 19617 (aptitude) R 19611 19612 17863 34816 17863 4202560 17688 2208 0 0 750 9 1 0 20 0 2 0 28186681 240091136 25940 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217663704 140348303810048 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.75
Current children cumulated vsize (KiB) 234464

[startup+9.20025 s]
/proc/loadavg: 0.98 0.57 0.23 2/57 19618
/proc/meminfo: memFree=163084/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=235824 CPUtime=9.15
/proc/19612/stat : 19612 (aptitude) R 19611 19612 17863 34816 17863 4202496 29085 2208 0 0 901 13 1 0 20 0 2 0 28186653 241483776 26497 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353772104 140348258586283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 58956 26497 5151 1052 0 39540 0
[pid=19612/tid=19617] ppid=19611 vsize=235824 CPUtime=7.8
/proc/19612/task/19617/stat : 19617 (aptitude) S 19611 19612 17863 34816 17863 4202560 18026 2208 0 0 770 9 1 0 20 0 2 0 28186681 241483776 26497 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217673728 140348269839060 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.15
Current children cumulated vsize (KiB) 235824

[startup+9.40023 s]
/proc/loadavg: 0.98 0.57 0.23 2/57 19618
/proc/meminfo: memFree=163084/1022884 swapFree=0/0
[pid=19612] ppid=19611 vsize=235824 CPUtime=9.35
/proc/19612/stat : 19612 (aptitude) R 19611 19612 17863 34816 17863 4202496 30533 2208 0 0 920 14 1 0 20 0 2 0 28186653 241483776 26476 18446744073709551615 140348301094912 140348305402264 140735353781968 140735353771728 140348258797878 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19612/statm: 58956 26476 5159 1052 0 39540 0
[pid=19612/tid=19617] ppid=19611 vsize=235824 CPUtime=7.8
/proc/19612/task/19617/stat : 19617 (aptitude) S 19611 19612 17863 34816 17863 4202560 18026 2208 0 0 770 9 1 0 20 0 2 0 28186681 241483776 26476 18446744073709551615 140348301094912 140348305402264 140735353781968 140348217673728 140348269839060 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.35
Current children cumulated vsize (KiB) 235824

Child status: 0
Real time (s): 9.45798
CPU time (s): 9.42059
CPU user time (s): 9.22858
CPU system time (s): 0.192012
CPU usage (%): 99.6046
Max. virtual memory (cumulated for all children) (KiB): 235824

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.22858
system time used= 0.192012
maximum resident set size= 106356
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 33969
page faults= 0
swaps= 0
block input operations= 0
block output operations= 112
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 78
involuntary context switches= 209

runsolver used 0 second user time and 0.048003 second system time

The end