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/rand790.cudf.s-e-l-s-s.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand790.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand790.cudf.s-e-l-s-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.52 1.21 1.07 6/35 12379 /proc/meminfo: memFree=302100/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2588 CPUtime=0 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 375 0 0 0 0 0 0 0 18 0 1 0 10576767 2650112 280 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/12377/statm: 647 280 234 194 0 34 0 [pid=12378] ppid=12377 vsize=2588 CPUtime=0 /proc/12378/stat : 12378 (aspcud-paranoid) R 12377 12377 4778 34817 4778 4202560 110 0 0 0 0 0 0 0 25 0 1 0 10576767 2650112 133 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/12378/statm: 647 133 86 194 0 34 0 [pid=12379] ppid=12378 vsize=2588 CPUtime=0 /proc/12379/stat : 12379 (aspcud-paranoid) R 12378 12377 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10576767 2650112 47 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/12379/statm: 647 47 0 194 0 34 0 [startup+0.142924 s] /proc/loadavg: 1.52 1.21 1.07 6/35 12379 /proc/meminfo: memFree=302100/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=0.01 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 2936 0 0 0 0 1 0 25 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.20693 s] /proc/loadavg: 1.52 1.21 1.07 6/35 12379 /proc/meminfo: memFree=302100/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=0.01 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 2936 0 0 0 0 1 0 25 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.306927 s] /proc/loadavg: 1.52 1.21 1.07 6/35 12379 /proc/meminfo: memFree=302100/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=0.01 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 2936 0 0 0 0 1 0 25 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.706956 s] /proc/loadavg: 1.52 1.21 1.07 6/35 12379 /proc/meminfo: memFree=302100/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=0.01 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 2936 0 0 0 0 1 0 25 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50699 s] /proc/loadavg: 1.52 1.21 1.07 2/37 12394 /proc/meminfo: memFree=266204/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=0.01 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 2936 0 0 0 0 1 0 25 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 [pid=12392] ppid=12377 vsize=1928 CPUtime=0 /proc/12392/stat : 12392 (clasp) S 12377 12377 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 10576768 1974272 159 1283457024 134512640 136285277 4294932960 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/12392/statm: 482 159 144 433 0 47 0 [pid=12393] ppid=12377 vsize=2584 CPUtime=0 /proc/12393/stat : 12393 (gringo) S 12377 12377 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 10576768 2646016 272 1283457024 134512640 136933539 4291012240 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/12393/statm: 646 272 242 592 0 51 0 [pid=12394] ppid=12377 vsize=40664 CPUtime=1.32 /proc/12394/stat : 12394 (cudf2lp) R 12377 12377 4778 34817 4778 4202496 11598 0 0 0 127 5 0 0 25 0 1 0 10576768 41639936 8687 1283457024 134512640 135786343 4286843568 18446744073709551615 134566245 0 0 6 0 0 0 0 17 0 0 0 0 /proc/12394/statm: 10166 8687 126 311 0 9853 0 Current children cumulated CPU time (s) 1.33 Current children cumulated vsize (KiB) 47772 [startup+3.11589 s] /proc/loadavg: 1.52 1.21 1.07 4/37 12394 /proc/meminfo: memFree=228332/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=2.1 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 19140 0 0 0 0 202 8 18 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 [pid=12392] ppid=12377 vsize=18392 CPUtime=0.06 /proc/12392/stat : 12392 (clasp) R 12377 12377 4778 34817 4778 4202496 5070 0 0 0 6 0 0 0 18 0 1 0 10576768 18833408 4279 1283457024 134512640 136285277 4294932960 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12392/statm: 4598 4279 177 433 0 4163 0 [pid=12393] ppid=12377 vsize=29644 CPUtime=0.77 /proc/12393/stat : 12393 (gringo) R 12377 12377 4778 34817 4778 4202496 8497 0 0 0 73 4 0 0 18 0 1 0 10576768 30355456 5965 1283457024 134512640 136933539 4291012240 18446744073709551615 136204768 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12393/statm: 7411 5965 253 592 0 6816 0 Current children cumulated CPU time (s) 2.93 Current children cumulated vsize (KiB) 50632 Solver just ended. Dumping a history of the last processes samples [startup+3.21596 s] /proc/loadavg: 1.52 1.21 1.07 4/37 12394 /proc/meminfo: memFree=228332/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=2.1 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 19140 0 0 0 0 202 8 18 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 [pid=12392] ppid=12377 vsize=21584 CPUtime=0.07 /proc/12392/stat : 12392 (clasp) R 12377 12377 4778 34817 4778 4202496 6003 0 0 0 7 0 0 0 18 0 1 0 10576768 22102016 5009 1283457024 134512640 136285277 4294932960 18446744073709551615 134782266 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12392/statm: 5396 5009 177 433 0 4961 0 [pid=12393] ppid=12377 vsize=35316 CPUtime=0.86 /proc/12393/stat : 12393 (gringo) R 12377 12377 4778 34817 4778 4202496 10140 0 0 0 80 6 0 0 18 0 1 0 10576768 36163584 7222 1283457024 134512640 136933539 4291012240 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12393/statm: 8829 7222 253 592 0 8234 0 Current children cumulated CPU time (s) 3.03 Current children cumulated vsize (KiB) 59496 [startup+3.60612 s] /proc/loadavg: 1.52 1.21 1.07 3/36 12394 /proc/meminfo: memFree=232564/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=2.1 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 19140 0 0 0 0 202 8 18 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 [pid=12392] ppid=12377 vsize=26988 CPUtime=0.12 /proc/12392/stat : 12392 (clasp) R 12377 12377 4778 34817 4778 4202496 7341 0 0 0 12 0 0 0 18 0 1 0 10576768 27635712 6347 1283457024 134512640 136285277 4294932960 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12392/statm: 6747 6347 177 433 0 6312 0 [pid=12393] ppid=12377 vsize=24452 CPUtime=1.19 /proc/12393/stat : 12393 (gringo) R 12377 12377 4778 34817 4778 4202496 13076 0 0 0 109 10 0 0 18 0 1 0 10576768 25038848 5563 1283457024 134512640 136933539 4291012240 18446744073709551615 136420622 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12393/statm: 6113 5563 254 592 0 5518 0 Current children cumulated CPU time (s) 3.41 Current children cumulated vsize (KiB) 54036 [startup+4.00614 s] /proc/loadavg: 1.52 1.21 1.07 3/36 12394 /proc/meminfo: memFree=232564/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=3.33 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 32217 0 0 0 0 313 20 18 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 [pid=12392] ppid=12377 vsize=34868 CPUtime=0.5 /proc/12392/stat : 12392 (clasp) R 12377 12377 4778 34817 4778 4202496 10218 0 0 0 48 2 0 0 18 0 1 0 10576768 35704832 8437 1283457024 134512640 136285277 4294932960 18446744073709551615 134889827 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12392/statm: 8717 8437 218 433 0 8282 0 Current children cumulated CPU time (s) 3.83 Current children cumulated vsize (KiB) 37464 [startup+4.10616 s] /proc/loadavg: 1.52 1.21 1.07 3/36 12394 /proc/meminfo: memFree=232564/1048576 swapFree=0/0 [pid=12377] ppid=12376 vsize=2596 CPUtime=3.33 /proc/12377/stat : 12377 (aspcud-paranoid) S 12376 12377 4778 34817 4778 4202496 658 32217 0 0 0 0 313 20 18 0 1 0 10576767 2658304 299 1283457024 134512640 135304128 4291679984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12377/statm: 649 299 251 194 0 36 0 [pid=12392] ppid=12377 vsize=34324 CPUtime=0.6 /proc/12392/stat : 12392 (clasp) R 12377 12377 4778 34817 4778 4202496 10240 0 0 0 58 2 0 0 18 0 1 0 10576768 35147776 8336 1283457024 134512640 136285277 4294932960 18446744073709551615 134931500 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12392/statm: 8581 8336 234 433 0 8146 0 Current children cumulated CPU time (s) 3.93 Current children cumulated vsize (KiB) 36920 Child status: 0 Real time (s): 4.20049 CPU time (s): 4.02825 CPU user time (s): 3.77624 CPU system time (s): 0.252015 CPU usage (%): 95.8995 Max. virtual memory (cumulated for all children) (KiB): 77284 getrusage(RUSAGE_CHILDREN,...) data: user time used= 3.77624 system time used= 0.252015 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 46716 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= 1364 involuntary context switches= 1035 runsolver used 0 second user time and 0.008 second system time The end