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/201108311143/aspcud-1.5/adf7b774-9af8-11df-bc37-00163e46d37a.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//adf7b774-9af8-11df-bc37-00163e46d37a.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/adf7b774-9af8-11df-bc37-00163e46d37a.cudf.dudf-real.result -sum(installedsize) 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.00 1.00 1.00 5/35 32624 /proc/meminfo: memFree=734784/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2588 CPUtime=0 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 18 0 1 0 67166272 2650112 279 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/32622/statm: 647 279 234 194 0 34 0 [pid=32623] ppid=32622 vsize=2588 CPUtime=0 /proc/32623/stat : 32623 (aspcud-1.5) R 32622 32622 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 67166272 2650112 132 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/32623/statm: 647 132 86 194 0 34 0 [pid=32624] ppid=32623 vsize=2588 CPUtime=0 /proc/32624/stat : 32624 (aspcud-1.5) R 32623 32622 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67166272 2650112 46 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/32624/statm: 647 46 0 194 0 34 0 [startup+0.202786 s] /proc/loadavg: 1.00 1.00 1.00 5/35 32624 /proc/meminfo: memFree=734784/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=0 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 1524 0 0 0 0 0 0 25 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306705 s] /proc/loadavg: 1.00 1.00 1.00 5/35 32624 /proc/meminfo: memFree=734784/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=0 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 1524 0 0 0 0 0 0 25 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.406717 s] /proc/loadavg: 1.00 1.00 1.00 5/35 32624 /proc/meminfo: memFree=734784/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=0 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 1524 0 0 0 0 0 0 25 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.70675 s] /proc/loadavg: 1.00 1.00 1.00 5/35 32624 /proc/meminfo: memFree=734784/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=0 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 1524 0 0 0 0 0 0 25 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50995 s] /proc/loadavg: 1.00 1.00 1.00 2/39 32635 /proc/meminfo: memFree=694552/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=0 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 1524 0 0 0 0 0 0 25 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=1924 CPUtime=0 /proc/32631/stat : 32631 (clasp) S 32622 32622 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 67166273 1970176 159 1283457024 134512640 136285277 4293771472 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/32631/statm: 481 159 144 433 0 46 0 [pid=32632] ppid=32622 vsize=2584 CPUtime=0 /proc/32632/stat : 32632 (gringo) S 32622 32622 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 67166273 2646016 272 1283457024 134512640 136933539 4293646640 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/32632/statm: 646 272 242 592 0 51 0 [pid=32633] ppid=32622 vsize=36876 CPUtime=1.25 /proc/32633/stat : 32633 (cudf2lp) R 32622 32622 19908 34817 19908 4202496 10260 0 0 0 119 6 0 0 25 0 1 0 67166273 37761024 8613 1283457024 134512640 135786343 4293771616 18446744073709551615 135208406 0 0 6 0 0 0 0 17 0 0 0 0 /proc/32633/statm: 9219 8613 135 311 0 8906 0 Current children cumulated CPU time (s) 1.25 Current children cumulated vsize (KiB) 43980 [startup+3.11039 s] /proc/loadavg: 1.00 1.00 1.00 2/37 32635 /proc/meminfo: memFree=704952/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=13860 CPUtime=0.89 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 3946 0 0 0 87 2 0 0 19 0 1 0 67166273 14192640 3257 1283457024 134512640 136285277 4293771472 18446744073709551615 134669852 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 3465 3257 234 433 0 3030 0 Current children cumulated CPU time (s) 2.83 Current children cumulated vsize (KiB) 16456 [startup+6.31114 s] /proc/loadavg: 1.00 1.00 1.00 2/37 32635 /proc/meminfo: memFree=689220/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=30544 CPUtime=4.08 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 8108 0 0 0 404 4 0 0 25 0 1 0 67166273 31277056 7419 1283457024 134512640 136285277 4293771472 18446744073709551615 134930743 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 7636 7419 234 433 0 7201 0 Current children cumulated CPU time (s) 6.02 Current children cumulated vsize (KiB) 33140 [startup+12.7124 s] /proc/loadavg: 1.00 1.00 1.00 2/37 32636 /proc/meminfo: memFree=678432/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=41568 CPUtime=10.48 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 10779 0 0 0 1042 6 0 0 25 0 1 0 67166273 42565632 10090 1283457024 134512640 136285277 4293771472 18446744073709551615 134649439 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 10392 10090 234 433 0 9957 0 Current children cumulated CPU time (s) 12.42 Current children cumulated vsize (KiB) 44164 [startup+25.5052 s] /proc/loadavg: 1.00 1.00 1.00 2/37 32637 /proc/meminfo: memFree=665164/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=52436 CPUtime=23.26 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 13486 0 0 0 2320 6 0 0 25 0 1 0 67166273 53694464 12797 1283457024 134512640 136285277 4293771472 18446744073709551615 134639147 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 13109 12797 234 433 0 12674 0 Current children cumulated CPU time (s) 25.2 Current children cumulated vsize (KiB) 55032 [startup+51.1119 s] /proc/loadavg: 1.00 1.00 1.00 2/37 32639 /proc/meminfo: memFree=658096/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=59316 CPUtime=48.85 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 15412 0 0 0 4877 8 0 0 25 0 1 0 67166273 60739584 14545 1283457024 134512640 136285277 4293771472 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 14829 14545 234 433 0 14394 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 61912 [startup+102.314 s] /proc/loadavg: 1.00 1.00 1.00 2/36 32644 /proc/meminfo: memFree=650796/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=66580 CPUtime=100.01 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 17675 0 0 0 9993 8 0 0 25 0 1 0 67166273 68177920 16366 1283457024 134512640 136285277 4293771472 18446744073709551615 134930706 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 16645 16366 234 433 0 16210 0 Current children cumulated CPU time (s) 101.95 Current children cumulated vsize (KiB) 69176 [startup+162.308 s] /proc/loadavg: 1.00 1.00 1.00 2/35 32644 /proc/meminfo: memFree=650432/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=66304 CPUtime=159.96 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 17774 0 0 0 15987 9 0 0 25 0 1 0 67166273 67895296 16317 1283457024 134512640 136285277 4293771472 18446744073709551615 134734701 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 16576 16317 234 433 0 16141 0 Current children cumulated CPU time (s) 161.9 Current children cumulated vsize (KiB) 68900 [startup+222.313 s] /proc/loadavg: 1.00 1.00 1.00 2/35 32644 /proc/meminfo: memFree=640512/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=76888 CPUtime=219.92 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 20394 0 0 0 21983 9 0 0 25 0 1 0 67166273 78733312 18937 1283457024 134512640 136285277 4293771472 18446744073709551615 134667747 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 19222 18937 234 433 0 18787 0 Current children cumulated CPU time (s) 221.86 Current children cumulated vsize (KiB) 79484 [startup+282.305 s] /proc/loadavg: 1.00 1.00 1.00 2/35 32644 /proc/meminfo: memFree=640512/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=76888 CPUtime=279.87 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 20395 0 0 0 27978 9 0 0 25 0 1 0 67166273 78733312 18938 1283457024 134512640 136285277 4293771472 18446744073709551615 134965218 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 19222 18938 234 433 0 18787 0 Current children cumulated CPU time (s) 281.81 Current children cumulated vsize (KiB) 79484 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.507 s] /proc/loadavg: 1.00 1.00 1.00 2/35 32644 /proc/meminfo: memFree=640512/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=76888 CPUtime=288.07 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 20395 0 0 0 28798 9 0 0 25 0 1 0 67166273 78733312 18938 1283457024 134512640 136285277 4293771472 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 19222 18938 234 433 0 18787 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 79484 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.507 s] /proc/loadavg: 1.00 1.00 1.00 2/35 32644 /proc/meminfo: memFree=640512/1048576 swapFree=0/0 [pid=32622] ppid=32621 vsize=2596 CPUtime=1.94 /proc/32622/stat : 32622 (aspcud-1.5) S 32621 32622 19908 34817 19908 4202496 575 17583 0 0 0 0 186 8 17 0 1 0 67166272 2658304 298 1283457024 134512640 135304128 4290960912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32622/statm: 649 298 251 194 0 36 0 [pid=32631] ppid=32622 vsize=76888 CPUtime=288.07 /proc/32631/stat : 32631 (clasp) R 32622 32622 19908 34817 19908 4202496 20395 0 0 0 28798 9 0 0 25 0 1 0 67166273 78733312 18938 1283457024 134512640 136285277 4293771472 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/32631/statm: 19222 18938 234 433 0 18787 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 79484 Child status: 0 Real time (s): 290.546 CPU time (s): 290.058 CPU user time (s): 289.854 CPU system time (s): 0.204012 CPU usage (%): 99.832 Max. virtual memory (cumulated for all children) (KiB): 79484 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.854 system time used= 0.204012 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 42232 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= 604 involuntary context switches= 3973 runsolver used 0 second user time and 0.012 second system time The end