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/rand95e48b.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand95e48b.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand95e48b.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.01 0.97 0.91 3/35 13517 /proc/meminfo: memFree=68700/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=0 /proc/13516/stat : 13516 (cudf2pbo4trendy) R 13515 13516 9023 34817 9081 4202496 365 0 0 0 0 0 0 0 25 0 1 0 894592754 2633728 279 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/13516/statm: 643 279 238 194 0 29 0 [pid=13517] ppid=13516 vsize=2572 CPUtime=0 /proc/13517/stat : 13517 (cudf2pbo4trendy) R 13516 13516 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 894592755 2633728 41 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/13517/statm: 643 41 0 194 0 29 0 [startup+0.117141 s] /proc/loadavg: 1.01 0.97 0.91 3/35 13517 /proc/meminfo: memFree=68700/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=0 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894592754 2633728 279 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 279 238 194 0 29 0 [pid=13517] ppid=13516 vsize=6932 CPUtime=0.12 /proc/13517/stat : 13517 (cudf_msu32) R 13516 13516 9023 34817 9081 4202496 1556 0 0 0 12 0 0 0 25 0 1 0 894592755 7098368 1448 1283457024 134512640 136125367 4286872272 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13517/statm: 1733 1448 142 394 0 1337 0 Current children cumulated CPU time (s) 0.12 Current children cumulated vsize (KiB) 9504 [startup+0.207175 s] /proc/loadavg: 1.01 0.97 0.91 3/35 13517 /proc/meminfo: memFree=68700/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=0 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894592754 2633728 279 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 279 238 194 0 29 0 [pid=13517] ppid=13516 vsize=10572 CPUtime=0.2 /proc/13517/stat : 13517 (cudf_msu32) R 13516 13516 9023 34817 9081 4202496 2445 0 0 0 20 0 0 0 25 0 1 0 894592755 10825728 2337 1283457024 134512640 136125367 4286872272 18446744073709551615 134728322 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13517/statm: 2643 2337 143 394 0 2247 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 13144 [startup+0.307188 s] /proc/loadavg: 1.01 0.97 0.91 3/35 13517 /proc/meminfo: memFree=68700/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=0 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894592754 2633728 279 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 279 238 194 0 29 0 [pid=13517] ppid=13516 vsize=14004 CPUtime=0.3 /proc/13517/stat : 13517 (cudf_msu32) R 13516 13516 9023 34817 9081 4202496 3324 0 0 0 30 0 0 0 25 0 1 0 894592755 14340096 3216 1283457024 134512640 136125367 4286872272 18446744073709551615 135176278 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13517/statm: 3501 3216 143 394 0 3105 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16576 [startup+0.707295 s] /proc/loadavg: 1.01 0.97 0.91 3/35 13517 /proc/meminfo: memFree=68700/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=0 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894592754 2633728 279 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 279 238 194 0 29 0 [pid=13517] ppid=13516 vsize=26080 CPUtime=0.7 /proc/13517/stat : 13517 (cudf_msu32) R 13516 13516 9023 34817 9081 4202496 6341 0 0 0 69 1 0 0 25 0 1 0 894592755 26705920 6233 1283457024 134512640 136125367 4286872272 18446744073709551615 134738395 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13517/statm: 6520 6233 143 394 0 6124 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 28652 [startup+1.50755 s] /proc/loadavg: 1.01 0.97 0.91 2/36 13518 /proc/meminfo: memFree=35804/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 Current children cumulated CPU time (s) 1.25 Current children cumulated vsize (KiB) 2572 [startup+3.10794 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=56636/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=12804 CPUtime=1.82 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 3512 0 0 0 118 64 0 0 25 0 1 0 894592881 13111296 2903 1283457024 134512640 135887319 4287253296 18446744073709551615 134624768 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 3201 2903 138 336 0 2863 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 15376 [startup+6.30881 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=48948/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=24384 CPUtime=5 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 8449 0 0 0 363 137 0 0 25 0 1 0 894592881 24969216 5812 1283457024 134512640 135887319 4287253296 18446744073709551615 134603601 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 6096 5812 144 336 0 5758 0 Current children cumulated CPU time (s) 6.25 Current children cumulated vsize (KiB) 26956 [startup+12.7104 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=44740/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=24384 CPUtime=11.39 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 8493 0 0 0 990 149 0 0 25 0 1 0 894592881 24969216 5852 1283457024 134512640 135887319 4287253296 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 6096 5852 144 336 0 5758 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 26956 [startup+25.5137 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=43376/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=25704 CPUtime=24.18 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 8838 0 0 0 2269 149 0 0 25 0 1 0 894592881 26320896 6184 1283457024 134512640 135887319 4287253296 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 6426 6184 144 336 0 6088 0 Current children cumulated CPU time (s) 25.43 Current children cumulated vsize (KiB) 28276 [startup+51.1116 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=40772/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=28644 CPUtime=49.77 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 9589 0 0 0 4818 159 0 0 25 0 1 0 894592881 29331456 6882 1283457024 134512640 135887319 4287253296 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 7161 6882 144 336 0 6823 0 Current children cumulated CPU time (s) 51.02 Current children cumulated vsize (KiB) 31216 [startup+102.308 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=35192/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=33860 CPUtime=100.81 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 10984 0 0 0 9917 164 0 0 25 0 1 0 894592881 34672640 8224 1283457024 134512640 135887319 4287253296 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 8465 8224 144 336 0 8127 0 Current children cumulated CPU time (s) 102.06 Current children cumulated vsize (KiB) 36432 [startup+162.313 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=29612/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=39628 CPUtime=160.74 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 12539 0 0 0 15892 182 0 0 25 0 1 0 894592881 40579072 9616 1283457024 134512640 135887319 4287253296 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 9907 9616 144 336 0 9569 0 Current children cumulated CPU time (s) 161.99 Current children cumulated vsize (KiB) 42200 [startup+222.308 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=29612/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=39628 CPUtime=220.67 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 12539 0 0 0 21880 187 0 0 25 0 1 0 894592881 40579072 9616 1283457024 134512640 135887319 4287253296 18446744073709551615 134527030 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 9907 9616 144 336 0 9569 0 Current children cumulated CPU time (s) 221.92 Current children cumulated vsize (KiB) 42200 [startup+282.304 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=28868/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=40420 CPUtime=280.48 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 12749 0 0 0 27842 206 0 0 25 0 1 0 894592881 41390080 9822 1283457024 134512640 135887319 4287253296 18446744073709551615 134526961 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 10105 9822 144 336 0 9767 0 Current children cumulated CPU time (s) 281.73 Current children cumulated vsize (KiB) 42992 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.607 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=27876/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=41344 CPUtime=288.78 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 12971 0 0 0 28670 208 0 0 25 0 1 0 894592881 42336256 10043 1283457024 134512640 135887319 4287253296 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 10336 10043 144 336 0 9998 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 43916 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.607 s] /proc/loadavg: 1.00 0.97 0.91 2/36 13519 /proc/meminfo: memFree=27876/1048576 swapFree=2095372/2097144 [pid=13516] ppid=13515 vsize=2572 CPUtime=1.25 /proc/13516/stat : 13516 (cudf2pbo4trendy) S 13515 13516 9023 34817 9081 4202496 403 8366 0 0 0 0 106 19 18 0 1 0 894592754 2633728 282 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13516/statm: 643 282 241 194 0 29 0 [pid=13519] ppid=13516 vsize=41344 CPUtime=288.78 /proc/13519/stat : 13519 (bmo-pblex32) R 13516 13516 9023 34817 9081 4202496 12971 0 0 0 28670 208 0 0 25 0 1 0 894592881 42336256 10043 1283457024 134512640 135887319 4287253296 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13519/statm: 10336 10043 144 336 0 9998 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 43916 Child status: 0 Real time (s): 290.676 CPU time (s): 290.11 CPU user time (s): 287.818 CPU system time (s): 2.29214 CPU usage (%): 99.8052 Max. virtual memory (cumulated for all children) (KiB): 43916 getrusage(RUSAGE_CHILDREN,...) data: user time used= 287.818 system time used= 2.29214 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 23460 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= 9 involuntary context switches= 5325 runsolver used 0 second user time and 0 second system time The end