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/85.runsolver.aptitude aptitude -s -y --without-recommends install po-debiandoc kreversi decompyle libiw27 libneon24-dev 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.34 1.12 1.08 2/55 26209 /proc/meminfo: memFree=950568/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=3152 CPUtime=0 /proc/26209/stat : 26209 (runsolver) R 26208 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29798047 3227648 32 18446744073709551615 134512640 134586868 4288678432 4288676480 4151387184 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/26209/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.153331 s] /proc/loadavg: 1.34 1.12 1.08 2/55 26209 /proc/meminfo: memFree=950568/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=23840 CPUtime=0 /proc/26209/stat : 26209 (aptitude) D 26208 26209 17863 34816 17863 4202496 145 0 8 0 0 0 0 0 20 0 1 0 29798047 24412160 67 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374455704 140223968670478 0 0 0 0 0 0 0 17 0 0 0 14 0 0 /proc/26209/statm: 5960 67 45 1052 0 31 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 23840 [startup+0.200467 s] /proc/loadavg: 1.34 1.12 1.08 2/55 26209 /proc/meminfo: memFree=950568/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=33024 CPUtime=0 /proc/26209/stat : 26209 (aptitude) D 26208 26209 17863 34816 17863 4202496 162 0 12 0 0 0 0 0 20 0 1 0 29798047 33816576 85 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374455416 140223968671267 0 0 0 0 0 0 0 17 0 0 0 18 0 0 /proc/26209/statm: 8256 85 55 1052 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 33024 [startup+0.300385 s] /proc/loadavg: 1.34 1.12 1.08 2/55 26209 /proc/meminfo: memFree=950568/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=54840 CPUtime=0 /proc/26209/stat : 26209 (aptitude) D 26208 26209 17863 34816 17863 4202496 200 0 21 0 0 0 0 0 20 0 1 0 29798047 56156160 124 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374452104 140223968671187 0 0 0 0 0 0 0 17 0 0 0 28 0 0 /proc/26209/statm: 13710 124 72 1052 0 68 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 54840 [startup+0.700344 s] /proc/loadavg: 1.34 1.12 1.08 2/55 26209 /proc/meminfo: memFree=950568/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=103288 CPUtime=0.02 /proc/26209/stat : 26209 (aptitude) D 26208 26209 17863 34816 17863 4202496 2886 1706 43 2 1 1 0 0 20 0 1 0 29798047 105766912 2730 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450464 140223965861786 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0 /proc/26209/statm: 25822 2730 1519 1052 0 1159 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 103288 [startup+1.50033 s] /proc/loadavg: 1.34 1.12 1.08 1/56 26213 /proc/meminfo: memFree=943112/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=103288 CPUtime=0.04 /proc/26209/stat : 26209 (aptitude) D 26208 26209 17863 34816 17863 4202496 7101 1706 128 2 2 2 0 0 20 0 1 0 29798047 105766912 7030 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450464 140223965659416 0 134217728 4096 0 0 0 0 17 0 0 0 141 0 0 /proc/26209/statm: 25822 7030 5819 1052 0 1159 0 Current children cumulated CPU time (s) 0.04 Current children cumulated vsize (KiB) 103288 [startup+3.10031 s] /proc/loadavg: 1.34 1.12 1.08 2/56 26213 /proc/meminfo: memFree=931456/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=123068 CPUtime=0.6 /proc/26209/stat : 26209 (aptitude) D 26208 26209 17863 34816 17863 4202496 17505 1706 176 2 51 9 0 0 20 0 1 0 29798047 126021632 15958 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374448424 140223939567984 0 134217728 4096 0 0 0 0 17 0 0 0 245 0 0 /proc/26209/statm: 30767 15958 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.6 Current children cumulated vsize (KiB) 123068 heavy processes: [startup+6.30025 s] /proc/loadavg: 1.32 1.12 1.08 2/57 26214 /proc/meminfo: memFree=806580/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=137796 CPUtime=3.18 /proc/26209/stat : 26209 (aptitude) R 26208 26209 17863 34816 17863 4202496 21799 2204 176 3 296 21 0 1 20 0 2 0 29798047 141103104 17920 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374445696 140223928307464 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 304 0 0 /proc/26209/statm: 34449 17920 10303 1052 0 9786 0 [pid=26209/tid=26214] ppid=26208 vsize=137796 CPUtime=0.01 /proc/26209/task/26214/stat : 26214 (aptitude) S 26208 26209 17863 34816 17863 4202560 6 2204 0 3 0 0 0 1 20 0 2 0 29798436 141103104 17920 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858489344 140223939556052 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.18 Current children cumulated vsize (KiB) 137796 heavy processes: [startup+12.7002 s] /proc/loadavg: 1.29 1.12 1.08 2/57 26215 /proc/meminfo: memFree=737512/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=275044 CPUtime=9.55 /proc/26209/stat : 26209 (aptitude) S 26208 26209 17863 34816 17863 4202496 40677 2204 176 3 923 31 0 1 20 0 2 0 29798047 281645056 36101 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450752 140223939556939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 304 0 0 /proc/26209/statm: 68761 36101 10360 1052 0 44098 0 [pid=26209/tid=26214] ppid=26208 vsize=275044 CPUtime=6.1 /proc/26209/task/26214/stat : 26214 (aptitude) R 26208 26209 17863 34816 17863 4202560 18877 2204 0 3 599 10 0 1 20 0 2 0 29798436 281645056 36101 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858480664 140223928312187 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 9.55 Current children cumulated vsize (KiB) 275044 heavy processes: [startup+25.5003 s] /proc/loadavg: 1.22 1.11 1.07 2/57 26215 /proc/meminfo: memFree=652448/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=356376 CPUtime=22.29 /proc/26209/stat : 26209 (aptitude) S 26208 26209 17863 34816 17863 4202496 61281 2204 176 3 2190 38 0 1 20 0 2 0 29798047 364929024 56407 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450752 140223939556939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 304 0 0 /proc/26209/statm: 89094 56407 10360 1052 0 64431 0 [pid=26209/tid=26214] ppid=26208 vsize=356376 CPUtime=18.83 /proc/26209/task/26214/stat : 26214 (aptitude) R 26208 26209 17863 34816 17863 4202560 39481 2204 0 3 1866 16 0 1 20 0 2 0 29798436 364929024 56407 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858482872 140223973613871 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 22.29 Current children cumulated vsize (KiB) 356376 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.22 1.11 1.07 2/57 26215 /proc/meminfo: memFree=652448/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=356904 CPUtime=22.39 /proc/26209/stat : 26209 (aptitude) S 26208 26209 17863 34816 17863 4202496 61423 2204 176 3 2200 38 0 1 20 0 2 0 29798047 365469696 56549 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450752 140223939556939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 304 0 0 /proc/26209/statm: 89226 56549 10360 1052 0 64563 0 [pid=26209/tid=26214] ppid=26208 vsize=356904 CPUtime=18.93 /proc/26209/task/26214/stat : 26214 (aptitude) R 26208 26209 17863 34816 17863 4202560 39623 2204 0 3 1876 16 0 1 20 0 2 0 29798436 365469696 56549 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858480664 140223973408953 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 22.39 Current children cumulated vsize (KiB) 356904 [startup+28.8002 s] /proc/loadavg: 1.21 1.11 1.07 2/57 26215 /proc/meminfo: memFree=638312/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=369996 CPUtime=25.57 /proc/26209/stat : 26209 (aptitude) S 26208 26209 17863 34816 17863 4202496 64705 2204 176 3 2516 40 0 1 20 0 2 0 29798047 378875904 59831 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450752 140223939556939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 304 0 0 /proc/26209/statm: 92499 59831 10360 1052 0 67836 0 [pid=26209/tid=26214] ppid=26208 vsize=369996 CPUtime=22.12 /proc/26209/task/26214/stat : 26214 (aptitude) R 26208 26209 17863 34816 17863 4202560 42905 2204 0 3 2192 19 0 1 20 0 2 0 29798436 378875904 59831 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858483704 140223928307550 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.57 Current children cumulated vsize (KiB) 369996 [startup+30.4002 s] /proc/loadavg: 1.21 1.11 1.07 2/57 26215 /proc/meminfo: memFree=634592/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=376932 CPUtime=27.17 /proc/26209/stat : 26209 (aptitude) S 26208 26209 17863 34816 17863 4202496 66461 2204 176 3 2674 42 0 1 20 0 2 0 29798047 385978368 61566 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450752 140223939556939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 304 0 0 /proc/26209/statm: 94233 61566 10360 1052 0 69570 0 [pid=26209/tid=26214] ppid=26208 vsize=376932 CPUtime=23.71 /proc/26209/task/26214/stat : 26214 (aptitude) R 26208 26209 17863 34816 17863 4202560 44661 2204 0 3 2350 20 0 1 20 0 2 0 29798436 385978368 61566 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858482872 140223973408605 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 27.17 Current children cumulated vsize (KiB) 376932 [startup+31.2002 s] /proc/loadavg: 1.21 1.11 1.07 2/57 26215 /proc/meminfo: memFree=629508/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=379968 CPUtime=27.96 /proc/26209/stat : 26209 (aptitude) S 26208 26209 17863 34816 17863 4202496 67219 2204 176 3 2753 42 0 1 20 0 2 0 29798047 389087232 62323 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450752 140223939556939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 304 0 0 /proc/26209/statm: 94992 62323 10361 1052 0 70329 0 [pid=26209/tid=26214] ppid=26208 vsize=379968 CPUtime=24.51 /proc/26209/task/26214/stat : 26214 (aptitude) R 26208 26209 17863 34816 17863 4202560 45419 2204 0 3 2429 21 0 1 20 0 2 0 29798436 389087232 62323 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858481016 140223973519969 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 27.96 Current children cumulated vsize (KiB) 379968 [startup+32.0033 s] /proc/loadavg: 1.21 1.11 1.07 2/57 26215 /proc/meminfo: memFree=626036/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=380288 CPUtime=28.67 /proc/26209/stat : 26209 (aptitude) R 26208 26209 17863 34816 17863 4202496 70130 2204 189 3 2824 42 0 1 20 0 2 0 29798047 389414912 62610 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374450760 140223965728880 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/26209/statm: 95072 62610 10410 1052 0 70402 0 [pid=26209/tid=26214] ppid=26208 vsize=380288 CPUtime=24.54 /proc/26209/task/26214/stat : 26214 (aptitude) S 26208 26209 17863 34816 17863 4202560 45483 2204 1 3 2432 21 0 1 20 0 2 0 29798436 389414912 62610 18446744073709551615 140223970811904 140223975119256 140734374458992 140223858489344 140223939556052 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 28.67 Current children cumulated vsize (KiB) 380288 [startup+32.4004 s] /proc/loadavg: 1.21 1.11 1.07 2/57 26215 /proc/meminfo: memFree=626036/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=234576 CPUtime=29.03 /proc/26209/stat : 26209 (aptitude) R 26208 26209 17863 34816 17863 4202496 70837 2704 191 3 2842 59 0 2 20 0 1 0 29798047 240205824 18949 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374456104 140223928693015 0 134217728 4096 0 0 0 0 17 0 0 0 315 0 0 /proc/26209/statm: 58644 18949 3245 1052 0 33974 0 Current children cumulated CPU time (s) 29.03 Current children cumulated vsize (KiB) 234576 [startup+32.5003 s] /proc/loadavg: 1.21 1.11 1.07 2/57 26215 /proc/meminfo: memFree=626036/1022884 swapFree=0/0 [pid=26209] ppid=26208 vsize=142064 CPUtime=29.04 /proc/26209/stat : 26209 (aptitude) D 26208 26209 17863 34816 17863 4202496 70911 2704 205 3 2842 60 0 2 20 0 1 0 29798047 145473536 3003 18446744073709551615 140223970811904 140223975119256 140734374458992 140734374458064 140223950473084 0 134217728 4096 0 0 0 0 17 0 0 0 323 0 0 /proc/26209/statm: 35516 3003 1531 1052 0 19772 0 Current children cumulated CPU time (s) 29.04 Current children cumulated vsize (KiB) 142064 Child status: 0 Real time (s): 32.5058 CPU time (s): 29.0658 CPU user time (s): 28.4338 CPU system time (s): 0.632039 CPU usage (%): 89.4174 Max. virtual memory (cumulated for all children) (KiB): 380288 getrusage(RUSAGE_CHILDREN,...) data: user time used= 28.4338 system time used= 0.632039 maximum resident set size= 251028 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 73633 page faults= 209 swaps= 0 block input operations= 231736 block output operations= 144 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2332 involuntary context switches= 545 runsolver used 0.056003 second user time and 0.108006 second system time The end