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/b2540c52-51b7-11e0-aa4f-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//b2540c52-51b7-11e0-aa4f-00163e1e087d.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/b2540c52-51b7-11e0-aa4f-00163e1e087d.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/36 331 /proc/meminfo: memFree=714392/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2588 CPUtime=0 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 25 0 1 0 67254026 2650112 280 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/330/statm: 647 280 234 194 0 34 0 [pid=331] ppid=330 vsize=2588 CPUtime=0 /proc/331/stat : 331 (aspcud-1.5) R 330 330 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 67254026 2650112 133 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/331/statm: 647 133 86 194 0 34 0 [pid=332] ppid=331 vsize=2588 CPUtime=0 /proc/332/stat : 332 (aspcud-1.5) R 331 330 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67254026 2650112 47 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/332/statm: 647 47 0 194 0 34 0 [startup+0.122368 s] /proc/loadavg: 1.00 1.00 1.00 5/36 331 /proc/meminfo: memFree=714392/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=0 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 1519 0 0 0 0 0 0 25 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206377 s] /proc/loadavg: 1.00 1.00 1.00 5/36 331 /proc/meminfo: memFree=714392/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=0 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 1519 0 0 0 0 0 0 25 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.30639 s] /proc/loadavg: 1.00 1.00 1.00 5/36 331 /proc/meminfo: memFree=714392/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=0 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 1519 0 0 0 0 0 0 25 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.707785 s] /proc/loadavg: 1.00 1.00 1.00 5/36 331 /proc/meminfo: memFree=714392/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=0 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 1519 0 0 0 0 0 0 25 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.51161 s] /proc/loadavg: 1.00 1.00 1.00 2/39 341 /proc/meminfo: memFree=675244/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=0 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 1519 0 0 0 0 0 0 25 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=2472 CPUtime=0 /proc/339/stat : 339 (clasp) S 330 330 19908 34817 19908 4202496 456 0 0 0 0 0 0 0 18 0 1 0 67254027 2531328 323 1283457024 134512640 136285277 4288756752 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/339/statm: 618 323 176 433 0 183 0 [pid=340] ppid=330 vsize=3596 CPUtime=0.02 /proc/340/stat : 340 (gringo) S 330 330 19908 34817 19908 4202496 631 0 0 0 2 0 0 0 18 0 1 0 67254027 3682304 465 1283457024 134512640 136933539 4287429440 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/340/statm: 899 465 242 592 0 304 0 [pid=341] ppid=330 vsize=32744 CPUtime=1.3 /proc/341/stat : 341 (cudf2lp) R 330 330 19908 34817 19908 4202496 10541 0 0 0 128 2 0 0 25 0 1 0 67254027 33529856 7988 1283457024 134512640 135786343 4289281296 18446744073709551615 135191469 0 0 6 0 0 0 0 17 0 0 0 0 /proc/341/statm: 8186 7988 139 311 0 7873 0 Current children cumulated CPU time (s) 1.32 Current children cumulated vsize (KiB) 41408 [startup+3.11182 s] /proc/loadavg: 1.08 1.02 1.01 3/38 341 /proc/meminfo: memFree=695292/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=3636 CPUtime=1.53 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 821 0 0 0 153 0 0 0 20 0 1 0 67254027 3723264 688 1283457024 134512640 136285277 4288756752 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 909 688 233 433 0 474 0 Current children cumulated CPU time (s) 2.92 Current children cumulated vsize (KiB) 6232 [startup+6.31231 s] /proc/loadavg: 1.08 1.02 1.01 2/37 341 /proc/meminfo: memFree=695052/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=4164 CPUtime=4.73 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 950 0 0 0 473 0 0 0 25 0 1 0 67254027 4263936 817 1283457024 134512640 136285277 4288756752 18446744073709551615 134959535 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1041 817 234 433 0 606 0 Current children cumulated CPU time (s) 6.12 Current children cumulated vsize (KiB) 6760 [startup+12.7136 s] /proc/loadavg: 1.07 1.02 1.00 2/37 342 /proc/meminfo: memFree=694688/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=4372 CPUtime=11.12 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1001 0 0 0 1112 0 0 0 25 0 1 0 67254027 4476928 868 1283457024 134512640 136285277 4288756752 18446744073709551615 134966761 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1093 868 234 433 0 658 0 Current children cumulated CPU time (s) 12.51 Current children cumulated vsize (KiB) 6968 [startup+25.5062 s] /proc/loadavg: 1.06 1.01 1.00 2/37 343 /proc/meminfo: memFree=694192/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=4828 CPUtime=23.89 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1122 0 0 0 2389 0 0 0 25 0 1 0 67254027 4943872 989 1283457024 134512640 136285277 4288756752 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1207 989 234 433 0 772 0 Current children cumulated CPU time (s) 25.28 Current children cumulated vsize (KiB) 7424 [startup+51.1114 s] /proc/loadavg: 1.04 1.01 1.00 2/36 343 /proc/meminfo: memFree=694084/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=4940 CPUtime=49.47 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1189 0 0 0 4947 0 0 0 25 0 1 0 67254027 5058560 1030 1283457024 134512640 136285277 4288756752 18446744073709551615 134930658 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1235 1030 234 433 0 800 0 Current children cumulated CPU time (s) 50.86 Current children cumulated vsize (KiB) 7536 [startup+102.312 s] /proc/loadavg: 1.01 1.01 1.00 2/35 343 /proc/meminfo: memFree=693720/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=5332 CPUtime=100.65 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1306 0 0 0 10065 0 0 0 25 0 1 0 67254027 5459968 1108 1283457024 134512640 136285277 4288756752 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1333 1108 234 433 0 898 0 Current children cumulated CPU time (s) 102.04 Current children cumulated vsize (KiB) 7928 [startup+162.305 s] /proc/loadavg: 1.00 1.00 1.00 2/35 343 /proc/meminfo: memFree=693472/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=5632 CPUtime=160.62 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1387 0 0 0 16062 0 0 0 25 0 1 0 67254027 5767168 1186 1283457024 134512640 136285277 4288756752 18446744073709551615 134652278 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1408 1186 234 433 0 973 0 Current children cumulated CPU time (s) 162.01 Current children cumulated vsize (KiB) 8228 [startup+222.307 s] /proc/loadavg: 1.00 1.00 1.00 2/35 343 /proc/meminfo: memFree=693348/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=5632 CPUtime=220.6 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1397 0 0 0 22060 0 0 0 25 0 1 0 67254027 5767168 1196 1283457024 134512640 136285277 4288756752 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1408 1196 234 433 0 973 0 Current children cumulated CPU time (s) 221.99 Current children cumulated vsize (KiB) 8228 [startup+282.308 s] /proc/loadavg: 1.00 1.00 1.00 2/35 343 /proc/meminfo: memFree=693348/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=5700 CPUtime=280.58 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1412 0 0 0 28058 0 0 0 25 0 1 0 67254027 5836800 1211 1283457024 134512640 136285277 4288756752 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1425 1211 234 433 0 990 0 Current children cumulated CPU time (s) 281.97 Current children cumulated vsize (KiB) 8296 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.41 s] /proc/loadavg: 1.00 1.00 1.00 2/35 343 /proc/meminfo: memFree=693348/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=5700 CPUtime=288.67 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1412 0 0 0 28867 0 0 0 25 0 1 0 67254027 5836800 1211 1283457024 134512640 136285277 4288756752 18446744073709551615 134959554 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1425 1211 234 433 0 990 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 8296 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.41 s] /proc/loadavg: 1.00 1.00 1.00 2/35 343 /proc/meminfo: memFree=693348/1048576 swapFree=0/0 [pid=330] ppid=329 vsize=2596 CPUtime=1.39 /proc/330/stat : 330 (aspcud-1.5) S 329 330 19908 34817 19908 4202496 580 13078 0 0 0 0 137 2 17 0 1 0 67254026 2658304 299 1283457024 134512640 135304128 4288238464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/330/statm: 649 299 251 194 0 36 0 [pid=339] ppid=330 vsize=5700 CPUtime=288.67 /proc/339/stat : 339 (clasp) R 330 330 19908 34817 19908 4202496 1412 0 0 0 28867 0 0 0 25 0 1 0 67254027 5836800 1211 1283457024 134512640 136285277 4288756752 18446744073709551615 134959554 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/339/statm: 1425 1211 234 433 0 990 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 8296 Child status: 0 Real time (s): 290.432 CPU time (s): 290.106 CPU user time (s): 290.062 CPU system time (s): 0.044002 CPU usage (%): 99.8877 Max. virtual memory (cumulated for all children) (KiB): 41408 getrusage(RUSAGE_CHILDREN,...) data: user time used= 290.062 system time used= 0.044002 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 18631 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= 161 involuntary context switches= 3654 runsolver used 0.012 second user time and 0 second system time The end