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/rand953.cudf.s-e-l-s-s.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand953.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand953.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.55 1.24 1.08 5/37 18215 /proc/meminfo: memFree=300160/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2584 CPUtime=0 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 372 0 0 0 0 0 0 0 18 0 1 0 11092638 2646016 279 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/18212/statm: 646 279 234 194 0 33 0 [pid=18213] ppid=18212 vsize=2584 CPUtime=0 /proc/18213/stat : 18213 (aspcud-paranoid) S 18212 18212 4778 34817 4778 4202560 118 0 0 0 0 0 0 0 18 0 1 0 11092638 2646016 133 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/18213/statm: 646 133 87 194 0 33 0 [pid=18214] ppid=18213 vsize=2584 CPUtime=0 /proc/18214/stat : 18214 (aspcud-paranoid) R 18213 18212 4778 34817 4778 4202560 127 0 0 0 0 0 0 0 25 0 1 0 11092638 2646016 150 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/18214/statm: 646 150 104 194 0 33 0 [pid=18215] ppid=18214 vsize=2584 CPUtime=0 /proc/18215/stat : 18215 (aspcud-paranoid) R 18214 18212 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11092638 2646016 46 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/18215/statm: 646 46 0 194 0 33 0 [startup+0.19312 s] /proc/loadavg: 1.55 1.24 1.08 5/37 18215 /proc/meminfo: memFree=300160/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=0.01 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 2936 0 0 0 0 1 0 25 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.253107 s] /proc/loadavg: 1.55 1.24 1.08 5/37 18215 /proc/meminfo: memFree=300160/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=0.01 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 2936 0 0 0 0 1 0 25 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.31345 s] /proc/loadavg: 1.55 1.24 1.08 5/37 18215 /proc/meminfo: memFree=300160/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=0.01 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 2936 0 0 0 0 1 0 25 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.713559 s] /proc/loadavg: 1.55 1.24 1.08 5/37 18215 /proc/meminfo: memFree=300160/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=0.01 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 2936 0 0 0 0 1 0 25 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.5052 s] /proc/loadavg: 1.50 1.23 1.08 2/38 18229 /proc/meminfo: memFree=264208/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=0.01 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 2936 0 0 0 0 1 0 25 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 [pid=18227] ppid=18212 vsize=1928 CPUtime=0 /proc/18227/stat : 18227 (clasp) S 18212 18212 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 11092639 1974272 159 1283457024 134512640 136285277 4288371616 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/18227/statm: 482 159 144 433 0 47 0 [pid=18228] ppid=18212 vsize=2584 CPUtime=0 /proc/18228/stat : 18228 (gringo) S 18212 18212 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 11092640 2646016 272 1283457024 134512640 136933539 4288496688 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18228/statm: 646 272 242 592 0 51 0 [pid=18229] ppid=18212 vsize=40668 CPUtime=1.33 /proc/18229/stat : 18229 (cudf2lp) R 18212 18212 4778 34817 4778 4202496 11632 0 0 0 130 3 0 0 25 0 1 0 11092640 41644032 8722 1283457024 134512640 135786343 4291930000 18446744073709551615 135214671 0 0 6 0 0 0 0 17 0 0 0 0 /proc/18229/statm: 10167 8722 126 311 0 9854 0 Current children cumulated CPU time (s) 1.34 Current children cumulated vsize (KiB) 47772 [startup+3.10569 s] /proc/loadavg: 1.50 1.23 1.08 2/38 18229 /proc/meminfo: memFree=225840/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=2.08 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 19140 0 0 0 0 202 6 18 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 [pid=18227] ppid=18212 vsize=18920 CPUtime=0.05 /proc/18227/stat : 18227 (clasp) R 18212 18212 4778 34817 4778 4202496 5207 0 0 0 4 1 0 0 18 0 1 0 11092639 19374080 4417 1283457024 134512640 136285277 4288371616 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18227/statm: 4730 4417 177 433 0 4295 0 [pid=18228] ppid=18212 vsize=30364 CPUtime=0.79 /proc/18228/stat : 18228 (gringo) R 18212 18212 4778 34817 4778 4202496 8712 0 0 0 76 3 0 0 18 0 1 0 11092640 31092736 6181 1283457024 134512640 136933539 4288496688 18446744073709551615 136183536 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18228/statm: 7591 6181 253 592 0 6996 0 Current children cumulated CPU time (s) 2.92 Current children cumulated vsize (KiB) 51876 Solver just ended. Dumping a history of the last processes samples [startup+3.2057 s] /proc/loadavg: 1.50 1.23 1.08 2/38 18229 /proc/meminfo: memFree=225840/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=2.08 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 19140 0 0 0 0 202 6 18 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 [pid=18227] ppid=18212 vsize=21964 CPUtime=0.05 /proc/18227/stat : 18227 (clasp) R 18212 18212 4778 34817 4778 4202496 6092 0 0 0 4 1 0 0 18 0 1 0 11092639 22491136 5099 1283457024 134512640 136285277 4288371616 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18227/statm: 5491 5099 177 433 0 5056 0 [pid=18228] ppid=18212 vsize=35360 CPUtime=0.89 /proc/18228/stat : 18228 (gringo) R 18212 18212 4778 34817 4778 4202496 10176 0 0 0 86 3 0 0 18 0 1 0 11092640 36208640 7259 1283457024 134512640 136933539 4288496688 18446744073709551615 134903600 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18228/statm: 8840 7259 253 592 0 8245 0 Current children cumulated CPU time (s) 3.02 Current children cumulated vsize (KiB) 59916 [startup+4.00597 s] /proc/loadavg: 1.50 1.23 1.08 3/37 18229 /proc/meminfo: memFree=229584/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=3.25 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 32258 0 0 0 0 315 10 18 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 [pid=18227] ppid=18212 vsize=35044 CPUtime=0.58 /proc/18227/stat : 18227 (clasp) R 18212 18212 4778 34817 4778 4202496 10278 0 0 0 55 3 0 0 18 0 1 0 11092639 35885056 8494 1283457024 134512640 136285277 4288371616 18446744073709551615 134902060 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18227/statm: 8761 8494 218 433 0 8326 0 Current children cumulated CPU time (s) 3.83 Current children cumulated vsize (KiB) 37636 [startup+4.4061 s] /proc/loadavg: 1.50 1.23 1.08 2/36 18229 /proc/meminfo: memFree=245596/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=3.25 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 32258 0 0 0 0 315 10 18 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 [pid=18227] ppid=18212 vsize=34500 CPUtime=0.98 /proc/18227/stat : 18227 (clasp) R 18212 18212 4778 34817 4778 4202496 10304 0 0 0 94 4 0 0 18 0 1 0 11092639 35328000 8395 1283457024 134512640 136285277 4288371616 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18227/statm: 8625 8395 234 433 0 8190 0 Current children cumulated CPU time (s) 4.23 Current children cumulated vsize (KiB) 37092 [startup+4.60617 s] /proc/loadavg: 1.50 1.23 1.08 2/36 18229 /proc/meminfo: memFree=245596/1048576 swapFree=0/0 [pid=18212] ppid=18211 vsize=2592 CPUtime=3.25 /proc/18212/stat : 18212 (aspcud-paranoid) S 18211 18212 4778 34817 4778 4202496 647 32258 0 0 0 0 315 10 18 0 1 0 11092638 2654208 298 1283457024 134512640 135304128 4293038144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18212/statm: 648 298 251 194 0 35 0 [pid=18227] ppid=18212 vsize=34500 CPUtime=1.18 /proc/18227/stat : 18227 (clasp) R 18212 18212 4778 34817 4778 4202496 10304 0 0 0 114 4 0 0 19 0 1 0 11092639 35328000 8395 1283457024 134512640 136285277 4288371616 18446744073709551615 134952629 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18227/statm: 8625 8395 234 433 0 8190 0 Current children cumulated CPU time (s) 4.43 Current children cumulated vsize (KiB) 37092 Child status: 0 Real time (s): 4.68399 CPU time (s): 4.51628 CPU user time (s): 4.34027 CPU system time (s): 0.176011 CPU usage (%): 96.4195 Max. virtual memory (cumulated for all children) (KiB): 77424 getrusage(RUSAGE_CHILDREN,...) data: user time used= 4.34027 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= 46835 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= 1374 involuntary context switches= 1050 runsolver used 0 second user time and 0.004 second system time The end