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/74.runsolver.aptitude aptitude -s -y --without-recommends install libhttp-ocaml-dev librsvg2-ruby libsvga1-dev regexplorer librlog1 

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 0.71 0.32 2/55 19881
/proc/meminfo: memFree=244852/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=54860 CPUtime=0
/proc/19881/stat : 19881 (aptitude) R 19880 19881 17863 34816 17863 4202496 621 0 0 0 0 0 0 0 20 0 1 0 28199746 56176640 520 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290669672 140224895625982 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 13715 520 426 1052 0 73 0

[startup+0.138277 s]
/proc/loadavg: 0.99 0.71 0.32 2/55 19881
/proc/meminfo: memFree=244852/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=80316 CPUtime=0.12
/proc/19881/stat : 19881 (aptitude) R 19880 19881 17863 34816 17863 4202496 5659 1709 0 0 10 2 0 0 20 0 1 0 28199746 82243584 5447 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290660240 140224893222904 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 20079 5447 4706 1052 0 670 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 80316

[startup+0.200295 s]
/proc/loadavg: 0.99 0.71 0.32 2/55 19881
/proc/meminfo: memFree=244852/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=87812 CPUtime=0.18
/proc/19881/stat : 19881 (aptitude) R 19880 19881 17863 34816 17863 4202496 7871 1709 0 0 16 2 0 0 20 0 1 0 28199746 89919488 7298 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290659976 140224900747121 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 21953 7298 4721 1052 0 2544 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 87812

[startup+0.300269 s]
/proc/loadavg: 0.99 0.71 0.32 2/55 19881
/proc/meminfo: memFree=244852/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=96032 CPUtime=0.28
/proc/19881/stat : 19881 (aptitude) R 19880 19881 17863 34816 17863 4202496 8843 1709 0 0 24 4 0 0 20 0 2 0 28199746 98336768 7475 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290661416 140224871008043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 24008 7475 4875 1052 0 4599 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 96032

[startup+0.700215 s]
/proc/loadavg: 0.99 0.71 0.32 2/55 19881
/proc/meminfo: memFree=244852/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=100760 CPUtime=0.68
/proc/19881/stat : 19881 (aptitude) R 19880 19881 17863 34816 17863 4202496 10160 1709 0 0 63 5 0 0 20 0 2 0 28199746 103178240 8787 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290660816 140224855333191 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 25190 8787 4994 1052 0 5781 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 100760

[startup+1.50028 s]
/proc/loadavg: 0.99 0.71 0.32 2/57 19887
/proc/meminfo: memFree=229096/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=108736 CPUtime=1.47
/proc/19881/stat : 19881 (aptitude) S 19880 19881 17863 34816 17863 4202496 13246 2208 0 0 140 7 0 0 20 0 2 0 28199746 111345664 10906 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290662224 140224866567755 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 27184 10906 5107 1052 0 7775 0
[pid=19881/tid=19886] ppid=19880 vsize=108736 CPUtime=0.2
/proc/19881/task/19886/stat : 19886 (aptitude) R 19880 19881 17863 34816 17863 4202560 2511 2208 0 0 20 0 0 0 20 0 2 0 28199775 111345664 10906 18446744073709551615 140224897822720 140224902130072 140734290670464 140224814390584 140224901247411 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) 108736

[startup+3.10024 s]
/proc/loadavg: 0.99 0.71 0.32 2/57 19887
/proc/meminfo: memFree=210372/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=192140 CPUtime=3.06
/proc/19881/stat : 19881 (aptitude) S 19880 19881 17863 34816 17863 4202496 17718 2208 0 0 298 8 0 0 20 0 2 0 28199746 196751360 15357 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290662224 140224866567755 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 48035 15357 5108 1052 0 28626 0
[pid=19881/tid=19886] ppid=19880 vsize=192140 CPUtime=1.8
/proc/19881/task/19886/stat : 19886 (aptitude) R 19880 19881 17863 34816 17863 4202560 6981 2208 0 0 178 2 0 0 20 0 2 0 28199775 196751360 15357 18446744073709551615 140224897822720 140224902130072 140734290670464 140224814395064 140224900558592 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 192140

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

[startup+3.20032 s]
/proc/loadavg: 0.99 0.71 0.32 2/57 19887
/proc/meminfo: memFree=210372/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=192808 CPUtime=3.16
/proc/19881/stat : 19881 (aptitude) S 19880 19881 17863 34816 17863 4202496 17882 2208 0 0 308 8 0 0 20 0 2 0 28199746 197435392 15521 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290662224 140224866567755 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 48202 15521 5108 1052 0 28793 0
[pid=19881/tid=19886] ppid=19880 vsize=192808 CPUtime=1.9
/proc/19881/task/19886/stat : 19886 (aptitude) R 19880 19881 17863 34816 17863 4202560 7145 2208 0 0 188 2 0 0 20 0 2 0 28199775 197435392 15521 18446744073709551615 140224897822720 140224902130072 140734290670464 140224814395112 140224900530820 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.16
Current children cumulated vsize (KiB) 192808

[startup+4.00024 s]
/proc/loadavg: 0.99 0.71 0.33 2/57 19887
/proc/meminfo: memFree=202064/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=198772 CPUtime=3.96
/proc/19881/stat : 19881 (aptitude) S 19880 19881 17863 34816 17863 4202496 19462 2208 0 0 387 9 0 0 20 0 2 0 28199746 203542528 17024 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290662224 140224866567755 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 49693 17024 5109 1052 0 30284 0
[pid=19881/tid=19886] ppid=19880 vsize=198772 CPUtime=2.7
/proc/19881/task/19886/stat : 19886 (aptitude) R 19880 19881 17863 34816 17863 4202560 8725 2208 0 0 267 3 0 0 20 0 2 0 28199775 203542528 17024 18446744073709551615 140224897822720 140224902130072 140734290670464 140224814392808 140224900469382 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.96
Current children cumulated vsize (KiB) 198772

[startup+4.40023 s]
/proc/loadavg: 0.99 0.71 0.33 2/57 19887
/proc/meminfo: memFree=194376/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=201156 CPUtime=4.37
/proc/19881/stat : 19881 (aptitude) S 19880 19881 17863 34816 17863 4202496 20072 2208 0 0 427 10 0 0 20 0 2 0 28199746 205983744 17634 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290662224 140224866567755 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 50289 17634 5110 1052 0 30880 0
[pid=19881/tid=19886] ppid=19880 vsize=201156 CPUtime=3.09
/proc/19881/task/19886/stat : 19886 (aptitude) R 19880 19881 17863 34816 17863 4202560 9335 2208 0 0 306 3 0 0 20 0 2 0 28199775 205983744 17634 18446744073709551615 140224897822720 140224902130072 140734290670464 140224814395064 140224900498969 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) 201156

[startup+4.80024 s]
/proc/loadavg: 0.99 0.71 0.33 2/57 19887
/proc/meminfo: memFree=194376/1022884 swapFree=0/0
[pid=19881] ppid=19880 vsize=202776 CPUtime=4.76
/proc/19881/stat : 19881 (aptitude) R 19880 19881 17863 34816 17863 4202496 22355 2707 0 0 464 11 0 1 20 0 2 0 28199746 207642624 18187 18446744073709551615 140224897822720 140224902130072 140734290670464 140734290660712 140224855666757 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19881/statm: 50694 18187 5159 1052 0 31278 0
[pid=19881/tid=19886] ppid=19880 vsize=202776 CPUtime=3.23
/proc/19881/task/19886/stat : 19886 (aptitude) S 19880 19881 17863 34816 17863 4202560 9738 2707 0 0 319 3 0 1 20 0 2 0 28199775 207642624 18187 18446744073709551615 140224897822720 140224902130072 140734290670464 140224814401536 140224866566868 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.76
Current children cumulated vsize (KiB) 202776

Child status: 0
Real time (s): 4.89523
CPU time (s): 4.8763
CPU user time (s): 4.70429
CPU system time (s): 0.17201
CPU usage (%): 99.6133
Max. virtual memory (cumulated for all children) (KiB): 202776

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.70429
system time used= 0.17201
maximum resident set size= 73392
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 34472
page faults= 0
swaps= 0
block input operations= 0
block output operations= 120
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 68
involuntary context switches= 133

runsolver used 0.012 second user time and 0.016001 second system time

The end