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/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: 0.99 0.73 0.34 2/55 19926
/proc/meminfo: memFree=244464/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=3152 CPUtime=0
/proc/19926/stat : 19926 (runsolver) R 19925 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28201818 3227648 32 18446744073709551615 134512640 134586868 4288966960 4288965008 4152165424 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.187985 s]
/proc/loadavg: 0.99 0.73 0.34 2/55 19926
/proc/meminfo: memFree=244464/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=86468 CPUtime=0.17
/proc/19926/stat : 19926 (aptitude) R 19925 19926 17863 34816 17863 4202496 7219 1709 0 0 15 2 0 0 20 0 1 0 28201818 88543232 6986 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677759672 140044993117332 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 21617 6986 4721 1052 0 2208 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 86468

[startup+0.200261 s]
/proc/loadavg: 0.99 0.73 0.34 2/55 19926
/proc/meminfo: memFree=244464/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=89348 CPUtime=0.18
/proc/19926/stat : 19926 (aptitude) R 19925 19926 17863 34816 17863 4202496 8318 1709 0 0 16 2 0 0 20 0 1 0 28201818 91492352 7361 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677759752 140044995000223 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 22337 7361 4721 1052 0 2928 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89348

[startup+0.300264 s]
/proc/loadavg: 0.99 0.73 0.34 2/55 19926
/proc/meminfo: memFree=244464/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=96684 CPUtime=0.29
/proc/19926/stat : 19926 (aptitude) R 19925 19926 17863 34816 17863 4202496 9023 1709 0 0 25 4 0 0 20 0 2 0 28201818 99004416 7655 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677766024 140044987461624 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 24171 7655 4890 1052 0 4762 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 96684

[startup+0.700201 s]
/proc/loadavg: 0.99 0.73 0.34 2/55 19926
/proc/meminfo: memFree=244464/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=100640 CPUtime=0.69
/proc/19926/stat : 19926 (aptitude) R 19925 19926 17863 34816 17863 4202496 10131 1709 0 0 65 4 0 0 20 0 2 0 28201818 103055360 8759 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677758536 140044993696886 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 25160 8759 4994 1052 0 5751 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 100640

[startup+1.50024 s]
/proc/loadavg: 0.99 0.73 0.34 2/57 19932
/proc/meminfo: memFree=228692/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=111724 CPUtime=1.49
/proc/19926/stat : 19926 (aptitude) S 19925 19926 17863 34816 17863 4202496 13991 2206 0 0 142 6 1 0 20 0 2 0 28201818 114405376 11633 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677762000 140044960806475 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 27931 11633 5099 1052 0 8522 0
[pid=19926/tid=19931] ppid=19925 vsize=111724 CPUtime=0.31
/proc/19926/task/19931/stat : 19931 (aptitude) R 19925 19926 17863 34816 17863 4202560 3302 2206 0 0 29 1 1 0 20 0 2 0 28201847 114405376 11633 18446744073709551615 140044992061440 140044996368792 140736677770240 140044908633784 140044958366677 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) 111724

[startup+3.10024 s]
/proc/loadavg: 0.99 0.73 0.34 2/57 19932
/proc/meminfo: memFree=210100/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=129148 CPUtime=3.08
/proc/19926/stat : 19926 (aptitude) S 19925 19926 17863 34816 17863 4202496 18411 2206 0 0 300 7 1 0 20 0 2 0 28201818 132247552 16003 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677762000 140044960806475 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 32287 16003 5101 1052 0 12878 0
[pid=19926/tid=19931] ppid=19925 vsize=129148 CPUtime=1.9
/proc/19926/task/19931/stat : 19931 (aptitude) R 19925 19926 17863 34816 17863 4202560 7721 2206 0 0 187 2 1 0 20 0 2 0 28201847 132247552 16003 18446744073709551615 140044992061440 140044996368792 140736677770240 140044908633912 140044994758530 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) 129148

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

[startup+3.2003 s]
/proc/loadavg: 0.99 0.73 0.34 2/57 19932
/proc/meminfo: memFree=210100/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=130072 CPUtime=3.18
/proc/19926/stat : 19926 (aptitude) S 19925 19926 17863 34816 17863 4202496 18643 2206 0 0 310 7 1 0 20 0 2 0 28201818 133193728 16235 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677762000 140044960806475 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 32518 16235 5101 1052 0 13109 0
[pid=19926/tid=19931] ppid=19925 vsize=130072 CPUtime=2
/proc/19926/task/19931/stat : 19931 (aptitude) R 19925 19926 17863 34816 17863 4202560 7953 2206 0 0 197 2 1 0 20 0 2 0 28201847 133193728 16235 18446744073709551615 140044992061440 140044996368792 140736677770240 140044908631656 140044994686010 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.18
Current children cumulated vsize (KiB) 130072

[startup+4.00025 s]
/proc/loadavg: 0.99 0.73 0.34 2/57 19932
/proc/meminfo: memFree=198692/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=136296 CPUtime=3.98
/proc/19926/stat : 19926 (aptitude) S 19925 19926 17863 34816 17863 4202496 20258 2206 0 0 389 8 1 0 20 0 2 0 28201818 139567104 17802 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677762000 140044960806475 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 34074 17802 5102 1052 0 14665 0
[pid=19926/tid=19931] ppid=19925 vsize=136296 CPUtime=2.8
/proc/19926/task/19931/stat : 19931 (aptitude) R 19925 19926 17863 34816 17863 4202560 9568 2206 0 0 276 3 1 0 20 0 2 0 28201847 139567104 17802 18446744073709551615 140044992061440 140044996368792 140736677770240 140044908630408 140044994757663 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 136296

[startup+4.40026 s]
/proc/loadavg: 0.99 0.73 0.34 2/57 19932
/proc/meminfo: memFree=189764/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=139768 CPUtime=4.37
/proc/19926/stat : 19926 (aptitude) R 19925 19926 17863 34816 17863 4202496 21602 2206 0 0 428 8 1 0 20 0 2 0 28201818 143122432 18697 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677760328 140044986764828 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 34942 18697 5152 1052 0 15526 0
[pid=19926/tid=19931] ppid=19925 vsize=139768 CPUtime=3.01
/proc/19926/task/19931/stat : 19931 (aptitude) S 19925 19926 17863 34816 17863 4202560 10142 2206 0 0 297 3 1 0 20 0 2 0 28201847 143122432 18697 18446744073709551615 140044992061440 140044996368792 140736677770240 140044908640256 140044960805588 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.37
Current children cumulated vsize (KiB) 139768

[startup+4.50314 s]
/proc/loadavg: 0.99 0.73 0.34 2/57 19932
/proc/meminfo: memFree=189764/1022884 swapFree=0/0
[pid=19926] ppid=19925 vsize=139768 CPUtime=4.48
/proc/19926/stat : 19926 (aptitude) R 19925 19926 17863 34816 17863 4202496 22605 2206 0 0 438 9 1 0 20 0 2 0 28201818 143122432 18704 18446744073709551615 140044992061440 140044996368792 140736677770240 140736677760000 140044949764406 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19926/statm: 34942 18704 5159 1052 0 15526 0
[pid=19926/tid=19931] ppid=19925 vsize=139768 CPUtime=3.01
/proc/19926/task/19931/stat : 19931 (aptitude) S 19925 19926 17863 34816 17863 4202560 10142 2206 0 0 297 3 1 0 20 0 2 0 28201847 143122432 18704 18446744073709551615 140044992061440 140044996368792 140736677770240 140044908640256 140044960805588 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.48
Current children cumulated vsize (KiB) 139768

Child status: 0
Real time (s): 4.54011
CPU time (s): 4.52428
CPU user time (s): 4.40027
CPU system time (s): 0.124007
CPU usage (%): 99.6514
Max. virtual memory (cumulated for all children) (KiB): 139768

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.40027
system time used= 0.124007
maximum resident set size= 74828
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25523
page faults= 0
swaps= 0
block input operations= 0
block output operations= 104
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 68
involuntary context switches= 127

runsolver used 0 second user time and 0.028001 second system time

The end