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/randa870aa.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//randa870aa.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/randa870aa.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.00 1.00 0.92 5/35 13990 /proc/meminfo: memFree=53832/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=0 /proc/13989/stat : 13989 (cudf2pbo4trendy) R 13988 13989 9023 34817 9081 4202496 365 0 0 0 0 0 0 0 25 0 1 0 894695388 2629632 278 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/13989/statm: 642 278 238 194 0 28 0 [pid=13990] ppid=13989 vsize=2568 CPUtime=0 /proc/13990/stat : 13990 (cudf2pbo4trendy) R 13989 13989 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 894695388 2629632 40 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/13990/statm: 642 40 0 194 0 28 0 [startup+0.115089 s] /proc/loadavg: 1.00 1.00 0.92 5/35 13990 /proc/meminfo: memFree=53832/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=0 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894695388 2629632 278 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 278 238 194 0 28 0 [pid=13990] ppid=13989 vsize=6664 CPUtime=0.11 /proc/13990/stat : 13990 (cudf_msu32) R 13989 13989 9023 34817 9081 4202496 1462 0 0 0 11 0 0 0 25 0 1 0 894695388 6823936 1355 1283457024 134512640 136125367 4292075456 18446744073709551615 134717966 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13990/statm: 1666 1355 142 394 0 1270 0 Current children cumulated CPU time (s) 0.11 Current children cumulated vsize (KiB) 9232 [startup+0.205109 s] /proc/loadavg: 1.00 1.00 0.92 5/35 13990 /proc/meminfo: memFree=53832/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=0 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894695388 2629632 278 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 278 238 194 0 28 0 [pid=13990] ppid=13989 vsize=10108 CPUtime=0.2 /proc/13990/stat : 13990 (cudf_msu32) R 13989 13989 9023 34817 9081 4202496 2328 0 0 0 18 2 0 0 25 0 1 0 894695388 10350592 2221 1283457024 134512640 136125367 4292075456 18446744073709551615 134727103 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13990/statm: 2527 2221 142 394 0 2131 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 12676 [startup+0.305123 s] /proc/loadavg: 1.00 1.00 0.92 5/35 13990 /proc/meminfo: memFree=53832/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=0 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894695388 2629632 278 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 278 238 194 0 28 0 [pid=13990] ppid=13989 vsize=13736 CPUtime=0.3 /proc/13990/stat : 13990 (cudf_msu32) R 13989 13989 9023 34817 9081 4202496 3235 0 0 0 28 2 0 0 25 0 1 0 894695388 14065664 3128 1283457024 134512640 136125367 4292075456 18446744073709551615 134717880 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13990/statm: 3434 3128 143 394 0 3038 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16304 [startup+0.705183 s] /proc/loadavg: 1.00 1.00 0.92 5/35 13990 /proc/meminfo: memFree=53832/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=0 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894695388 2629632 278 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 278 238 194 0 28 0 [pid=13990] ppid=13989 vsize=26076 CPUtime=0.7 /proc/13990/stat : 13990 (cudf_msu32) R 13989 13989 9023 34817 9081 4202496 6326 0 0 0 67 3 0 0 25 0 1 0 894695388 26701824 6219 1283457024 134512640 136125367 4292075456 18446744073709551615 134718178 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/13990/statm: 6519 6219 143 394 0 6123 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 28644 [startup+1.50538 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13991 /proc/meminfo: memFree=20952/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 Current children cumulated CPU time (s) 1.22 Current children cumulated vsize (KiB) 2568 [startup+3.10563 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=41784/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=16296 CPUtime=1.87 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 5020 0 0 0 120 67 0 0 25 0 1 0 894695511 16687104 3749 1283457024 134512640 135887319 4290395696 18446744073709551615 134600912 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 4074 3749 144 336 0 3736 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 18864 [startup+6.30682 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=30128/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=24400 CPUtime=5.06 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 8451 0 0 0 402 104 0 0 25 0 1 0 894695511 24985600 5789 1283457024 134512640 135887319 4290395696 18446744073709551615 134603622 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 6100 5789 144 336 0 5762 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 26968 [startup+12.71 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=30012/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=24400 CPUtime=11.46 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 8468 0 0 0 1041 105 0 0 25 0 1 0 894695511 24985600 5806 1283457024 134512640 135887319 4290395696 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 6100 5806 144 336 0 5762 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 26968 [startup+25.5033 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=29640/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=24664 CPUtime=24.26 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 8560 0 0 0 2318 108 0 0 25 0 1 0 894695511 25255936 5892 1283457024 134512640 135887319 4290395696 18446744073709551615 134605912 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 6166 5892 144 336 0 5828 0 Current children cumulated CPU time (s) 25.48 Current children cumulated vsize (KiB) 27232 [startup+51.109 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=28524/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=26004 CPUtime=49.85 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 8917 0 0 0 4873 112 0 0 25 0 1 0 894695511 26628096 6210 1283457024 134512640 135887319 4290395696 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 6501 6210 144 336 0 6163 0 Current children cumulated CPU time (s) 51.07 Current children cumulated vsize (KiB) 28572 [startup+102.311 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=25796/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=28584 CPUtime=100.99 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 9626 0 0 0 9977 122 0 0 25 0 1 0 894695511 29270016 6866 1283457024 134512640 135887319 4290395696 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 7146 6866 144 336 0 6808 0 Current children cumulated CPU time (s) 102.21 Current children cumulated vsize (KiB) 31152 [startup+162.31 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=22820/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=31696 CPUtime=160.91 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 10490 0 0 0 15956 135 0 0 25 0 1 0 894695511 32456704 7610 1283457024 134512640 135887319 4290395696 18446744073709551615 134624367 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 7924 7610 144 336 0 7586 0 Current children cumulated CPU time (s) 162.13 Current children cumulated vsize (KiB) 34264 [startup+222.305 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=19100/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=35168 CPUtime=220.85 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 11542 0 0 0 21940 145 0 0 25 0 1 0 894695511 36012032 8510 1283457024 134512640 135887319 4290395696 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 8792 8510 144 336 0 8454 0 Current children cumulated CPU time (s) 222.07 Current children cumulated vsize (KiB) 37736 [startup+282.312 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=18728/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=35864 CPUtime=280.79 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 11727 0 0 0 27925 154 0 0 25 0 1 0 894695511 36724736 8619 1283457024 134512640 135887319 4290395696 18446744073709551615 135381632 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 8966 8619 144 336 0 8628 0 Current children cumulated CPU time (s) 282.01 Current children cumulated vsize (KiB) 38432 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.404 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=18728/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=35864 CPUtime=288.87 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 11727 0 0 0 28731 156 0 0 25 0 1 0 894695511 36724736 8619 1283457024 134512640 135887319 4290395696 18446744073709551615 134603241 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 8966 8619 144 336 0 8628 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 38432 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.404 s] /proc/loadavg: 1.00 1.00 0.92 2/36 13992 /proc/meminfo: memFree=18728/1048576 swapFree=2095372/2097144 [pid=13989] ppid=13988 vsize=2568 CPUtime=1.22 /proc/13989/stat : 13989 (cudf2pbo4trendy) S 13988 13989 9023 34817 9081 4202496 402 8336 0 0 0 0 102 20 18 0 1 0 894695388 2629632 281 1283457024 134512640 135304128 4288314304 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/13989/statm: 642 281 241 194 0 28 0 [pid=13992] ppid=13989 vsize=35864 CPUtime=288.87 /proc/13992/stat : 13992 (bmo-pblex32) R 13989 13989 9023 34817 9081 4202496 11727 0 0 0 28731 156 0 0 25 0 1 0 894695511 36724736 8619 1283457024 134512640 135887319 4290395696 18446744073709551615 134603241 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/13992/statm: 8966 8619 144 336 0 8628 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 38432 Child status: 0 Real time (s): 290.465 CPU time (s): 290.162 CPU user time (s): 288.378 CPU system time (s): 1.78411 CPU usage (%): 99.8957 Max. virtual memory (cumulated for all children) (KiB): 38432 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.378 system time used= 1.78411 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22176 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= 4783 runsolver used 0 second user time and 0 second system time The end