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/161.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove libcroco3-dev libgtk2.0-0 klogd cdrecord desktop-file-utils 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: 0.99 0.98 0.99 2/55 8766 /proc/meminfo: memFree=577700/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=3152 CPUtime=0 /proc/8766/stat : 8766 (runsolver) R 8765 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 32067715 3227648 32 18446744073709551615 134512640 134586868 4289925936 4289923984 4151211056 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 7509 369 305 242 0 65 0 [startup+0.136022 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8766 /proc/meminfo: memFree=577700/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=34168 CPUtime=0.15 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 2012 7204 0 0 6 3 4 2 20 0 1 0 32067715 34988032 1830 18446744073709551615 4194304 5184042 140734715303328 140734715300520 140098850256624 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 8542 1830 729 242 0 1104 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 34168 [startup+0.200259 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8766 /proc/meminfo: memFree=577700/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=35888 CPUtime=0.21 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 2436 7204 0 0 12 3 4 2 20 0 1 0 32067715 36749312 2253 18446744073709551615 4194304 5184042 140734715303328 140734715300520 140098849914420 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 8972 2253 729 242 0 1534 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35888 [startup+0.30025 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8766 /proc/meminfo: memFree=577700/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=38384 CPUtime=0.31 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 3155 7204 0 0 20 5 4 2 20 0 1 0 32067715 39305216 2908 18446744073709551615 4194304 5184042 140734715303328 140734715300520 140098849976441 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 9596 2908 739 242 0 2158 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 38384 [startup+0.700183 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8766 /proc/meminfo: memFree=577700/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=66684 CPUtime=0.71 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 10304 7204 0 0 56 9 4 2 20 0 1 0 32067715 68284416 10048 18446744073709551615 4194304 5184042 140734715303328 140734715300632 140098866304336 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 16671 10048 851 242 0 9233 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 66684 [startup+1.50014 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8786 /proc/meminfo: memFree=539756/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=68172 CPUtime=1.51 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 10868 7204 0 0 135 10 4 2 20 0 1 0 32067715 69808128 10418 18446744073709551615 4194304 5184042 140734715303328 140734715297624 140098866254848 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 17043 10418 851 242 0 9605 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 68172 [startup+3.10014 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8786 /proc/meminfo: memFree=538764/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=71244 CPUtime=3.1 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 11985 7204 0 0 294 10 4 2 20 0 1 0 32067715 72953856 10765 18446744073709551615 4194304 5184042 140734715303328 140734715300776 140098866403440 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 17811 10765 851 242 0 10373 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 71244 [startup+6.30014 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8786 /proc/meminfo: memFree=536532/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=71664 CPUtime=6.29 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 12442 7204 0 0 612 11 4 2 20 0 1 0 32067715 73383936 11222 18446744073709551615 4194304 5184042 140734715303328 140734715300632 140098858725253 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 17916 11222 851 242 0 10478 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 71664 [startup+12.7001 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8786 /proc/meminfo: memFree=533432/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=75904 CPUtime=12.68 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 14232 7204 0 0 1250 12 4 2 20 0 1 0 32067715 77725696 11987 18446744073709551615 4194304 5184042 140734715303328 140734715300632 140098866233476 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 18976 11987 851 242 0 11538 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 75904 [startup+25.5001 s] /proc/loadavg: 1.07 1.00 1.00 2/56 8786 /proc/meminfo: memFree=527604/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=84096 CPUtime=25.43 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 17677 7204 0 0 2524 13 4 2 20 0 1 0 32067715 86114304 13383 18446744073709551615 4194304 5184042 140734715303328 140734715300760 140098849912628 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 21024 13383 851 242 0 13586 0 Current children cumulated CPU time (s) 25.43 Current children cumulated vsize (KiB) 84096 [startup+51.1001 s] /proc/loadavg: 1.05 1.00 1.00 2/56 8786 /proc/meminfo: memFree=515700/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=101300 CPUtime=50.95 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 24765 7204 0 0 5073 16 4 2 20 0 1 0 32067715 103731200 16374 18446744073709551615 4194304 5184042 140734715303328 140734715300760 140098866255403 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 25325 16374 851 242 0 17887 0 Current children cumulated CPU time (s) 50.95 Current children cumulated vsize (KiB) 101300 [startup+102.3 s] /proc/loadavg: 1.02 1.00 1.00 2/56 8786 /proc/meminfo: memFree=493008/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=134068 CPUtime=101.99 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 38545 7204 0 0 10174 19 4 2 20 0 1 0 32067715 137285632 21961 18446744073709551615 4194304 5184042 140734715303328 140734715300760 140098866255267 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 33517 21961 851 242 0 26079 0 Current children cumulated CPU time (s) 101.99 Current children cumulated vsize (KiB) 134068 [startup+162.3 s] /proc/loadavg: 1.00 1.00 1.00 2/56 8786 /proc/meminfo: memFree=465356/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=201112 CPUtime=161.8 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 61873 7204 0 0 16148 26 4 2 20 0 1 0 32067715 205938688 28904 18446744073709551615 4194304 5184042 140734715303328 140734715300760 140098849911123 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 50278 28904 851 242 0 42840 0 Current children cumulated CPU time (s) 161.8 Current children cumulated vsize (KiB) 201112 [startup+222.303 s] /proc/loadavg: 1.00 1.00 1.00 2/56 8786 /proc/meminfo: memFree=438820/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=201112 CPUtime=221.61 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 68422 7204 0 0 22127 28 4 2 20 0 1 0 32067715 205938688 35453 18446744073709551615 4194304 5184042 140734715303328 140734715300760 140098849911113 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 50278 35453 851 242 0 42840 0 Current children cumulated CPU time (s) 221.61 Current children cumulated vsize (KiB) 201112 [startup+282.3 s] /proc/loadavg: 1.00 1.00 1.00 2/56 8786 /proc/meminfo: memFree=385624/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=335308 CPUtime=281.42 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 114615 7204 0 0 28095 41 4 2 20 0 1 0 32067715 343355392 48877 18446744073709551615 4194304 5184042 140734715303328 140734715300776 140098866255400 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 83827 48877 851 242 0 76389 0 Current children cumulated CPU time (s) 281.42 Current children cumulated vsize (KiB) 335308 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 1.00 2/56 8786 /proc/meminfo: memFree=367272/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=335308 CPUtime=299.07 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 119033 7204 0 0 29859 42 4 2 20 0 1 0 32067715 343355392 53295 18446744073709551615 4194304 5184042 140734715303328 140734715300776 140098866254848 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 83827 53295 851 242 0 76389 0 Current children cumulated CPU time (s) 299.07 Current children cumulated vsize (KiB) 335308 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+300 s] /proc/loadavg: 1.00 1.00 1.00 2/56 8786 /proc/meminfo: memFree=367272/1022884 swapFree=0/0 [pid=8766] ppid=8765 vsize=335308 CPUtime=299.07 /proc/8766/stat : 8766 (cupt) R 8765 8766 17872 34816 17872 4202496 119033 7204 0 0 29859 42 4 2 20 0 1 0 32067715 343355392 53295 18446744073709551615 4194304 5184042 140734715303328 140734715300776 140098866254848 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8766/statm: 83827 53295 851 242 0 76389 0 Current children cumulated CPU time (s) 299.07 Current children cumulated vsize (KiB) 335308 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.019 CPU time (s): 299.095 CPU user time (s): 298.639 CPU system time (s): 0.456028 CPU usage (%): 99.6918 Max. virtual memory (cumulated for all children) (KiB): 466384 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.639 system time used= 0.456028 maximum resident set size= 308912 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 126237 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 4357 runsolver used 0.348021 second user time and 0.608038 second system time The end