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/logs/79.runsolver.aptitude aptitude -s -y --without-recommends install avrp elib libzip-ocaml liblip1 imaze-sounds 

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.01 1.03 0.99 2/55 21784
/proc/meminfo: memFree=907588/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=3152 CPUtime=0
/proc/21784/stat : 21784 (runsolver) R 21783 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28561234 3227648 32 18446744073709551615 134512640 134586868 4290120144 4290118192 4151964720 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21784/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.152735 s]
/proc/loadavg: 1.01 1.03 0.99 2/55 21784
/proc/meminfo: memFree=907588/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=89152 CPUtime=0.14
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 7776 1708 0 0 12 2 0 0 20 0 1 0 28561234 91291648 7574 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311682528 140637420150816 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21784/statm: 22288 7574 6663 1052 0 858 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 89152

[startup+0.200276 s]
/proc/loadavg: 1.01 1.03 0.99 2/55 21784
/proc/meminfo: memFree=907588/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=89152 CPUtime=0.19
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 7872 1708 0 0 17 2 0 0 20 0 1 0 28561234 91291648 7662 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311681040 140637419603938 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21784/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300253 s]
/proc/loadavg: 1.01 1.03 0.99 2/55 21784
/proc/meminfo: memFree=907588/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=101864 CPUtime=0.29
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 11711 1708 0 0 25 4 0 0 20 0 1 0 28561234 104308736 10756 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311680696 140637427675930 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21784/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.7002 s]
/proc/loadavg: 1.01 1.03 0.99 2/55 21784
/proc/meminfo: memFree=907588/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=114076 CPUtime=0.68
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 13697 1708 0 0 62 6 0 0 20 0 2 0 28561234 116813824 12068 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311682536 140637426952280 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21784/statm: 28519 12068 6977 1052 0 7089 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 114076

[startup+1.50024 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21789
/proc/meminfo: memFree=886872/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=115484 CPUtime=1.45
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 14554 2209 0 0 137 8 0 0 20 0 2 0 28561234 118255616 12309 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311683288 140637427320368 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 28871 12309 7073 1052 0 7441 0
[pid=21784/tid=21789] ppid=21783 vsize=115484 CPUtime=0
/proc/21784/task/21789/stat : 21789 (aptitude) S 21783 21784 17863 34816 17863 4202560 6 2209 0 0 0 0 0 0 20 0 2 0 28561279 118255616 12309 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328156672 140637393494740 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 115484

[startup+3.10024 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21790
/proc/meminfo: memFree=870504/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=142548 CPUtime=3.05
/proc/21784/stat : 21784 (aptitude) S 21783 21784 17863 34816 17863 4202496 22344 2209 0 0 294 11 0 0 20 0 2 0 28561234 145969152 19368 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311683024 140637393495627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 35637 19368 7129 1052 0 14207 0
[pid=21784/tid=21789] ppid=21783 vsize=142548 CPUtime=1.19
/proc/21784/task/21789/stat : 21789 (aptitude) R 21783 21784 17863 34816 17863 4202560 7767 2209 0 0 116 3 0 0 20 0 2 0 28561279 145969152 19368 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328146920 140637419578412 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 142548

[startup+6.30024 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21790
/proc/meminfo: memFree=831568/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=246212 CPUtime=6.23
/proc/21784/stat : 21784 (aptitude) S 21783 21784 17863 34816 17863 4202496 31995 2209 0 0 607 16 0 0 20 0 2 0 28561234 252121088 28885 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311683024 140637393495627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 61553 28885 7129 1052 0 40123 0
[pid=21784/tid=21789] ppid=21783 vsize=246212 CPUtime=4.37
/proc/21784/task/21789/stat : 21789 (aptitude) R 21783 21784 17863 34816 17863 4202560 17417 2209 0 0 429 8 0 0 20 0 2 0 28561279 252121088 28885 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328150328 140637427449375 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 246212

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

[startup+6.40031 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21790
/proc/meminfo: memFree=831568/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=247532 CPUtime=6.33
/proc/21784/stat : 21784 (aptitude) S 21783 21784 17863 34816 17863 4202496 32316 2209 0 0 616 17 0 0 20 0 2 0 28561234 253472768 29205 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311683024 140637393495627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 61883 29205 7129 1052 0 40453 0
[pid=21784/tid=21789] ppid=21783 vsize=247532 CPUtime=4.47
/proc/21784/task/21789/stat : 21789 (aptitude) R 21783 21784 17863 34816 17863 4202560 17738 2209 0 0 438 9 0 0 20 0 2 0 28561279 253472768 29205 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328150328 140637427509685 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.33
Current children cumulated vsize (KiB) 247532

[startup+7.20023 s]
/proc/loadavg: 1.00 1.03 0.99 2/57 21790
/proc/meminfo: memFree=817680/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=254008 CPUtime=7.13
/proc/21784/stat : 21784 (aptitude) S 21783 21784 17863 34816 17863 4202496 34083 2209 0 0 696 17 0 0 20 0 2 0 28561234 260104192 30833 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311683024 140637393495627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 63502 30833 7129 1052 0 42072 0
[pid=21784/tid=21789] ppid=21783 vsize=254008 CPUtime=5.27
/proc/21784/task/21789/stat : 21789 (aptitude) R 21783 21784 17863 34816 17863 4202560 19505 2209 0 0 518 9 0 0 20 0 2 0 28561279 260104192 30833 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328150152 140637427383648 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.13
Current children cumulated vsize (KiB) 254008

[startup+7.60025 s]
/proc/loadavg: 1.00 1.03 0.99 2/57 21790
/proc/meminfo: memFree=817680/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=256620 CPUtime=7.52
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 35064 2209 0 0 735 17 0 0 20 0 2 0 28561234 262778880 31693 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311681400 140637382241739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 64155 31693 7178 1052 0 42718 0
[pid=21784/tid=21789] ppid=21783 vsize=256620 CPUtime=5.5
/proc/21784/task/21789/stat : 21789 (aptitude) S 21783 21784 17863 34816 17863 4202560 20127 2209 0 0 541 9 0 0 20 0 2 0 28561279 262778880 31693 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328156672 140637393494740 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.52
Current children cumulated vsize (KiB) 256620

[startup+7.8032 s]
/proc/loadavg: 1.00 1.03 0.99 2/57 21790
/proc/meminfo: memFree=808752/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=256620 CPUtime=7.72
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 35743 2209 0 0 755 17 0 0 20 0 2 0 28561234 262778880 31694 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311679128 140637419605228 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 64155 31694 7179 1052 0 42718 0
[pid=21784/tid=21789] ppid=21783 vsize=256620 CPUtime=5.5
/proc/21784/task/21789/stat : 21789 (aptitude) S 21783 21784 17863 34816 17863 4202560 20127 2209 0 0 541 9 0 0 20 0 2 0 28561279 262778880 31694 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328156672 140637393494740 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.72
Current children cumulated vsize (KiB) 256620

[startup+7.90026 s]
/proc/loadavg: 1.00 1.03 0.99 2/57 21790
/proc/meminfo: memFree=808752/1022884 swapFree=0/0
[pid=21784] ppid=21783 vsize=256620 CPUtime=7.83
/proc/21784/stat : 21784 (aptitude) R 21783 21784 17863 34816 17863 4202496 37007 2209 0 0 765 18 0 0 20 0 2 0 28561234 262778880 31686 18446744073709551615 140637424750592 140637429057944 140734311691264 140734311683080 140637419643245 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/21784/statm: 64155 31686 7179 1052 0 42718 0
[pid=21784/tid=21789] ppid=21783 vsize=256620 CPUtime=5.5
/proc/21784/task/21789/stat : 21789 (aptitude) S 21783 21784 17863 34816 17863 4202560 20127 2209 0 0 541 9 0 0 20 0 2 0 28561279 262778880 31686 18446744073709551615 140637424750592 140637429057944 140734311691264 140637328156672 140637393494740 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.83
Current children cumulated vsize (KiB) 256620

Child status: 0
Real time (s): 7.9867
CPU time (s): 7.9365
CPU user time (s): 7.68048
CPU system time (s): 0.256016
CPU usage (%): 99.3714
Max. virtual memory (cumulated for all children) (KiB): 256620

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.68048
system time used= 0.256016
maximum resident set size= 127096
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40473
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= 77
involuntary context switches= 187

runsolver used 0 second user time and 0.040002 second system time

The end