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/201012081719/cudf2pbo4trendy-1.0/rand332173.cudf.impossible.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/impossible//rand332173.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand332173.cudf.impossible.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: 0.88 0.94 0.90 5/39 9738 /proc/meminfo: memFree=66256/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=0 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892495191 2629632 277 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 277 238 194 0 28 0 [pid=9738] ppid=9737 vsize=2580 CPUtime=0.02 /proc/9738/stat : 9738 (cudf_msu32) R 9737 9737 9023 34817 9081 4202496 438 0 0 0 2 0 0 0 25 0 1 0 892495191 2641920 331 1283457024 134512640 136125367 4286927584 18446744073709551615 134717807 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9738/statm: 645 331 141 394 0 249 0 [startup+0.185364 s] /proc/loadavg: 0.88 0.94 0.90 5/39 9738 /proc/meminfo: memFree=66256/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=0 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892495191 2629632 277 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 277 238 194 0 28 0 [pid=9738] ppid=9737 vsize=9372 CPUtime=0.18 /proc/9738/stat : 9738 (cudf_msu32) R 9737 9737 9023 34817 9081 4202496 2160 0 0 0 18 0 0 0 25 0 1 0 892495191 9596928 2053 1283457024 134512640 136125367 4286927584 18446744073709551615 135549868 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9738/statm: 2343 2053 142 394 0 1947 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 11940 [startup+0.205365 s] /proc/loadavg: 0.88 0.94 0.90 5/39 9738 /proc/meminfo: memFree=66256/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=0 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892495191 2629632 277 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 277 238 194 0 28 0 [pid=9738] ppid=9737 vsize=10164 CPUtime=0.2 /proc/9738/stat : 9738 (cudf_msu32) R 9737 9737 9023 34817 9081 4202496 2335 0 0 0 20 0 0 0 25 0 1 0 892495191 10407936 2228 1283457024 134512640 136125367 4286927584 18446744073709551615 134738431 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9738/statm: 2541 2228 142 394 0 2145 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 12732 [startup+0.305387 s] /proc/loadavg: 0.88 0.94 0.90 5/39 9738 /proc/meminfo: memFree=66256/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=0 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892495191 2629632 277 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 277 238 194 0 28 0 [pid=9738] ppid=9737 vsize=13620 CPUtime=0.3 /proc/9738/stat : 9738 (cudf_msu32) R 9737 9737 9023 34817 9081 4202496 3229 0 0 0 28 2 0 0 25 0 1 0 892495191 13946880 3122 1283457024 134512640 136125367 4286927584 18446744073709551615 135533302 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9738/statm: 3405 3122 143 394 0 3009 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16188 [startup+0.705453 s] /proc/loadavg: 0.88 0.94 0.90 5/39 9738 /proc/meminfo: memFree=66256/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=0 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892495191 2629632 277 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 277 238 194 0 28 0 [pid=9738] ppid=9737 vsize=25696 CPUtime=0.7 /proc/9738/stat : 9738 (cudf_msu32) R 9737 9737 9023 34817 9081 4202496 6246 0 0 0 67 3 0 0 25 0 1 0 892495191 26312704 6139 1283457024 134512640 136125367 4286927584 18446744073709551615 134711046 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9738/statm: 6424 6139 143 394 0 6028 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 28264 [startup+1.50559 s] /proc/loadavg: 0.89 0.94 0.90 2/40 9739 /proc/meminfo: memFree=32188/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=0 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892495191 2629632 277 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 277 238 194 0 28 0 [pid=9738] ppid=9737 vsize=46248 CPUtime=1.5 /proc/9738/stat : 9738 (cudf_msu32) R 9737 9737 9023 34817 9081 4202496 11446 0 0 0 144 6 0 0 25 0 1 0 892495191 47357952 11290 1283457024 134512640 136125367 4286927584 18446744073709551615 135078406 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9738/statm: 11562 11290 153 394 0 11166 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 48816 [startup+3.10586 s] /proc/loadavg: 0.89 0.94 0.90 3/40 9739 /proc/meminfo: memFree=5296/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=0 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892495191 2629632 277 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 277 238 194 0 28 0 [pid=9738] ppid=9737 vsize=74308 CPUtime=3.09 /proc/9738/stat : 9738 (cudf_msu32) R 9737 9737 9023 34817 9081 4202496 18766 0 0 0 249 60 0 0 25 0 1 0 892495191 76091392 18315 1283457024 134512640 136125367 4286927584 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9738/statm: 18577 18315 165 394 0 18181 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 76876 [startup+6.3066 s] /proc/loadavg: 0.89 0.94 0.90 2/40 9740 /proc/meminfo: memFree=42588/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=37604 CPUtime=3.11 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 9920 0 0 0 237 74 0 0 25 0 1 0 892495510 38506496 8999 1283457024 134512640 135887319 4294541872 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 9401 8999 138 336 0 9063 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 40172 [startup+12.708 s] /proc/loadavg: 0.90 0.94 0.90 2/40 9740 /proc/meminfo: memFree=28576/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=51880 CPUtime=9.5 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 15453 0 0 0 722 228 0 0 25 0 1 0 892495510 53125120 12589 1283457024 134512640 135887319 4294541872 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 12970 12589 144 336 0 12632 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 54448 [startup+25.5115 s] /proc/loadavg: 0.92 0.94 0.90 2/40 9740 /proc/meminfo: memFree=6572/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=78800 CPUtime=22.27 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 26981 0 0 0 1830 397 0 0 25 0 1 0 892495510 80691200 19440 1283457024 134512640 135887319 4294541872 18446744073709551615 134598397 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 19700 19440 144 336 0 19362 0 Current children cumulated CPU time (s) 25.45 Current children cumulated vsize (KiB) 81368 [startup+51.1092 s] /proc/loadavg: 0.94 0.94 0.91 2/40 9740 /proc/meminfo: memFree=5136/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=90684 CPUtime=47.8 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 30162 0 0 0 4129 651 0 0 25 0 1 0 892495510 92860416 22420 1283457024 134512640 135887319 4294541872 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 22671 22420 144 336 0 22333 0 Current children cumulated CPU time (s) 50.98 Current children cumulated vsize (KiB) 93252 [startup+102.307 s] /proc/loadavg: 0.98 0.95 0.91 2/40 9740 /proc/meminfo: memFree=6060/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=96548 CPUtime=98.92 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 31707 0 0 0 9232 660 0 0 25 0 1 0 892495510 98865152 23866 1283457024 134512640 135887319 4294541872 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 24137 23866 144 336 0 23799 0 Current children cumulated CPU time (s) 102.1 Current children cumulated vsize (KiB) 99116 [startup+162.304 s] /proc/loadavg: 0.99 0.95 0.91 2/40 9740 /proc/meminfo: memFree=5496/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=102848 CPUtime=158.88 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 33336 0 0 0 15218 670 0 0 25 0 1 0 892495510 105316352 25442 1283457024 134512640 135887319 4294541872 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 25712 25442 144 336 0 25374 0 Current children cumulated CPU time (s) 162.06 Current children cumulated vsize (KiB) 105416 [startup+222.313 s] /proc/loadavg: 0.99 0.96 0.91 2/41 9744 /proc/meminfo: memFree=5520/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=108080 CPUtime=218.83 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 34703 0 0 0 21207 676 0 0 25 0 1 0 892495510 110673920 26747 1283457024 134512640 135887319 4294541872 18446744073709551615 134617654 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 27020 26747 144 336 0 26682 0 Current children cumulated CPU time (s) 222.01 Current children cumulated vsize (KiB) 110648 [startup+282.31 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9744 /proc/meminfo: memFree=5252/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=113112 CPUtime=278.78 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 36045 0 0 0 27190 688 0 0 25 0 1 0 892495510 115826688 27985 1283457024 134512640 135887319 4294541872 18446744073709551615 134614989 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 28278 27985 144 336 0 27940 0 Current children cumulated CPU time (s) 281.96 Current children cumulated vsize (KiB) 115680 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.412 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9744 /proc/meminfo: memFree=5708/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2568 CPUtime=3.18 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 400 18768 0 0 0 0 256 62 20 0 1 0 892495191 2629632 280 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 642 280 241 194 0 28 0 [pid=9740] ppid=9737 vsize=113784 CPUtime=286.87 /proc/9740/stat : 9740 (bmo-pblex32) R 9737 9737 9023 34817 9081 4202496 36219 0 0 0 27999 688 0 0 25 0 1 0 892495510 116514816 28141 1283457024 134512640 135887319 4294541872 18446744073709551615 134605656 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9740/statm: 28446 28141 144 336 0 28108 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 116352 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.532 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9744 /proc/meminfo: memFree=5708/1048576 swapFree=2095372/2097144 [pid=9737] ppid=9736 vsize=2572 CPUtime=290.06 /proc/9737/stat : 9737 (cudf2pbo4trendy) S 9736 9737 9023 34817 9081 4202496 440 54991 0 0 0 0 28256 750 17 0 1 0 892495191 2633728 285 1283457024 134512640 135304128 4291321504 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9737/statm: 643 285 245 194 0 29 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 2572 Child status: 0 Real time (s): 290.553 CPU time (s): 290.194 CPU user time (s): 282.67 CPU system time (s): 7.52447 CPU usage (%): 99.8765 Max. virtual memory (cumulated for all children) (KiB): 116352 getrusage(RUSAGE_CHILDREN,...) data: user time used= 282.67 system time used= 7.52447 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 57786 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= 24 involuntary context switches= 11200 runsolver used 0 second user time and 0 second system time The end