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/rand4d6b1c.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand4d6b1c.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand4d6b1c.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: 0.92 0.93 0.90 4/35 12084 /proc/meminfo: memFree=62580/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=0 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893861016 2629632 278 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 278 238 194 0 28 0 [pid=12084] ppid=12083 vsize=2576 CPUtime=0.02 /proc/12084/stat : 12084 (cudf_msu32) R 12083 12083 9023 34817 9081 4202496 464 0 0 0 2 0 0 0 25 0 1 0 893861016 2637824 357 1283457024 134512640 136125367 4290969280 18446744073709551615 134727069 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/12084/statm: 644 357 142 394 0 248 0 [startup+0.227477 s] /proc/loadavg: 0.92 0.93 0.90 4/35 12084 /proc/meminfo: memFree=62580/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=0 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893861016 2629632 278 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 278 238 194 0 28 0 [pid=12084] ppid=12083 vsize=11232 CPUtime=0.22 /proc/12084/stat : 12084 (cudf_msu32) R 12083 12083 9023 34817 9081 4202496 2617 0 0 0 22 0 0 0 25 0 1 0 893861016 11501568 2510 1283457024 134512640 136125367 4290969280 18446744073709551615 134738215 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/12084/statm: 2808 2510 143 394 0 2412 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 13800 [startup+0.307494 s] /proc/loadavg: 0.92 0.93 0.90 4/35 12084 /proc/meminfo: memFree=62580/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=0 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893861016 2629632 278 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 278 238 194 0 28 0 [pid=12084] ppid=12083 vsize=14136 CPUtime=0.3 /proc/12084/stat : 12084 (cudf_msu32) R 12083 12083 9023 34817 9081 4202496 3353 0 0 0 30 0 0 0 25 0 1 0 893861016 14475264 3246 1283457024 134512640 136125367 4290969280 18446744073709551615 134717890 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/12084/statm: 3534 3246 143 394 0 3138 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16704 [startup+0.407514 s] /proc/loadavg: 0.92 0.93 0.90 4/35 12084 /proc/meminfo: memFree=62580/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=0 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893861016 2629632 278 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 278 238 194 0 28 0 [pid=12084] ppid=12083 vsize=17436 CPUtime=0.4 /proc/12084/stat : 12084 (cudf_msu32) R 12083 12083 9023 34817 9081 4202496 4170 0 0 0 38 2 0 0 25 0 1 0 893861016 17854464 4063 1283457024 134512640 136125367 4290969280 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/12084/statm: 4359 4063 143 394 0 3963 0 Current children cumulated CPU time (s) 0.4 Current children cumulated vsize (KiB) 20004 [startup+0.707573 s] /proc/loadavg: 0.92 0.93 0.90 4/35 12084 /proc/meminfo: memFree=62580/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=0 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893861016 2629632 278 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 278 238 194 0 28 0 [pid=12084] ppid=12083 vsize=26608 CPUtime=0.7 /proc/12084/stat : 12084 (cudf_msu32) R 12083 12083 9023 34817 9081 4202496 6457 0 0 0 66 4 0 0 25 0 1 0 893861016 27246592 6350 1283457024 134512640 136125367 4290969280 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/12084/statm: 6652 6350 153 394 0 6256 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 29176 [startup+1.50773 s] /proc/loadavg: 0.92 0.93 0.90 3/36 12086 /proc/meminfo: memFree=55840/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=12436 CPUtime=0.33 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 3407 0 0 0 25 8 0 0 22 0 1 0 893861133 12734464 2811 1283457024 134512640 135887319 4293234928 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 3109 2811 138 336 0 2771 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 15004 [startup+3.10806 s] /proc/loadavg: 0.92 0.93 0.90 2/36 12086 /proc/meminfo: memFree=50756/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=16384 CPUtime=1.94 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 5004 0 0 0 129 65 0 0 25 0 1 0 893861133 16777216 3782 1283457024 134512640 135887319 4293234928 18446744073709551615 134637796 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 4096 3782 144 336 0 3758 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 18952 [startup+6.30872 s] /proc/loadavg: 0.93 0.94 0.90 2/36 12086 /proc/meminfo: memFree=38116/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=25276 CPUtime=5.11 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 8624 0 0 0 379 132 0 0 25 0 1 0 893861133 25882624 6027 1283457024 134512640 135887319 4293234928 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 6319 6027 144 336 0 5981 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 27844 [startup+12.7098 s] /proc/loadavg: 0.93 0.94 0.90 2/36 12086 /proc/meminfo: memFree=37124/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=26068 CPUtime=11.52 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 8848 0 0 0 1015 137 0 0 25 0 1 0 893861133 26693632 6239 1283457024 134512640 135887319 4293234928 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 6517 6239 144 336 0 6179 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 28636 [startup+25.509 s] /proc/loadavg: 0.95 0.94 0.90 2/36 12086 /proc/meminfo: memFree=36132/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=27136 CPUtime=24.19 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 9127 0 0 0 2279 140 0 0 25 0 1 0 893861133 27787264 6503 1283457024 134512640 135887319 4293234928 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 6784 6503 144 336 0 6446 0 Current children cumulated CPU time (s) 25.35 Current children cumulated vsize (KiB) 29704 [startup+51.107 s] /proc/loadavg: 0.96 0.94 0.91 2/36 12086 /proc/meminfo: memFree=33652/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=29568 CPUtime=49.62 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 9774 0 0 0 4816 146 0 0 25 0 1 0 893861133 30277632 7108 1283457024 134512640 135887319 4293234928 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 7392 7108 144 336 0 7054 0 Current children cumulated CPU time (s) 50.78 Current children cumulated vsize (KiB) 32136 [startup+102.309 s] /proc/loadavg: 0.98 0.95 0.91 2/36 12086 /proc/meminfo: memFree=28320/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=34928 CPUtime=100.78 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 11300 0 0 0 9926 152 0 0 25 0 1 0 893861133 35766272 8432 1283457024 134512640 135887319 4293234928 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 8732 8432 144 336 0 8394 0 Current children cumulated CPU time (s) 101.94 Current children cumulated vsize (KiB) 37496 [startup+162.311 s] /proc/loadavg: 0.99 0.95 0.91 2/36 12086 /proc/meminfo: memFree=26708/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=36512 CPUtime=160.75 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 11709 0 0 0 15907 168 0 0 25 0 1 0 893861133 37388288 8835 1283457024 134512640 135887319 4293234928 18446744073709551615 134603601 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 9128 8835 144 336 0 8790 0 Current children cumulated CPU time (s) 161.91 Current children cumulated vsize (KiB) 39080 [startup+222.305 s] /proc/loadavg: 0.99 0.96 0.91 2/36 12086 /proc/meminfo: memFree=24848/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=38476 CPUtime=220.67 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 12264 0 0 0 21876 191 0 0 25 0 1 0 893861133 39399424 9299 1283457024 134512640 135887319 4293234928 18446744073709551615 134525046 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 9619 9299 144 336 0 9281 0 Current children cumulated CPU time (s) 221.83 Current children cumulated vsize (KiB) 41044 [startup+282.311 s] /proc/loadavg: 0.99 0.97 0.91 2/36 12086 /proc/meminfo: memFree=23732/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=39556 CPUtime=280.6 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 12543 0 0 0 27855 205 0 0 25 0 1 0 893861133 40505344 9557 1283457024 134512640 135887319 4293234928 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 9889 9557 144 336 0 9551 0 Current children cumulated CPU time (s) 281.76 Current children cumulated vsize (KiB) 42124 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.613 s] /proc/loadavg: 0.99 0.97 0.91 2/36 12086 /proc/meminfo: memFree=23732/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=39556 CPUtime=288.89 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 12543 0 0 0 28684 205 0 0 25 0 1 0 893861133 40505344 9557 1283457024 134512640 135887319 4293234928 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 9889 9557 144 336 0 9551 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 42124 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.613 s] /proc/loadavg: 0.99 0.97 0.91 2/36 12086 /proc/meminfo: memFree=23732/1048576 swapFree=2095372/2097144 [pid=12083] ppid=12082 vsize=2568 CPUtime=1.16 /proc/12083/stat : 12083 (cudf2pbo4trendy) S 12082 12083 9023 34817 9081 4202496 401 8294 0 0 0 0 92 24 20 0 1 0 893861016 2629632 281 1283457024 134512640 135304128 4288658464 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/12083/statm: 642 281 241 194 0 28 0 [pid=12086] ppid=12083 vsize=39556 CPUtime=288.89 /proc/12086/stat : 12086 (bmo-pblex32) R 12083 12083 9023 34817 9081 4202496 12543 0 0 0 28684 205 0 0 25 0 1 0 893861133 40505344 9557 1283457024 134512640 135887319 4293234928 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/12086/statm: 9889 9557 144 336 0 9551 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 42124 Child status: 0 Real time (s): 290.674 CPU time (s): 290.13 CPU user time (s): 287.822 CPU system time (s): 2.30814 CPU usage (%): 99.8128 Max. virtual memory (cumulated for all children) (KiB): 42124 getrusage(RUSAGE_CHILDREN,...) data: user time used= 287.822 system time used= 2.30814 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22947 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= 8 involuntary context switches= 5931 runsolver used 0 second user time and 0 second system time The end