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-squeeze-sid/logs/59.runsolver.aptitude aptitude -s -y --without-recommends install bonobo-conf gdis ooo2dbk python-optik libmon-perl 

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.05 1.04 2/55 25743
/proc/meminfo: memFree=830064/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=3152 CPUtime=0
/proc/25743/stat : 25743 (runsolver) R 25742 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29606401 3227648 32 18446744073709551615 134512640 134586868 4290914944 4290912992 4152075312 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.11415 s]
/proc/loadavg: 1.01 1.05 1.04 2/55 25743
/proc/meminfo: memFree=830064/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=103288 CPUtime=0.11
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 11135 1708 0 0 8 2 0 1 20 0 1 0 29606401 105766912 10936 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027120 140655046896110 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 25822 10936 9724 1052 0 1159 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 103288

[startup+0.200282 s]
/proc/loadavg: 1.01 1.05 1.04 2/55 25743
/proc/meminfo: memFree=830064/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=103288 CPUtime=0.19
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 11300 1708 0 0 16 2 0 1 20 0 1 0 29606401 105766912 11101 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027120 140655046895879 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300268 s]
/proc/loadavg: 1.01 1.05 1.04 2/55 25743
/proc/meminfo: memFree=830064/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=103432 CPUtime=0.29
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 11427 1708 0 0 26 2 0 1 20 0 1 0 29606401 105914368 11220 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258025632 140655046907874 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103432

[startup+0.700203 s]
/proc/loadavg: 1.01 1.05 1.04 2/55 25743
/proc/meminfo: memFree=830064/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=123068 CPUtime=0.69
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 17688 1708 0 0 62 6 0 1 20 0 1 0 29606401 126021632 15965 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258025288 140655020810608 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25748
/proc/meminfo: memFree=810092/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=136048 CPUtime=1.48
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 20642 1708 0 0 140 7 0 1 20 0 2 0 29606401 139313152 17561 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027128 140655046882348 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 34012 17561 10207 1052 0 9349 0
[pid=25743/tid=25748] ppid=25742 vsize=136048 CPUtime=0.01
/proc/25743/task/25748/stat : 25748 (aptitude) S 25742 25743 17863 34816 17863 4202560 4 1708 0 0 0 0 0 1 20 0 2 0 29606478 139313152 17561 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939731968 140655020798676 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 136048

[startup+3.10025 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25748
/proc/meminfo: memFree=799800/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=137808 CPUtime=3.07
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 21995 2207 0 0 292 14 0 1 20 0 2 0 29606401 141115392 17938 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258022560 140655055082355 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 34452 17938 10303 1052 0 9789 0
[pid=25743/tid=25748] ppid=25742 vsize=137808 CPUtime=0.01
/proc/25743/task/25748/stat : 25748 (aptitude) S 25742 25743 17863 34816 17863 4202560 6 2207 0 0 0 0 0 1 20 0 2 0 29606478 141115392 17938 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939731968 140655020798676 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) 137808

[startup+6.3003 s]
/proc/loadavg: 1.00 1.05 1.04 2/57 25749
/proc/meminfo: memFree=765700/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=246516 CPUtime=6.26
/proc/25743/stat : 25743 (aptitude) S 25742 25743 17863 34816 17863 4202496 33312 2207 0 0 603 22 0 1 20 0 2 0 29606401 252432384 28975 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027616 140655020799563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 61629 28975 10359 1052 0 36966 0
[pid=25743/tid=25748] ppid=25742 vsize=246516 CPUtime=2.87
/proc/25743/task/25748/stat : 25748 (aptitude) R 25742 25743 17863 34816 17863 4202560 11316 2207 0 0 278 8 0 1 20 0 2 0 29606478 252432384 28975 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939725768 140655054762214 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 246516

[startup+12.7002 s]
/proc/loadavg: 1.00 1.05 1.04 2/57 25749
/proc/meminfo: memFree=702584/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=302612 CPUtime=12.64
/proc/25743/stat : 25743 (aptitude) S 25742 25743 17863 34816 17863 4202496 47625 2207 0 0 1234 29 0 1 20 0 2 0 29606401 309874688 42977 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027616 140655020799563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 75653 42977 10359 1052 0 50990 0
[pid=25743/tid=25748] ppid=25742 vsize=302612 CPUtime=9.24
/proc/25743/task/25748/stat : 25748 (aptitude) R 25742 25743 17863 34816 17863 4202560 25629 2207 0 0 909 14 0 1 20 0 2 0 29606478 309874688 42977 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939723288 140655054684953 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 302612

[startup+25.5003 s]
/proc/loadavg: 1.00 1.05 1.04 2/57 25749
/proc/meminfo: memFree=612684/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=389724 CPUtime=25.38
/proc/25743/stat : 25743 (aptitude) S 25742 25743 17863 34816 17863 4202496 69712 2207 0 0 2499 38 0 1 20 0 2 0 29606401 399077376 64712 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027616 140655020799563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 97431 64712 10360 1052 0 72768 0
[pid=25743/tid=25748] ppid=25742 vsize=389724 CPUtime=21.98
/proc/25743/task/25748/stat : 25748 (aptitude) R 25742 25743 17863 34816 17863 4202560 47716 2207 0 0 2174 23 0 1 20 0 2 0 29606478 399077376 64712 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939725496 140655054790315 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.38
Current children cumulated vsize (KiB) 389724

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

[startup+25.6003 s]
/proc/loadavg: 1.00 1.05 1.04 2/57 25749
/proc/meminfo: memFree=612684/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=390392 CPUtime=25.47
/proc/25743/stat : 25743 (aptitude) S 25742 25743 17863 34816 17863 4202496 69894 2207 0 0 2508 38 0 1 20 0 2 0 29606401 399761408 64894 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027616 140655020799563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 97598 64894 10360 1052 0 72935 0
[pid=25743/tid=25748] ppid=25742 vsize=390392 CPUtime=22.08
/proc/25743/task/25748/stat : 25748 (aptitude) R 25742 25743 17863 34816 17863 4202560 47898 2207 0 0 2183 24 0 1 20 0 2 0 29606478 399761408 64894 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939723240 140655054753347 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 390392

[startup+32.0031 s]
/proc/loadavg: 1.00 1.04 1.04 2/57 25749
/proc/meminfo: memFree=581188/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=420580 CPUtime=31.85
/proc/25743/stat : 25743 (aptitude) S 25742 25743 17863 34816 17863 4202496 77472 2207 0 0 3140 44 0 1 20 0 2 0 29606401 430673920 72449 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027616 140655020799563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 105145 72449 10360 1052 0 80482 0
[pid=25743/tid=25748] ppid=25742 vsize=420580 CPUtime=28.46
/proc/25743/task/25748/stat : 25748 (aptitude) R 25742 25743 17863 34816 17863 4202560 55476 2207 0 0 2816 29 0 1 20 0 2 0 29606478 430673920 72449 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939723288 140655047455152 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) 420580

[startup+38.4003 s]
/proc/loadavg: 1.00 1.04 1.04 2/57 25749
/proc/meminfo: memFree=555644/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=450084 CPUtime=38.21
/proc/25743/stat : 25743 (aptitude) S 25742 25743 17863 34816 17863 4202496 84885 2207 0 0 3772 48 0 1 20 0 2 0 29606401 460886016 79834 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027616 140655020799563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 112521 79834 10360 1052 0 87858 0
[pid=25743/tid=25748] ppid=25742 vsize=450084 CPUtime=34.83
/proc/25743/task/25748/stat : 25748 (aptitude) R 25742 25743 17863 34816 17863 4202560 62889 2207 0 0 3448 34 0 1 20 0 2 0 29606478 460886016 79834 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939723288 140655053682611 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.21
Current children cumulated vsize (KiB) 450084

[startup+41.6002 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25749
/proc/meminfo: memFree=540144/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=465052 CPUtime=41.41
/proc/25743/stat : 25743 (aptitude) S 25742 25743 17863 34816 17863 4202496 88631 2207 0 0 4089 51 0 1 20 0 2 0 29606401 476213248 83580 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258027616 140655020799563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25743/statm: 116263 83580 10360 1052 0 91600 0
[pid=25743/tid=25748] ppid=25742 vsize=465052 CPUtime=38.01
/proc/25743/task/25748/stat : 25748 (aptitude) R 25742 25743 17863 34816 17863 4202560 66635 2207 0 0 3764 36 0 1 20 0 2 0 29606478 476213248 83580 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939723288 140655010206931 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.41
Current children cumulated vsize (KiB) 465052

[startup+42.4002 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25749
/proc/meminfo: memFree=535556/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=466400 CPUtime=42.19
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 89184 2207 0 0 4167 51 0 1 20 0 2 0 29606401 477593600 84074 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258025992 140655009564717 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25743/statm: 116600 84074 10408 1052 0 91930 0
[pid=25743/tid=25748] ppid=25742 vsize=466400 CPUtime=38.44
/proc/25743/task/25748/stat : 25748 (aptitude) S 25742 25743 17863 34816 17863 4202560 66968 2207 0 0 3807 36 0 1 20 0 2 0 29606478 477593600 84074 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939731968 140655020798676 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 42.19
Current children cumulated vsize (KiB) 466400

[startup+43.2002 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25749
/proc/meminfo: memFree=534068/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=466440 CPUtime=42.98
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 91986 2706 0 0 4237 59 0 2 20 0 2 0 29606401 477634560 84166 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258026104 140655010319202 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25743/statm: 116610 84166 10409 1052 0 91940 0
[pid=25743/tid=25748] ppid=25742 vsize=466440 CPUtime=38.45
/proc/25743/task/25748/stat : 25748 (aptitude) S 25742 25743 17863 34816 17863 4202560 66968 2706 0 0 3807 36 0 2 20 0 2 0 29606478 477634560 84166 18446744073709551615 140655052054528 140655056361880 140736258035856 140654939731968 140655020798676 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 42.98
Current children cumulated vsize (KiB) 466440

[startup+43.4006 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25749
/proc/meminfo: memFree=534068/1022884 swapFree=0/0
[pid=25743] ppid=25742 vsize=195264 CPUtime=43.18
/proc/25743/stat : 25743 (aptitude) R 25742 25743 17863 34816 17863 4202496 92595 2706 0 0 4247 69 0 2 20 0 1 0 29606401 199950336 11160 18446744073709551615 140655052054528 140655056361880 140736258035856 140736258035416 140655009920490 0 134217728 4096 0 0 0 0 17 0 0 0 1 0 0
/proc/25743/statm: 48816 11160 1508 1052 0 33072 0
Current children cumulated CPU time (s) 43.18
Current children cumulated vsize (KiB) 195264

Child status: 0
Real time (s): 43.4107
CPU time (s): 43.2107
CPU user time (s): 42.4787
CPU system time (s): 0.732045
CPU usage (%): 99.5392
Max. virtual memory (cumulated for all children) (KiB): 466440

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 42.4787
system time used= 0.732045
maximum resident set size= 337128
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 95368
page faults= 0
swaps= 0
block input operations= 0
block output operations= 160
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 141
involuntary context switches= 776

runsolver used 0.104006 second user time and 0.096006 second system time

The end