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/randf61f65.cudf.difficult.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/difficult//randf61f65.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/randf61f65.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.12 1.12 1.06 5/43 7849 /proc/meminfo: memFree=654376/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2592 CPUtime=0 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 18 0 1 0 885700943 2654208 282 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/7846/statm: 648 282 237 194 0 34 0 [pid=7847] ppid=7846 vsize=2592 CPUtime=0 /proc/7847/stat : 7847 (aspcud-trendy-1) S 7846 7846 4159 34819 4229 4202560 113 0 0 0 0 0 0 0 18 0 1 0 885700943 2654208 129 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/7847/statm: 648 129 83 194 0 34 0 [pid=7848] ppid=7847 vsize=2592 CPUtime=0 /proc/7848/stat : 7848 (aspcud-trendy-1) R 7847 7846 4159 34819 4229 4202560 126 0 0 0 0 0 0 0 25 0 1 0 885700943 2654208 149 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/7848/statm: 648 149 103 194 0 34 0 [pid=7849] ppid=7848 vsize=2592 CPUtime=0 /proc/7849/stat : 7849 (aspcud-trendy-1) R 7848 7846 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 885700943 2654208 46 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/7849/statm: 648 46 0 194 0 34 0 [startup+0.144156 s] /proc/loadavg: 1.12 1.12 1.06 5/43 7849 /proc/meminfo: memFree=654376/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=0 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 2220 0 0 0 0 0 0 25 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.204174 s] /proc/loadavg: 1.12 1.12 1.06 5/43 7849 /proc/meminfo: memFree=654376/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=0 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 2220 0 0 0 0 0 0 25 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.304187 s] /proc/loadavg: 1.12 1.12 1.06 5/43 7849 /proc/meminfo: memFree=654376/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=0 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 2220 0 0 0 0 0 0 25 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.70426 s] /proc/loadavg: 1.12 1.12 1.06 5/43 7849 /proc/meminfo: memFree=654376/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=0 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 2220 0 0 0 0 0 0 25 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+1.50439 s] /proc/loadavg: 1.12 1.12 1.06 3/44 7860 /proc/meminfo: memFree=614676/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=0.88 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 11440 0 0 0 0 84 4 18 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=14336 CPUtime=0.06 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 3790 0 0 0 6 0 0 0 18 0 1 0 885700944 14680064 3270 1283457024 134512640 136223643 4290305392 18446744073709551615 134820334 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 3584 3270 174 418 0 3164 0 [pid=7859] ppid=7846 vsize=24224 CPUtime=0.53 /proc/7859/stat : 7859 (gringo) R 7846 7846 4159 34819 4229 4202496 6097 0 0 0 53 0 0 0 18 0 1 0 885700944 24805376 4516 1283457024 134512640 136959103 4288183280 18446744073709551615 135656494 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7859/statm: 6056 4516 256 598 0 5455 0 Current children cumulated CPU time (s) 1.47 Current children cumulated vsize (KiB) 41164 [startup+3.10476 s] /proc/loadavg: 1.12 1.12 1.06 2/42 7860 /proc/meminfo: memFree=633060/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=23972 CPUtime=1.49 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 6637 0 0 0 148 1 0 0 19 0 1 0 885700944 24547328 5442 1283457024 134512640 136223643 4290305392 18446744073709551615 134929444 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 5993 5442 225 418 0 5573 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 26576 [startup+6.3055 s] /proc/loadavg: 1.11 1.12 1.06 2/42 7860 /proc/meminfo: memFree=633060/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=23972 CPUtime=4.69 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 6637 0 0 0 468 1 0 0 25 0 1 0 885700944 24547328 5442 1283457024 134512640 136223643 4290305392 18446744073709551615 134711200 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 5993 5442 225 418 0 5573 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 26576 [startup+12.7068 s] /proc/loadavg: 1.10 1.12 1.06 2/42 7860 /proc/meminfo: memFree=629844/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=27536 CPUtime=11.07 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 7536 0 0 0 1106 1 0 0 25 0 1 0 885700944 28196864 6341 1283457024 134512640 136223643 4290305392 18446744073709551615 134650453 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 6884 6341 225 418 0 6464 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 30140 [startup+25.5094 s] /proc/loadavg: 1.08 1.11 1.06 2/42 7860 /proc/meminfo: memFree=609880/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=47552 CPUtime=23.86 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 12530 0 0 0 2384 2 0 0 25 0 1 0 885700944 48693248 11335 1283457024 134512640 136223643 4290305392 18446744073709551615 134929219 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 11888 11335 225 418 0 11468 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 50156 [startup+51.1063 s] /proc/loadavg: 1.05 1.10 1.06 2/42 7860 /proc/meminfo: memFree=582352/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=75116 CPUtime=49.44 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 19543 0 0 0 4938 6 0 0 25 0 1 0 885700944 76918784 18195 1283457024 134512640 136223643 4290305392 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 18779 18195 225 418 0 18359 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 77720 [startup+102.31 s] /proc/loadavg: 1.02 1.08 1.05 2/42 7860 /proc/meminfo: memFree=547260/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=110244 CPUtime=100.59 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 28783 0 0 0 10051 8 0 0 25 0 1 0 885700944 112889856 26936 1283457024 134512640 136223643 4290305392 18446744073709551615 134630032 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 27561 26936 225 418 0 27141 0 Current children cumulated CPU time (s) 102.19 Current children cumulated vsize (KiB) 112848 [startup+162.305 s] /proc/loadavg: 1.01 1.07 1.04 2/42 7860 /proc/meminfo: memFree=545772/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=111696 CPUtime=160.56 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 29148 0 0 0 16047 9 0 0 25 0 1 0 885700944 114376704 27301 1283457024 134512640 136223643 4290305392 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 27924 27301 225 418 0 27504 0 Current children cumulated CPU time (s) 162.16 Current children cumulated vsize (KiB) 114300 [startup+222.313 s] /proc/loadavg: 1.00 1.05 1.04 2/42 7860 /proc/meminfo: memFree=543540/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=113280 CPUtime=220.48 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 29796 0 0 0 22039 9 0 0 25 0 1 0 885700944 115998720 27711 1283457024 134512640 136223643 4290305392 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 28320 27711 225 418 0 27900 0 Current children cumulated CPU time (s) 222.08 Current children cumulated vsize (KiB) 115884 [startup+282.306 s] /proc/loadavg: 1.00 1.04 1.03 2/42 7860 /proc/meminfo: memFree=543540/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=113676 CPUtime=280.41 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 29870 0 0 0 28031 10 0 0 25 0 1 0 885700944 116404224 27785 1283457024 134512640 136223643 4290305392 18446744073709551615 134906376 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 28419 27785 225 418 0 27999 0 Current children cumulated CPU time (s) 282.01 Current children cumulated vsize (KiB) 116280 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.307 s] /proc/loadavg: 1.00 1.04 1.03 2/42 7860 /proc/meminfo: memFree=543540/1048576 swapFree=2080288/2097144 [pid=7846] ppid=7845 vsize=2604 CPUtime=1.6 /proc/7846/stat : 7846 (aspcud-trendy-1) S 7845 7846 4159 34819 4229 4202496 623 18678 0 0 0 0 155 5 15 0 1 0 885700943 2666496 301 1283457024 134512640 135304128 4288185264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7846/statm: 651 301 253 194 0 37 0 [pid=7858] ppid=7846 vsize=113676 CPUtime=288.41 /proc/7858/stat : 7858 (clasp) R 7846 7846 4159 34819 4229 4202496 29870 0 0 0 28830 11 0 0 25 0 1 0 885700944 116404224 27785 1283457024 134512640 136223643 4290305392 18446744073709551615 134704859 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7858/statm: 28419 27785 225 418 0 27999 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 116280 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.337 CPU time (s): 290.03 CPU user time (s): 289.854 CPU system time (s): 0.176011 CPU usage (%): 99.8942 Max. virtual memory (cumulated for all children) (KiB): 116940 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.854 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= 51781 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= 747 involuntary context switches= 3927 runsolver used 0 second user time and 0.012 second system time The end