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/101.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove libgal2.2-common libmlgtk-ocaml-dev nano libksba8 libcomerr2 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 1.00 2/55 6258 /proc/meminfo: memFree=577560/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=3152 CPUtime=0 /proc/6258/stat : 6258 (runsolver) R 6257 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 31222939 3227648 33 18446744073709551615 134512640 134586868 4294678544 4294676592 4151817264 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.162273 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6258 /proc/meminfo: memFree=577560/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=34568 CPUtime=0.18 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 2114 7201 0 0 10 2 4 2 20 0 1 0 31222939 35397632 1930 18446744073709551615 4194304 5184042 140736384346352 140736384343544 140615865176387 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 8642 1930 729 242 0 1204 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 34568 [startup+0.200287 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6258 /proc/meminfo: memFree=577560/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=35492 CPUtime=0.22 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 2350 7201 0 0 14 2 4 2 20 0 1 0 31222939 36343808 2166 18446744073709551615 4194304 5184042 140736384346352 140736384343544 140615865245236 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 8873 2166 729 242 0 1435 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35492 [startup+0.300257 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6258 /proc/meminfo: memFree=577560/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=37984 CPUtime=0.32 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 3050 7201 0 0 22 4 4 2 20 0 1 0 31222939 38895616 2803 18446744073709551615 4194304 5184042 140736384346352 140736384343544 140615865307273 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 9496 2803 739 242 0 2058 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 37984 [startup+0.700197 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6258 /proc/meminfo: memFree=577560/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=65720 CPUtime=0.71 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 10078 7201 0 0 56 9 4 2 20 0 1 0 31222939 67297280 9822 18446744073709551615 4194304 5184042 140736384346352 140736384343656 140615881586243 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 16430 9822 851 242 0 8992 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 65720 [startup+1.5002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=540856/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=67036 CPUtime=1.51 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 10579 7201 0 0 136 9 4 2 20 0 1 0 31222939 68644864 10129 18446744073709551615 4194304 5184042 140736384346352 140736384343784 140615881560511 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 16759 10129 851 242 0 9321 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 67036 [startup+3.10021 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=539740/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=68808 CPUtime=3.1 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 11239 7201 0 0 294 10 4 2 20 0 1 0 31222939 70459392 10532 18446744073709551615 4194304 5184042 140736384346352 140736384343656 140615881601907 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 17202 10532 851 242 0 9764 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 68808 [startup+6.3002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=537756/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=71000 CPUtime=6.29 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 12153 7201 0 0 611 12 4 2 20 0 1 0 31222939 72704000 10933 18446744073709551615 4194304 5184042 140736384346352 140736384343656 140615881586227 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 17750 10933 851 242 0 10312 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 71000 [startup+12.7002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=534780/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=75096 CPUtime=12.66 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 13830 7201 0 0 1248 12 4 2 20 0 1 0 31222939 76898304 11585 18446744073709551615 4194304 5184042 140736384346352 140736384343784 140615881586133 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 18774 11585 851 242 0 11336 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 75096 [startup+25.5002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=528828/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=83736 CPUtime=25.41 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 17315 7201 0 0 2521 14 4 2 20 0 1 0 31222939 85745664 13021 18446744073709551615 4194304 5184042 140736384346352 140736384343784 140615881586284 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 20934 13021 851 242 0 13496 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 83736 [startup+51.1002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=518412/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=100120 CPUtime=50.91 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 24032 7201 0 0 5063 22 4 2 20 0 1 0 31222939 102522880 15641 18446744073709551615 4194304 5184042 140736384346352 140736384343784 140615881586024 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 25030 15641 851 242 0 17592 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 100120 [startup+102.3 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=494604/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=135544 CPUtime=101.9 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 38083 7201 0 0 10154 30 4 2 20 0 1 0 31222939 138797056 21499 18446744073709551615 4194304 5184042 140736384346352 140736384343784 140615881586219 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 33886 21499 851 242 0 26448 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 135544 [startup+162.3 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=461248/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=208368 CPUtime=161.65 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 62821 7201 0 0 16117 42 4 2 20 0 1 0 31222939 213368832 29852 18446744073709551615 4194304 5184042 140736384346352 140736384340616 140615881603988 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 52092 29852 851 242 0 44654 0 Current children cumulated CPU time (s) 161.65 Current children cumulated vsize (KiB) 208368 Solver just ended. Dumping a history of the last processes samples [startup+179.2 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=445996/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=218940 CPUtime=178.49 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 66642 7201 0 0 17798 45 4 2 20 0 1 0 31222939 224194560 33673 18446744073709551615 4194304 5184042 140736384346352 140736384340616 140615881585760 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 54735 33673 851 242 0 47297 0 Current children cumulated CPU time (s) 178.49 Current children cumulated vsize (KiB) 218940 [startup+192 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=440416/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=221464 CPUtime=191.24 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 68063 7201 0 0 19072 46 4 2 20 0 1 0 31222939 226779136 35094 18446744073709551615 4194304 5184042 140736384346352 140736384343656 140615881586256 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 55366 35094 851 242 0 47928 0 Current children cumulated CPU time (s) 191.24 Current children cumulated vsize (KiB) 221464 [startup+195.2 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=437564/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=223540 CPUtime=194.42 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 68756 7201 0 0 19390 46 4 2 20 0 1 0 31222939 228904960 35787 18446744073709551615 4194304 5184042 140736384346352 140736384343656 140615865243760 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 55885 35787 851 242 0 48447 0 Current children cumulated CPU time (s) 194.42 Current children cumulated vsize (KiB) 223540 [startup+196.8 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=437192/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=223540 CPUtime=196.02 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 68840 7201 0 0 19550 46 4 2 20 0 1 0 31222939 228904960 35871 18446744073709551615 4194304 5184042 140736384346352 140736384340648 140615881586216 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 55885 35871 851 242 0 48447 0 Current children cumulated CPU time (s) 196.02 Current children cumulated vsize (KiB) 223540 [startup+198.4 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=436696/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=223540 CPUtime=197.6 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 68932 7201 0 0 19708 46 4 2 20 0 1 0 31222939 228904960 35963 18446744073709551615 4194304 5184042 140736384346352 140736384340648 140615881586219 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 55885 35963 851 242 0 48447 0 Current children cumulated CPU time (s) 197.6 Current children cumulated vsize (KiB) 223540 [startup+198.8 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=436696/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=223540 CPUtime=198 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 68964 7201 0 0 19748 46 4 2 20 0 1 0 31222939 228904960 35995 18446744073709551615 4194304 5184042 140736384346352 140736384340648 140615881586287 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 55885 35995 851 242 0 48447 0 Current children cumulated CPU time (s) 198 Current children cumulated vsize (KiB) 223540 [startup+199.203 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=436448/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=223540 CPUtime=198.4 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 68988 7201 0 0 19788 46 4 2 20 0 1 0 31222939 228904960 36019 18446744073709551615 4194304 5184042 140736384346352 140736384340648 140615873674861 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 55885 36019 851 242 0 48447 0 Current children cumulated CPU time (s) 198.4 Current children cumulated vsize (KiB) 223540 [startup+199.3 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6278 /proc/meminfo: memFree=436448/1022884 swapFree=0/0 [pid=6258] ppid=6257 vsize=92464 CPUtime=198.5 /proc/6258/stat : 6258 (cupt) R 6257 6258 17872 34816 17872 4202496 69002 7201 0 0 19796 48 4 2 20 0 1 0 31222939 94683136 16528 18446744073709551615 4194304 5184042 140736384346352 140736384344728 140615865232839 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6258/statm: 23116 16528 862 242 0 15678 0 Current children cumulated CPU time (s) 198.5 Current children cumulated vsize (KiB) 92464 Child status: 1 Real time (s): 199.391 CPU time (s): 198.616 CPU user time (s): 198.084 CPU system time (s): 0.532033 CPU usage (%): 99.6115 Max. virtual memory (cumulated for all children) (KiB): 223540 getrusage(RUSAGE_CHILDREN,...) data: user time used= 198.084 system time used= 0.532033 maximum resident set size= 182048 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 76223 page faults= 0 swaps= 0 block input operations= 0 block output operations= 32 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 2916 runsolver used 0.272017 second user time and 0.536033 second system time The end