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/29.runsolver.aptitude aptitude -s -y --without-recommends install curl rmagic gnomeicu-common libxml-stream-perl liblablgl-ocaml 

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.14 1.04 0.89 2/55 21092
/proc/meminfo: memFree=971104/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=3152 CPUtime=0
/proc/21092/stat : 21092 (runsolver) R 21091 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28372090 3227648 32 18446744073709551615 134512640 134586868 4290373056 4290371104 4151596080 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21092/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.182788 s]
/proc/loadavg: 1.14 1.04 0.89 2/55 21092
/proc/meminfo: memFree=971104/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=33024 CPUtime=0
/proc/21092/stat : 21092 (aptitude) D 21091 21092 17863 34816 17863 4202496 164 0 11 0 0 0 0 0 20 0 1 0 28372090 33816576 85 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860532840 140254231012899 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/21092/statm: 8256 85 55 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 33024

[startup+0.200386 s]
/proc/loadavg: 1.14 1.04 0.89 2/55 21092
/proc/meminfo: memFree=971104/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=36128 CPUtime=0
/proc/21092/stat : 21092 (aptitude) D 21091 21092 17863 34816 17863 4202496 170 0 12 0 0 0 0 0 20 0 1 0 28372090 36995072 91 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860532840 140254231012742 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/21092/statm: 9032 91 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.300356 s]
/proc/loadavg: 1.14 1.04 0.89 2/55 21092
/proc/meminfo: memFree=971104/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=54968 CPUtime=0
/proc/21092/stat : 21092 (aptitude) D 21091 21092 17863 34816 17863 4202496 1023 0 23 0 0 0 0 0 20 0 1 0 28372090 56287232 936 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860531528 140254190998784 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/21092/statm: 13742 936 783 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700329 s]
/proc/loadavg: 1.14 1.04 0.89 2/55 21092
/proc/meminfo: memFree=971104/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=89152 CPUtime=0.02
/proc/21092/stat : 21092 (aptitude) D 21091 21092 17863 34816 17863 4202496 2551 1704 56 4 0 2 0 0 20 0 1 0 28372090 91291648 2404 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860527888 140254228203418 0 134217728 4096 0 0 0 0 17 0 0 0 60 0 0
/proc/21092/statm: 22288 2404 1494 1052 0 858 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 89152

[startup+1.50026 s]
/proc/loadavg: 1.13 1.04 0.89 1/56 21096
/proc/meminfo: memFree=964144/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=101864 CPUtime=0.28
/proc/21092/stat : 21092 (aptitude) R 21091 21092 17863 34816 17863 4202496 11551 1704 160 4 26 2 0 0 20 0 1 0 28372090 104308736 10755 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860525848 140254201909616 0 134217728 4096 0 0 0 0 17 0 0 0 116 0 0
/proc/21092/statm: 25466 10755 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+3.10024 s]
/proc/loadavg: 1.13 1.04 0.89 2/57 21097
/proc/meminfo: memFree=889116/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=115520 CPUtime=1.51
/proc/21092/stat : 21092 (aptitude) R 21091 21092 17863 34816 17863 4202496 14401 2201 160 6 143 7 1 0 20 0 2 0 28372090 118292480 12310 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860523120 140254190663776 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/21092/statm: 28880 12310 7066 1052 0 7450 0
[pid=21092/tid=21097] ppid=21091 vsize=115520 CPUtime=0.01
/proc/21092/task/21097/stat : 21097 (aptitude) S 21091 21092 17863 34816 17863 4202560 6 2201 0 6 0 0 1 0 20 0 2 0 28372284 118292480 12310 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136559616 140254201897684 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 115520
heavy processes:

[startup+6.30023 s]
/proc/loadavg: 1.13 1.04 0.89 2/57 21098
/proc/meminfo: memFree=848320/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=227400 CPUtime=4.69
/proc/21092/stat : 21092 (aptitude) S 21091 21092 17863 34816 17863 4202496 27305 2201 160 6 457 11 1 0 20 0 2 0 28372090 232857600 24189 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860528176 140254201898571 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/21092/statm: 56850 24189 7122 1052 0 35420 0
[pid=21092/tid=21097] ppid=21091 vsize=227400 CPUtime=2.89
/proc/21092/task/21097/stat : 21097 (aptitude) R 21091 21092 17863 34816 17863 4202560 12886 2201 0 6 284 4 1 0 20 0 2 0 28372284 232857600 24189 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136550328 140254235980302 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.69
Current children cumulated vsize (KiB) 227400
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.11 1.04 0.89 2/57 21098
/proc/meminfo: memFree=779128/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=294972 CPUtime=11.06
/proc/21092/stat : 21092 (aptitude) S 21091 21092 17863 34816 17863 4202496 44224 2201 160 6 1087 18 1 0 20 0 2 0 28372090 302051328 41075 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860528176 140254201898571 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/21092/statm: 73743 41075 7124 1052 0 52313 0
[pid=21092/tid=21097] ppid=21091 vsize=294972 CPUtime=9.25
/proc/21092/task/21097/stat : 21097 (aptitude) R 21091 21092 17863 34816 17863 4202560 29805 2201 0 6 914 10 1 0 20 0 2 0 28372284 302051328 41075 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136552544 140254236044691 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.06
Current children cumulated vsize (KiB) 294972

[startup+25.5003 s]
/proc/loadavg: 1.17 1.06 0.90 2/57 21098
/proc/meminfo: memFree=663932/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=405804 CPUtime=23.79
/proc/21092/stat : 21092 (aptitude) S 21091 21092 17863 34816 17863 4202496 71933 2201 160 6 2342 36 1 0 20 0 2 0 28372090 415543296 68784 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860528176 140254201898571 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/21092/statm: 101451 68784 7138 1052 0 80021 0
[pid=21092/tid=21097] ppid=21091 vsize=405804 CPUtime=21.99
/proc/21092/task/21097/stat : 21097 (aptitude) R 21091 21092 17863 34816 17863 4202560 57508 2201 0 6 2170 28 1 0 20 0 2 0 28372284 415543296 68784 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136548904 140254234782034 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.79
Current children cumulated vsize (KiB) 405804

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

[startup+25.6003 s]
/proc/loadavg: 1.17 1.06 0.90 2/57 21098
/proc/meminfo: memFree=663932/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=407264 CPUtime=23.89
/proc/21092/stat : 21092 (aptitude) S 21091 21092 17863 34816 17863 4202496 72207 2201 160 6 2352 36 1 0 20 0 2 0 28372090 417038336 69058 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860528176 140254201898571 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/21092/statm: 101816 69058 7138 1052 0 80386 0
[pid=21092/tid=21097] ppid=21091 vsize=407264 CPUtime=22.09
/proc/21092/task/21097/stat : 21097 (aptitude) R 21091 21092 17863 34816 17863 4202560 57782 2201 0 6 2180 28 1 0 20 0 2 0 28372284 417038336 69058 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136550984 140254235364445 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.89
Current children cumulated vsize (KiB) 407264

[startup+32.0032 s]
/proc/loadavg: 1.14 1.05 0.90 2/57 21098
/proc/meminfo: memFree=605280/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=464288 CPUtime=30.26
/proc/21092/stat : 21092 (aptitude) S 21091 21092 17863 34816 17863 4202496 86496 2201 160 6 2985 40 1 0 20 0 2 0 28372090 475430912 83347 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860528176 140254201898571 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/21092/statm: 116072 83347 7138 1052 0 94642 0
[pid=21092/tid=21097] ppid=21091 vsize=464288 CPUtime=28.46
/proc/21092/task/21097/stat : 21097 (aptitude) R 21091 21092 17863 34816 17863 4202560 72071 2201 0 6 2812 33 1 0 20 0 2 0 28372284 475430912 83347 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136553048 140254190664057 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 30.26
Current children cumulated vsize (KiB) 464288

[startup+33.6002 s]
/proc/loadavg: 1.14 1.05 0.90 2/57 21098
/proc/meminfo: memFree=591888/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=482044 CPUtime=31.85
/proc/21092/stat : 21092 (aptitude) S 21091 21092 17863 34816 17863 4202496 90917 2201 160 6 3143 41 1 0 20 0 2 0 28372090 493613056 87768 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860528176 140254201898571 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 151 0 0
/proc/21092/statm: 120511 87768 7138 1052 0 99081 0
[pid=21092/tid=21097] ppid=21091 vsize=482044 CPUtime=30.05
/proc/21092/task/21097/stat : 21097 (aptitude) R 21091 21092 17863 34816 17863 4202560 76492 2201 0 6 2970 34 1 0 20 0 2 0 28372284 493613056 87768 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136551288 140254234781873 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 31.85
Current children cumulated vsize (KiB) 482044

[startup+34.4002 s]
/proc/loadavg: 1.14 1.05 0.90 2/57 21098
/proc/meminfo: memFree=581844/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=487088 CPUtime=32.53
/proc/21092/stat : 21092 (aptitude) R 21091 21092 17863 34816 17863 4202496 92262 2201 174 6 3210 42 1 0 20 0 2 0 28372090 498778112 89120 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860526712 140254199175143 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 162 0 0
/proc/21092/statm: 121772 89120 7186 1052 0 100335 0
[pid=21092/tid=21097] ppid=21091 vsize=487088 CPUtime=30.65
/proc/21092/task/21097/stat : 21097 (aptitude) S 21091 21092 17863 34816 17863 4202560 77744 2201 1 6 3029 35 1 0 20 0 2 0 28372284 498778112 89120 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136559616 140254201897684 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 32.53
Current children cumulated vsize (KiB) 487088

[startup+35.2002 s]
/proc/loadavg: 1.14 1.05 0.90 2/57 21098
/proc/meminfo: memFree=579488/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=487172 CPUtime=33.32
/proc/21092/stat : 21092 (aptitude) R 21091 21092 17863 34816 17863 4202496 94075 2201 174 6 3289 42 1 0 20 0 2 0 28372090 498864128 89137 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860528616 140254235360574 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 162 0 0
/proc/21092/statm: 121793 89137 7187 1052 0 100356 0
[pid=21092/tid=21097] ppid=21091 vsize=487172 CPUtime=30.65
/proc/21092/task/21097/stat : 21097 (aptitude) S 21091 21092 17863 34816 17863 4202560 77744 2201 1 6 3029 35 1 0 20 0 2 0 28372284 498864128 89137 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136559616 140254201897684 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 33.32
Current children cumulated vsize (KiB) 487172

[startup+35.4003 s]
/proc/loadavg: 1.14 1.05 0.90 2/57 21098
/proc/meminfo: memFree=579488/1022884 swapFree=0/0
[pid=21092] ppid=21091 vsize=283424 CPUtime=33.51
/proc/21092/stat : 21092 (aptitude) D 21091 21092 17863 34816 17863 4202496 94367 2699 175 6 3295 54 1 1 20 0 2 0 28372090 290226176 38318 18446744073709551615 140254233153536 140254237460888 140735860536416 140735860532680 140254215452800 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 163 0 0
/proc/21092/statm: 70856 38318 7196 1052 0 49419 0
[pid=21092/tid=21097] ppid=21091 vsize=283424 CPUtime=30.66
/proc/21092/task/21097/stat : 21097 (aptitude) S 21091 21092 17863 34816 17863 4202560 77744 2699 1 6 3029 35 1 1 20 0 2 0 28372284 290226176 38318 18446744073709551615 140254233153536 140254237460888 140735860536416 140254136559616 140254201897684 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 33.51
Current children cumulated vsize (KiB) 283424

Child status: 0
Real time (s): 35.4998
CPU time (s): 33.5701
CPU user time (s): 32.9741
CPU system time (s): 0.596037
CPU usage (%): 94.5643
Max. virtual memory (cumulated for all children) (KiB): 487172

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 32.9741
system time used= 0.596037
maximum resident set size= 356968
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 97187
page faults= 196
swaps= 0
block input operations= 127064
block output operations= 128
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1449
involuntary context switches= 624

runsolver used 0.060003 second user time and 0.112007 second system time

The end