MySQL Binary Log activated = high-end server damn slow

Question

On MySQL 5.1(.57-1.dotdeb), I have a ~2.0Gb database, and an average of ~350 requests per second.

All is running fine if I don't activate the binary log. The CPU usage is decent (~15% of 1 CPU core).

And if I activate the binary log, all is suddenly HYPER slow. The requests average come down to ~90 requests / sec, and every request takes +/- 4 seconds to finish.

You have to know that :

• MySQL is properly tuned, tuning-primer.sh gives good results in "normal" time
• The hardware is a Bi-Xeon E5620 (Westmere generation) with 24 GO RAM
• 12 GO of RAM is allowed for InnoDB
• Running Debian 6 64bits

When the binary log is activated :

• The CPU usage of MySQL is damn LOW. About 1 or 2% of 1 core. No much %wa for I/O in "top", about 5-7%.
• The memory usage seems fine. I have tested with 1 GO for InnoDB instead of 12 GO, no change.
• The queries are so long to execute, then php5-fpm create a lot of new processes to handle the traffic.

In normal time, I have ~15 PHP-FPM workers, and if the binary log is activated, this number can up to 150-200 (max).

No need to precise that all the system is frozen at this point. :-)

Here is my.cnf :

    [client] 
    port     = 3306 
    socket   = /var/run/mysqld/mysqld.sock 


    [mysqld_safe] 
    socket   = /var/run/mysqld/mysqld.sock 
    nice     = 0 

    [mysqld] 
    user     = mysql 
    pid-file    = /var/run/mysqld/mysqld.pid 
    socket   = /var/run/mysqld/mysqld.sock 
    port     = 3306 
    basedir  = /usr 
    datadir  = /var/lib/mysql 
    tmpdir   = /tmp 
    language    = /usr/share/mysql/english 
    skip-external-locking 

    bind-address     = 127.0.0.1 

    key_buffer   = 16M 
    max_allowed_packet  = 16M 
    thread_stack     = 192K 
    thread_cache_size = 32 

    myisam-recover = BACKUP 
    max_connections = 200 

    table_cache = 512 

    #thread_concurrency = 10 

    query_cache_limit   = 1M 
    query_cache_size = 16M 

    max_heap_table_size = 64M 
    tmp_table_size = 64M 

    innodb_buffer_pool_size = 12G 

    #general_log_file = /var/log/mysql/mysql.log 
    #general_log = 1 

    long_query_time = 4 
    #log_slow_queries   = /var/log/mysql/mysql-slow.log 
    #log-queries-not-using-indexes 

    #server-id   = 1 
    #report-host=host 


    # NOTE : All the values here are uncommented when i activate binlog 

    #log-bin     = /var/log/mysql/mysql-bin.log 
    #log-error   = /var/log/mysql/mysql-err.log 
    #sync_binlog = 0 
    #binlog_cache_size = 128M 
    #expire_logs_days   = 2 
    #max_binlog_size = 100M 
    #max_binlog_cache_size = 1G 


    [mysqldump] 
    quick 
    quote-names 
    max_allowed_packet  = 16M 

    [mysql] 
    #no-auto-rehash # faster start of mysql but no tab completition 

    [isamchk] 
    key_buffer   = 16M 

    !includedir /etc/mysql/conf.d/ 

Tell me if you have any idea about that issue !

Thanks

---

EDIT 1 @Jason :

After setting innodb_log_file_size = 1G, shutting down the server, renamed the ib_logfile0 and ib_logfile1, restarted the server with binlog.

The mysql server just do not respond at all. It's so slow that no page is displayed this time.

Note that there is no problem if I deactivate the binlog again.

The load averages seems to be high : 3.5, even if the CPU is not so solicited...

---

EDIT 3 :

@Jason , @Bryan

After all,

It seems to be a bug of MySQL 5.1.

After many tests, nothing changed.

Not a CPU, RAM, or IO related problem.

I switched one of my server to Percona MySQL 5.5 and it just works fine now, with the same hardware, database and configuration.

Maybe 20% or 30% faster than MySQL 5.1...

What else?

Solution 1

What is your distribution of reads to writes? Do you have a write intensive application?

What is your disk subsystem like?

You have not specified innodb_log_file_size. On a busy server the default is way too low. Increasing this may help with your I/O woes when the binary log is enabled.

Also, sync_binlog = 0 is not recommended since if the server crashes your binary log will be out of sync with the transactions.

Cheers

Solution 2

Your hardware setup seems pretty powerful on memory and processor. Turning on bin-logs means quite a bit more writing to disk, have you tried putting your bin-logs on a different physical disk?

Comments

[HTTP500]

Anything noteworthy in mysql-err.log when the binary log is enabled?

[HTTP500]

Can you keep binlog_cache_size commented out when you enable the binary log? I think that is being allocated FOR EACH CLIENT.

[Romain]

@Jason : tested, seems better, PHPMyAdmin is working with binlog now, but the webapp still absolutely slow. Note that if i try to acceed to the webapp DB into PHPMyAdmin, it's slow too. Maybe a DB related problem ?!

[HTTP500]

Not sure. Hard to troubleshoot in this medium - you might need to engage a consultant for some hands on troubleshooting. Another common performance penalty in webapps though is that a lot of temporary tables are created on disk. You can run: mysqladmin -u root -p ext -ri 30 | grep Created_tmp_disk to see if you get a lot of tables created on disk. If you do you can put MySQL's tmpdir on tmpfs (RAM disk).

[Romain]

@Jason : thanks anyways for your tips :) I have 48 tmp disk tables, but only because I use some longblobs. Not seems to be a serious issue...

[Romain]

Hi, thanks for your answer ! There is about 50% writes, and 50% reads on the requests. The DB in on an Hard RAID 1, 2Gb disks, SAS. The innodb_log_file_size is 5M. What value should I set here ?

[Romain]

So yes, we can say there is a lot of "small" writes in my web application. The idea to me was to make a master/slave replication, and distribute the write requests to the master, and the read requests to the slave(s). The read requests are much bigger that write requests.

[HTTP500]

MySQL will say that innodb_log_file_size should be 1/2 the size of your buffer pool but specifying such a large size may take a long time upon recovery if the server crashes. You could probably set it to 1024M to start and go from there. Note that you need to cleanly create new ib_logfile* i.e. you need to specify the parameter/value, cleanly shutdown your server, move aside the old files and restart your server.

[HTTP500]

If your RAID card has a battery-backed write cache you can also consider setting innodb_flush_method = O_DIRECT but I'd suggest doing the changes systematically to determine the relative benefit.

[Romain]

@Jason : view my EDIT 2 please for my.cnf details. Nothing changed, when I restart MySQL, the server is absolutely slow. Nothing anormal in logs.

[Romain]

Hello Bryan, thanks for the answer ! No I can't because I only have this RAID 1 to work with (data-center based server). How can I test the speed of the actual hardware ?

[HTTP500]

@Romain,Did you you keep binlog_cache_size commented out when you enabled the binary log? Did you see my comment above?

[Romain]

@Jason : yes, answer previous :-)