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/94.runsolver.aptitude aptitude -s -y --without-recommends install blas-dev xgsmlib librmail-ruby-doc koffice-dev xconq-doc 

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.00 1.04 1.00 2/55 22142
/proc/meminfo: memFree=849476/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=3152 CPUtime=0
/proc/22142/stat : 22142 (runsolver) R 22141 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28611264 3227648 33 18446744073709551615 134512640 134586868 4288301376 4288299424 4151329840 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.19162 s]
/proc/loadavg: 1.00 1.04 1.00 2/55 22142
/proc/meminfo: memFree=849476/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=89152 CPUtime=0.18
/proc/22142/stat : 22142 (aptitude) R 22141 22142 17863 34816 17863 4202496 7777 1709 0 0 17 1 0 0 20 0 1 0 28611264 91291648 7575 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555056 139931258937720 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 22288 7575 6665 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.200301 s]
/proc/loadavg: 1.00 1.04 1.00 2/55 22142
/proc/meminfo: memFree=849476/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=89152 CPUtime=0.19
/proc/22142/stat : 22142 (aptitude) R 22141 22142 17863 34816 17863 4202496 7871 1709 0 0 18 1 0 0 20 0 1 0 28611264 91291648 7661 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393553568 139931258937620 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 22288 7661 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300298 s]
/proc/loadavg: 1.00 1.04 1.00 2/55 22142
/proc/meminfo: memFree=849476/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=101864 CPUtime=0.28
/proc/22142/stat : 22142 (aptitude) R 22141 22142 17863 34816 17863 4202496 11710 1709 0 0 26 2 0 0 20 0 1 0 28611264 104308736 10755 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393553224 139931221077543 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 25466 10755 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.700202 s]
/proc/loadavg: 1.00 1.04 1.00 2/55 22142
/proc/meminfo: memFree=849476/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=108400 CPUtime=0.68
/proc/22142/stat : 22142 (aptitude) R 22141 22142 17863 34816 17863 4202496 12226 1709 0 0 64 4 0 0 20 0 2 0 28611264 111001600 10599 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393559288 139931221040692 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 27100 10599 6925 1052 0 5670 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 108400

[startup+1.5002 s]
/proc/loadavg: 1.00 1.04 1.00 2/57 22147
/proc/meminfo: memFree=828512/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=115500 CPUtime=1.47
/proc/22142/stat : 22142 (aptitude) R 22141 22142 17863 34816 17863 4202496 14152 2210 0 0 140 7 0 0 20 0 2 0 28611264 118272000 12374 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393554952 139931221047673 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 28875 12374 7057 1052 0 7445 0
[pid=22142/tid=22147] ppid=22141 vsize=115500 CPUtime=0
/proc/22142/task/22147/stat : 22147 (aptitude) S 22141 22142 17863 34816 17863 4202560 4 2210 0 0 0 0 0 0 20 0 2 0 28611309 118272000 12374 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166943232 139931232281300 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) 115500

[startup+3.1003 s]
/proc/loadavg: 1.00 1.04 1.00 2/57 22148
/proc/meminfo: memFree=821940/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=198592 CPUtime=3.07
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 19540 2210 0 0 298 9 0 0 20 0 2 0 28611264 203358208 16991 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 49648 16991 7129 1052 0 28218 0
[pid=22142/tid=22147] ppid=22141 vsize=198592 CPUtime=1.01
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 4815 2210 0 0 100 1 0 0 20 0 2 0 28611309 203358208 16991 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166938728 139931266244580 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 198592

[startup+6.3002 s]
/proc/loadavg: 1.00 1.04 1.00 2/57 22148
/proc/meminfo: memFree=792180/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=221340 CPUtime=6.25
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 25321 2210 0 0 612 13 0 0 20 0 2 0 28611264 226652160 22654 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 55335 22654 7129 1052 0 33905 0
[pid=22142/tid=22147] ppid=22141 vsize=221340 CPUtime=4.19
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 10596 2210 0 0 414 5 0 0 20 0 2 0 28611309 226652160 22654 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166936760 139931266139424 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 221340

[startup+12.7002 s]
/proc/loadavg: 1.00 1.04 1.00 2/57 22148
/proc/meminfo: memFree=738984/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=273832 CPUtime=12.63
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 38484 2210 0 0 1242 21 0 0 20 0 2 0 28611264 280403968 35797 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 68458 35797 7129 1052 0 47028 0
[pid=22142/tid=22147] ppid=22141 vsize=273832 CPUtime=10.57
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 23759 2210 0 0 1044 13 0 0 20 0 2 0 28611309 280403968 35797 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166936760 139931266296297 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 273832

[startup+25.5002 s]
/proc/loadavg: 1.00 1.04 1.00 2/57 22148
/proc/meminfo: memFree=641892/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=367632 CPUtime=25.37
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 62219 2210 0 0 2504 33 0 0 20 0 2 0 28611264 376455168 59216 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 91908 59216 7129 1052 0 70478 0
[pid=22142/tid=22147] ppid=22141 vsize=367632 CPUtime=23.31
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 47494 2210 0 0 2306 25 0 0 20 0 2 0 28611309 376455168 59216 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166937032 139931266121982 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 367632

[startup+51.1003 s]
/proc/loadavg: 1.00 1.03 1.00 2/57 22148
/proc/meminfo: memFree=473872/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=537012 CPUtime=50.85
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 104536 2210 0 0 5029 56 0 0 20 0 2 0 28611264 549900288 101525 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 134253 101525 7143 1052 0 112823 0
[pid=22142/tid=22147] ppid=22141 vsize=537012 CPUtime=48.78
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 89804 2210 0 0 4830 48 0 0 20 0 2 0 28611309 549900288 101525 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166936760 139931266245189 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 537012

[startup+102.3 s]
/proc/loadavg: 1.00 1.02 1.00 2/57 22148
/proc/meminfo: memFree=164864/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=842692 CPUtime=101.82
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 180880 2210 0 0 10081 101 0 0 20 0 2 0 28611264 862916608 177856 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 210673 177856 7143 1052 0 189243 0
[pid=22142/tid=22147] ppid=22141 vsize=842692 CPUtime=99.75
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 166148 2210 0 0 9882 93 0 0 20 0 2 0 28611309 862916608 177856 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166936440 139931258936881 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 101.82
Current children cumulated vsize (KiB) 842692

[startup+162.3 s]
/proc/loadavg: 1.11 1.05 1.01 2/57 22148
/proc/meminfo: memFree=10204/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=1120860 CPUtime=160.97
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 250180 2210 4 0 15950 147 0 0 20 0 2 0 28611264 1147760640 247013 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 280215 247013 7003 1052 0 258785 0
[pid=22142/tid=22147] ppid=22141 vsize=1120860 CPUtime=158.9
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 235448 2210 4 0 15751 139 0 0 20 0 2 0 28611309 1147760640 247013 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166934552 139931266272915 0 134217728 4096 0 0 0 0 -1 0 0 0 22 0 0
Current children cumulated CPU time (s) 160.97
Current children cumulated vsize (KiB) 1120860



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+171.2 s]
/proc/loadavg: 1.10 1.05 1.01 2/57 22148
/proc/meminfo: memFree=10076/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=1151244 CPUtime=167.47
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 259015 2210 362 0 16595 152 0 0 20 0 2 0 28611264 1178873856 245333 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 287811 245333 6493 1052 0 266381 0
[pid=22142/tid=22147] ppid=22141 vsize=1151244 CPUtime=165.4
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 244283 2210 362 0 16396 144 0 0 20 0 2 0 28611309 1178873856 245333 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166934552 139931266198668 0 134217728 4096 0 0 0 0 -1 0 0 0 248 0 0
Current children cumulated CPU time (s) 167.47
Current children cumulated vsize (KiB) 1151244

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

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

[startup+171.2 s]
/proc/loadavg: 1.10 1.05 1.01 2/57 22148
/proc/meminfo: memFree=10076/1022884 swapFree=0/0
[pid=22142] ppid=22141 vsize=1151244 CPUtime=167.47
/proc/22142/stat : 22142 (aptitude) S 22141 22142 17863 34816 17863 4202496 259015 2210 362 0 16595 152 0 0 20 0 2 0 28611264 1178873856 245333 18446744073709551615 139931263537152 139931267844504 140735393563792 140735393555552 139931232282187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22142/statm: 287811 245333 6493 1052 0 266381 0
[pid=22142/tid=22147] ppid=22141 vsize=1151244 CPUtime=165.4
/proc/22142/task/22147/stat : 22147 (aptitude) R 22141 22142 17863 34816 17863 4202560 244283 2210 362 0 16396 144 0 0 20 0 2 0 28611309 1178873856 245333 18446744073709551615 139931263537152 139931267844504 140735393563792 139931166934552 139931266198668 0 134217728 4096 0 0 0 0 -1 0 0 0 248 0 0
Current children cumulated CPU time (s) 167.47
Current children cumulated vsize (KiB) 1151244

Child ended because it received signal 15 (SIGTERM)
Real time (s): 171.327
CPU time (s): 167.618
CPU user time (s): 166.026
CPU system time (s): 1.5921
CPU usage (%): 97.8353
Max. virtual memory (cumulated for all children) (KiB): 1151244

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 166.026
system time used= 1.5921
maximum resident set size= 991208
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 261301
page faults= 362
swaps= 0
block input operations= 22352
block output operations= 56
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 771
involuntary context switches= 3631

runsolver used 0.756047 second user time and 0.020001 second system time

The end