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/201108251442/aspcud-paranoid-1.5/rand576.cudf.s-e-l-s.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l-s/rand576.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand576.cudf.s-e-l-s.result 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.40 1.26 1.09 5/35 18390 /proc/meminfo: memFree=358792/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2588 CPUtime=0 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 374 0 0 0 0 0 0 0 18 0 1 0 11097748 2650112 280 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/18388/statm: 647 280 234 194 0 34 0 [pid=18389] ppid=18388 vsize=2588 CPUtime=0 /proc/18389/stat : 18389 (aspcud-paranoid) R 18388 18388 4778 34817 4778 4202560 111 0 0 0 0 0 0 0 25 0 1 0 11097748 2650112 133 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/18389/statm: 647 133 86 194 0 34 0 [pid=18390] ppid=18389 vsize=2588 CPUtime=0 /proc/18390/stat : 18390 (aspcud-paranoid) R 18389 18388 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11097748 2650112 47 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/18390/statm: 647 47 0 194 0 34 0 [startup+0.140409 s] /proc/loadavg: 1.40 1.26 1.09 5/35 18390 /proc/meminfo: memFree=358792/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=0.01 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 2937 0 0 1 0 0 0 25 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.204404 s] /proc/loadavg: 1.40 1.26 1.09 5/35 18390 /proc/meminfo: memFree=358792/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=0.01 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 2937 0 0 1 0 0 0 25 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.332419 s] /proc/loadavg: 1.40 1.26 1.09 5/35 18390 /proc/meminfo: memFree=358792/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=0.01 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 2937 0 0 1 0 0 0 25 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.705338 s] /proc/loadavg: 1.40 1.26 1.09 5/35 18390 /proc/meminfo: memFree=358792/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=0.01 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 2937 0 0 1 0 0 0 25 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50449 s] /proc/loadavg: 1.40 1.26 1.09 2/37 18405 /proc/meminfo: memFree=322764/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=0.01 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 2937 0 0 1 0 0 0 25 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 [pid=18403] ppid=18388 vsize=1924 CPUtime=0 /proc/18403/stat : 18403 (clasp) S 18388 18388 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 11097750 1970176 159 1283457024 134512640 136285277 4291325552 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/18403/statm: 481 159 144 433 0 46 0 [pid=18404] ppid=18388 vsize=2584 CPUtime=0 /proc/18404/stat : 18404 (gringo) S 18388 18388 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11097750 2646016 272 1283457024 134512640 136933539 4293962080 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18404/statm: 646 272 242 592 0 51 0 [pid=18405] ppid=18388 vsize=40452 CPUtime=1.34 /proc/18405/stat : 18405 (cudf2lp) R 18388 18388 4778 34817 4778 4202496 11607 0 0 0 124 10 0 0 25 0 1 0 11097750 41422848 8696 1283457024 134512640 135786343 4286603904 18446744073709551615 135220087 0 0 6 0 0 0 0 17 0 0 0 0 /proc/18405/statm: 10113 8696 126 311 0 9800 0 Current children cumulated CPU time (s) 1.35 Current children cumulated vsize (KiB) 47556 [startup+3.10684 s] /proc/loadavg: 1.40 1.26 1.09 4/37 18405 /proc/meminfo: memFree=284548/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=1.98 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 18635 0 0 1 0 182 15 18 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 [pid=18403] ppid=18388 vsize=21732 CPUtime=0.08 /proc/18403/stat : 18403 (clasp) R 18388 18388 4778 34817 4778 4202496 6035 0 0 0 6 2 0 0 18 0 1 0 11097750 22253568 5041 1283457024 134512640 136285277 4291325552 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18403/statm: 5433 5041 177 433 0 4998 0 [pid=18404] ppid=18388 vsize=35380 CPUtime=0.87 /proc/18404/stat : 18404 (gringo) R 18388 18388 4778 34817 4778 4202496 10095 0 0 0 86 1 0 0 18 0 1 0 11097750 36229120 7177 1283457024 134512640 136933539 4293962080 18446744073709551615 135821904 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18404/statm: 8845 7177 253 592 0 8250 0 Current children cumulated CPU time (s) 2.93 Current children cumulated vsize (KiB) 59708 Solver just ended. Dumping a history of the last processes samples [startup+3.20686 s] /proc/loadavg: 1.40 1.26 1.09 4/37 18405 /proc/meminfo: memFree=284548/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=1.98 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 18635 0 0 1 0 182 15 18 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 [pid=18403] ppid=18388 vsize=22396 CPUtime=0.1 /proc/18403/stat : 18403 (clasp) R 18388 18388 4778 34817 4778 4202496 6206 0 0 0 8 2 0 0 18 0 1 0 11097750 22933504 5212 1283457024 134512640 136285277 4291325552 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18403/statm: 5599 5212 177 433 0 5164 0 [pid=18404] ppid=18388 vsize=37192 CPUtime=0.95 /proc/18404/stat : 18404 (gringo) R 18388 18388 4778 34817 4778 4202496 10466 0 0 0 94 1 0 0 18 0 1 0 11097750 38084608 7548 1283457024 134512640 136933539 4293962080 18446744073709551615 134903707 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18404/statm: 9298 7548 253 592 0 8703 0 Current children cumulated CPU time (s) 3.03 Current children cumulated vsize (KiB) 62184 [startup+4.00706 s] /proc/loadavg: 1.40 1.26 1.09 3/36 18405 /proc/meminfo: memFree=285804/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=3.14 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 31628 0 0 1 0 296 17 18 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 [pid=18403] ppid=18388 vsize=34568 CPUtime=0.7 /proc/18403/stat : 18403 (clasp) R 18388 18388 4778 34817 4778 4202496 10132 0 0 0 65 5 0 0 18 0 1 0 11097750 35397632 8355 1283457024 134512640 136285277 4291325552 18446744073709551615 134899822 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18403/statm: 8642 8355 218 433 0 8207 0 Current children cumulated CPU time (s) 3.84 Current children cumulated vsize (KiB) 37164 [startup+4.40719 s] /proc/loadavg: 1.40 1.26 1.09 2/35 18405 /proc/meminfo: memFree=306652/1048576 swapFree=0/0 [pid=18388] ppid=18387 vsize=2596 CPUtime=3.14 /proc/18388/stat : 18388 (aspcud-paranoid) S 18387 18388 4778 34817 4778 4202496 657 31628 0 0 1 0 296 17 18 0 1 0 11097748 2658304 299 1283457024 134512640 135304128 4291487440 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18388/statm: 649 299 251 194 0 36 0 [pid=18403] ppid=18388 vsize=32952 CPUtime=1.1 /proc/18403/stat : 18403 (clasp) R 18388 18388 4778 34817 4778 4202496 10166 0 0 0 105 5 0 0 18 0 1 0 11097750 33742848 7999 1283457024 134512640 136285277 4291325552 18446744073709551615 135631817 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18403/statm: 8238 7999 241 433 0 7803 0 Current children cumulated CPU time (s) 4.24 Current children cumulated vsize (KiB) 35548 Child status: 0 Real time (s): 4.44759 CPU time (s): 4.28827 CPU user time (s): 4.04825 CPU system time (s): 0.240015 CPU usage (%): 96.4178 Max. virtual memory (cumulated for all children) (KiB): 75256 getrusage(RUSAGE_CHILDREN,...) data: user time used= 4.04825 system time used= 0.240015 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 46092 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= 1334 involuntary context switches= 1010 runsolver used 0 second user time and 0.012 second system time The end