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/688250e8-4bb4-11df-a561-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aspcud-1.3 /home/misc2010/data/2010/debian-dudf//688250e8-4bb4-11df-a561-00163e7a6f5e.cudf /home/misc2010/tmp/201012091704/aspcud-1.3/688250e8-4bb4-11df-a561-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.07 1.07 1.02 5/40 6538 /proc/meminfo: memFree=351032/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2588 CPUtime=0 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 376 0 0 0 0 0 0 0 18 0 1 0 901395960 2650112 282 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/6536/statm: 647 282 237 194 0 33 0 [pid=6537] ppid=6536 vsize=2588 CPUtime=0 /proc/6537/stat : 6537 (aspcud-1.3) S 6536 6536 25521 34816 2180 4202560 113 0 0 0 0 0 0 0 25 0 1 0 901395960 2650112 129 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/6537/statm: 647 129 83 194 0 33 0 [pid=6538] ppid=6537 vsize=2588 CPUtime=0 /proc/6538/stat : 6538 (aspcud-1.3) R 6537 6536 25521 34816 2180 4202560 125 0 0 0 0 0 0 0 25 0 1 0 901395960 2650112 149 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/6538/statm: 647 149 103 194 0 33 0 [pid=6539] ppid=6538 vsize=2588 CPUtime=0 /proc/6539/stat : 6539 (aspcud-1.3) R 6538 6536 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 901395960 2650112 46 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/6539/statm: 647 46 0 194 0 33 0 [startup+0.172797 s] /proc/loadavg: 1.07 1.07 1.02 5/40 6538 /proc/meminfo: memFree=351032/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=0 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 575 1505 0 0 0 0 0 0 25 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.202817 s] /proc/loadavg: 1.07 1.07 1.02 5/40 6538 /proc/meminfo: memFree=351032/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=0 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 575 1505 0 0 0 0 0 0 25 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.312816 s] /proc/loadavg: 1.07 1.07 1.02 5/40 6538 /proc/meminfo: memFree=351032/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=0 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 575 1505 0 0 0 0 0 0 25 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.712889 s] /proc/loadavg: 1.07 1.07 1.02 5/40 6538 /proc/meminfo: memFree=351032/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=0 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 575 1505 0 0 0 0 0 0 25 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.51304 s] /proc/loadavg: 1.07 1.07 1.02 2/42 6547 /proc/meminfo: memFree=308968/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=0 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 575 1505 0 0 0 0 0 0 25 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=6176 CPUtime=0.03 /proc/6545/stat : 6545 (clasp) S 6536 6536 25521 34816 2180 4202496 1477 0 0 0 2 1 0 0 18 0 1 0 901395961 6324224 1263 1283457024 134512640 136223643 4289953072 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6545/statm: 1544 1263 174 418 0 1124 0 [pid=6546] ppid=6536 vsize=9200 CPUtime=0.22 /proc/6546/stat : 6546 (gringo) S 6536 6536 25521 34816 2180 4202496 2414 0 0 0 20 2 0 0 18 0 1 0 901395961 9420800 1507 1283457024 134512640 136959103 4287964112 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6546/statm: 2300 1507 247 598 0 1699 0 [pid=6547] ppid=6536 vsize=40872 CPUtime=1.24 /proc/6547/stat : 6547 (cudf2lp) R 6536 6536 25521 34816 2180 4202496 13294 0 0 0 118 6 0 0 25 0 1 0 901395961 41852928 10025 1283457024 134512640 135749571 4288382000 18446744073709551615 134564313 0 0 6 0 0 0 0 17 0 0 0 0 /proc/6547/statm: 10218 10025 132 302 0 9914 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 58844 [startup+3.10343 s] /proc/loadavg: 1.07 1.07 1.02 3/42 6547 /proc/meminfo: memFree=280820/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=1.57 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 14802 0 0 0 0 149 8 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=33072 CPUtime=0.23 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 9331 0 0 0 18 5 0 0 18 0 1 0 901395961 33865728 7831 1283457024 134512640 136223643 4289953072 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 8268 7831 174 418 0 7848 0 [pid=6546] ppid=6536 vsize=53424 CPUtime=1.27 /proc/6546/stat : 6546 (gringo) R 6536 6536 25521 34816 2180 4202496 15786 0 0 0 116 11 0 0 18 0 1 0 901395961 54706176 11025 1283457024 134512640 136959103 4287964112 18446744073709551615 136227567 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6546/statm: 13356 11025 256 598 0 12755 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 89092 [startup+6.30438 s] /proc/loadavg: 1.06 1.07 1.02 2/40 6547 /proc/meminfo: memFree=297096/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=58696 CPUtime=2.85 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 17120 0 0 0 276 9 0 0 21 0 1 0 901395961 60104704 13553 1283457024 134512640 136223643 4289953072 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 14674 13553 225 418 0 14254 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 61292 [startup+12.7064 s] /proc/loadavg: 1.06 1.07 1.01 2/40 6547 /proc/meminfo: memFree=289036/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=70628 CPUtime=9.24 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 20083 0 0 0 912 12 0 0 25 0 1 0 901395961 72323072 16516 1283457024 134512640 136223643 4289953072 18446744073709551615 134615552 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 17657 16516 225 418 0 17237 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 73224 [startup+25.5103 s] /proc/loadavg: 1.04 1.06 1.01 2/40 6547 /proc/meminfo: memFree=239808/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=116516 CPUtime=22.04 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 31528 0 0 0 2184 20 0 0 25 0 1 0 901395961 119312384 27961 1283457024 134512640 136223643 4289953072 18446744073709551615 134650405 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 29129 27961 225 418 0 28709 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 119112 [startup+51.1082 s] /proc/loadavg: 1.03 1.06 1.01 2/40 6547 /proc/meminfo: memFree=239684/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=116516 CPUtime=47.63 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 31553 0 0 0 4743 20 0 0 25 0 1 0 901395961 119312384 27986 1283457024 134512640 136223643 4289953072 18446744073709551615 134924494 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 29129 27986 225 418 0 28709 0 Current children cumulated CPU time (s) 51.05 Current children cumulated vsize (KiB) 119112 [startup+102.314 s] /proc/loadavg: 1.01 1.05 1.01 2/40 6547 /proc/meminfo: memFree=194424/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=161704 CPUtime=98.78 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 42816 0 0 0 9850 28 0 0 25 0 1 0 901395961 165584896 39249 1283457024 134512640 136223643 4289953072 18446744073709551615 134711793 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 40426 39249 225 418 0 40006 0 Current children cumulated CPU time (s) 102.2 Current children cumulated vsize (KiB) 164300 [startup+162.311 s] /proc/loadavg: 1.00 1.03 1.00 2/40 6547 /proc/meminfo: memFree=159084/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=196864 CPUtime=158.73 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 51598 0 0 0 15836 37 0 0 25 0 1 0 901395961 201588736 48031 1283457024 134512640 136223643 4289953072 18446744073709551615 134664693 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 49216 48031 225 418 0 48796 0 Current children cumulated CPU time (s) 162.15 Current children cumulated vsize (KiB) 199460 [startup+222.309 s] /proc/loadavg: 1.00 1.03 1.00 2/40 6547 /proc/meminfo: memFree=134284/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=221628 CPUtime=218.68 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 57885 0 0 0 21826 42 0 0 25 0 1 0 901395961 226947072 54213 1283457024 134512640 136223643 4289953072 18446744073709551615 134910773 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 55407 54213 225 418 0 54987 0 Current children cumulated CPU time (s) 222.1 Current children cumulated vsize (KiB) 224224 [startup+282.306 s] /proc/loadavg: 1.00 1.02 1.00 2/40 6547 /proc/meminfo: memFree=5776/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=356976 CPUtime=278.35 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 91945 0 0 0 27771 64 0 0 25 0 1 0 901395961 365543424 87980 1283457024 134512640 136223643 4289953072 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 89244 87980 225 418 0 88824 0 Current children cumulated CPU time (s) 281.77 Current children cumulated vsize (KiB) 359572 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.608 s] /proc/loadavg: 1.00 1.02 1.00 2/40 6547 /proc/meminfo: memFree=5776/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=356976 CPUtime=286.65 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 91945 0 0 0 28601 64 0 0 25 0 1 0 901395961 365543424 87980 1283457024 134512640 136223643 4289953072 18446744073709551615 134664711 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 89244 87980 225 418 0 88824 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 359572 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.608 s] /proc/loadavg: 1.00 1.02 1.00 2/40 6547 /proc/meminfo: memFree=5776/1048576 swapFree=2095372/2097144 [pid=6536] ppid=6535 vsize=2596 CPUtime=3.42 /proc/6536/stat : 6536 (aspcud-1.3) S 6535 6536 25521 34816 2180 4202496 576 33428 0 0 0 0 317 25 18 0 1 0 901395960 2658304 300 1283457024 134512640 135304128 4292790208 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6536/statm: 649 300 253 194 0 35 0 [pid=6545] ppid=6536 vsize=356976 CPUtime=286.65 /proc/6545/stat : 6545 (clasp) R 6536 6536 25521 34816 2180 4202496 91945 0 0 0 28601 64 0 0 25 0 1 0 901395961 365543424 87980 1283457024 134512640 136223643 4289953072 18446744073709551615 134664711 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6545/statm: 89244 87980 225 418 0 88824 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 359572 Child status: 0 Real time (s): 290.655 CPU time (s): 290.13 CPU user time (s): 289.202 CPU system time (s): 0.928058 CPU usage (%): 99.8193 Max. virtual memory (cumulated for all children) (KiB): 359572 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.202 system time used= 0.928058 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 128571 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= 2929 involuntary context switches= 5941 runsolver used 0.012 second user time and 0 second system time The end