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/201012070034/aspcud-trendy-1.3/rand0aa5c1.cudf.difficult.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/difficult//rand0aa5c1.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand0aa5c1.cudf.difficult.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.10 1.10 1.03 2/43 7410 /proc/meminfo: memFree=850868/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=3024 CPUtime=0 /proc/7410/stat : 7410 (runsolver) D 7409 7410 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 878274218 3096576 94 1283457024 134512640 134586868 4294535408 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/7410/statm: 756 94 62 19 0 54 0 [startup+0.201862 s] /proc/loadavg: 1.10 1.10 1.03 2/43 7410 /proc/meminfo: memFree=850868/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=0 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.305888 s] /proc/loadavg: 1.10 1.10 1.03 2/43 7410 /proc/meminfo: memFree=850868/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=0 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.410848 s] /proc/loadavg: 1.10 1.10 1.03 2/43 7410 /proc/meminfo: memFree=850868/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=0 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.710917 s] /proc/loadavg: 1.10 1.10 1.03 2/43 7410 /proc/meminfo: memFree=850868/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=0 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.51199 s] /proc/loadavg: 1.10 1.10 1.03 3/47 7424 /proc/meminfo: memFree=810012/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=0.85 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 11421 0 18 0 0 78 7 18 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=8960 CPUtime=0.02 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 2261 0 19 0 2 0 0 0 18 0 1 0 878274225 9175040 1943 1283457024 134512640 136223643 4292719136 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 2240 1943 174 418 0 1820 0 [pid=7423] ppid=7410 vsize=14556 CPUtime=0.36 /proc/7423/stat : 7423 (gringo) R 7410 7410 4159 34819 4229 4202496 3733 0 22 0 34 2 0 0 18 0 1 0 878274225 14905344 2817 1283457024 134512640 136959103 4288297424 18446744073709551615 134931415 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7423/statm: 3639 2817 256 598 0 3038 0 Current children cumulated CPU time (s) 1.23 Current children cumulated vsize (KiB) 26116 [startup+3.11385 s] /proc/loadavg: 1.17 1.12 1.04 2/45 7424 /proc/meminfo: memFree=824616/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=23672 CPUtime=1.25 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 6446 0 20 0 124 1 0 0 19 0 1 0 878274225 24240128 5381 1283457024 134512640 136223643 4292719136 18446744073709551615 134712523 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 5918 5381 225 418 0 5498 0 Current children cumulated CPU time (s) 2.82 Current children cumulated vsize (KiB) 26272 [startup+6.30456 s] /proc/loadavg: 1.17 1.12 1.04 2/45 7424 /proc/meminfo: memFree=824616/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=23672 CPUtime=4.44 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 6446 0 20 0 443 1 0 0 25 0 1 0 878274225 24240128 5381 1283457024 134512640 136223643 4292719136 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 5918 5381 225 418 0 5498 0 Current children cumulated CPU time (s) 6.01 Current children cumulated vsize (KiB) 26272 [startup+12.706 s] /proc/loadavg: 1.14 1.11 1.04 2/45 7424 /proc/meminfo: memFree=820152/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=29488 CPUtime=10.84 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 7901 0 20 0 1082 2 0 0 25 0 1 0 878274225 30195712 6836 1283457024 134512640 136223643 4292719136 18446744073709551615 134924244 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 7372 6836 225 418 0 6952 0 Current children cumulated CPU time (s) 12.41 Current children cumulated vsize (KiB) 32088 [startup+25.5085 s] /proc/loadavg: 1.12 1.11 1.03 2/45 7424 /proc/meminfo: memFree=794608/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=54176 CPUtime=23.62 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 14043 0 20 0 2360 2 0 0 25 0 1 0 878274225 55476224 12978 1283457024 134512640 136223643 4292719136 18446744073709551615 134928869 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 13544 12978 225 418 0 13124 0 Current children cumulated CPU time (s) 25.19 Current children cumulated vsize (KiB) 56776 [startup+51.1143 s] /proc/loadavg: 1.08 1.10 1.03 2/45 7424 /proc/meminfo: memFree=771668/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=76820 CPUtime=49.22 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 19735 0 20 0 4918 4 0 0 25 0 1 0 878274225 78663680 18670 1283457024 134512640 136223643 4292719136 18446744073709551615 134929640 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 19205 18670 225 418 0 18785 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 79420 [startup+102.307 s] /proc/loadavg: 1.03 1.08 1.03 2/45 7424 /proc/meminfo: memFree=726532/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=121544 CPUtime=100.34 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 31342 0 20 0 10023 11 0 0 25 0 1 0 878274225 124461056 29801 1283457024 134512640 136223643 4292719136 18446744073709551615 135607564 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 30386 29801 225 418 0 29966 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 124144 [startup+162.313 s] /proc/loadavg: 1.01 1.06 1.02 2/45 7424 /proc/meminfo: memFree=723184/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=125464 CPUtime=160.32 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 32286 0 20 0 16021 11 0 0 25 0 1 0 878274225 128475136 30745 1283457024 134512640 136223643 4292719136 18446744073709551615 134712559 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 31366 30745 225 418 0 30946 0 Current children cumulated CPU time (s) 161.89 Current children cumulated vsize (KiB) 128064 [startup+222.311 s] /proc/loadavg: 1.00 1.05 1.01 2/45 7424 /proc/meminfo: memFree=722068/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=126468 CPUtime=220.28 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 33332 0 20 0 22015 13 0 0 25 0 1 0 878274225 129503232 31028 1283457024 134512640 136223643 4292719136 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 31617 31028 225 418 0 31197 0 Current children cumulated CPU time (s) 221.85 Current children cumulated vsize (KiB) 129068 [startup+282.306 s] /proc/loadavg: 1.00 1.04 1.01 2/45 7424 /proc/meminfo: memFree=719464/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=129204 CPUtime=280.19 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 34330 0 20 0 28006 13 0 0 25 0 1 0 878274225 132304896 31699 1283457024 134512640 136223643 4292719136 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 32301 31699 225 418 0 31881 0 Current children cumulated CPU time (s) 281.76 Current children cumulated vsize (KiB) 131804 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.608 s] /proc/loadavg: 1.00 1.04 1.01 2/45 7424 /proc/meminfo: memFree=719464/1048576 swapFree=2077664/2097144 [pid=7410] ppid=7409 vsize=2600 CPUtime=1.57 /proc/7410/stat : 7410 (aspcud-trendy-1) S 7409 7410 4159 34819 4229 4202496 619 18601 0 40 0 0 146 11 15 0 1 0 878274218 2662400 300 1283457024 134512640 135304128 4290084224 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7410/statm: 650 300 253 194 0 36 0 [pid=7422] ppid=7410 vsize=129204 CPUtime=288.5 /proc/7422/stat : 7422 (clasp) R 7410 7410 4159 34819 4229 4202496 34330 0 20 0 28837 13 0 0 25 0 1 0 878274225 132304896 31699 1283457024 134512640 136223643 4292719136 18446744073709551615 134924369 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7422/statm: 32301 31699 225 418 0 31881 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 131804 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.661 CPU time (s): 290.09 CPU user time (s): 289.838 CPU system time (s): 0.252015 CPU usage (%): 99.8034 Max. virtual memory (cumulated for all children) (KiB): 132236 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.838 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= 56165 page faults= 62 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 816 involuntary context switches= 3965 runsolver used 0 second user time and 0.004 second system time The end