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/logs/80.runsolver.aptitude aptitude -s -y --without-recommends install xscreensaver-nognome amanda-server libtemplate-plugin-calendar-simple-perl libmm13 gap-core 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.08 1.07 1.01 2/55 23855 /proc/meminfo: memFree=870648/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=3152 CPUtime=0 /proc/23855/stat : 23855 (runsolver) R 23854 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29069713 3227648 32 18446744073709551615 134512640 134586868 4293329088 4293327136 4152071216 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.138245 s] /proc/loadavg: 1.08 1.07 1.01 2/55 23855 /proc/meminfo: memFree=870648/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=100508 CPUtime=0.13 /proc/23855/stat : 23855 (aptitude) R 23854 23855 17863 34816 17863 4202496 10580 1707 0 0 11 1 1 0 20 0 1 0 29069713 102920192 10381 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039906640 140307247482739 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 25127 10381 9205 1052 0 1122 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 100508 [startup+0.200275 s] /proc/loadavg: 1.08 1.07 1.01 2/55 23855 /proc/meminfo: memFree=870648/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=100508 CPUtime=0.19 /proc/23855/stat : 23855 (aptitude) R 23854 23855 17863 34816 17863 4202496 10607 1707 0 0 17 1 1 0 20 0 1 0 29069713 102920192 10408 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039906640 140307247482344 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 25127 10408 9232 1052 0 1122 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 100508 [startup+0.300264 s] /proc/loadavg: 1.08 1.07 1.01 2/55 23855 /proc/meminfo: memFree=870648/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=111108 CPUtime=0.3 /proc/23855/stat : 23855 (aptitude) R 23854 23855 17863 34816 17863 4202496 12015 1707 0 0 27 2 1 0 20 0 1 0 29069713 113774592 11808 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039906968 140307254773324 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 27777 11808 9302 1052 0 3772 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 111108 [startup+0.700236 s] /proc/loadavg: 1.08 1.07 1.01 2/55 23855 /proc/meminfo: memFree=870648/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=123288 CPUtime=0.69 /proc/23855/stat : 23855 (aptitude) R 23854 23855 17863 34816 17863 4202496 17030 1707 0 0 63 5 1 0 20 0 2 0 29069713 126246912 14304 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039911160 140307247337200 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 30822 14304 9482 1052 0 6817 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 123288 [startup+1.50023 s] /proc/loadavg: 1.07 1.07 1.01 2/57 23860 /proc/meminfo: memFree=842368/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=132408 CPUtime=1.49 /proc/23855/stat : 23855 (aptitude) R 23854 23855 17863 34816 17863 4202496 19441 1707 0 0 142 6 1 0 20 0 2 0 29069713 135585792 16710 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039905728 140307210152313 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 33102 16710 9585 1052 0 9097 0 [pid=23855/tid=23860] ppid=23854 vsize=132408 CPUtime=0.01 /proc/23855/task/23860/stat : 23860 (aptitude) S 23854 23855 17863 34816 17863 4202560 4 1707 0 0 0 0 1 0 20 0 2 0 29069778 135585792 16710 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143469056 140307221385940 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) 132408 [startup+3.10024 s] /proc/loadavg: 1.07 1.07 1.01 2/57 23861 /proc/meminfo: memFree=841244/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=133816 CPUtime=3.08 /proc/23855/stat : 23855 (aptitude) R 23854 23855 17863 34816 17863 4202496 20616 2205 0 0 297 10 1 0 20 0 2 0 29069713 137027584 16945 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039902192 140307210794195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 33454 16945 9644 1052 0 9449 0 [pid=23855/tid=23860] ppid=23854 vsize=133816 CPUtime=0.01 /proc/23855/task/23860/stat : 23860 (aptitude) S 23854 23855 17863 34816 17863 4202560 6 2205 0 0 0 0 1 0 20 0 2 0 29069778 137027584 16945 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143469056 140307221385940 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) 133816 [startup+6.30024 s] /proc/loadavg: 1.07 1.06 1.01 2/57 23861 /proc/meminfo: memFree=797728/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=245700 CPUtime=6.26 /proc/23855/stat : 23855 (aptitude) S 23854 23855 17863 34816 17863 4202496 33169 2205 0 0 608 17 1 0 20 0 2 0 29069713 251596800 28748 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039907136 140307221386827 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 61425 28748 9700 1052 0 37420 0 [pid=23855/tid=23860] ppid=23854 vsize=245700 CPUtime=3.15 /proc/23855/task/23860/stat : 23860 (aptitude) R 23854 23855 17863 34816 17863 4202560 12552 2205 0 0 308 6 1 0 20 0 2 0 29069778 251596800 28748 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143460376 140307255340572 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) 245700 [startup+12.7002 s] /proc/loadavg: 1.06 1.06 1.01 2/57 23861 /proc/meminfo: memFree=751228/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=292928 CPUtime=12.63 /proc/23855/stat : 23855 (aptitude) S 23854 23855 17863 34816 17863 4202496 45510 2205 0 0 1242 20 1 0 20 0 2 0 29069713 299958272 40551 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039907136 140307221386827 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 73232 40551 9700 1052 0 49227 0 [pid=23855/tid=23860] ppid=23854 vsize=292928 CPUtime=9.53 /proc/23855/task/23860/stat : 23860 (aptitude) R 23854 23855 17863 34816 17863 4202560 24893 2205 0 0 942 10 1 0 20 0 2 0 29069778 299958272 40551 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143462536 140307210142035 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) 292928 [startup+25.5003 s] /proc/loadavg: 1.05 1.06 1.01 2/57 23861 /proc/meminfo: memFree=643596/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=397400 CPUtime=25.37 /proc/23855/stat : 23855 (aptitude) S 23854 23855 17863 34816 17863 4202496 71659 2205 0 0 2502 34 1 0 20 0 2 0 29069713 406937600 66635 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039907136 140307221386827 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 99350 66635 9700 1052 0 75345 0 [pid=23855/tid=23860] ppid=23854 vsize=397400 CPUtime=22.27 /proc/23855/task/23860/stat : 23860 (aptitude) R 23854 23855 17863 34816 17863 4202560 51042 2205 0 0 2202 24 1 0 20 0 2 0 29069778 406937600 66635 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143460504 140307210145332 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) 397400 [startup+51.1003 s] /proc/loadavg: 1.03 1.05 1.01 2/57 23861 /proc/meminfo: memFree=484256/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=557976 CPUtime=50.86 /proc/23855/stat : 23855 (aptitude) S 23854 23855 17863 34816 17863 4202496 111781 2205 0 0 5034 51 1 0 20 0 2 0 29069713 571367424 106738 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039907136 140307221386827 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 139494 106738 9714 1052 0 115489 0 [pid=23855/tid=23860] ppid=23854 vsize=557976 CPUtime=47.75 /proc/23855/task/23860/stat : 23860 (aptitude) R 23854 23855 17863 34816 17863 4202560 91157 2205 0 0 4733 41 1 0 20 0 2 0 29069778 571367424 106738 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143460504 140307255470647 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 50.86 Current children cumulated vsize (KiB) 557976 [startup+102.3 s] /proc/loadavg: 1.09 1.06 1.01 2/57 23861 /proc/meminfo: memFree=8148/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=1054272 CPUtime=100.27 /proc/23855/stat : 23855 (aptitude) S 23854 23855 17863 34816 17863 4202496 235965 2205 94 0 9910 116 1 0 20 0 2 0 29069713 1079574528 228383 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039907136 140307221386827 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 263568 228383 9120 1052 0 239563 0 [pid=23855/tid=23860] ppid=23854 vsize=1054272 CPUtime=97.16 /proc/23855/task/23860/stat : 23860 (aptitude) D 23854 23855 17863 34816 17863 4202560 215341 2205 94 0 9609 106 1 0 20 0 2 0 29069778 1079574528 228383 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143460424 140307254852695 0 134217728 4096 0 0 0 0 -1 0 0 0 147 0 0 Current children cumulated CPU time (s) 100.27 Current children cumulated vsize (KiB) 1054272 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+112.2 s] /proc/loadavg: 1.23 1.09 1.02 2/57 23861 /proc/meminfo: memFree=9992/1022884 swapFree=0/0 [pid=23855] ppid=23854 vsize=1151952 CPUtime=108.88 /proc/23855/stat : 23855 (aptitude) S 23854 23855 17863 34816 17863 4202496 260539 2205 216 0 10753 134 1 0 20 0 2 0 29069713 1179598848 247143 18446744073709551615 140307252641792 140307256949144 140736039915376 140736039907136 140307221386827 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23855/statm: 287988 247143 8684 1052 0 263983 0 [pid=23855/tid=23860] ppid=23854 vsize=1151952 CPUtime=105.78 /proc/23855/task/23860/stat : 23860 (aptitude) R 23854 23855 17863 34816 17863 4202560 239904 2205 212 0 10453 124 1 0 20 0 2 0 29069778 1179598848 247143 18446744073709551615 140307252641792 140307256949144 140736039915376 140307143463400 140307255532947 0 134217728 4096 0 0 0 0 -1 0 0 0 256 0 0 Current children cumulated CPU time (s) 108.88 Current children cumulated vsize (KiB) 1151952 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples Child ended because it received signal 15 (SIGTERM) Real time (s): 112.306 CPU time (s): 108.995 CPU user time (s): 107.575 CPU system time (s): 1.42009 CPU usage (%): 97.0513 Max. virtual memory (cumulated for all children) (KiB): 1151952 getrusage(RUSAGE_CHILDREN,...) data: user time used= 107.575 system time used= 1.42009 maximum resident set size= 990604 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 262782 page faults= 216 swaps= 0 block input operations= 7304 block output operations= 72 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 558 involuntary context switches= 2326 runsolver used 0 second user time and 0.524032 second system time The end