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/201108241238/aspcud-trendy-1.5/rand7.cudf.s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s/rand7.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand7.cudf.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.02 1.02 1.00 5/36 16055 /proc/meminfo: memFree=535404/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2592 CPUtime=0 /proc/16054/stat : 16054 (aspcud-trendy-1) R 16053 16054 1511 34817 1511 4202496 367 0 0 0 0 0 0 0 25 0 1 0 3701245 2654208 280 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/16054/statm: 648 280 234 194 0 35 0 [pid=16055] ppid=16054 vsize=2592 CPUtime=0 /proc/16055/stat : 16055 (aspcud-trendy-1) R 16054 16054 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3701245 2654208 46 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/16055/statm: 648 46 0 194 0 35 0 [startup+0.175178 s] /proc/loadavg: 1.02 1.02 1.00 5/36 16055 /proc/meminfo: memFree=535404/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 625 2226 0 0 0 0 0 0 25 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.205188 s] /proc/loadavg: 1.02 1.02 1.00 5/36 16055 /proc/meminfo: memFree=535404/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 625 2226 0 0 0 0 0 0 25 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.305199 s] /proc/loadavg: 1.02 1.02 1.00 5/36 16055 /proc/meminfo: memFree=535404/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 625 2226 0 0 0 0 0 0 25 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.70529 s] /proc/loadavg: 1.02 1.02 1.00 5/36 16055 /proc/meminfo: memFree=535404/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.36 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 5419 0 0 0 0 34 2 21 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.36 Current children cumulated vsize (KiB) 2600 [startup+1.50544 s] /proc/loadavg: 1.02 1.02 1.00 2/37 16068 /proc/meminfo: memFree=526952/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=0.85 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2690 0 0 0 85 0 0 0 20 0 1 0 3701246 10067968 2228 1283457024 134512640 136285277 4290145616 18446744073709551615 134734701 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2228 234 433 0 2023 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 12432 [startup+3.10573 s] /proc/loadavg: 1.02 1.02 1.00 2/37 16068 /proc/meminfo: memFree=526952/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=2.45 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2697 0 0 0 245 0 0 0 25 0 1 0 3701246 10067968 2235 1283457024 134512640 136285277 4290145616 18446744073709551615 134734704 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2235 234 433 0 2023 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 12432 [startup+6.30652 s] /proc/loadavg: 1.01 1.02 1.00 2/37 16068 /proc/meminfo: memFree=526960/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=5.65 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2697 0 0 0 565 0 0 0 25 0 1 0 3701246 10067968 2235 1283457024 134512640 136285277 4290145616 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2235 234 433 0 2023 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 12432 [startup+12.7078 s] /proc/loadavg: 1.01 1.02 1.00 2/37 16069 /proc/meminfo: memFree=526960/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=12.04 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2697 0 0 0 1204 0 0 0 25 0 1 0 3701246 10067968 2235 1283457024 134512640 136285277 4290145616 18446744073709551615 134946232 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2235 234 433 0 2023 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 12432 [startup+25.5107 s] /proc/loadavg: 1.01 1.02 1.00 2/37 16070 /proc/meminfo: memFree=526960/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=24.84 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2697 0 0 0 2484 0 0 0 25 0 1 0 3701246 10067968 2235 1283457024 134512640 136285277 4290145616 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2235 234 433 0 2023 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 12432 [startup+51.1087 s] /proc/loadavg: 1.00 1.02 1.00 2/36 16072 /proc/meminfo: memFree=526976/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=50.44 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2697 0 0 0 5044 0 0 0 25 0 1 0 3701246 10067968 2235 1283457024 134512640 136285277 4290145616 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2235 234 433 0 2023 0 Current children cumulated CPU time (s) 51.07 Current children cumulated vsize (KiB) 12432 [startup+102.309 s] /proc/loadavg: 1.00 1.01 1.00 2/36 16072 /proc/meminfo: memFree=526976/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=101.61 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2697 0 0 0 10159 2 0 0 25 0 1 0 3701246 10067968 2235 1283457024 134512640 136285277 4290145616 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2235 234 433 0 2023 0 Current children cumulated CPU time (s) 102.24 Current children cumulated vsize (KiB) 12432 [startup+162.305 s] /proc/loadavg: 1.00 1.01 1.00 2/35 16072 /proc/meminfo: memFree=526984/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9832 CPUtime=161.57 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2699 0 0 0 16155 2 0 0 25 0 1 0 3701246 10067968 2237 1283457024 134512640 136285277 4290145616 18446744073709551615 134735687 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2458 2237 234 433 0 2023 0 Current children cumulated CPU time (s) 162.2 Current children cumulated vsize (KiB) 12432 [startup+222.308 s] /proc/loadavg: 1.00 1.00 1.00 2/35 16072 /proc/meminfo: memFree=526984/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=9964 CPUtime=221.53 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2720 0 0 0 22150 3 0 0 25 0 1 0 3701246 10203136 2258 1283457024 134512640 136285277 4290145616 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2491 2258 234 433 0 2056 0 Current children cumulated CPU time (s) 222.16 Current children cumulated vsize (KiB) 12564 [startup+282.311 s] /proc/loadavg: 1.00 1.00 1.00 2/35 16072 /proc/meminfo: memFree=526984/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=10228 CPUtime=281.48 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2808 0 0 0 28144 4 0 0 25 0 1 0 3701246 10473472 2346 1283457024 134512640 136285277 4290145616 18446744073709551615 134723310 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2557 2346 234 433 0 2122 0 Current children cumulated CPU time (s) 282.11 Current children cumulated vsize (KiB) 12828 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.203 s] /proc/loadavg: 1.00 1.00 1.00 2/35 16072 /proc/meminfo: memFree=526984/1048576 swapFree=0/0 [pid=16054] ppid=16053 vsize=2600 CPUtime=0.63 /proc/16054/stat : 16054 (aspcud-trendy-1) S 16053 16054 1511 34817 1511 4202496 626 8850 0 0 0 0 60 3 20 0 1 0 3701245 2662400 299 1283457024 134512640 135304128 4290541056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16054/statm: 650 299 251 194 0 37 0 [pid=16066] ppid=16054 vsize=10228 CPUtime=289.37 /proc/16066/stat : 16066 (clasp) R 16054 16054 1511 34817 1511 4202496 2808 0 0 0 28933 4 0 0 25 0 1 0 3701246 10473472 2346 1283457024 134512640 136285277 4290145616 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16066/statm: 2557 2346 234 433 0 2122 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 12828 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.225 CPU time (s): 290.034 CPU user time (s): 289.938 CPU system time (s): 0.096006 CPU usage (%): 99.9341 Max. virtual memory (cumulated for all children) (KiB): 12828 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.938 system time used= 0.096006 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 15890 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= 542 involuntary context switches= 3964 runsolver used 0 second user time and 0 second system time The end