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/66.runsolver.aptitude aptitude -s -y --without-recommends install libgnomedb0-common libeditex-dev lft libgcc1 pimppa 

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: 1.13 1.06 0.97 2/55 21659
/proc/meminfo: memFree=972380/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=3152 CPUtime=0
/proc/21659/stat : 21659 (runsolver) R 21658 21659 17863 34816 17863 4202560 76 0 0 0 0 0 0 0 20 0 1 0 28523021 3227648 98 18446744073709551615 134512640 134586868 4292181392 4292179416 4149285791 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21659/statm: 788 98 66 19 0 73 0

[startup+0.182843 s]
/proc/loadavg: 1.13 1.06 0.97 2/55 21659
/proc/meminfo: memFree=972380/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=38696 CPUtime=0
/proc/21659/stat : 21659 (aptitude) D 21658 21659 17863 34816 17863 4202496 172 0 15 0 0 0 0 0 20 0 1 0 28523021 39624704 96 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016534152 140015126741750 0 0 0 0 0 0 0 17 0 0 0 16 0 0
/proc/21659/statm: 9674 96 61 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 38696

[startup+0.200397 s]
/proc/loadavg: 1.13 1.06 0.97 2/55 21659
/proc/meminfo: memFree=972380/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=40832 CPUtime=0
/proc/21659/stat : 21659 (aptitude) D 21658 21659 17863 34816 17863 4202496 176 0 16 0 0 0 0 0 20 0 1 0 28523021 41811968 100 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016534248 140015126742563 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/21659/statm: 10208 100 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.30037 s]
/proc/loadavg: 1.13 1.06 0.97 2/55 21659
/proc/meminfo: memFree=972380/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=54968 CPUtime=0.01
/proc/21659/stat : 21659 (aptitude) D 21658 21659 17863 34816 17863 4202496 1087 0 25 0 0 1 0 0 20 0 1 0 28523021 56287232 1003 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016533864 140015086728448 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/21659/statm: 13742 1003 833 1052 0 106 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 54968

[startup+0.700326 s]
/proc/loadavg: 1.13 1.06 0.97 2/55 21659
/proc/meminfo: memFree=972380/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=89152 CPUtime=0.02
/proc/21659/stat : 21659 (aptitude) D 21658 21659 17863 34816 17863 4202496 2454 1704 63 4 0 2 0 0 20 0 1 0 28523021 91291648 2317 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529296 140015123933082 0 134217728 4096 0 0 0 0 17 0 0 0 64 0 0
/proc/21659/statm: 22288 2317 1406 1052 0 858 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 89152

[startup+1.50028 s]
/proc/loadavg: 1.13 1.06 0.97 2/56 21663
/proc/meminfo: memFree=965172/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=101864 CPUtime=0.34
/proc/21659/stat : 21659 (aptitude) R 21658 21659 17863 34816 17863 4202496 11565 1704 144 4 29 5 0 0 20 0 1 0 28523021 104308736 10756 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016527256 140015097639280 0 134217728 4096 0 0 0 0 17 0 0 0 111 0 0
/proc/21659/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.34
Current children cumulated vsize (KiB) 101864

[startup+3.10024 s]
/proc/loadavg: 1.13 1.06 0.97 2/57 21664
/proc/meminfo: memFree=890144/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=115556 CPUtime=1.62
/proc/21659/stat : 21659 (aptitude) R 21658 21659 17863 34816 17863 4202496 14465 2200 144 6 152 10 0 0 20 0 2 0 28523021 118329344 12326 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016524528 140015131590644 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 28889 12326 7073 1052 0 7459 0
[pid=21659/tid=21664] ppid=21658 vsize=115556 CPUtime=0
/proc/21659/task/21664/stat : 21664 (aptitude) S 21658 21659 17863 34816 17863 4202560 6 2200 0 6 0 0 0 0 20 0 2 0 28523206 118329344 12326 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032289280 140015097627348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.62
Current children cumulated vsize (KiB) 115556
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.12 1.06 0.97 2/57 21665
/proc/meminfo: memFree=846372/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=169832 CPUtime=4.79
/proc/21659/stat : 21659 (aptitude) S 21658 21659 17863 34816 17863 4202496 28933 2200 144 6 465 14 0 0 20 0 2 0 28523021 173907968 26162 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529584 140015097628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 42458 26162 7129 1052 0 21028 0
[pid=21659/tid=21664] ppid=21658 vsize=169832 CPUtime=2.84
/proc/21659/task/21664/stat : 21664 (aptitude) R 21658 21659 17863 34816 17863 4202560 14458 2200 0 6 280 4 0 0 20 0 2 0 28523206 173907968 26162 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032280600 140015131529616 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.79
Current children cumulated vsize (KiB) 169832
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.11 1.06 0.97 2/57 21665
/proc/meminfo: memFree=796028/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=276420 CPUtime=11.17
/proc/21659/stat : 21659 (aptitude) S 21658 21659 17863 34816 17863 4202496 39284 2200 144 6 1096 21 0 0 20 0 2 0 28523021 283054080 36425 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529584 140015097628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 69105 36425 7129 1052 0 47675 0
[pid=21659/tid=21664] ppid=21658 vsize=276420 CPUtime=9.2
/proc/21659/task/21664/stat : 21664 (aptitude) R 21658 21659 17863 34816 17863 4202560 24808 2200 0 6 910 10 0 0 20 0 2 0 28523206 283054080 36425 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032282808 140015131516379 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.17
Current children cumulated vsize (KiB) 276420

[startup+25.5003 s]
/proc/loadavg: 1.08 1.05 0.97 2/57 21665
/proc/meminfo: memFree=713568/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=357096 CPUtime=23.91
/proc/21659/stat : 21659 (aptitude) S 21658 21659 17863 34816 17863 4202496 59433 2200 144 6 2363 28 0 0 20 0 2 0 28523021 365666304 56559 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529584 140015097628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 89274 56559 7129 1052 0 67844 0
[pid=21659/tid=21664] ppid=21658 vsize=357096 CPUtime=21.94
/proc/21659/task/21664/stat : 21664 (aptitude) R 21658 21659 17863 34816 17863 4202560 44957 2200 0 6 2177 17 0 0 20 0 2 0 28523206 365666304 56559 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032282808 140015086393480 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.91
Current children cumulated vsize (KiB) 357096

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

[startup+25.6003 s]
/proc/loadavg: 1.08 1.05 0.97 2/57 21665
/proc/meminfo: memFree=713568/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=357756 CPUtime=24.01
/proc/21659/stat : 21659 (aptitude) S 21658 21659 17863 34816 17863 4202496 59612 2200 144 6 2373 28 0 0 20 0 2 0 28523021 366342144 56738 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529584 140015097628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 89439 56738 7129 1052 0 68009 0
[pid=21659/tid=21664] ppid=21658 vsize=357756 CPUtime=22.04
/proc/21659/task/21664/stat : 21664 (aptitude) R 21658 21659 17863 34816 17863 4202560 45136 2200 0 6 2187 17 0 0 20 0 2 0 28523206 366342144 56738 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032282808 140015131529498 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 24.01
Current children cumulated vsize (KiB) 357756

[startup+32.0031 s]
/proc/loadavg: 1.08 1.05 0.97 2/57 21665
/proc/meminfo: memFree=665828/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=404068 CPUtime=30.38
/proc/21659/stat : 21659 (aptitude) S 21658 21659 17863 34816 17863 4202496 71239 2200 144 6 3006 32 0 0 20 0 2 0 28523021 413765632 68321 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529584 140015097628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 101017 68321 7143 1052 0 79587 0
[pid=21659/tid=21664] ppid=21658 vsize=404068 CPUtime=28.42
/proc/21659/task/21664/stat : 21664 (aptitude) R 21658 21659 17863 34816 17863 4202560 56756 2200 0 6 2820 22 0 0 20 0 2 0 28523206 413765632 68321 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032282760 140015131445308 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 30.38
Current children cumulated vsize (KiB) 404068

[startup+35.2002 s]
/proc/loadavg: 1.07 1.05 0.97 2/57 21665
/proc/meminfo: memFree=648716/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=420280 CPUtime=33.57
/proc/21659/stat : 21659 (aptitude) S 21658 21659 17863 34816 17863 4202496 75412 2200 144 6 3321 36 0 0 20 0 2 0 28523021 430366720 72402 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529584 140015097628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 105070 72402 7143 1052 0 83640 0
[pid=21659/tid=21664] ppid=21658 vsize=420280 CPUtime=31.6
/proc/21659/task/21664/stat : 21664 (aptitude) R 21658 21659 17863 34816 17863 4202560 60929 2200 0 6 3134 26 0 0 20 0 2 0 28523206 430366720 72402 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032282808 140015086393480 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 33.57
Current children cumulated vsize (KiB) 420280

[startup+38.4002 s]
/proc/loadavg: 1.07 1.05 0.97 2/57 21665
/proc/meminfo: memFree=640036/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=433660 CPUtime=36.75
/proc/21659/stat : 21659 (aptitude) S 21658 21659 17863 34816 17863 4202496 78846 2200 144 6 3637 38 0 0 20 0 2 0 28523021 444067840 75730 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016529584 140015097628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 140 0 0
/proc/21659/statm: 108415 75730 7143 1052 0 86985 0
[pid=21659/tid=21664] ppid=21658 vsize=433660 CPUtime=34.79
/proc/21659/task/21664/stat : 21664 (aptitude) R 21658 21659 17863 34816 17863 4202560 64363 2200 0 6 3451 28 0 0 20 0 2 0 28523206 444067840 75730 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032282856 140015131619020 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 36.75
Current children cumulated vsize (KiB) 433660

[startup+40.0003 s]
/proc/loadavg: 1.06 1.05 0.97 2/57 21665
/proc/meminfo: memFree=627140/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=440488 CPUtime=38.32
/proc/21659/stat : 21659 (aptitude) R 21658 21659 17863 34816 17863 4202496 80925 2200 145 6 3794 38 0 0 20 0 2 0 28523021 451059712 77679 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016527960 140015086374343 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 142 0 0
/proc/21659/statm: 110122 77679 7191 1052 0 88685 0
[pid=21659/tid=21664] ppid=21658 vsize=440488 CPUtime=35.84
/proc/21659/task/21664/stat : 21664 (aptitude) S 21658 21659 17863 34816 17863 4202560 66073 2200 0 6 3556 28 0 0 20 0 2 0 28523206 451059712 77679 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032289280 140015097627348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.32
Current children cumulated vsize (KiB) 440488

[startup+40.4002 s]
/proc/loadavg: 1.06 1.05 0.97 2/57 21665
/proc/meminfo: memFree=627140/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=440488 CPUtime=38.71
/proc/21659/stat : 21659 (aptitude) R 21658 21659 17863 34816 17863 4202496 82834 2200 145 6 3833 38 0 0 20 0 2 0 28523021 451059712 77680 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016525688 140015129712176 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 142 0 0
/proc/21659/statm: 110122 77680 7192 1052 0 88685 0
[pid=21659/tid=21664] ppid=21658 vsize=440488 CPUtime=35.84
/proc/21659/task/21664/stat : 21664 (aptitude) S 21658 21659 17863 34816 17863 4202560 66073 2200 0 6 3556 28 0 0 20 0 2 0 28523206 451059712 77680 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032289280 140015097627348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.71
Current children cumulated vsize (KiB) 440488

[startup+40.6008 s]
/proc/loadavg: 1.06 1.05 0.97 2/57 21665
/proc/meminfo: memFree=627140/1022884 swapFree=0/0
[pid=21659] ppid=21658 vsize=440488 CPUtime=38.92
/proc/21659/stat : 21659 (aptitude) R 21658 21659 17863 34816 17863 4202496 83517 2698 145 6 3845 46 0 1 20 0 2 0 28523021 451059712 61239 18446744073709551615 140015128883200 140015133190552 140735016537824 140735016534088 140015086749162 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 142 0 0
/proc/21659/statm: 110122 61239 7192 1052 0 88685 0
[pid=21659/tid=21664] ppid=21658 vsize=440488 CPUtime=35.85
/proc/21659/task/21664/stat : 21664 (aptitude) S 21658 21659 17863 34816 17863 4202560 66073 2698 0 6 3556 28 0 1 20 0 2 0 28523206 451059712 61239 18446744073709551615 140015128883200 140015133190552 140735016537824 140015032289280 140015097627348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.92
Current children cumulated vsize (KiB) 440488

Child status: 0
Real time (s): 40.6624
CPU time (s): 39.0024
CPU user time (s): 38.4624
CPU system time (s): 0.540033
CPU usage (%): 95.9177
Max. virtual memory (cumulated for all children) (KiB): 440488

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 38.4624
system time used= 0.540033
maximum resident set size= 311084
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 86362
page faults= 151
swaps= 0
block input operations= 123512
block output operations= 128
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1385
involuntary context switches= 720

runsolver used 0.056003 second user time and 0.140008 second system time

The end