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/76.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install python2.4-reportlab quack-el acl2-books-certs steptalk curl 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: 0.95 0.98 0.99 2/55 5202 /proc/meminfo: memFree=579368/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=3152 CPUtime=0 /proc/5202/stat : 5202 (runsolver) R 5201 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 30777721 3227648 33 18446744073709551615 134512640 134586868 4294604864 4294602912 4151436336 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.159191 s] /proc/loadavg: 0.95 0.98 0.99 2/55 5202 /proc/meminfo: memFree=579368/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=34568 CPUtime=0.17 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 2096 7199 0 0 10 1 4 2 20 0 1 0 30777721 35397632 1912 18446744073709551615 4194304 5184042 140735646545744 140735646542936 140496237867137 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 8642 1912 729 242 0 1204 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 34568 [startup+0.200271 s] /proc/loadavg: 0.95 0.98 0.99 2/55 5202 /proc/meminfo: memFree=579368/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=35492 CPUtime=0.21 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 2343 7199 0 0 13 2 4 2 20 0 1 0 30777721 36343808 2159 18446744073709551615 4194304 5184042 140735646545744 140735646542936 140496237736263 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 8873 2159 729 242 0 1435 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35492 [startup+0.300259 s] /proc/loadavg: 0.95 0.98 0.99 2/55 5202 /proc/meminfo: memFree=579368/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=37984 CPUtime=0.32 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 3048 7199 0 0 22 4 4 2 20 0 1 0 30777721 38895616 2801 18446744073709551615 4194304 5184042 140735646545744 140735646542936 140496254331907 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 9496 2801 739 242 0 2058 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 37984 [startup+0.700195 s] /proc/loadavg: 0.95 0.98 0.99 2/55 5202 /proc/meminfo: memFree=579368/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=66340 CPUtime=0.71 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 10257 7199 0 0 53 12 4 2 20 0 1 0 30777721 67932160 10001 18446744073709551615 4194304 5184042 140735646545744 140735646543048 140496237801943 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 16585 10001 851 242 0 9147 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 66340 [startup+1.5002 s] /proc/loadavg: 0.95 0.98 0.99 2/56 5222 /proc/meminfo: memFree=541920/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=67652 CPUtime=1.51 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 10749 7199 0 0 133 12 4 2 20 0 1 0 30777721 69275648 10299 18446744073709551615 4194304 5184042 140735646545744 140735646543192 140496254228595 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 16913 10299 851 242 0 9475 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 67652 [startup+3.10021 s] /proc/loadavg: 0.95 0.98 0.99 2/56 5222 /proc/meminfo: memFree=540680/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=71028 CPUtime=3.1 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 12015 7199 0 0 292 12 4 2 20 0 1 0 30777721 72732672 10795 18446744073709551615 4194304 5184042 140735646545744 140735646543048 140496237801811 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 17757 10795 851 242 0 10319 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 71028 [startup+6.3002 s] /proc/loadavg: 0.95 0.98 0.99 2/56 5222 /proc/meminfo: memFree=537084/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=75276 CPUtime=6.29 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 13850 7199 0 0 610 13 4 2 20 0 1 0 30777721 77082624 11605 18446744073709551615 4194304 5184042 140735646545744 140735646543048 140496237792939 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 18819 11605 851 242 0 11381 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 75276 [startup+12.7002 s] /proc/loadavg: 0.95 0.98 0.99 2/56 5222 /proc/meminfo: memFree=530264/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=83468 CPUtime=12.66 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 17699 7199 0 0 1245 15 4 2 20 0 1 0 30777721 85471232 13405 18446744073709551615 4194304 5184042 140735646545744 140735646543176 140496254090814 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 20867 13405 851 242 0 13429 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 83468 [startup+25.5002 s] /proc/loadavg: 0.96 0.98 0.99 2/56 5222 /proc/meminfo: memFree=516128/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=100004 CPUtime=25.41 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 25064 7199 0 0 2519 16 4 2 20 0 1 0 30777721 102404096 16673 18446744073709551615 4194304 5184042 140735646545744 140735646543176 140496254145523 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 25001 16673 851 242 0 17563 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 100004 [startup+51.1002 s] /proc/loadavg: 0.97 0.98 0.99 2/56 5222 /proc/meminfo: memFree=493064/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=132772 CPUtime=50.9 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 39056 7199 0 0 5060 24 4 2 20 0 1 0 30777721 135958528 22472 18446744073709551615 4194304 5184042 140735646545744 140735646543192 140496254145536 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 33193 22472 851 242 0 25755 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 132772 [startup+102.3 s] /proc/loadavg: 0.99 0.98 0.99 2/56 5222 /proc/meminfo: memFree=453756/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=198308 CPUtime=101.9 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 65145 7199 0 0 10144 40 4 2 20 0 1 0 30777721 203067392 32176 18446744073709551615 4194304 5184042 140735646545744 140735646543192 140496246215680 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 49577 32176 851 242 0 42139 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 198308 [startup+162.3 s] /proc/loadavg: 1.03 1.00 1.00 2/56 5222 /proc/meminfo: memFree=414572/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=200804 CPUtime=161.66 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 74953 7199 0 0 16106 54 4 2 20 0 1 0 30777721 205623296 41984 18446744073709551615 4194304 5184042 140735646545744 140735646543048 140496254120353 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 50201 41984 851 242 0 42763 0 Current children cumulated CPU time (s) 161.66 Current children cumulated vsize (KiB) 200804 [startup+222.303 s] /proc/loadavg: 1.01 1.00 1.00 2/56 5222 /proc/meminfo: memFree=366708/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=343764 CPUtime=221.42 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 119612 7199 0 0 22062 74 4 2 20 0 1 0 30777721 352014336 53874 18446744073709551615 4194304 5184042 140735646545744 140735646539160 140496254145536 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 85941 53874 851 242 0 78503 0 Current children cumulated CPU time (s) 221.42 Current children cumulated vsize (KiB) 343764 [startup+282.3 s] /proc/loadavg: 1.00 1.00 1.00 2/56 5222 /proc/meminfo: memFree=339676/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=343764 CPUtime=281.18 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 126427 7199 0 0 28031 81 4 2 20 0 1 0 30777721 352014336 60689 18446744073709551615 4194304 5184042 140735646545744 140735646539160 140496254228428 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 85941 60689 851 242 0 78503 0 Current children cumulated CPU time (s) 281.18 Current children cumulated vsize (KiB) 343764 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 1.00 2/56 5222 /proc/meminfo: memFree=331244/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=343764 CPUtime=298.81 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 128462 7199 0 0 29790 85 4 2 20 0 1 0 30777721 352014336 62724 18446744073709551615 4194304 5184042 140735646545744 140735646539160 140496254145942 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 85941 62724 851 242 0 78503 0 Current children cumulated CPU time (s) 298.81 Current children cumulated vsize (KiB) 343764 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 5222 /proc/meminfo: memFree=331244/1022884 swapFree=0/0 [pid=5202] ppid=5201 vsize=343764 CPUtime=298.81 /proc/5202/stat : 5202 (cupt) R 5201 5202 17872 34816 17872 4202496 128462 7199 0 0 29790 85 4 2 20 0 1 0 30777721 352014336 62724 18446744073709551615 4194304 5184042 140735646545744 140735646539160 140496254145942 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5202/statm: 85941 62724 851 242 0 78503 0 Current children cumulated CPU time (s) 298.81 Current children cumulated vsize (KiB) 343764 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.023 CPU time (s): 298.851 CPU user time (s): 297.955 CPU system time (s): 0.896056 CPU usage (%): 99.6092 Max. virtual memory (cumulated for all children) (KiB): 463520 getrusage(RUSAGE_CHILDREN,...) data: user time used= 297.955 system time used= 0.896056 maximum resident set size= 306144 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 135661 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= 4381 runsolver used 0.424026 second user time and 0.780048 second system time The end