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/33.runsolver.aptitude aptitude -s -y --without-recommends install python-rpy-doc fbgrab pileup python2.1-gdbm gtk-engines-qtpixmap 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.03 1.06 1.03 2/55 25275 /proc/meminfo: memFree=832792/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=54860 CPUtime=0 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 584 0 0 0 0 0 0 0 20 0 1 0 29454914 56176640 484 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219633416 140016831837245 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 13715 484 397 1052 0 73 0 [startup+0.1565 s] /proc/loadavg: 1.03 1.06 1.03 2/55 25275 /proc/meminfo: memFree=832792/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=103288 CPUtime=0.14 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 11282 1707 0 0 12 2 0 0 20 0 1 0 29454914 105766912 11083 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625472 140016828869102 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 25822 11083 9872 1052 0 1159 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 103288 [startup+0.200281 s] /proc/loadavg: 1.03 1.06 1.03 2/55 25275 /proc/meminfo: memFree=832792/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=103288 CPUtime=0.18 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 11299 1707 0 0 16 2 0 0 20 0 1 0 29454914 105766912 11100 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625472 140016828869102 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 25822 11100 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 103288 [startup+0.300323 s] /proc/loadavg: 1.03 1.06 1.03 2/55 25275 /proc/meminfo: memFree=832792/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=103432 CPUtime=0.28 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 11426 1707 0 0 26 2 0 0 20 0 1 0 29454914 105914368 11219 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219623984 140016828880866 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 25858 11219 9956 1052 0 1195 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 103432 [startup+0.7002 s] /proc/loadavg: 1.03 1.06 1.03 2/55 25275 /proc/meminfo: memFree=832792/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=123068 CPUtime=0.68 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 17687 1707 0 0 60 8 0 0 20 0 1 0 29454914 126021632 15964 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219623640 140016836952831 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 30767 15964 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123068 [startup+1.50024 s] /proc/loadavg: 1.03 1.06 1.03 2/57 25280 /proc/meminfo: memFree=812820/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=136044 CPUtime=1.48 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 20637 1707 0 0 139 9 0 0 20 0 2 0 29454914 139309056 17557 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625480 140016836228891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 34011 17557 10207 1052 0 9348 0 [pid=25275/tid=25280] ppid=25274 vsize=136044 CPUtime=0 /proc/25275/task/25280/stat : 25280 (aptitude) S 25274 25275 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 29454991 139309056 17557 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721704960 140016802771668 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) 136044 [startup+3.10025 s] /proc/loadavg: 1.03 1.06 1.03 2/57 25280 /proc/meminfo: memFree=802652/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=137796 CPUtime=3.08 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 21978 2210 0 0 293 14 0 1 20 0 2 0 29454914 141103104 17925 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219620912 140016791538041 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 34449 17925 10303 1052 0 9786 0 [pid=25275/tid=25280] ppid=25274 vsize=137796 CPUtime=0.01 /proc/25275/task/25280/stat : 25280 (aptitude) S 25274 25275 17863 34816 17863 4202560 6 2210 0 0 0 0 0 1 20 0 2 0 29454991 141103104 17925 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721704960 140016802771668 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) 137796 [startup+6.30024 s] /proc/loadavg: 1.03 1.06 1.03 2/57 25281 /proc/meminfo: memFree=767684/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=248504 CPUtime=6.26 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 33763 2210 0 0 607 18 0 1 20 0 2 0 29454914 254468096 29445 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 62126 29445 10359 1052 0 37463 0 [pid=25275/tid=25280] ppid=25274 vsize=248504 CPUtime=2.89 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 11784 2210 0 0 284 4 0 1 20 0 2 0 29454991 254468096 29445 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721696232 140016791528116 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) 248504 [startup+12.7002 s] /proc/loadavg: 1.02 1.06 1.03 2/57 25281 /proc/meminfo: memFree=704072/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=304512 CPUtime=12.63 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 48067 2210 0 0 1234 28 0 1 20 0 2 0 29454914 311820288 43435 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 76128 43435 10359 1052 0 51465 0 [pid=25275/tid=25280] ppid=25274 vsize=304512 CPUtime=9.26 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 26088 2210 0 0 912 13 0 1 20 0 2 0 29454991 311820288 43435 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721698440 140016836622684 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) 304512 [startup+25.5003 s] /proc/loadavg: 1.02 1.06 1.03 2/57 25281 /proc/meminfo: memFree=612064/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=393448 CPUtime=25.37 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 70650 2210 0 0 2496 40 0 1 20 0 2 0 29454914 402890752 65654 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 98362 65654 10360 1052 0 73699 0 [pid=25275/tid=25280] ppid=25274 vsize=393448 CPUtime=21.99 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 48671 2210 0 0 2173 25 0 1 20 0 2 0 29454991 402890752 65654 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721697888 140016836726300 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) 393448 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.02 1.06 1.03 2/57 25281 /proc/meminfo: memFree=612064/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=393988 CPUtime=25.47 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 70795 2210 0 0 2506 40 0 1 20 0 2 0 29454914 403443712 65799 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 98497 65799 10360 1052 0 73834 0 [pid=25275/tid=25280] ppid=25274 vsize=393988 CPUtime=22.09 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 48816 2210 0 0 2183 25 0 1 20 0 2 0 29454991 403443712 65799 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721698392 140016791538041 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) 393988 [startup+32.0073 s] /proc/loadavg: 1.02 1.05 1.03 2/57 25281 /proc/meminfo: memFree=580568/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=424304 CPUtime=31.84 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 78402 2210 0 0 3141 42 0 1 20 0 2 0 29454914 434487296 73376 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 106076 73376 10360 1052 0 81413 0 [pid=25275/tid=25280] ppid=25274 vsize=424304 CPUtime=28.46 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 56423 2210 0 0 2818 27 0 1 20 0 2 0 29454991 434487296 73376 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721696280 140016800336480 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 31.84 Current children cumulated vsize (KiB) 424304 [startup+38.4002 s] /proc/loadavg: 1.01 1.05 1.03 2/57 25281 /proc/meminfo: memFree=554776/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=454096 CPUtime=38.2 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 85861 2210 0 0 3772 47 0 1 20 0 2 0 29454914 464994304 80807 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 113524 80807 10360 1052 0 88861 0 [pid=25275/tid=25280] ppid=25274 vsize=454096 CPUtime=34.82 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 63882 2210 0 0 3449 32 0 1 20 0 2 0 29454991 464994304 80807 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721699208 140016834672946 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 38.2 Current children cumulated vsize (KiB) 454096 [startup+40.0002 s] /proc/loadavg: 1.01 1.05 1.03 2/57 25281 /proc/meminfo: memFree=544856/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=460584 CPUtime=39.79 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 87510 2210 0 0 3931 47 0 1 20 0 2 0 29454914 471638016 82456 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 115146 82456 10360 1052 0 90483 0 [pid=25275/tid=25280] ppid=25274 vsize=460584 CPUtime=36.41 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 65531 2210 0 0 3608 32 0 1 20 0 2 0 29454991 471638016 82456 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721698488 140016836673879 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 39.79 Current children cumulated vsize (KiB) 460584 [startup+40.8073 s] /proc/loadavg: 1.01 1.05 1.03 2/57 25281 /proc/meminfo: memFree=539896/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=464308 CPUtime=40.6 /proc/25275/stat : 25275 (aptitude) S 25274 25275 17863 34816 17863 4202496 88444 2210 0 0 4012 47 0 1 20 0 2 0 29454914 475451392 83390 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219625968 140016802772555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25275/statm: 116077 83390 10360 1052 0 91414 0 [pid=25275/tid=25280] ppid=25274 vsize=464308 CPUtime=37.22 /proc/25275/task/25280/stat : 25280 (aptitude) R 25274 25275 17863 34816 17863 4202560 66465 2210 0 0 3689 32 0 1 20 0 2 0 29454991 475451392 83390 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721696280 140016836876108 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 40.6 Current children cumulated vsize (KiB) 464308 [startup+41.6002 s] /proc/loadavg: 1.01 1.05 1.03 2/57 25281 /proc/meminfo: memFree=539896/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=464508 CPUtime=41.38 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 89446 2210 0 0 4089 48 0 1 20 0 2 0 29454914 475656192 83610 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219624296 140016828851680 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/25275/statm: 116127 83610 10409 1052 0 91457 0 [pid=25275/tid=25280] ppid=25274 vsize=464508 CPUtime=37.23 /proc/25275/task/25280/stat : 25280 (aptitude) S 25274 25275 17863 34816 17863 4202560 66505 2210 0 0 3690 32 0 1 20 0 2 0 29454991 475656192 83610 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721704960 140016802771668 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 41.38 Current children cumulated vsize (KiB) 464508 [startup+42.0002 s] /proc/loadavg: 1.01 1.05 1.03 2/57 25281 /proc/meminfo: memFree=538656/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=464508 CPUtime=41.77 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 91556 2710 0 0 4121 54 0 2 20 0 2 0 29454914 475656192 83729 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219624920 140016828720192 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/25275/statm: 116127 83729 10409 1052 0 91457 0 [pid=25275/tid=25280] ppid=25274 vsize=464508 CPUtime=37.24 /proc/25275/task/25280/stat : 25280 (aptitude) S 25274 25275 17863 34816 17863 4202560 66505 2710 0 0 3690 32 0 2 20 0 2 0 29454991 475656192 83729 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721704960 140016802771668 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 41.77 Current children cumulated vsize (KiB) 464508 [startup+42.1002 s] /proc/loadavg: 1.01 1.05 1.03 2/57 25281 /proc/meminfo: memFree=538656/1022884 swapFree=0/0 [pid=25275] ppid=25274 vsize=464508 CPUtime=41.87 /proc/25275/stat : 25275 (aptitude) R 25274 25275 17863 34816 17863 4202496 92010 2710 0 0 4127 58 0 2 20 0 2 0 29454914 475656192 81520 18446744073709551615 140016834027520 140016838334872 140734219634208 140734219630472 140016791893482 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/25275/statm: 116127 81520 10409 1052 0 91457 0 [pid=25275/tid=25280] ppid=25274 vsize=464508 CPUtime=37.24 /proc/25275/task/25280/stat : 25280 (aptitude) S 25274 25275 17863 34816 17863 4202560 66505 2710 0 0 3690 32 0 2 20 0 2 0 29454991 475656192 81520 18446744073709551615 140016834027520 140016838334872 140734219634208 140016721704960 140016802771668 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 41.87 Current children cumulated vsize (KiB) 464508 Child status: 0 Real time (s): 42.1814 CPU time (s): 41.9706 CPU user time (s): 41.2826 CPU system time (s): 0.688043 CPU usage (%): 99.5002 Max. virtual memory (cumulated for all children) (KiB): 464508 getrusage(RUSAGE_CHILDREN,...) data: user time used= 41.2826 system time used= 0.688043 maximum resident set size= 335204 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 94879 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= 143 involuntary context switches= 777 runsolver used 0.084005 second user time and 0.116007 second system time The end