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/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.00 1.00 0.94 2/55 21593
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=3152 CPUtime=0
/proc/21593/stat : 21593 (runsolver) R 21592 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28476384 3227648 32 18446744073709551615 134512640 134586868 4288125920 4288123968 4151559216 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.158196 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21593
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=89152 CPUtime=0.15
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 7773 1707 0 0 12 2 1 0 20 0 1 0 28476384 91291648 7574 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452400 139960340287351 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 22288 7574 6663 1052 0 858 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 89152

[startup+0.200278 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21593
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=89152 CPUtime=0.2
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 7869 1707 0 0 16 3 1 0 20 0 1 0 28476384 91291648 7662 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101450912 139960339735293 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 89152

[startup+0.300265 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21593
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=101864 CPUtime=0.3
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 11708 1707 0 0 25 4 1 0 20 0 1 0 28476384 104308736 10756 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101450568 139960302427679 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 101864

[startup+0.700241 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21593
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=110232 CPUtime=0.69
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 12688 1707 0 0 64 4 1 0 20 0 2 0 28476384 112877568 11062 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101453176 139960347594982 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 27558 11062 6961 1052 0 6128 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 110232

[startup+1.50024 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21598
/proc/meminfo: memFree=834064/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=115412 CPUtime=1.49
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 14580 2205 0 0 140 8 1 0 20 0 2 0 28476384 118181888 12368 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101453160 139960302397921 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 28853 12368 7073 1052 0 7423 0
[pid=21593/tid=21598] ppid=21592 vsize=115412 CPUtime=0.01
/proc/21593/task/21598/stat : 21598 (aptitude) S 21592 21593 17863 34816 17863 4202560 6 2205 0 0 0 0 1 0 20 0 2 0 28476429 118181888 12368 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248293376 139960313631444 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) 115412

[startup+3.10024 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=827740/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=136136 CPUtime=3.08
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 20715 2205 0 0 296 11 1 0 20 0 2 0 28476384 139403264 17746 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 34034 17746 7129 1052 0 12604 0
[pid=21593/tid=21598] ppid=21592 vsize=136136 CPUtime=1.06
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 6054 2205 0 0 102 3 1 0 20 0 2 0 28476429 139403264 17746 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248283144 139960347505024 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) 136136

[startup+6.30023 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=781860/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=240496 CPUtime=6.27
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 30422 2205 0 0 610 16 1 0 20 0 2 0 28476384 246267904 27451 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 60124 27451 7129 1052 0 38694 0
[pid=21593/tid=21598] ppid=21592 vsize=240496 CPUtime=4.25
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 15760 2205 0 0 416 8 1 0 20 0 2 0 28476429 246267904 27451 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248284696 139960347533671 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 240496

[startup+12.7002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=695432/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=321284 CPUtime=12.64
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 50636 2205 0 0 1235 28 1 0 20 0 2 0 28476384 328994816 47659 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 80321 47659 7129 1052 0 58891 0
[pid=21593/tid=21598] ppid=21592 vsize=321284 CPUtime=10.62
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 35974 2205 0 0 1041 20 1 0 20 0 2 0 28476429 328994816 47659 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248287080 139960347098202 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) 321284

[startup+25.5003 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=618056/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=396712 CPUtime=25.37
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 69477 2205 0 0 2497 39 1 0 20 0 2 0 28476384 406233088 66476 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 99178 66476 7129 1052 0 77748 0
[pid=21593/tid=21598] ppid=21592 vsize=396712 CPUtime=23.35
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 54815 2205 0 0 2303 31 1 0 20 0 2 0 28476429 406233088 66476 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248284696 139960347533594 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) 396712

[startup+51.1003 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=495420/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=520132 CPUtime=50.85
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 100497 2205 0 0 5028 56 1 0 20 0 2 0 28476384 532615168 97307 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 130033 97307 7143 1052 0 108603 0
[pid=21593/tid=21598] ppid=21592 vsize=520132 CPUtime=48.83
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 85828 2205 0 0 4834 48 1 0 20 0 2 0 28476429 532615168 97307 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248284696 139960347533827 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) 520132

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

[startup+51.2003 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=495420/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=520532 CPUtime=50.95
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 100601 2205 0 0 5038 56 1 0 20 0 2 0 28476384 533024768 97411 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 130133 97411 7143 1052 0 108703 0
[pid=21593/tid=21598] ppid=21592 vsize=520532 CPUtime=48.93
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 85932 2205 0 0 4844 48 1 0 20 0 2 0 28476429 533024768 97411 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248284696 139960347583333 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.95
Current children cumulated vsize (KiB) 520532

[startup+76.8002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=390888/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=624820 CPUtime=76.44
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 126711 2205 0 0 7573 70 1 0 20 0 2 0 28476384 639815680 123485 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 156205 123485 7143 1052 0 134775 0
[pid=21593/tid=21598] ppid=21592 vsize=624820 CPUtime=74.42
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 112042 2205 0 0 7379 62 1 0 20 0 2 0 28476429 639815680 123485 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248284648 139960347472126 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 76.44
Current children cumulated vsize (KiB) 624820

[startup+83.2002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=365840/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=650280 CPUtime=82.81
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 133090 2205 0 0 8206 74 1 0 20 0 2 0 28476384 665886720 129864 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 162570 129864 7143 1052 0 141140 0
[pid=21593/tid=21598] ppid=21592 vsize=650280 CPUtime=80.79
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 118421 2205 0 0 8012 66 1 0 20 0 2 0 28476429 665886720 129864 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248286904 139960347620530 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 82.81
Current children cumulated vsize (KiB) 650280

[startup+86.4002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=351952/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=663284 CPUtime=86
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 136337 2205 0 0 8523 76 1 0 20 0 2 0 28476384 679202816 133109 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 165821 133109 7143 1052 0 144391 0
[pid=21593/tid=21598] ppid=21592 vsize=663284 CPUtime=83.98
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 121668 2205 0 0 8329 68 1 0 20 0 2 0 28476429 679202816 133109 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248284648 139960347533594 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 86
Current children cumulated vsize (KiB) 663284

[startup+88.0002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=343520/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=669504 CPUtime=87.59
/proc/21593/stat : 21593 (aptitude) S 21592 21593 17863 34816 17863 4202496 137901 2205 0 0 8682 76 1 0 20 0 2 0 28476384 685572096 134666 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452896 139960313632331 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 167376 134666 7143 1052 0 145946 0
[pid=21593/tid=21598] ppid=21592 vsize=669504 CPUtime=85.57
/proc/21593/task/21598/stat : 21598 (aptitude) R 21592 21593 17863 34816 17863 4202560 123232 2205 0 0 8488 68 1 0 20 0 2 0 28476429 685572096 134666 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248284648 139960347457940 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 87.59
Current children cumulated vsize (KiB) 669504

[startup+89.6002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=338188/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=673716 CPUtime=89.18
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 139312 2205 0 0 8840 77 1 0 20 0 2 0 28476384 689885184 135947 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101451272 139960302378443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 168429 135947 7191 1052 0 146992 0
[pid=21593/tid=21598] ppid=21592 vsize=673716 CPUtime=86.31
/proc/21593/task/21598/stat : 21598 (aptitude) S 21592 21593 17863 34816 17863 4202560 124264 2205 0 0 8562 68 1 0 20 0 2 0 28476429 689885184 135947 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248293376 139960313631444 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 89.18
Current children cumulated vsize (KiB) 673716

[startup+90.4002 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=338188/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=673716 CPUtime=89.97
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 141260 2205 0 0 8919 77 1 0 20 0 2 0 28476384 689885184 135936 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101452840 139960339785016 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 168429 135936 7192 1052 0 146992 0
[pid=21593/tid=21598] ppid=21592 vsize=673716 CPUtime=86.31
/proc/21593/task/21598/stat : 21598 (aptitude) S 21592 21593 17863 34816 17863 4202560 124264 2205 0 0 8562 68 1 0 20 0 2 0 28476429 689885184 135936 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248293376 139960313631444 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 89.97
Current children cumulated vsize (KiB) 673716

[startup+90.6011 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=338188/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=673716 CPUtime=90.17
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 141999 2705 0 0 8925 90 1 1 20 0 2 0 28476384 689885184 128725 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101457400 139960302753258 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 168429 128725 7192 1052 0 146992 0
[pid=21593/tid=21598] ppid=21592 vsize=673716 CPUtime=86.32
/proc/21593/task/21598/stat : 21598 (aptitude) S 21592 21593 17863 34816 17863 4202560 124264 2705 0 0 8562 68 1 1 20 0 2 0 28476429 689885184 128725 18446744073709551615 139960344887296 139960349194648 140734101461136 139960248293376 139960313631444 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 90.17
Current children cumulated vsize (KiB) 673716

[startup+90.7011 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21599
/proc/meminfo: memFree=338188/1022884 swapFree=0/0
[pid=21593] ppid=21592 vsize=330756 CPUtime=90.27
/proc/21593/stat : 21593 (aptitude) R 21592 21593 17863 34816 17863 4202496 142079 2705 0 0 8925 100 1 1 20 0 1 0 28476384 338694144 26613 18446744073709551615 139960344887296 139960349194648 140734101461136 140734101460696 139960302753258 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21593/statm: 82689 26613 1521 1052 0 66945 0
Current children cumulated CPU time (s) 90.27
Current children cumulated vsize (KiB) 330756

Child status: 0
Real time (s): 90.7269
CPU time (s): 90.3136
CPU user time (s): 89.2696
CPU system time (s): 1.04406
CPU usage (%): 99.5445
Max. virtual memory (cumulated for all children) (KiB): 673716

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 89.2696
system time used= 1.04407
maximum resident set size= 544152
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 144851
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= 239
involuntary context switches= 1595

runsolver used 0.416026 second user time and 0 second system time

The end