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/rand461.cudf.s-e-l.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l/rand461.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand461.cudf.s-e-l.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.12 1.12 5/36 14161 /proc/meminfo: memFree=385772/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2584 CPUtime=0 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 373 0 0 0 0 0 0 0 18 0 1 0 10651420 2646016 279 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/14159/statm: 646 279 234 194 0 33 0 [pid=14160] ppid=14159 vsize=2584 CPUtime=0 /proc/14160/stat : 14160 (aspcud-paranoid) R 14159 14159 4778 34817 4778 4202560 110 0 0 0 0 0 0 0 25 0 1 0 10651420 2646016 132 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/14160/statm: 646 132 86 194 0 33 0 [pid=14161] ppid=14160 vsize=2584 CPUtime=0 /proc/14161/stat : 14161 (aspcud-paranoid) R 14160 14159 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10651420 2646016 46 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/14161/statm: 646 46 0 194 0 33 0 [startup+0.135844 s] /proc/loadavg: 1.10 1.12 1.12 5/36 14161 /proc/meminfo: memFree=385772/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=0.01 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 2939 0 0 0 0 0 1 25 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.205026 s] /proc/loadavg: 1.10 1.12 1.12 5/36 14161 /proc/meminfo: memFree=385772/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=0.01 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 2939 0 0 0 0 0 1 25 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.305022 s] /proc/loadavg: 1.10 1.12 1.12 5/36 14161 /proc/meminfo: memFree=385772/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=0.01 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 2939 0 0 0 0 0 1 25 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.705138 s] /proc/loadavg: 1.10 1.12 1.12 5/36 14161 /proc/meminfo: memFree=385772/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=0.01 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 2939 0 0 0 0 0 1 25 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.50616 s] /proc/loadavg: 1.10 1.12 1.12 2/38 14176 /proc/meminfo: memFree=344904/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=0.01 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 2939 0 0 0 0 0 1 25 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=5708 CPUtime=0.03 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 1337 0 0 0 2 1 0 0 18 0 1 0 10651422 5844992 1123 1283457024 134512640 136285277 4289037376 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 1427 1123 177 433 0 992 0 [pid=14175] ppid=14159 vsize=7400 CPUtime=0.16 /proc/14175/stat : 14175 (gringo) R 14159 14159 4778 34817 4778 4202496 1911 0 0 0 16 0 0 0 18 0 1 0 10651422 7577600 1357 1283457024 134512640 136933539 4293443824 18446744073709551615 135997923 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14175/statm: 1850 1357 242 592 0 1255 0 [pid=14176] ppid=14159 vsize=30576 CPUtime=1.1 /proc/14176/stat : 14176 (cudf2lp) R 14159 14159 4778 34817 4778 4202496 10055 0 0 0 107 3 0 0 25 0 1 0 10651422 31309824 7426 1283457024 134512640 135786343 4292782176 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/14176/statm: 7644 7426 137 311 0 7331 0 Current children cumulated CPU time (s) 1.3 Current children cumulated vsize (KiB) 46276 [startup+3.10784 s] /proc/loadavg: 1.10 1.12 1.12 3/37 14176 /proc/meminfo: memFree=334132/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=24668 CPUtime=0.92 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 7140 0 0 0 86 6 0 0 18 0 1 0 10651422 25260032 5925 1283457024 134512640 136285277 4289037376 18446744073709551615 134959961 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 6167 5925 234 433 0 5732 0 Current children cumulated CPU time (s) 2.9 Current children cumulated vsize (KiB) 27260 [startup+6.30819 s] /proc/loadavg: 1.09 1.12 1.12 2/36 14176 /proc/meminfo: memFree=348788/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=24668 CPUtime=4.12 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 7154 0 0 0 406 6 0 0 25 0 1 0 10651422 25260032 5939 1283457024 134512640 136285277 4289037376 18446744073709551615 134667739 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 6167 5939 234 433 0 5732 0 Current children cumulated CPU time (s) 6.1 Current children cumulated vsize (KiB) 27260 [startup+12.7092 s] /proc/loadavg: 1.08 1.12 1.11 2/36 14176 /proc/meminfo: memFree=348788/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=24668 CPUtime=10.52 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 7155 0 0 0 1046 6 0 0 25 0 1 0 10651422 25260032 5940 1283457024 134512640 136285277 4289037376 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 6167 5940 234 433 0 5732 0 Current children cumulated CPU time (s) 12.5 Current children cumulated vsize (KiB) 27260 [startup+25.5115 s] /proc/loadavg: 1.06 1.11 1.11 2/35 14176 /proc/meminfo: memFree=348796/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=24668 CPUtime=23.32 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 7155 0 0 0 2326 6 0 0 25 0 1 0 10651422 25260032 5940 1283457024 134512640 136285277 4289037376 18446744073709551615 134686712 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 6167 5940 234 433 0 5732 0 Current children cumulated CPU time (s) 25.3 Current children cumulated vsize (KiB) 27260 [startup+51.1076 s] /proc/loadavg: 1.04 1.10 1.11 2/35 14176 /proc/meminfo: memFree=336272/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=38516 CPUtime=48.89 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 10564 0 0 0 4881 8 0 0 25 0 1 0 10651422 39440384 9349 1283457024 134512640 136285277 4289037376 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 9629 9349 234 433 0 9194 0 Current children cumulated CPU time (s) 50.87 Current children cumulated vsize (KiB) 41108 [startup+102.311 s] /proc/loadavg: 1.02 1.08 1.10 2/35 14176 /proc/meminfo: memFree=324864/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=49272 CPUtime=100.04 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 13241 0 0 0 9995 9 0 0 25 0 1 0 10651422 50454528 12026 1283457024 134512640 136285277 4289037376 18446744073709551615 134966690 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 12318 12026 234 433 0 11883 0 Current children cumulated CPU time (s) 102.02 Current children cumulated vsize (KiB) 51864 [startup+162.307 s] /proc/loadavg: 1.00 1.07 1.09 2/35 14176 /proc/meminfo: memFree=324368/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=49536 CPUtime=159.98 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 13327 0 0 0 15988 10 0 0 25 0 1 0 10651422 50724864 12112 1283457024 134512640 136285277 4289037376 18446744073709551615 134733705 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 12384 12112 234 433 0 11949 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 52128 [startup+222.312 s] /proc/loadavg: 1.00 1.05 1.08 2/35 14176 /proc/meminfo: memFree=324120/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=49800 CPUtime=219.92 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 13394 0 0 0 21982 10 0 0 25 0 1 0 10651422 50995200 12179 1283457024 134512640 136285277 4289037376 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 12450 12179 234 433 0 12015 0 Current children cumulated CPU time (s) 221.9 Current children cumulated vsize (KiB) 52392 [startup+282.306 s] /proc/loadavg: 1.00 1.04 1.08 2/37 14180 /proc/meminfo: memFree=323600/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=50064 CPUtime=279.86 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 13470 0 0 0 27976 10 0 0 25 0 1 0 10651422 51265536 12255 1283457024 134512640 136285277 4289037376 18446744073709551615 134930672 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 12516 12255 234 433 0 12081 0 Current children cumulated CPU time (s) 281.84 Current children cumulated vsize (KiB) 52656 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.509 s] /proc/loadavg: 1.00 1.04 1.08 2/37 14181 /proc/meminfo: memFree=323600/1048576 swapFree=0/0 [pid=14159] ppid=14158 vsize=2592 CPUtime=1.98 /proc/14159/stat : 14159 (aspcud-paranoid) S 14158 14159 4778 34817 4778 4202496 654 21221 0 0 0 0 190 8 15 0 1 0 10651420 2654208 298 1283457024 134512640 135304128 4286691904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14159/statm: 648 298 251 194 0 35 0 [pid=14174] ppid=14159 vsize=50064 CPUtime=288.05 /proc/14174/stat : 14174 (clasp) R 14159 14159 4778 34817 4778 4202496 13470 0 0 0 28795 10 0 0 25 0 1 0 10651422 51265536 12255 1283457024 134512640 136285277 4289037376 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/14174/statm: 12516 12255 234 433 0 12081 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 52656 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.538 CPU time (s): 290.066 CPU user time (s): 289.878 CPU system time (s): 0.188011 CPU usage (%): 99.8375 Max. virtual memory (cumulated for all children) (KiB): 52656 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.878 system time used= 0.188011 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 38953 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= 894 involuntary context switches= 4112 runsolver used 0 second user time and 0 second system time The end