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/201109011757/aspcud-1.5/e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/e2f6303a-4fe9-11e0-aa4f-00163e1e087d.cudf.dudf-real.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-notuptodate,-removed,-changed 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.39 1.14 1.04 5/35 3709 /proc/meminfo: memFree=248052/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2584 CPUtime=0 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 373 0 0 0 0 0 0 0 20 0 1 0 73601095 2646016 279 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/3707/statm: 646 279 234 194 0 33 0 [pid=3708] ppid=3707 vsize=2584 CPUtime=0 /proc/3708/stat : 3708 (aspcud-1.5) R 3707 3707 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 73601095 2646016 132 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/3708/statm: 646 132 86 194 0 33 0 [pid=3709] ppid=3708 vsize=2584 CPUtime=0 /proc/3709/stat : 3709 (aspcud-1.5) R 3708 3707 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 73601096 2646016 46 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/3709/statm: 646 46 0 194 0 33 0 [startup+0.115678 s] /proc/loadavg: 1.39 1.14 1.04 5/35 3709 /proc/meminfo: memFree=248052/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=0 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.207671 s] /proc/loadavg: 1.39 1.14 1.04 5/35 3709 /proc/meminfo: memFree=248052/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=0 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.307678 s] /proc/loadavg: 1.39 1.14 1.04 5/35 3709 /proc/meminfo: memFree=248052/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=0 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.707694 s] /proc/loadavg: 1.39 1.14 1.04 5/35 3709 /proc/meminfo: memFree=248052/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=0 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.5066 s] /proc/loadavg: 1.35 1.14 1.04 2/37 3718 /proc/meminfo: memFree=208732/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=0 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=2872 CPUtime=0.02 /proc/3716/stat : 3716 (clasp) S 3707 3707 22717 34817 22717 4202496 575 0 0 0 2 0 0 0 18 0 1 0 73601096 2940928 442 1283457024 134512640 136285277 4289313936 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/3716/statm: 718 442 176 433 0 283 0 [pid=3717] ppid=3707 vsize=4144 CPUtime=0.05 /proc/3717/stat : 3717 (gringo) R 3707 3707 22717 34817 22717 4202496 811 0 0 0 3 2 0 0 18 0 1 0 73601096 4243456 580 1283457024 134512640 136933539 4293579040 18446744073709551615 135830612 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3717/statm: 1036 580 242 592 0 441 0 [pid=3718] ppid=3707 vsize=32680 CPUtime=1.25 /proc/3718/stat : 3718 (cudf2lp) R 3707 3707 22717 34817 22717 4202496 10361 0 0 0 120 5 0 0 25 0 1 0 73601097 33464320 7958 1283457024 134512640 135786343 4289219776 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/3718/statm: 8170 7958 139 311 0 7857 0 Current children cumulated CPU time (s) 1.32 Current children cumulated vsize (KiB) 42288 [startup+3.10682 s] /proc/loadavg: 1.35 1.14 1.04 3/36 3718 /proc/meminfo: memFree=200252/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=20780 CPUtime=0.91 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 6015 0 0 0 88 3 0 0 18 0 1 0 73601096 21278720 4977 1283457024 134512640 136285277 4289313936 18446744073709551615 134669863 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 5195 4977 234 433 0 4760 0 Current children cumulated CPU time (s) 2.93 Current children cumulated vsize (KiB) 23372 [startup+6.30735 s] /proc/loadavg: 1.33 1.14 1.04 2/35 3718 /proc/meminfo: memFree=207344/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=25408 CPUtime=4.1 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 7173 0 0 0 406 4 0 0 25 0 1 0 73601096 26017792 6135 1283457024 134512640 136285277 4289313936 18446744073709551615 134723317 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 6352 6135 234 433 0 5917 0 Current children cumulated CPU time (s) 6.12 Current children cumulated vsize (KiB) 28000 [startup+12.7093 s] /proc/loadavg: 1.30 1.14 1.04 2/35 3718 /proc/meminfo: memFree=207344/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=25408 CPUtime=10.5 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 7173 0 0 0 1046 4 0 0 25 0 1 0 73601096 26017792 6135 1283457024 134512640 136285277 4289313936 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 6352 6135 234 433 0 5917 0 Current children cumulated CPU time (s) 12.52 Current children cumulated vsize (KiB) 28000 [startup+25.5022 s] /proc/loadavg: 1.23 1.13 1.04 2/35 3718 /proc/meminfo: memFree=179196/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=53700 CPUtime=23.28 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 14209 0 0 0 2319 9 0 0 25 0 1 0 73601096 54988800 13171 1283457024 134512640 136285277 4289313936 18446744073709551615 134966782 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 13425 13171 234 433 0 12990 0 Current children cumulated CPU time (s) 25.3 Current children cumulated vsize (KiB) 56292 [startup+51.1114 s] /proc/loadavg: 1.15 1.12 1.03 2/35 3718 /proc/meminfo: memFree=158736/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=74112 CPUtime=48.87 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 19316 0 0 0 4875 12 0 0 25 0 1 0 73601096 75890688 18278 1283457024 134512640 136285277 4289313936 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 18528 18278 234 433 0 18093 0 Current children cumulated CPU time (s) 50.89 Current children cumulated vsize (KiB) 76704 [startup+102.316 s] /proc/loadavg: 1.06 1.10 1.03 2/35 3718 /proc/meminfo: memFree=153528/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=79260 CPUtime=100.02 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 20599 0 0 0 9989 13 0 0 25 0 1 0 73601096 81162240 19561 1283457024 134512640 136285277 4289313936 18446744073709551615 134734704 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 19815 19561 234 433 0 19380 0 Current children cumulated CPU time (s) 102.04 Current children cumulated vsize (KiB) 81852 [startup+162.313 s] /proc/loadavg: 1.02 1.08 1.02 2/35 3718 /proc/meminfo: memFree=108020/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=124400 CPUtime=159.92 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 32138 0 0 0 15968 24 0 0 25 0 1 0 73601096 127385600 30763 1283457024 134512640 136285277 4289313936 18446744073709551615 134733720 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 31100 30763 234 433 0 30665 0 Current children cumulated CPU time (s) 161.94 Current children cumulated vsize (KiB) 126992 [startup+222.309 s] /proc/loadavg: 1.01 1.06 1.02 2/36 3719 /proc/meminfo: memFree=110976/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=119372 CPUtime=219.86 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 32138 0 0 0 21962 24 0 0 25 0 1 0 73601096 122236928 29506 1283457024 134512640 136285277 4289313936 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 29843 29506 234 433 0 29408 0 Current children cumulated CPU time (s) 221.88 Current children cumulated vsize (KiB) 121964 [startup+282.313 s] /proc/loadavg: 1.00 1.05 1.01 2/37 3726 /proc/meminfo: memFree=110552/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=119372 CPUtime=279.81 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 32138 0 0 0 27955 26 0 0 25 0 1 0 73601096 122236928 29506 1283457024 134512640 136285277 4289313936 18446744073709551615 134930644 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 29843 29506 234 433 0 29408 0 Current children cumulated CPU time (s) 281.83 Current children cumulated vsize (KiB) 121964 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.515 s] /proc/loadavg: 1.00 1.05 1.01 2/37 3727 /proc/meminfo: memFree=110552/1048576 swapFree=0/0 [pid=3707] ppid=3706 vsize=2592 CPUtime=2.02 /proc/3707/stat : 3707 (aspcud-1.5) S 3706 3707 22717 34817 22717 4202496 580 19297 0 0 0 0 192 10 15 0 1 0 73601095 2654208 298 1283457024 134512640 135304128 4293867664 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3707/statm: 648 298 251 194 0 35 0 [pid=3716] ppid=3707 vsize=119372 CPUtime=288 /proc/3716/stat : 3716 (clasp) R 3707 3707 22717 34817 22717 4202496 32138 0 0 0 28774 26 0 0 25 0 1 0 73601096 122236928 29506 1283457024 134512640 136285277 4289313936 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3716/statm: 29843 29506 234 433 0 29408 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 121964 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.546 CPU time (s): 290.074 CPU user time (s): 289.678 CPU system time (s): 0.396024 CPU usage (%): 99.8377 Max. virtual memory (cumulated for all children) (KiB): 128452 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.678 system time used= 0.396024 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 55689 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= 805 involuntary context switches= 4198 runsolver used 0 second user time and 0.008 second system time The end