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/logs/140.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove libstartup-notification0 libxi6 libgtkhtml3.2-11 kspaceduel libice-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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.09 1.02 0.93 2/55 28977 /proc/meminfo: memFree=303872/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=30148 CPUtime=0 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 797 0 0 0 0 0 0 0 20 0 1 0 28580443 30871552 695 18446744073709551615 4194304 5184042 140736230577232 140736230575240 140337830713951 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 7537 695 601 242 0 99 0 [startup+0.129092 s] /proc/loadavg: 1.09 1.02 0.93 2/55 28977 /proc/meminfo: memFree=303872/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=33640 CPUtime=0.15 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 1880 7217 0 0 8 0 5 2 20 0 1 0 28580443 34447360 1698 18446744073709551615 4194304 5184042 140736230577232 140736230574424 140337814466924 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 8410 1698 729 242 0 972 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 33640 [startup+0.200275 s] /proc/loadavg: 1.09 1.02 0.93 2/55 28977 /proc/meminfo: memFree=303872/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=35360 CPUtime=0.22 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 2323 7217 0 0 13 2 5 2 20 0 1 0 28580443 36208640 2140 18446744073709551615 4194304 5184042 140736230577232 140736230574424 140337814597729 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 8840 2140 729 242 0 1402 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35360 [startup+0.300262 s] /proc/loadavg: 1.09 1.02 0.93 2/55 28977 /proc/meminfo: memFree=303872/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=46976 CPUtime=0.32 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 5339 7217 0 0 22 3 5 2 20 0 1 0 28580443 48103424 5147 18446744073709551615 4194304 5184042 140736230577232 140736230571720 140337814877936 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 11744 5147 835 242 0 4306 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 46976 [startup+0.700202 s] /proc/loadavg: 1.09 1.02 0.93 2/55 28977 /proc/meminfo: memFree=303872/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=58360 CPUtime=0.72 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 8176 7217 0 0 60 5 5 2 20 0 1 0 28580443 59760640 7919 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830882941 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 14590 7919 842 242 0 7152 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 58360 [startup+1.50021 s] /proc/loadavg: 1.09 1.02 0.93 2/56 28997 /proc/meminfo: memFree=273864/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=62676 CPUtime=1.51 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 9399 7217 0 0 139 5 5 2 20 0 1 0 28580443 64180224 9013 18446744073709551615 4194304 5184042 140736230577232 140736230574184 140337830876160 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 15669 9013 842 242 0 8231 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 62676 [startup+3.10021 s] /proc/loadavg: 1.09 1.02 0.93 2/56 28997 /proc/meminfo: memFree=265928/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=70460 CPUtime=3.11 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 11561 7217 0 0 298 6 5 2 20 0 1 0 28580443 72151040 10918 18446744073709551615 4194304 5184042 140736230577232 140736230571496 140337830823328 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 17615 10918 842 242 0 10177 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 70460 [startup+6.30021 s] /proc/loadavg: 1.08 1.02 0.93 2/56 28997 /proc/meminfo: memFree=259232/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=75372 CPUtime=6.29 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 13216 7217 0 0 615 7 5 2 20 0 1 0 28580443 77180928 12060 18446744073709551615 4194304 5184042 140736230577232 140736230571496 140337830887328 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 18843 12060 842 242 0 11405 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 75372 [startup+12.7002 s] /proc/loadavg: 1.08 1.02 0.93 2/56 28997 /proc/meminfo: memFree=250552/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=86028 CPUtime=12.67 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 16553 7217 0 0 1251 9 5 2 20 0 1 0 28580443 88092672 14372 18446744073709551615 4194304 5184042 140736230577232 140736230574536 140337830876680 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 21507 14372 842 242 0 14069 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 86028 [startup+25.5002 s] /proc/loadavg: 1.06 1.02 0.93 2/56 28997 /proc/meminfo: memFree=241376/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=94820 CPUtime=25.41 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 20688 7217 0 0 2521 13 5 2 20 0 1 0 28580443 97095680 16458 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337814528124 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 23705 16458 842 242 0 16267 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 94820 [startup+51.1002 s] /proc/loadavg: 1.04 1.01 0.93 2/56 28997 /proc/meminfo: memFree=225132/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=111204 CPUtime=50.92 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 28822 7217 0 0 5067 18 5 2 20 0 1 0 28580443 113872896 20495 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337822958155 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 27801 20495 842 242 0 20363 0 Current children cumulated CPU time (s) 50.92 Current children cumulated vsize (KiB) 111204 [startup+102.3 s] /proc/loadavg: 1.02 1.01 0.93 2/56 28997 /proc/meminfo: memFree=193264/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=143972 CPUtime=101.9 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 44942 7217 0 0 10154 29 5 2 20 0 1 0 28580443 147427328 28422 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830876880 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 35993 28422 842 242 0 28555 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 143972 Solver just ended. Dumping a history of the last processes samples [startup+102.403 s] /proc/loadavg: 1.02 1.01 0.93 2/56 28997 /proc/meminfo: memFree=193264/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=143972 CPUtime=102 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 44958 7217 0 0 10164 29 5 2 20 0 1 0 28580443 147427328 28438 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830885519 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 35993 28438 842 242 0 28555 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 143972 [startup+128 s] /proc/loadavg: 1.01 1.01 0.93 2/56 28997 /proc/meminfo: memFree=177516/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=209508 CPUtime=127.5 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 65276 7217 0 0 12705 38 5 2 20 0 1 0 28580443 214536192 32371 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830876160 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 52377 32371 842 242 0 44939 0 Current children cumulated CPU time (s) 127.5 Current children cumulated vsize (KiB) 209508 [startup+140.8 s] /proc/loadavg: 1.01 1.00 0.93 2/56 28997 /proc/meminfo: memFree=169332/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=209508 CPUtime=140.24 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 67282 7217 0 0 13978 39 5 2 20 0 1 0 28580443 214536192 34377 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830876889 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 52377 34377 842 242 0 44939 0 Current children cumulated CPU time (s) 140.24 Current children cumulated vsize (KiB) 209508 [startup+153.6 s] /proc/loadavg: 1.00 1.00 0.93 2/56 28997 /proc/meminfo: memFree=161892/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=209508 CPUtime=152.99 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 69223 7217 0 0 15251 41 5 2 20 0 1 0 28580443 214536192 36318 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830885055 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 52377 36318 842 242 0 44939 0 Current children cumulated CPU time (s) 152.99 Current children cumulated vsize (KiB) 209508 [startup+156.8 s] /proc/loadavg: 1.00 1.00 0.93 2/56 28997 /proc/meminfo: memFree=159908/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=209508 CPUtime=156.17 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 69694 7217 0 0 15568 42 5 2 20 0 1 0 28580443 214536192 36789 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830876258 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 52377 36789 842 242 0 44939 0 Current children cumulated CPU time (s) 156.17 Current children cumulated vsize (KiB) 209508 [startup+160 s] /proc/loadavg: 1.00 1.00 0.93 2/56 28997 /proc/meminfo: memFree=157924/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=209508 CPUtime=159.36 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 70172 7217 0 0 15886 43 5 2 20 0 1 0 28580443 214536192 37267 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337830861557 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 52377 37267 842 242 0 44939 0 Current children cumulated CPU time (s) 159.36 Current children cumulated vsize (KiB) 209508 [startup+160.8 s] /proc/loadavg: 1.00 1.00 0.93 2/56 28997 /proc/meminfo: memFree=157180/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=209508 CPUtime=160.16 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 70365 7217 0 0 15966 43 5 2 20 0 1 0 28580443 214536192 37460 18446744073709551615 4194304 5184042 140736230577232 140736230574664 140337815264736 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 52377 37460 842 242 0 44939 0 Current children cumulated CPU time (s) 160.16 Current children cumulated vsize (KiB) 209508 [startup+161.6 s] /proc/loadavg: 1.00 1.00 0.93 2/56 28997 /proc/meminfo: memFree=157180/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=209508 CPUtime=160.96 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 70571 7217 0 0 16046 43 5 2 20 0 1 0 28580443 214536192 37666 18446744073709551615 4194304 5184042 140736230577232 140736230571496 140337830892403 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 52377 37666 842 242 0 44939 0 Current children cumulated CPU time (s) 160.96 Current children cumulated vsize (KiB) 209508 [startup+161.803 s] /proc/loadavg: 1.00 1.00 0.93 2/56 28997 /proc/meminfo: memFree=155816/1022884 swapFree=0/0 [pid=28977] ppid=28976 vsize=78172 CPUtime=161.16 /proc/28977/stat : 28977 (cupt) R 28976 28977 17872 34816 17872 4202496 70615 7217 0 0 16064 45 5 2 20 0 1 0 28580443 80048128 12938 18446744073709551615 4194304 5184042 140736230577232 140736230576680 140337814523454 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28977/statm: 19543 12938 853 242 0 12105 0 Current children cumulated CPU time (s) 161.16 Current children cumulated vsize (KiB) 78172 Child status: 1 Real time (s): 161.815 CPU time (s): 161.178 CPU user time (s): 160.694 CPU system time (s): 0.48403 CPU usage (%): 99.6066 Max. virtual memory (cumulated for all children) (KiB): 275048 getrusage(RUSAGE_CHILDREN,...) data: user time used= 160.694 system time used= 0.48403 maximum resident set size= 183048 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 77851 page faults= 0 swaps= 0 block input operations= 0 block output operations= 16 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 2377 runsolver used 0.208013 second user time and 0.460028 second system time The end