February 10, 2009

Impact of logging on MySQL’s performance

Posted by Aleksandr Kuzminsky |

Introduction
When people think about Percona’s microslow patch immediately a question arises how much logging impacts on performance. When we do performance audit often we log every query to find not only slow queries. A query may take less than a second to execute, but a huge number of such queries may significantly load a server. On one hand logging causes sequential writes which can’t impair performance much, on other hand when every query is logged there is a plenty of write operations and obviously performance suffers. Let’s investigate how much.

I took DBT2, an OSDL’s implementation of TPC-C.
Hardware used
The benchmark was run on a DELL server running CentOS release 4.7 (Final)
There are four CPUs Intel(R) Xeon(R) CPU 5150 @ 2.66GHz, 32GB RAM. There are 8 disks in RAID10(a mirror of 4+4 striped disks).
Software
It was used MySQL 5.0.75-percona-b11 on CentOS release 4.7
MySQL setting
There were two cases considered CPU- and IO-bound.
Each case had three options:

  • logging turned off;
  • logging queries which take more than a second to execute;
  • logging every query;

MySQL was run with default settings except following:

[mysqld]
user=root
max_connections=3000
innodb_log_file_size=128M
innodb_flush_log_at_trx_commit=1
innodb_file_per_table
table_cache=2000

Depending on workload different InnoDB buffer was used.
In CPU-bound case

innodb_buffer_pool_size=2G

In IO-bound case

innodb_buffer_pool_size=512M
innodb_flush_method=O_DIRECT

DBT2 settings
For CPU-bound case number of warehouses was 10(1.31GiB). In case of IO-bound load – 100 warehouses which is 10GiB in terms of database size.
The test was run with 1, 20 and 100 database connections
Results
To reduce random error the test was run 3 times per each parameter set.
The metric of a DBT2 test is NOTPM (New Order Transaction per Minute) – the more the better.

CPU-bound case – 10 warehouses

Database size 1.31 GiB
# of connections No logging, NOTPM Logging queries >1 SEC, NOTPM ratio 1 sec / no_logging Logging all queries, NOTPM Ratio all_logging / no_logging
1 9607 9632 1.00 8434 0.88
20 27612 27720 1.00 22105 0.80
100 11704 11741 1.00 10956 0.94


We see here that logging all queries decreases MySQL’s performance on 6-20% depending on a number of connections to a database.
It should be noted during the test it was executed roughly 20-25k queries per second. If all queries are logged – a slow log is populated at rate about 10MB/sec. This is the highest rate observed.
IO-bound case – 100 warehouses

Database size 10GiB
# of connections No logging, NOTPM Logging queries > 1 sec, NOTPM Ratio no_logging / 1 sec_logging Logging all, NOTPM Ratio no_logging / all_logging
1 225 ± 9 211 ± 3 0.94 213 ± 9 0.95
20 767 ± 41 730 ± 35 0.95 751 ± 33 0.98
100 746 ± 54 731 ± 12 0.98 703 ± 36 0.94


In this case every test was run 5 times and random measurement error was calculated. As it is seen from the chart above the performance almost doesn’t depend on logging – the difference doesn’t exceed the measurement error.

The query rate in this case is about 1000 per second.

Logging to /dev/null
It is interesting to know how much from performance degradation caused by the microslow patch itself. Let’s do the same tests but logging to /dev/null.

CPU-bound case – 10 warehouses, Database size: 1.31 GiB
# of connections No logging, NOTPM Logging all queries, NOTPM Ratio all_logging /no_logging
1 9512 8943 0.94
20 27675 25869 0.93
100 11609 11236 0.97


Conclusion
From the all tests above there are two conclusions can be made:

  1. It is safe to log slow queries with execution time bigger than a second without worry about performance impact in case of CPU-bound workload. The performance impact is negligibly small in IO-bound workload even if all queries are logged.
  2. In general logging all queries can hurt MySQL and you should consider the load while using it, especially in CPU-bound case.
Related posts: :Enabling/Disabling query log without server restart in MySQL 5.0::Logging your MySQL command line client sessions::Poor man’s query logging:
 

6 Comments »

  1. So nothing new really, but good to have the numbers. Thanks!

    Comment :: February 10, 2009 @ 4:32 pm

  2. Arjen,

    Exactly — and as has been pointed out over and over, the minute you propose to people the means to figure out where their performance problems are, the first thing they do is anxiously ask “how much overhead does it have.” Look at the PostgreSQL blogging world’s take on this last week:

    http://carymillsap.blogspot.com/2009/02/on-usefulness-of-software.html
    http://prodlife.wordpress.com/2009/02/04/psychology-of-instrumentation/
    http://tkyte.blogspot.com/2005/06/instrumentation.html

    I think this benchmark shows that a) in cases where you’re I/O bound, which is exactly the time when people worry about the impact of logging, it isn’t measurable, and b) it’s not that much overhead anyway.

    Comment :: February 10, 2009 @ 5:02 pm

  3. Interesting your point to Cary Millsap blog.

    I think his Book on Oracle Performance Optimization is one of the best books on performance tuning. It surely taught me a lot when… And a lot of principles are general being it Oracle or MySQL just tools (or lack of tools) is different.

    Comment :: February 10, 2009 @ 10:46 pm

  4. What about logging queries like INSERT INTO binary_table VALUES (123, ‘%LARGE_BINARY_BLOB%’)?

    I’ve found some time ago that for PostgreSQL logging such queries takes more time (and uses a lot of CPU) than this insert executes.

    Comment :: February 11, 2009 @ 7:48 am

  5. This whole topic is one of the reason’s we’ve always been so excited about dtrace. I wonder, perhaps you guys should query the mysql developers to get a copy of their dtrace probes patch for 6.0, and put it into OurDelta now. Probes are pretty non-intrusive; we’ve done them for both Apache and Postgres on our own (though we worked with Sun to get the Postgres ones into core for Postgres 8.4).

    http://labs.omniti.com/trac/project-dtrace/wiki
    http://lethargy.org/~jesus/index.php?serendipity%5Baction%5D=search&serendipity%5BsearchTerm%5D=dtrace&serendipity%5BsearchButton%5D=%3E

    Comment :: February 11, 2009 @ 1:34 pm

  6. Robert,

    Dtrace is cool. The thing is though very little of our customers runs Solaris. I worked w Sun on Dtrace support for MySQL during my time there.

    Comment :: February 11, 2009 @ 5:36 pm

 

Subscribe without commenting

Trackbacks/Pingbacks