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/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/ab9005be-bacc-11e0-b0f6-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: 0.97 0.97 0.99 3/36 1198 /proc/meminfo: memFree=328932/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2584 CPUtime=0 /proc/1197/stat : 1197 (aspcud-1.5) R 1196 1197 22717 34817 22717 4202496 365 0 0 0 0 0 0 0 25 0 1 0 73346186 2646016 279 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/1197/statm: 646 279 234 194 0 33 0 [pid=1198] ppid=1197 vsize=2584 CPUtime=0 /proc/1198/stat : 1198 (aspcud-1.5) R 1197 1197 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 73346186 2646016 45 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/1198/statm: 646 45 0 194 0 33 0 [startup+0.118326 s] /proc/loadavg: 0.97 0.97 0.99 3/36 1198 /proc/meminfo: memFree=328932/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=0 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 1523 0 0 0 0 0 0 25 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.203086 s] /proc/loadavg: 0.97 0.97 0.99 3/36 1198 /proc/meminfo: memFree=328932/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=0 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 1523 0 0 0 0 0 0 25 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.307106 s] /proc/loadavg: 0.97 0.97 0.99 3/36 1198 /proc/meminfo: memFree=328932/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=0 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 1523 0 0 0 0 0 0 25 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.70712 s] /proc/loadavg: 0.97 0.97 0.99 3/36 1198 /proc/meminfo: memFree=328932/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=0 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 1523 0 0 0 0 0 0 25 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50743 s] /proc/loadavg: 0.97 0.97 0.99 2/39 1209 /proc/meminfo: memFree=289296/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=0 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 1523 0 0 0 0 0 0 25 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 [pid=1206] ppid=1197 vsize=1932 CPUtime=0 /proc/1206/stat : 1206 (clasp) S 1197 1197 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 73346187 1978368 160 1283457024 134512640 136285277 4287828784 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/1206/statm: 483 160 144 433 0 48 0 [pid=1208] ppid=1197 vsize=2580 CPUtime=0 /proc/1208/stat : 1208 (gringo) S 1197 1197 22717 34817 22717 4202496 403 0 0 0 0 0 0 0 25 0 1 0 73346187 2641920 271 1283457024 134512640 136933539 4293775696 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/1208/statm: 645 271 242 592 0 50 0 [pid=1209] ppid=1197 vsize=29344 CPUtime=1.26 /proc/1209/stat : 1209 (cudf2lp) R 1197 1197 22717 34817 22717 4202496 8371 0 0 0 124 2 0 0 25 0 1 0 73346187 30048256 6870 1283457024 134512640 135786343 4288437248 18446744073709551615 134613239 0 0 6 0 0 0 0 17 0 0 0 0 /proc/1209/statm: 7336 6870 128 311 0 7023 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 36448 [startup+3.10883 s] /proc/loadavg: 0.97 0.97 0.99 2/39 1209 /proc/meminfo: memFree=255404/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=2 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 15568 0 0 0 0 196 4 18 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 [pid=1206] ppid=1197 vsize=18128 CPUtime=0.08 /proc/1206/stat : 1206 (clasp) R 1197 1197 22717 34817 22717 4202496 4967 0 0 0 8 0 0 0 18 0 1 0 73346187 18563072 4177 1283457024 134512640 136285277 4287828784 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1206/statm: 4532 4177 177 433 0 4097 0 [pid=1208] ppid=1197 vsize=27700 CPUtime=0.75 /proc/1208/stat : 1208 (gringo) R 1197 1197 22717 34817 22717 4202496 7835 0 0 0 71 4 0 0 18 0 1 0 73346187 28364800 5755 1283457024 134512640 136933539 4293775696 18446744073709551615 134688168 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1208/statm: 6925 5755 253 592 0 6330 0 Current children cumulated CPU time (s) 2.83 Current children cumulated vsize (KiB) 48420 Solver just ended. Dumping a history of the last processes samples [startup+3.20891 s] /proc/loadavg: 0.97 0.97 0.99 2/39 1209 /proc/meminfo: memFree=255404/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=2 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 15568 0 0 0 0 196 4 18 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 [pid=1206] ppid=1197 vsize=20768 CPUtime=0.09 /proc/1206/stat : 1206 (clasp) R 1197 1197 22717 34817 22717 4202496 5662 0 0 0 9 0 0 0 18 0 1 0 73346187 21266432 4872 1283457024 134512640 136285277 4287828784 18446744073709551615 134782592 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1206/statm: 5192 4872 177 433 0 4757 0 [pid=1208] ppid=1197 vsize=33352 CPUtime=0.84 /proc/1208/stat : 1208 (gringo) R 1197 1197 22717 34817 22717 4202496 9452 0 0 0 80 4 0 0 18 0 1 0 73346187 34152448 6986 1283457024 134512640 136933539 4293775696 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1208/statm: 8338 6986 253 592 0 7743 0 Current children cumulated CPU time (s) 2.93 Current children cumulated vsize (KiB) 56712 [startup+4.80925 s] /proc/loadavg: 0.97 0.97 0.99 2/37 1209 /proc/meminfo: memFree=272052/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=3.34 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 29242 0 0 0 0 322 12 18 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 [pid=1206] ppid=1197 vsize=36300 CPUtime=1.15 /proc/1206/stat : 1206 (clasp) R 1197 1197 22717 34817 22717 4202496 10788 0 0 0 113 2 0 0 19 0 1 0 73346187 37171200 8854 1283457024 134512640 136285277 4287828784 18446744073709551615 134893008 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1206/statm: 9075 8854 234 433 0 8640 0 Current children cumulated CPU time (s) 4.49 Current children cumulated vsize (KiB) 38892 [startup+5.20949 s] /proc/loadavg: 0.97 0.97 0.99 2/37 1209 /proc/meminfo: memFree=272052/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=3.34 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 29242 0 0 0 0 322 12 18 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 [pid=1206] ppid=1197 vsize=36300 CPUtime=1.54 /proc/1206/stat : 1206 (clasp) R 1197 1197 22717 34817 22717 4202496 10788 0 0 0 152 2 0 0 19 0 1 0 73346187 37171200 8854 1283457024 134512640 136285277 4287828784 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1206/statm: 9075 8854 234 433 0 8640 0 Current children cumulated CPU time (s) 4.88 Current children cumulated vsize (KiB) 38892 [startup+5.40952 s] /proc/loadavg: 0.97 0.97 0.99 2/37 1209 /proc/meminfo: memFree=272052/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=3.34 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 29242 0 0 0 0 322 12 18 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 [pid=1206] ppid=1197 vsize=36300 CPUtime=1.74 /proc/1206/stat : 1206 (clasp) R 1197 1197 22717 34817 22717 4202496 10788 0 0 0 172 2 0 0 20 0 1 0 73346187 37171200 8854 1283457024 134512640 136285277 4287828784 18446744073709551615 134719444 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1206/statm: 9075 8854 234 433 0 8640 0 Current children cumulated CPU time (s) 5.08 Current children cumulated vsize (KiB) 38892 [startup+5.51044 s] /proc/loadavg: 0.97 0.97 0.99 2/37 1209 /proc/meminfo: memFree=290536/1048576 swapFree=0/0 [pid=1197] ppid=1196 vsize=2592 CPUtime=3.34 /proc/1197/stat : 1197 (aspcud-1.5) S 1196 1197 22717 34817 22717 4202496 580 29242 0 0 0 0 322 12 18 0 1 0 73346186 2654208 298 1283457024 134512640 135304128 4289055728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1197/statm: 648 298 251 194 0 35 0 [pid=1206] ppid=1197 vsize=25912 CPUtime=1.84 /proc/1206/stat : 1206 (clasp) R 1197 1197 22717 34817 22717 4202496 10796 0 0 0 181 3 0 0 20 0 1 0 73346187 26533888 4230 1283457024 134512640 136285277 4287828784 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1206/statm: 6478 4230 242 433 0 6043 0 Current children cumulated CPU time (s) 5.18 Current children cumulated vsize (KiB) 28504 Child status: 0 Real time (s): 5.53886 CPU time (s): 5.22033 CPU user time (s): 5.04431 CPU system time (s): 0.176011 CPU usage (%): 94.2492 Max. virtual memory (cumulated for all children) (KiB): 81508 getrusage(RUSAGE_CHILDREN,...) data: user time used= 5.04432 system time used= 0.176011 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 44175 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= 1677 involuntary context switches= 1345 runsolver used 0 second user time and 0.012 second system time The end