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/rand14ba69.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand14ba69.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand14ba69.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.99 0.96 0.91 3/39 10062 /proc/meminfo: memFree=72864/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=0 /proc/10061/stat : 10061 (cudf2pbo4trendy) R 10060 10061 9023 34817 9081 4202496 365 0 0 0 0 0 0 0 25 0 1 0 892759495 2637824 279 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/10061/statm: 644 279 238 194 0 30 0 [pid=10062] ppid=10061 vsize=2576 CPUtime=0 /proc/10062/stat : 10062 (cudf2pbo4trendy) R 10061 10061 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 892759495 2637824 41 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/10062/statm: 644 41 0 194 0 30 0 [startup+0.11538 s] /proc/loadavg: 0.99 0.96 0.91 3/39 10062 /proc/meminfo: memFree=72864/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=0 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892759495 2637824 279 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 279 238 194 0 30 0 [pid=10062] ppid=10061 vsize=6932 CPUtime=0.12 /proc/10062/stat : 10062 (cudf_msu32) R 10061 10061 9023 34817 9081 4202496 1539 0 0 0 12 0 0 0 25 0 1 0 892759495 7098368 1431 1283457024 134512640 136125367 4288052208 18446744073709551615 134717880 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10062/statm: 1733 1431 142 394 0 1337 0 Current children cumulated CPU time (s) 0.12 Current children cumulated vsize (KiB) 9508 [startup+0.205409 s] /proc/loadavg: 0.99 0.96 0.91 3/39 10062 /proc/meminfo: memFree=72864/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=0 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892759495 2637824 279 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 279 238 194 0 30 0 [pid=10062] ppid=10061 vsize=10572 CPUtime=0.2 /proc/10062/stat : 10062 (cudf_msu32) R 10061 10061 9023 34817 9081 4202496 2445 0 0 0 20 0 0 0 25 0 1 0 892759495 10825728 2337 1283457024 134512640 136125367 4288052208 18446744073709551615 134728322 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10062/statm: 2643 2337 143 394 0 2247 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 13148 [startup+0.30541 s] /proc/loadavg: 0.99 0.96 0.91 3/39 10062 /proc/meminfo: memFree=72864/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=0 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892759495 2637824 279 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 279 238 194 0 30 0 [pid=10062] ppid=10061 vsize=14136 CPUtime=0.3 /proc/10062/stat : 10062 (cudf_msu32) R 10061 10061 9023 34817 9081 4202496 3345 0 0 0 30 0 0 0 25 0 1 0 892759495 14475264 3237 1283457024 134512640 136125367 4288052208 18446744073709551615 134717811 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10062/statm: 3534 3237 143 394 0 3138 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16712 [startup+0.70547 s] /proc/loadavg: 0.99 0.96 0.91 3/39 10062 /proc/meminfo: memFree=72864/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=0 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892759495 2637824 279 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 279 238 194 0 30 0 [pid=10062] ppid=10061 vsize=26476 CPUtime=0.7 /proc/10062/stat : 10062 (cudf_msu32) R 10061 10061 9023 34817 9081 4202496 6421 0 0 0 69 1 0 0 25 0 1 0 892759495 27111424 6313 1283457024 134512640 136125367 4288052208 18446744073709551615 134717805 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10062/statm: 6619 6313 143 394 0 6223 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 29052 [startup+1.50558 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10063 /proc/meminfo: memFree=39736/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 Current children cumulated CPU time (s) 1.16 Current children cumulated vsize (KiB) 2576 [startup+3.10588 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10064 /proc/meminfo: memFree=60816/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=16256 CPUtime=1.93 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 5015 0 0 0 133 60 0 0 25 0 1 0 892759612 16646144 3764 1283457024 134512640 135887319 4289564016 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 4064 3764 144 336 0 3726 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 18832 [startup+6.30666 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10064 /proc/meminfo: memFree=48912/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=24572 CPUtime=5.12 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 8401 0 0 0 403 109 0 0 25 0 1 0 892759612 25161728 5839 1283457024 134512640 135887319 4289564016 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 6143 5839 144 336 0 5805 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 27148 [startup+12.7083 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10064 /proc/meminfo: memFree=48788/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=24572 CPUtime=11.52 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 8404 0 0 0 1043 109 0 0 25 0 1 0 892759612 25161728 5842 1283457024 134512640 135887319 4289564016 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 6143 5842 144 336 0 5805 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 27148 [startup+25.5112 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10064 /proc/meminfo: memFree=48664/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=24704 CPUtime=24.31 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 8464 0 0 0 2318 113 0 0 25 0 1 0 892759612 25296896 5902 1283457024 134512640 135887319 4289564016 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 6176 5902 144 336 0 5838 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 27280 [startup+51.1067 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10064 /proc/meminfo: memFree=47300/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=26060 CPUtime=49.88 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 8823 0 0 0 4871 117 0 0 25 0 1 0 892759612 26685440 6235 1283457024 134512640 135887319 4289564016 18446744073709551615 134615472 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 6515 6235 144 336 0 6177 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 28636 [startup+102.308 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10064 /proc/meminfo: memFree=44448/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=28836 CPUtime=101.06 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 9557 0 0 0 9982 124 0 0 25 0 1 0 892759612 29528064 6922 1283457024 134512640 135887319 4289564016 18446744073709551615 134526961 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 7209 6922 144 336 0 6871 0 Current children cumulated CPU time (s) 102.22 Current children cumulated vsize (KiB) 31412 [startup+162.304 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10064 /proc/meminfo: memFree=43828/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=29424 CPUtime=160.94 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 9735 0 0 0 15962 132 0 0 25 0 1 0 892759612 30130176 7064 1283457024 134512640 135887319 4289564016 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 7356 7064 144 336 0 7018 0 Current children cumulated CPU time (s) 162.1 Current children cumulated vsize (KiB) 32000 [startup+222.308 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10064 /proc/meminfo: memFree=41100/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=32048 CPUtime=220.9 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 10514 0 0 0 21953 137 0 0 25 0 1 0 892759612 32817152 7723 1283457024 134512640 135887319 4289564016 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 8012 7723 144 336 0 7674 0 Current children cumulated CPU time (s) 222.06 Current children cumulated vsize (KiB) 34624 [startup+282.305 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10064 /proc/meminfo: memFree=38744/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=34500 CPUtime=280.53 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 11234 0 0 0 27911 142 0 0 25 0 1 0 892759612 35328000 8292 1283457024 134512640 135887319 4289564016 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 8625 8292 144 336 0 8287 0 Current children cumulated CPU time (s) 281.69 Current children cumulated vsize (KiB) 37076 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.707 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10064 /proc/meminfo: memFree=38744/1048576 swapFree=2095372/2097144 [pid=10061] ppid=10060 vsize=2576 CPUtime=1.16 /proc/10061/stat : 10061 (cudf2pbo4trendy) S 10060 10061 9023 34817 9081 4202496 402 8314 0 0 0 0 95 21 18 0 1 0 892759495 2637824 282 1283457024 134512640 135304128 4292741120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10061/statm: 644 282 241 194 0 30 0 [pid=10064] ppid=10061 vsize=34500 CPUtime=288.93 /proc/10064/stat : 10064 (bmo-pblex32) R 10061 10061 9023 34817 9081 4202496 11234 0 0 0 28749 144 0 0 25 0 1 0 892759612 35328000 8292 1283457024 134512640 135887319 4289564016 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10064/statm: 8625 8292 144 336 0 8287 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 37076 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.766 CPU time (s): 290.158 CPU user time (s): 288.502 CPU system time (s): 1.6561 CPU usage (%): 99.791 Max. virtual memory (cumulated for all children) (KiB): 37076 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.502 system time used= 1.6561 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 21672 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= 4611 runsolver used 0 second user time and 0 second system time The end