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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012091704/aspcud-1.3/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aspcud-1.3 /home/misc2010/data/2010/debian-dudf//218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf /home/misc2010/tmp/201012091704/aspcud-1.3/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.result -changed,-notuptodate,-removed,-new Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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.10 0.98 0.86 5/39 3173 /proc/meminfo: memFree=597320/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2588 CPUtime=0 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 374 0 0 0 0 0 0 0 18 0 1 0 900883399 2650112 281 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/3171/statm: 647 281 237 194 0 33 0 [pid=3172] ppid=3171 vsize=2588 CPUtime=0 /proc/3172/stat : 3172 (aspcud-1.3) R 3171 3171 25521 34816 2180 4202560 105 0 0 0 0 0 0 0 25 0 1 0 900883399 2650112 127 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/3172/statm: 647 127 82 194 0 33 0 [pid=3173] ppid=3172 vsize=2588 CPUtime=0 /proc/3173/stat : 3173 (aspcud-1.3) R 3172 3171 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 900883399 2650112 45 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/3173/statm: 647 45 0 194 0 33 0 [startup+0.122714 s] /proc/loadavg: 1.10 0.98 0.86 5/39 3173 /proc/meminfo: memFree=597320/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=0 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 574 1507 0 0 0 0 0 0 25 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.212744 s] /proc/loadavg: 1.10 0.98 0.86 5/39 3173 /proc/meminfo: memFree=597320/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=0 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 574 1507 0 0 0 0 0 0 25 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.302755 s] /proc/loadavg: 1.10 0.98 0.86 5/39 3173 /proc/meminfo: memFree=597320/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=0 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 574 1507 0 0 0 0 0 0 25 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.702845 s] /proc/loadavg: 1.10 0.98 0.86 5/39 3173 /proc/meminfo: memFree=597320/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=0 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 574 1507 0 0 0 0 0 0 25 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50305 s] /proc/loadavg: 1.10 0.98 0.86 2/41 3182 /proc/meminfo: memFree=555256/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=0 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 574 1507 0 0 0 0 0 0 25 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=6312 CPUtime=0.02 /proc/3180/stat : 3180 (clasp) S 3171 3171 25521 34816 2180 4202496 1520 0 0 0 2 0 0 0 18 0 1 0 900883400 6463488 1307 1283457024 134512640 136223643 4292134736 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3180/statm: 1578 1307 174 418 0 1158 0 [pid=3181] ppid=3171 vsize=9320 CPUtime=0.24 /proc/3181/stat : 3181 (gringo) R 3171 3171 25521 34816 2180 4202496 2459 0 0 0 24 0 0 0 18 0 1 0 900883400 9543680 1553 1283457024 134512640 136959103 4293431552 18446744073709551615 134977381 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3181/statm: 2330 1553 247 598 0 1729 0 [pid=3182] ppid=3171 vsize=40872 CPUtime=1.22 /proc/3182/stat : 3182 (cudf2lp) R 3171 3171 25521 34816 2180 4202496 13293 0 0 0 114 8 0 0 25 0 1 0 900883400 41852928 10025 1283457024 134512640 135749571 4291833712 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/3182/statm: 10218 10025 132 302 0 9914 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 59100 [startup+3.10343 s] /proc/loadavg: 1.10 0.98 0.86 3/41 3182 /proc/meminfo: memFree=525868/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=1.49 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 14803 0 0 0 0 138 11 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=33348 CPUtime=0.13 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 9402 0 0 0 11 2 0 0 18 0 1 0 900883400 34148352 7903 1283457024 134512640 136223643 4292134736 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 8337 7903 174 418 0 7917 0 [pid=3181] ppid=3171 vsize=53420 CPUtime=1.46 /proc/3181/stat : 3181 (gringo) R 3171 3171 25521 34816 2180 4202496 15801 0 0 0 143 3 0 0 18 0 1 0 900883400 54702080 11041 1283457024 134512640 136959103 4293431552 18446744073709551615 136161280 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3181/statm: 13355 11041 256 598 0 12754 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 89364 [startup+6.30434 s] /proc/loadavg: 1.09 0.98 0.86 2/39 3182 /proc/meminfo: memFree=543756/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=58268 CPUtime=2.84 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 16776 0 0 0 278 6 0 0 22 0 1 0 900883400 59666432 13427 1283457024 134512640 136223643 4292134736 18446744073709551615 134665081 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 14567 13427 223 418 0 14147 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 60864 [startup+12.7062 s] /proc/loadavg: 1.08 0.98 0.86 2/39 3182 /proc/meminfo: memFree=515856/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=87996 CPUtime=9.23 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 24202 0 0 0 915 8 0 0 25 0 1 0 900883400 90107904 20853 1283457024 134512640 136223643 4292134736 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 21999 20853 225 418 0 21579 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 90592 [startup+25.5103 s] /proc/loadavg: 1.06 0.98 0.86 2/39 3182 /proc/meminfo: memFree=499116/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103308 CPUtime=22.04 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28039 0 0 0 2195 9 0 0 25 0 1 0 900883400 105787392 24690 1283457024 134512640 136223643 4292134736 18446744073709551615 134924336 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25827 24690 225 418 0 25407 0 Current children cumulated CPU time (s) 25.49 Current children cumulated vsize (KiB) 105904 [startup+51.1073 s] /proc/loadavg: 1.04 0.98 0.87 2/39 3182 /proc/meminfo: memFree=499116/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103308 CPUtime=47.6 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28043 0 0 0 4751 9 0 0 25 0 1 0 900883400 105787392 24694 1283457024 134512640 136223643 4292134736 18446744073709551615 134928992 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25827 24694 225 418 0 25407 0 Current children cumulated CPU time (s) 51.05 Current children cumulated vsize (KiB) 105904 [startup+102.307 s] /proc/loadavg: 1.02 0.98 0.87 2/39 3182 /proc/meminfo: memFree=498620/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103836 CPUtime=98.8 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28152 0 0 0 9870 10 0 0 25 0 1 0 900883400 106328064 24803 1283457024 134512640 136223643 4292134736 18446744073709551615 134664680 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25959 24803 225 418 0 25539 0 Current children cumulated CPU time (s) 102.25 Current children cumulated vsize (KiB) 106432 [startup+162.307 s] /proc/loadavg: 1.00 0.98 0.88 2/39 3182 /proc/meminfo: memFree=498496/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103836 CPUtime=158.74 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28152 0 0 0 15864 10 0 0 25 0 1 0 900883400 106328064 24803 1283457024 134512640 136223643 4292134736 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25959 24803 225 418 0 25539 0 Current children cumulated CPU time (s) 162.19 Current children cumulated vsize (KiB) 106432 [startup+222.309 s] /proc/loadavg: 1.00 0.98 0.88 2/39 3182 /proc/meminfo: memFree=498496/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103836 CPUtime=218.72 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28152 0 0 0 21860 12 0 0 25 0 1 0 900883400 106328064 24803 1283457024 134512640 136223643 4292134736 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25959 24803 225 418 0 25539 0 Current children cumulated CPU time (s) 222.17 Current children cumulated vsize (KiB) 106432 [startup+282.308 s] /proc/loadavg: 1.00 0.98 0.89 2/39 3182 /proc/meminfo: memFree=498496/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103836 CPUtime=278.65 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28152 0 0 0 27853 12 0 0 25 0 1 0 900883400 106328064 24803 1283457024 134512640 136223643 4292134736 18446744073709551615 134630084 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25959 24803 225 418 0 25539 0 Current children cumulated CPU time (s) 282.1 Current children cumulated vsize (KiB) 106432 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.211 s] /proc/loadavg: 1.00 0.98 0.89 2/39 3182 /proc/meminfo: memFree=498496/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103836 CPUtime=286.55 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28152 0 0 0 28643 12 0 0 25 0 1 0 900883400 106328064 24803 1283457024 134512640 136223643 4292134736 18446744073709551615 134712495 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25959 24803 225 418 0 25539 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 106432 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.211 s] /proc/loadavg: 1.00 0.98 0.89 2/39 3182 /proc/meminfo: memFree=498496/1048576 swapFree=2095372/2097144 [pid=3171] ppid=3170 vsize=2596 CPUtime=3.45 /proc/3171/stat : 3171 (aspcud-1.3) S 3170 3171 25521 34816 2180 4202496 575 33441 0 0 0 0 330 15 18 0 1 0 900883399 2658304 299 1283457024 134512640 135304128 4287474352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3171/statm: 649 299 253 194 0 35 0 [pid=3180] ppid=3171 vsize=103836 CPUtime=286.55 /proc/3180/stat : 3180 (clasp) R 3171 3171 25521 34816 2180 4202496 28152 0 0 0 28643 12 0 0 25 0 1 0 900883400 106328064 24803 1283457024 134512640 136223643 4292134736 18446744073709551615 134712495 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3180/statm: 25959 24803 225 418 0 25539 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 106432 Child status: 0 Real time (s): 290.238 CPU time (s): 290.038 CPU user time (s): 289.75 CPU system time (s): 0.288018 CPU usage (%): 99.931 Max. virtual memory (cumulated for all children) (KiB): 109680 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.75 system time used= 0.288018 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 64781 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= 2906 involuntary context switches= 5695 runsolver used 0 second user time and 0.012 second system time The end