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/rand576.cudf.s-e-l-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s/rand576.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-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.02 1.03 1.00 5/36 19082 /proc/meminfo: memFree=544912/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2592 CPUtime=0 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 4271456 2654208 280 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/19080/statm: 648 280 234 194 0 35 0 [pid=19081] ppid=19080 vsize=2592 CPUtime=0 /proc/19081/stat : 19081 (aspcud-trendy-1) R 19080 19080 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4271456 2654208 133 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/19081/statm: 648 133 86 194 0 35 0 [pid=19082] ppid=19081 vsize=2592 CPUtime=0 /proc/19082/stat : 19082 (aspcud-trendy-1) R 19081 19080 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4271456 2654208 47 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/19082/statm: 648 47 0 194 0 35 0 [startup+0.157402 s] /proc/loadavg: 1.02 1.03 1.00 5/36 19082 /proc/meminfo: memFree=544912/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=0.01 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 624 2227 0 0 0 1 0 0 25 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.207432 s] /proc/loadavg: 1.02 1.03 1.00 5/36 19082 /proc/meminfo: memFree=544912/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=0.01 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 624 2227 0 0 0 1 0 0 25 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.307452 s] /proc/loadavg: 1.02 1.03 1.00 5/36 19082 /proc/meminfo: memFree=544912/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=0.01 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 624 2227 0 0 0 1 0 0 25 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.707532 s] /proc/loadavg: 1.02 1.03 1.00 5/36 19082 /proc/meminfo: memFree=544912/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=0.01 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 624 2227 0 0 0 1 0 0 25 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+1.50806 s] /proc/loadavg: 1.02 1.03 1.00 2/38 19094 /proc/meminfo: memFree=524292/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=0.01 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 624 2227 0 0 0 1 0 0 25 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=1924 CPUtime=0 /proc/19092/stat : 19092 (clasp) S 19080 19080 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 4271457 1970176 159 1283457024 134512640 136285277 4290620864 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/19092/statm: 481 159 144 433 0 46 0 [pid=19093] ppid=19080 vsize=2588 CPUtime=0 /proc/19093/stat : 19093 (gringo) S 19080 19080 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 4271457 2650112 272 1283457024 134512640 136933539 4290315760 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/19093/statm: 647 272 242 592 0 52 0 [pid=19094] ppid=19080 vsize=40452 CPUtime=1.49 /proc/19094/stat : 19094 (cudf2lp) R 19080 19080 1511 34817 1511 4202496 11650 0 0 0 141 8 0 0 25 0 1 0 4271457 41422848 8739 1283457024 134512640 135786343 4292372480 18446744073709551615 134581892 0 0 6 0 0 0 0 17 0 0 0 0 /proc/19094/statm: 10113 8739 131 311 0 9800 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 47564 [startup+3.10853 s] /proc/loadavg: 1.02 1.03 1.00 3/38 19094 /proc/meminfo: memFree=489944/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=2.13 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 17925 0 0 0 1 198 14 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=19704 CPUtime=0.01 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 5412 0 0 0 0 1 0 0 18 0 1 0 4271457 20176896 4621 1283457024 134512640 136285277 4290620864 18446744073709551615 135658284 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 4926 4621 177 433 0 4491 0 [pid=19093] ppid=19080 vsize=33176 CPUtime=0.94 /proc/19093/stat : 19093 (gringo) R 19080 19080 1511 34817 1511 4202496 9807 0 0 0 91 3 0 0 18 0 1 0 4271457 33972224 6123 1283457024 134512640 136933539 4290315760 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19093/statm: 8294 6123 253 592 0 7699 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 55480 [startup+6.30932 s] /proc/loadavg: 1.10 1.04 1.01 2/36 19094 /proc/meminfo: memFree=493216/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=53048 CPUtime=2.26 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 16190 0 0 0 221 5 0 0 21 0 1 0 4271457 54321152 12996 1283457024 134512640 136285277 4290620864 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 13262 12996 234 433 0 12827 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 55648 [startup+12.711 s] /proc/loadavg: 1.09 1.04 1.00 2/36 19094 /proc/meminfo: memFree=493216/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=53048 CPUtime=8.67 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 16206 0 0 0 862 5 0 0 25 0 1 0 4271457 54321152 13012 1283457024 134512640 136285277 4290620864 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 13262 13012 234 433 0 12827 0 Current children cumulated CPU time (s) 12.7 Current children cumulated vsize (KiB) 55648 [startup+25.5032 s] /proc/loadavg: 1.07 1.04 1.00 2/35 19094 /proc/meminfo: memFree=463216/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=83624 CPUtime=21.45 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 23833 0 0 0 2139 6 0 0 25 0 1 0 4271457 85630976 20639 1283457024 134512640 136285277 4290620864 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 20906 20639 234 433 0 20471 0 Current children cumulated CPU time (s) 25.48 Current children cumulated vsize (KiB) 86224 [startup+51.1095 s] /proc/loadavg: 1.05 1.03 1.00 2/35 19094 /proc/meminfo: memFree=441764/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=105048 CPUtime=47.05 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 29192 0 0 0 4693 12 0 0 25 0 1 0 4271457 107569152 25998 1283457024 134512640 136285277 4290620864 18446744073709551615 134930714 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 26262 25998 234 433 0 25827 0 Current children cumulated CPU time (s) 51.08 Current children cumulated vsize (KiB) 107648 [startup+102.312 s] /proc/loadavg: 1.02 1.03 1.00 2/35 19094 /proc/meminfo: memFree=392412/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=154348 CPUtime=98.23 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 41929 0 0 0 9804 19 0 0 25 0 1 0 4271457 158052352 38303 1283457024 134512640 136285277 4290620864 18446744073709551615 134960026 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 38587 38303 234 433 0 38152 0 Current children cumulated CPU time (s) 102.26 Current children cumulated vsize (KiB) 156948 [startup+162.312 s] /proc/loadavg: 1.00 1.02 1.00 2/35 19094 /proc/meminfo: memFree=375796/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=170924 CPUtime=158.13 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 46298 0 0 0 15793 20 0 0 25 0 1 0 4271457 175026176 42453 1283457024 134512640 136285277 4290620864 18446744073709551615 134931382 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 42731 42453 234 433 0 42296 0 Current children cumulated CPU time (s) 162.16 Current children cumulated vsize (KiB) 173524 [startup+222.307 s] /proc/loadavg: 1.00 1.01 1.00 2/35 19094 /proc/meminfo: memFree=310076/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=237268 CPUtime=218.06 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 62826 0 0 0 21784 22 0 0 25 0 1 0 4271457 242962432 58981 1283457024 134512640 136285277 4290620864 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 59317 58981 234 433 0 58882 0 Current children cumulated CPU time (s) 222.09 Current children cumulated vsize (KiB) 239868 [startup+282.306 s] /proc/loadavg: 1.00 1.01 1.00 2/37 19097 /proc/meminfo: memFree=211968/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=334436 CPUtime=277.99 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 87128 0 0 0 27756 43 0 0 25 0 1 0 4271457 342462464 83283 1283457024 134512640 136285277 4290620864 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 83609 83283 234 433 0 83174 0 Current children cumulated CPU time (s) 282.02 Current children cumulated vsize (KiB) 337036 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.307 s] /proc/loadavg: 1.00 1.01 1.00 2/37 19098 /proc/meminfo: memFree=211968/1048576 swapFree=0/0 [pid=19080] ppid=19079 vsize=2600 CPUtime=4.03 /proc/19080/stat : 19080 (aspcud-trendy-1) S 19079 19080 1511 34817 1511 4202496 625 36930 0 0 0 1 381 21 18 0 1 0 4271456 2662400 299 1283457024 134512640 135304128 4289656080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19080/statm: 650 299 251 194 0 37 0 [pid=19092] ppid=19080 vsize=334436 CPUtime=285.99 /proc/19092/stat : 19092 (clasp) R 19080 19080 1511 34817 1511 4202496 87128 0 0 0 28556 43 0 0 25 0 1 0 4271457 342462464 83283 1283457024 134512640 136285277 4290620864 18446744073709551615 134931533 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19092/statm: 83609 83283 234 433 0 83174 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 337036 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.353 CPU time (s): 290.082 CPU user time (s): 289.39 CPU system time (s): 0.692043 CPU usage (%): 99.9066 Max. virtual memory (cumulated for all children) (KiB): 337036 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.39 system time used= 0.692043 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 128357 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= 2675 involuntary context switches= 5551 runsolver used 0 second user time and 0 second system time The end