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/rand7902a8.cudf.impossible.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/impossible//rand7902a8.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand7902a8.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.95 0.97 0.91 6/35 11762 /proc/meminfo: memFree=62896/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=0 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893678266 2629632 277 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 277 238 194 0 28 0 [pid=11762] ppid=11761 vsize=2312 CPUtime=0.01 /proc/11762/stat : 11762 (cudf_msu32) R 11761 11761 9023 34817 9081 4202496 392 0 0 0 1 0 0 0 25 0 1 0 893678266 2367488 285 1283457024 134512640 136125367 4292413472 18446744073709551615 134738371 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11762/statm: 578 285 141 394 0 182 0 [startup+0.202693 s] /proc/loadavg: 0.95 0.97 0.91 6/35 11762 /proc/meminfo: memFree=62896/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=0 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893678266 2629632 277 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 277 238 194 0 28 0 [pid=11762] ppid=11761 vsize=10028 CPUtime=0.2 /proc/11762/stat : 11762 (cudf_msu32) R 11761 11761 9023 34817 9081 4202496 2323 0 0 0 20 0 0 0 25 0 1 0 893678266 10268672 2216 1283457024 134512640 136125367 4292413472 18446744073709551615 134738423 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11762/statm: 2507 2216 142 394 0 2111 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 12596 [startup+0.312716 s] /proc/loadavg: 0.95 0.97 0.91 6/35 11762 /proc/meminfo: memFree=62896/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=0 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893678266 2629632 277 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 277 238 194 0 28 0 [pid=11762] ppid=11761 vsize=14012 CPUtime=0.31 /proc/11762/stat : 11762 (cudf_msu32) R 11761 11761 9023 34817 9081 4202496 3305 0 0 0 30 1 0 0 25 0 1 0 893678266 14348288 3198 1283457024 134512640 136125367 4292413472 18446744073709551615 135544633 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11762/statm: 3503 3198 143 394 0 3107 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 16580 [startup+0.402738 s] /proc/loadavg: 0.95 0.97 0.91 6/35 11762 /proc/meminfo: memFree=62896/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=0 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893678266 2629632 277 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 277 238 194 0 28 0 [pid=11762] ppid=11761 vsize=16916 CPUtime=0.39 /proc/11762/stat : 11762 (cudf_msu32) R 11761 11761 9023 34817 9081 4202496 4040 0 0 0 37 2 0 0 25 0 1 0 893678266 17321984 3933 1283457024 134512640 136125367 4292413472 18446744073709551615 134717946 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11762/statm: 4229 3933 143 394 0 3833 0 Current children cumulated CPU time (s) 0.39 Current children cumulated vsize (KiB) 19484 [startup+0.712802 s] /proc/loadavg: 0.95 0.97 0.91 6/35 11762 /proc/meminfo: memFree=62896/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=0 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893678266 2629632 277 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 277 238 194 0 28 0 [pid=11762] ppid=11761 vsize=26088 CPUtime=0.7 /proc/11762/stat : 11762 (cudf_msu32) R 11761 11761 9023 34817 9081 4202496 6325 0 0 0 67 3 0 0 25 0 1 0 893678266 26714112 6218 1283457024 134512640 136125367 4292413472 18446744073709551615 134717759 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11762/statm: 6522 6218 143 394 0 6126 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 28656 [startup+1.51297 s] /proc/loadavg: 1.04 0.99 0.92 2/36 11763 /proc/meminfo: memFree=27952/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=0 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893678266 2629632 277 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 277 238 194 0 28 0 [pid=11762] ppid=11761 vsize=46524 CPUtime=1.5 /proc/11762/stat : 11762 (cudf_msu32) R 11761 11761 9023 34817 9081 4202496 11492 0 0 0 143 7 0 0 25 0 1 0 893678266 47640576 11336 1283457024 134512640 136125367 4292413472 18446744073709551615 134712016 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11762/statm: 11631 11336 153 394 0 11235 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 49092 [startup+3.11337 s] /proc/loadavg: 1.04 0.99 0.92 2/36 11763 /proc/meminfo: memFree=5356/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=0 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893678266 2629632 277 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 277 238 194 0 28 0 [pid=11762] ppid=11761 vsize=73668 CPUtime=3.08 /proc/11762/stat : 11762 (cudf_msu32) R 11761 11761 9023 34817 9081 4202496 18655 0 0 0 248 60 0 0 25 0 1 0 893678266 75436032 18156 1283457024 134512640 136125367 4292413472 18446744073709551615 135516509 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11762/statm: 18417 18156 165 394 0 18021 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 76236 [startup+6.31421 s] /proc/loadavg: 1.04 0.99 0.92 2/36 11764 /proc/meminfo: memFree=44584/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=36228 CPUtime=3.15 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 9587 0 0 0 221 94 0 0 25 0 1 0 893678582 37097472 8639 1283457024 134512640 135887319 4289271072 18446744073709551615 134617654 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 9057 8639 138 336 0 8719 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 38796 [startup+12.711 s] /proc/loadavg: 1.03 0.99 0.92 2/36 11764 /proc/meminfo: memFree=31820/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=49176 CPUtime=9.37 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 14741 0 0 0 683 254 0 0 25 0 1 0 893678582 50356224 11892 1283457024 134512640 135887319 4289271072 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 12294 11892 144 336 0 11956 0 Current children cumulated CPU time (s) 12.49 Current children cumulated vsize (KiB) 51744 [startup+25.5046 s] /proc/loadavg: 1.03 0.99 0.92 2/36 11764 /proc/meminfo: memFree=5764/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=76924 CPUtime=22.16 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 25898 0 0 0 1776 440 0 0 25 0 1 0 893678582 78770176 18948 1283457024 134512640 135887319 4289271072 18446744073709551615 134640425 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 19231 18948 144 336 0 18893 0 Current children cumulated CPU time (s) 25.28 Current children cumulated vsize (KiB) 79492 [startup+51.113 s] /proc/loadavg: 1.02 0.99 0.92 2/36 11764 /proc/meminfo: memFree=6020/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=82124 CPUtime=47.73 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 27235 0 0 0 4305 468 0 0 25 0 1 0 893678582 84094976 20250 1283457024 134512640 135887319 4289271072 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 20531 20250 144 336 0 20193 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 84692 [startup+102.307 s] /proc/loadavg: 1.00 0.99 0.92 2/36 11764 /proc/meminfo: memFree=5132/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=89168 CPUtime=98.86 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 29040 0 0 0 9411 475 0 0 25 0 1 0 893678582 91308032 22007 1283457024 134512640 135887319 4289271072 18446744073709551615 134614902 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 22292 22007 144 336 0 21954 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 91736 [startup+162.304 s] /proc/loadavg: 1.00 0.99 0.92 2/36 11764 /proc/meminfo: memFree=6304/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=93852 CPUtime=158.84 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 30267 0 0 0 15400 484 0 0 25 0 1 0 893678582 96104448 23151 1283457024 134512640 135887319 4289271072 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 23463 23151 144 336 0 23125 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 96420 Solver just ended. Dumping a history of the last processes samples [startup+166.506 s] /proc/loadavg: 1.00 0.99 0.92 2/38 11766 /proc/meminfo: memFree=5396/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=94116 CPUtime=162.98 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 30335 0 0 0 15814 484 0 0 25 0 1 0 893678582 96374784 23216 1283457024 134512640 135887319 4289271072 18446744073709551615 134605835 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 23529 23216 144 336 0 23191 0 Current children cumulated CPU time (s) 166.1 Current children cumulated vsize (KiB) 96684 [startup+169.707 s] /proc/loadavg: 1.00 0.99 0.92 2/38 11766 /proc/meminfo: memFree=6164/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=94248 CPUtime=166.17 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 30388 0 0 0 16133 484 0 0 25 0 1 0 893678582 96509952 23263 1283457024 134512640 135887319 4289271072 18446744073709551615 134603354 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 23562 23263 144 336 0 23224 0 Current children cumulated CPU time (s) 169.29 Current children cumulated vsize (KiB) 96816 [startup+172.908 s] /proc/loadavg: 1.00 0.99 0.92 2/39 11767 /proc/meminfo: memFree=5892/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=94512 CPUtime=169.37 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 30439 0 0 0 16453 484 0 0 25 0 1 0 893678582 96780288 23314 1283457024 134512640 135887319 4289271072 18446744073709551615 134604726 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 23628 23314 144 336 0 23290 0 Current children cumulated CPU time (s) 172.49 Current children cumulated vsize (KiB) 97080 [startup+174.508 s] /proc/loadavg: 1.00 0.99 0.92 2/39 11769 /proc/meminfo: memFree=6016/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=94512 CPUtime=170.95 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 30457 0 0 0 16609 486 0 0 25 0 1 0 893678582 96780288 23332 1283457024 134512640 135887319 4289271072 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 23628 23332 144 336 0 23290 0 Current children cumulated CPU time (s) 174.07 Current children cumulated vsize (KiB) 97080 [startup+175.309 s] /proc/loadavg: 1.00 0.99 0.92 2/39 11769 /proc/meminfo: memFree=5892/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=3.12 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 399 18657 0 0 0 0 250 62 18 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 [pid=11764] ppid=11761 vsize=94644 CPUtime=171.75 /proc/11764/stat : 11764 (bmo-pblex32) R 11761 11761 9023 34817 9081 4202496 30479 0 0 0 16689 486 0 0 25 0 1 0 893678582 96915456 23350 1283457024 134512640 135887319 4289271072 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11764/statm: 23661 23350 144 336 0 23323 0 Current children cumulated CPU time (s) 174.87 Current children cumulated vsize (KiB) 97212 [startup+175.709 s] /proc/loadavg: 1.00 0.99 0.92 2/39 11769 /proc/meminfo: memFree=5892/1048576 swapFree=2095372/2097144 [pid=11761] ppid=11760 vsize=2568 CPUtime=175.17 /proc/11761/stat : 11761 (cudf2pbo4trendy) S 11760 11761 9023 34817 9081 4202496 429 49585 0 0 0 0 16967 550 21 0 1 0 893678266 2629632 280 1283457024 134512640 135304128 4290424272 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11761/statm: 642 280 241 194 0 28 0 Current children cumulated CPU time (s) 175.17 Current children cumulated vsize (KiB) 2568 Child status: 0 Real time (s): 175.712 CPU time (s): 175.291 CPU user time (s): 169.783 CPU system time (s): 5.50834 CPU usage (%): 99.7603 Max. virtual memory (cumulated for all children) (KiB): 97212 getrusage(RUSAGE_CHILDREN,...) data: user time used= 169.783 system time used= 5.50834 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 51970 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= 26 involuntary context switches= 5966 runsolver used 0.008 second user time and 0 second system time The end