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/rand440.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand440.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand440.cudf.dudf-random.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.04 1.00 4/37 23564 /proc/meminfo: memFree=704224/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2588 CPUtime=0 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 18 0 1 0 62586477 2650112 279 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/23563/statm: 647 279 234 194 0 34 0 [pid=23564] ppid=23563 vsize=2588 CPUtime=0.01 /proc/23564/stat : 23564 (aspcud-1.5) R 23563 23563 19908 34817 19908 4202560 24 0 0 0 0 1 0 0 25 0 1 0 62586477 2650112 61 1283457024 134512640 135304128 4294351248 18446744073709551615 4158799520 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/23564/statm: 647 61 15 194 0 34 0 [startup+0.153974 s] /proc/loadavg: 1.00 1.04 1.00 4/37 23564 /proc/meminfo: memFree=704224/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=0.01 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 1520 0 0 0 0 0 1 25 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.205996 s] /proc/loadavg: 1.00 1.04 1.00 4/37 23564 /proc/meminfo: memFree=704224/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=0.01 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 1520 0 0 0 0 0 1 25 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.305979 s] /proc/loadavg: 1.00 1.04 1.00 4/37 23564 /proc/meminfo: memFree=704224/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=0.01 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 1520 0 0 0 0 0 1 25 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.706013 s] /proc/loadavg: 1.00 1.04 1.00 4/37 23564 /proc/meminfo: memFree=704224/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=0.01 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 1520 0 0 0 0 0 1 25 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50607 s] /proc/loadavg: 1.00 1.04 1.00 2/40 23574 /proc/meminfo: memFree=672452/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=0.01 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 1520 0 0 0 0 0 1 25 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=1924 CPUtime=0 /proc/23572/stat : 23572 (clasp) S 23563 23563 19908 34817 19908 4202496 292 0 0 0 0 0 0 0 25 0 1 0 62586478 1970176 159 1283457024 134512640 136285277 4289047632 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/23572/statm: 481 159 144 433 0 46 0 [pid=23573] ppid=23563 vsize=2584 CPUtime=0 /proc/23573/stat : 23573 (gringo) S 23563 23563 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 62586478 2646016 272 1283457024 134512640 136933539 4286884544 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/23573/statm: 646 272 242 592 0 51 0 [pid=23574] ppid=23563 vsize=27484 CPUtime=1.3 /proc/23574/stat : 23574 (cudf2lp) R 23563 23563 19908 34817 19908 4202496 7666 0 0 0 129 1 0 0 25 0 1 0 62586478 28143616 6164 1283457024 134512640 135786343 4287126288 18446744073709551615 135199569 0 0 6 0 0 0 0 17 0 0 0 0 /proc/23574/statm: 6871 6164 128 311 0 6558 0 Current children cumulated CPU time (s) 1.31 Current children cumulated vsize (KiB) 34588 [startup+3.10937 s] /proc/loadavg: 1.00 1.04 1.00 2/40 23574 /proc/meminfo: memFree=630948/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.18 /proc/23563/stat : 23563 (aspcud-1.5) R 23562 23563 19908 34817 19908 4202496 580 15027 0 0 0 0 214 4 19 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=5780 CPUtime=0.54 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 1348 0 0 0 54 0 0 0 18 0 1 0 62586478 5918720 1215 1283457024 134512640 136285277 4289047632 18446744073709551615 134734261 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 1445 1215 234 433 0 1010 0 [pid=23573] ppid=23563 vsize=0 CPUtime=0.11 /proc/23573/stat : 23573 (gringo) Z 23563 23563 19908 34817 19908 4202508 1456 0 0 0 11 0 0 0 18 0 1 0 62586478 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/23573/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.83 Current children cumulated vsize (KiB) 8376 [startup+6.31002 s] /proc/loadavg: 1.00 1.04 1.00 2/38 23574 /proc/meminfo: memFree=670288/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=8300 CPUtime=3.73 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 1988 0 0 0 372 1 0 0 25 0 1 0 62586478 8499200 1854 1283457024 134512640 136285277 4289047632 18446744073709551615 134959529 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 2075 1854 234 433 0 1640 0 Current children cumulated CPU time (s) 6.03 Current children cumulated vsize (KiB) 10896 [startup+12.7115 s] /proc/loadavg: 1.00 1.04 1.00 2/38 23574 /proc/meminfo: memFree=669676/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=8680 CPUtime=10.13 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 2168 0 0 0 1012 1 0 0 25 0 1 0 62586478 8888320 1965 1283457024 134512640 136285277 4289047632 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 2170 1965 234 433 0 1735 0 Current children cumulated CPU time (s) 12.43 Current children cumulated vsize (KiB) 11276 [startup+25.5139 s] /proc/loadavg: 1.00 1.03 1.00 2/38 23574 /proc/meminfo: memFree=668932/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=9488 CPUtime=22.92 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 2383 0 0 0 2291 1 0 0 25 0 1 0 62586478 9715712 2153 1283457024 134512640 136285277 4289047632 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 2372 2153 234 433 0 1937 0 Current children cumulated CPU time (s) 25.22 Current children cumulated vsize (KiB) 12084 [startup+51.11 s] /proc/loadavg: 1.00 1.03 1.00 2/38 23574 /proc/meminfo: memFree=668064/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=10276 CPUtime=48.5 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 2632 0 0 0 4849 1 0 0 25 0 1 0 62586478 10522624 2361 1283457024 134512640 136285277 4289047632 18446744073709551615 134959886 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 2569 2361 234 433 0 2134 0 Current children cumulated CPU time (s) 50.8 Current children cumulated vsize (KiB) 12872 [startup+102.312 s] /proc/loadavg: 1.00 1.02 1.00 2/40 23579 /proc/meminfo: memFree=666056/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=12068 CPUtime=99.66 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 3606 0 0 0 9964 2 0 0 25 0 1 0 62586478 12357632 2797 1283457024 134512640 136285277 4289047632 18446744073709551615 134955177 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 3017 2797 234 433 0 2582 0 Current children cumulated CPU time (s) 101.96 Current children cumulated vsize (KiB) 14664 [startup+162.305 s] /proc/loadavg: 1.00 1.02 1.00 2/40 23585 /proc/meminfo: memFree=665312/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=12764 CPUtime=159.61 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 3840 0 0 0 15958 3 0 0 25 0 1 0 62586478 13070336 2971 1283457024 134512640 136285277 4289047632 18446744073709551615 134669906 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 3191 2971 234 433 0 2756 0 Current children cumulated CPU time (s) 161.91 Current children cumulated vsize (KiB) 15360 [startup+222.307 s] /proc/loadavg: 1.00 1.01 1.00 2/39 23585 /proc/meminfo: memFree=665328/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=12764 CPUtime=219.56 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 3850 0 0 0 21952 4 0 0 25 0 1 0 62586478 13070336 2981 1283457024 134512640 136285277 4289047632 18446744073709551615 134930683 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 3191 2981 234 433 0 2756 0 Current children cumulated CPU time (s) 221.86 Current children cumulated vsize (KiB) 15360 [startup+282.312 s] /proc/loadavg: 1.00 1.01 1.00 2/38 23585 /proc/meminfo: memFree=665088/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=13092 CPUtime=279.54 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 3978 0 0 0 27949 5 0 0 25 0 1 0 62586478 13406208 3066 1283457024 134512640 136285277 4289047632 18446744073709551615 134955659 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 3273 3066 234 433 0 2838 0 Current children cumulated CPU time (s) 281.84 Current children cumulated vsize (KiB) 15688 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.514 s] /proc/loadavg: 1.00 1.00 1.00 2/38 23585 /proc/meminfo: memFree=664840/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=13220 CPUtime=287.73 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 4207 0 0 0 28768 5 0 0 25 0 1 0 62586478 13537280 3100 1283457024 134512640 136285277 4289047632 18446744073709551615 134735727 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 3305 3100 234 433 0 2870 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 15816 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.514 s] /proc/loadavg: 1.00 1.00 1.00 2/38 23585 /proc/meminfo: memFree=664840/1048576 swapFree=0/0 [pid=23563] ppid=23562 vsize=2596 CPUtime=2.3 /proc/23563/stat : 23563 (aspcud-1.5) S 23562 23563 19908 34817 19908 4202496 580 16483 0 0 0 0 226 4 17 0 1 0 62586477 2658304 298 1283457024 134512640 135304128 4294351248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23563/statm: 649 298 251 194 0 36 0 [pid=23572] ppid=23563 vsize=13220 CPUtime=287.73 /proc/23572/stat : 23572 (clasp) R 23563 23563 19908 34817 19908 4202496 4207 0 0 0 28768 5 0 0 25 0 1 0 62586478 13537280 3100 1283457024 134512640 136285277 4289047632 18446744073709551615 134735727 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23572/statm: 3305 3100 234 433 0 2870 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 15816 Child status: 0 Real time (s): 290.536 CPU time (s): 290.066 CPU user time (s): 289.946 CPU system time (s): 0.120007 CPU usage (%): 99.8384 Max. virtual memory (cumulated for all children) (KiB): 54456 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.946 system time used= 0.120007 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 24851 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= 224 involuntary context switches= 3786 runsolver used 0 second user time and 0 second system time The end