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/42.runsolver.aptitude aptitude -s -y --without-recommends install gstreamer0.8-jack g77-2.95-doc upx-ucl libginac1.3 ted-gtk 

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: 1.10 1.11 1.04 2/55 25580
/proc/meminfo: memFree=749300/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=3152 CPUtime=0
/proc/25580/stat : 25580 (runsolver) R 25579 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29491837 3227648 32 18446744073709551615 134512640 134586868 4288245760 4288243808 4152132656 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.116781 s]
/proc/loadavg: 1.10 1.11 1.04 2/55 25580
/proc/meminfo: memFree=749300/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=103288 CPUtime=0.1
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 11075 1708 0 0 8 2 0 0 20 0 1 0 29491837 105766912 10877 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692622912 140050591901014 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 25822 10877 9665 1052 0 1159 0
Current children cumulated CPU time (s) 0.1
Current children cumulated vsize (KiB) 103288

[startup+0.200298 s]
/proc/loadavg: 1.10 1.11 1.04 2/55 25580
/proc/meminfo: memFree=749300/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=103288 CPUtime=0.18
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 11298 1708 0 0 16 2 0 0 20 0 1 0 29491837 105766912 11100 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692622912 140050590935707 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 25822 11100 9888 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300313 s]
/proc/loadavg: 1.10 1.11 1.04 2/55 25580
/proc/meminfo: memFree=749300/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=103288 CPUtime=0.28
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 11307 1708 0 0 26 2 0 0 20 0 1 0 29491837 105766912 11109 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692622912 140050628589891 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 25822 11109 9897 1052 0 1159 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103288

[startup+0.700301 s]
/proc/loadavg: 1.10 1.11 1.04 2/55 25580
/proc/meminfo: memFree=749300/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=123068 CPUtime=0.68
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 17687 1708 0 0 61 7 0 0 20 0 1 0 29491837 126021632 15965 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692621080 140050636673791 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50029 s]
/proc/loadavg: 1.10 1.11 1.04 2/57 25585
/proc/meminfo: memFree=720276/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=135872 CPUtime=1.48
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 20646 1708 0 0 138 10 0 0 20 0 2 0 29491837 139132928 17564 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692618520 140050636776243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 33968 17564 10244 1052 0 9305 0
[pid=25580/tid=25585] ppid=25579 vsize=135872 CPUtime=0
/proc/25580/task/25585/stat : 25585 (aptitude) S 25579 25580 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29491916 139132928 17564 18446744073709551615 140050633748480 140050638055832 140736692631648 140050521425920 140050602492628 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) 135872

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

[startup+1.60033 s]
/proc/loadavg: 1.10 1.11 1.04 2/57 25585
/proc/meminfo: memFree=720276/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=135872 CPUtime=1.58
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 20655 1708 0 0 148 10 0 0 20 0 2 0 29491837 139132928 17573 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692618520 140050591258995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 33968 17573 10244 1052 0 9305 0
[pid=25580/tid=25585] ppid=25579 vsize=135872 CPUtime=0
/proc/25580/task/25585/stat : 25585 (aptitude) S 25579 25580 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29491916 139132928 17573 18446744073709551615 140050633748480 140050638055832 140736692631648 140050521425920 140050602492628 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.58
Current children cumulated vsize (KiB) 135872

[startup+2.4003 s]
/proc/loadavg: 1.10 1.11 1.04 2/57 25586
/proc/meminfo: memFree=718788/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=137588 CPUtime=2.38
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 21674 2207 0 0 226 11 0 1 20 0 2 0 29491837 140890112 17740 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692618352 140050591259051 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 34397 17740 10296 1052 0 9734 0
[pid=25580/tid=25585] ppid=25579 vsize=137588 CPUtime=0.01
/proc/25580/task/25585/stat : 25585 (aptitude) S 25579 25580 17863 34816 17863 4202560 6 2207 0 0 0 0 0 1 20 0 2 0 29491916 140890112 17740 18446744073709551615 140050633748480 140050638055832 140736692631648 140050521425920 140050602492628 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.38
Current children cumulated vsize (KiB) 137588

[startup+2.8003 s]
/proc/loadavg: 1.10 1.11 1.04 2/57 25586
/proc/meminfo: memFree=718788/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=137588 CPUtime=2.78
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 21675 2207 0 0 266 11 0 1 20 0 2 0 29491837 140890112 17740 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692618352 140050600053740 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 34397 17740 10296 1052 0 9734 0
[pid=25580/tid=25585] ppid=25579 vsize=137588 CPUtime=0.01
/proc/25580/task/25585/stat : 25585 (aptitude) S 25579 25580 17863 34816 17863 4202560 6 2207 0 0 0 0 0 1 20 0 2 0 29491916 140890112 17740 18446744073709551615 140050633748480 140050638055832 140736692631648 140050521425920 140050602492628 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.78
Current children cumulated vsize (KiB) 137588

[startup+3.0003 s]
/proc/loadavg: 1.10 1.11 1.04 2/57 25586
/proc/meminfo: memFree=718788/1022884 swapFree=0/0
[pid=25580] ppid=25579 vsize=137616 CPUtime=2.98
/proc/25580/stat : 25580 (aptitude) R 25579 25580 17863 34816 17863 4202496 24104 2207 0 0 286 11 0 1 20 0 2 0 29491837 140918784 17844 18446744073709551615 140050633748480 140050638055832 140736692631648 140736692619512 140050635952615 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25580/statm: 34404 17844 10397 1052 0 9734 0
[pid=25580/tid=25585] ppid=25579 vsize=137616 CPUtime=0.01
/proc/25580/task/25585/stat : 25585 (aptitude) S 25579 25580 17863 34816 17863 4202560 59 2207 0 0 0 0 0 1 20 0 2 0 29491916 140918784 17844 18446744073709551615 140050633748480 140050638055832 140736692631648 140050521425920 140050602492628 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 137616

Child status: 0
Real time (s): 3.09375
CPU time (s): 3.08419
CPU user time (s): 2.92818
CPU system time (s): 0.156009
CPU usage (%): 99.6911
Max. virtual memory (cumulated for all children) (KiB): 137616

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 2.92818
system time used= 0.156009
maximum resident set size= 71388
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 27055
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= 60
involuntary context switches= 95

runsolver used 0.004 second user time and 0.016001 second system time

The end