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/9.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install nrg2iso ipopd ttf-junicode python2.4-svn yacas-proteus 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.00 1.00 0.97 2/55 2305 /proc/meminfo: memFree=539752/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=3152 CPUtime=0 /proc/2305/stat : 2305 (runsolver) R 2304 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29844466 3227648 32 18446744073709551615 134512640 134586868 4290413376 4290411424 4151194672 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.156655 s] /proc/loadavg: 1.00 1.00 0.97 2/55 2305 /proc/meminfo: memFree=539752/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=34436 CPUtime=0.17 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 2064 7193 0 0 8 3 4 2 20 0 1 0 29844466 35262464 1881 18446744073709551615 4194304 5184042 140734528811024 140734528808216 140160965669105 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 8609 1881 729 242 0 1171 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 34436 [startup+0.200273 s] /proc/loadavg: 1.00 1.00 0.97 2/55 2305 /proc/meminfo: memFree=539752/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=35360 CPUtime=0.21 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 2319 7193 0 0 11 4 4 2 20 0 1 0 29844466 36208640 2136 18446744073709551615 4194304 5184042 140734528811024 140734528808216 140160965538136 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 8840 2136 729 242 0 1402 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35360 [startup+0.300263 s] /proc/loadavg: 1.00 1.00 0.97 2/55 2305 /proc/meminfo: memFree=539752/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=37852 CPUtime=0.31 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 3021 7193 0 0 20 5 4 2 20 0 1 0 29844466 38760448 2775 18446744073709551615 4194304 5184042 140734528811024 140734528808216 140160982815152 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 9463 2775 739 242 0 2025 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37852 [startup+0.700201 s] /proc/loadavg: 1.00 1.00 0.97 2/55 2305 /proc/meminfo: memFree=539752/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=64620 CPUtime=0.71 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 9808 7193 0 0 55 10 4 2 20 0 1 0 29844466 66170880 9553 18446744073709551615 4194304 5184042 140734528811024 140734528808328 140160982005324 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 16155 9553 851 242 0 8717 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 64620 [startup+1.5002 s] /proc/loadavg: 1.00 1.00 0.97 2/57 2334 /proc/meminfo: memFree=502792/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=67324 CPUtime=1.4 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 10636 7193 0 0 124 10 4 2 20 0 1 0 29844466 68939776 10187 18446744073709551615 4194304 5184042 140734528811024 140734528808328 140160981947816 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 16831 10187 851 242 0 9393 0 Current children cumulated CPU time (s) 1.4 Current children cumulated vsize (KiB) 67324 [startup+3.10021 s] /proc/loadavg: 1.00 1.00 0.97 2/57 2334 /proc/meminfo: memFree=500932/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=71112 CPUtime=2.88 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 11955 7193 0 0 272 10 4 2 20 0 1 0 29844466 72818688 10736 18446744073709551615 4194304 5184042 140734528811024 140734528808472 140160981947552 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 17778 10736 851 242 0 10340 0 Current children cumulated CPU time (s) 2.88 Current children cumulated vsize (KiB) 71112 [startup+6.30019 s] /proc/loadavg: 1.08 1.02 0.98 3/56 2465 /proc/meminfo: memFree=498204/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=75208 CPUtime=4.71 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 13517 7193 0 0 453 12 4 2 20 0 1 0 29844466 77012992 11273 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981956287 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 18802 11273 851 242 0 11364 0 Current children cumulated CPU time (s) 4.71 Current children cumulated vsize (KiB) 75208 heavy processes: [startup+12.7002 s] /proc/loadavg: 1.15 1.03 0.98 2/56 2549 /proc/meminfo: memFree=493624/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=83548 CPUtime=9.6 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 16800 7193 0 0 939 15 4 2 20 0 1 0 29844466 85553152 12507 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981948000 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 20887 12507 851 242 0 13449 0 Current children cumulated CPU time (s) 9.6 Current children cumulated vsize (KiB) 83548 heavy processes: [startup+25.5002 s] /proc/loadavg: 1.12 1.03 0.98 2/56 2549 /proc/meminfo: memFree=478372/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=102032 CPUtime=22.35 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 24625 7193 0 0 2208 21 4 2 20 0 1 0 29844466 104480768 16235 18446744073709551615 4194304 5184042 140734528811024 140734528808328 140160981948121 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 25508 16235 851 242 0 18070 0 Current children cumulated CPU time (s) 22.35 Current children cumulated vsize (KiB) 102032 [startup+51.1002 s] /proc/loadavg: 1.08 1.03 0.98 2/56 2549 /proc/meminfo: memFree=469568/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=102032 CPUtime=47.85 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 26779 7193 0 0 4756 23 4 2 20 0 1 0 29844466 104480768 18389 18446744073709551615 4194304 5184042 140734528811024 140734528808328 140160981948116 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 25508 18389 851 242 0 18070 0 Current children cumulated CPU time (s) 47.85 Current children cumulated vsize (KiB) 102032 [startup+102.3 s] /proc/loadavg: 1.03 1.02 0.98 2/56 2549 /proc/meminfo: memFree=451960/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=134800 CPUtime=98.84 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 39320 7193 0 0 9847 31 4 2 20 0 1 0 29844466 138035200 22737 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981947936 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 33700 22737 851 242 0 26262 0 Current children cumulated CPU time (s) 98.84 Current children cumulated vsize (KiB) 134800 [startup+162.3 s] /proc/loadavg: 1.01 1.02 0.98 2/56 2549 /proc/meminfo: memFree=431004/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=200336 CPUtime=158.59 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 60922 7193 0 0 15809 44 4 2 20 0 1 0 29844466 205144064 27954 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981947552 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 50084 27954 851 242 0 42646 0 Current children cumulated CPU time (s) 158.59 Current children cumulated vsize (KiB) 200336 [startup+222.303 s] /proc/loadavg: 1.00 1.01 0.98 2/56 2549 /proc/meminfo: memFree=409924/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=200336 CPUtime=218.35 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 66176 7193 0 0 21778 51 4 2 20 0 1 0 29844466 205144064 33208 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981954981 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 50084 33208 851 242 0 42646 0 Current children cumulated CPU time (s) 218.35 Current children cumulated vsize (KiB) 200336 [startup+282.3 s] /proc/loadavg: 1.00 1.00 0.98 2/56 2549 /proc/meminfo: memFree=389836/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=200336 CPUtime=278.1 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 71261 7193 0 0 27746 58 4 2 20 0 1 0 29844466 205144064 38293 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981894563 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 50084 38293 851 242 0 42646 0 Current children cumulated CPU time (s) 278.1 Current children cumulated vsize (KiB) 200336 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 0.98 2/56 2549 /proc/meminfo: memFree=383636/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=200336 CPUtime=295.73 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 72723 7193 0 0 29507 60 4 2 20 0 1 0 29844466 205144064 39755 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981947779 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 50084 39755 851 242 0 42646 0 Current children cumulated CPU time (s) 295.73 Current children cumulated vsize (KiB) 200336 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 0.98 2/56 2549 /proc/meminfo: memFree=383636/1022884 swapFree=0/0 [pid=2305] ppid=2304 vsize=200336 CPUtime=295.73 /proc/2305/stat : 2305 (cupt) R 2304 2305 17872 34816 17872 4202496 72723 7193 0 0 29507 60 4 2 20 0 1 0 29844466 205144064 39755 18446744073709551615 4194304 5184042 140734528811024 140734528808456 140160981947779 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2305/statm: 50084 39755 851 242 0 42646 0 Current children cumulated CPU time (s) 295.73 Current children cumulated vsize (KiB) 200336 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.019 CPU time (s): 295.762 CPU user time (s): 295.122 CPU system time (s): 0.64004 CPU usage (%): 98.5812 Max. virtual memory (cumulated for all children) (KiB): 265876 getrusage(RUSAGE_CHILDREN,...) data: user time used= 295.122 system time used= 0.64004 maximum resident set size= 173988 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 79916 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= 5405 runsolver used 0.228014 second user time and 1.00406 second system time The end