MySQL Bugs: #30414: Slowdown (related to logging) in 5.1.21 vs. 5.1.20

Bug #30414	Slowdown (related to logging) in 5.1.21 vs. 5.1.20
Submitted:	14 Aug 2007 17:09	Modified:	23 Apr 2013 19:01
Reporter:	Omer Barnir (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S5 (Performance)
Version:	5.1	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	bfsm_2007_10_18, regression

Description:
Running the OLTP throughput tests showed performance to be much slower (on the order of 30-35%. Further investigation revieled that the slowdown is only observed when the system is running with logging on (--log-output=file,table).

The following are three run averages of the sysbench OLTP test (each round included 50 concurrent users and was executed for five minutes) to demonstrate the slowdown. 

Note that without logging the two releases are 'on-par' with 5.1.21 being slightly faster. With logging on, 5.1.21 is about 25% slower.

Results are as follows:
 Release / Logging |   None  |File,Table|
-------+-----------+---------+----------+
       | Read/Sec  |  9,870  |   9,160  |
5.1.20 | Write/Sec |  3,525  |   3,271  |
       | Trans/Sec |    703  |     648  |
-------+-----------+---------+----------+			
       | Read/Sec  | 10,037  |   6,824  |
5.1.21 | Write/Sec |  3,584  |   2,433  |
       | Trans/Sec |    716  |     484  |
-------+-----------+---------+----------+
       | Read/Sec  |  1.69%  | -25.50%  |
Diff   | Write/Sec |  1.69%  | -25.60%  |
       | Trans/Sec |  1.82%  | -25.22%  |
-------+-----------+---------+----------+

Results breaking the file vs table logging will be posted later
 

How to repeat:
Run a sysbench OLTP test with logging turned on and off

Adding data relating to running with 'table' and 'file' logging separately.

 Release / Logging |   None  |File,Table|   File  |   Table  |
-------+-----------+---------+----------+---------+----------+
       | Read/Sec  |  9,870  |   9,160  |  9,657  |   9,391  |
5.1.20 | Write/Sec |  3,525  |   3,271  |  3,456  |   3,353  |
       | Trans/Sec |    703  |     648  |    691  |     669  |
-------+-----------+---------+----------+---------+----------+
       | Read/Sec  | 10,037  |   6,824  |  9,804  |   6,920  |
5.1.21 | Write/Sec |  3,584  |   2,433  |  3,501  |   2,468  |
       | Trans/Sec |    716  |     484  |    699  |     491  |
-------+-----------+---------+----------+---------+----------+
       | Read/Sec  |  1.69%  | -25.50%  |  1.53%  | -26.31%  |
Diff   | Write/Sec |  1.69%  | -25.60%  |  1.31%  | -26.40%  |
       | Trans/Sec |  1.82%  | -25.22%  |  1.27%  | -26.62%  |
-------+-----------+---------+----------+---------+----------+

The numbers show that the slowdown is a result of changes done to table logging and that 'file' logging in 'on-par' with the previous release

One of the possible solutions is to accumulate log records in a thread-local cache and batch writes to the log table. Things that should be taken into account when implementing it:
1. timestamp of the log record should correspond to the time when a log record was generated (and stored in the cache), not when it was written to the table
2. cached log records should not be lost in a crash (but they could go to stderr or a file, not necessarily to a log table)

WL#3726 increases the throughput of LOCK_open, which is the cause of the slowdown, significantly.
The impact/effect of this bug needs to be re-assessed against bzr_mysql-6.0-3726 tree.

The way to fix this bug was discussed in detail by Marc Alff and me in September last year and we agreed how it should be fixed and that it should be fixed ASAP.
Somehow the ASAP got lost...

The impact of a fix should be resonalbe low (ie, very low change to cause regression).

I regard this bug as a critical bug to be fixed before we can make 5.1 GA as this makes one of the flagship features of MySQL 5.1 practically useless.

A note to Manyis comment about LOCK_open:

The problem has nothing to do with log open. Making open faster will only have  a marginal impact on the slowdown. The real problem is that the bug fix in 5.1.21 to address some other problems was done without clear understanding of how the log code works.  Major part of that patch should be reverted and the then the original bugs should be fixed in a proper way.

I don't know a reasonably sized fix for 5.1

Konstantin, ask Marc Alff or me.

Even easier, remove the patch that caused the slowdown and fix the issues the patch tried to do in another way.

As table based logging would be one of our reasons for use to use 5.1.
This big will effect our ability to migrate to 5.1.

I made another measurement, using a MacBook laptop (Intel dual core)
I ran a test with mysqlslap on both versions, under the same conditions.
mysqlslap \
    --concurrency=10,50 \
    --iterations=10 \
    --number-int-cols=2 \
    --number-char-cols=3 \
    --engine=myisam \
    --auto-generate-sql \
    --auto-generate-sql-add-autoincrement \
    --auto-generate-sql-load-type=write,read \
    --auto-generate-sql-execute-number=500

The test was run 10 times for each version and condition. The times below are the averages in seconds.
For each run with table logs, I stopped the logging, emptied the log table, removed the log file, and continued with the next iteration.

+---------+--------+--------------------------+---------------------------+
| version |no logs |  file logs               | table logs                |
+---------+--------+--------------------------+---------------------------+
|         |        |            delta    %    |            delta    %     |
| 5.1.20  |25.809  |  28.942    3.133  10.82% | 33.058     7.248   21.93% |
| 5.1.26  |26.258  |  29.827    3.568  11.96% | 42.550     16.292  38.29% |
+---------+--------+--------------------------+---------------------------+
|  delta   0.449   | 0.884                    |  9.493                    |
|  %       1.71%   | 2.96%                    | 22.31%                    |
+------------------+--------------------------+---------------------------+
The test shows the following:
* 5.1.26 is slightly slower than 5.1.20 (-1.71%)
* the cost of file logging is similar in both versions (10.82% vs 11.96%)
* the regression performance loss of 5.1.26 is 2.96%
* the cost of table logging is 21.93% in 5.1.20 and 38.29% in 5.1.26
* the regression performance loss of 5.1.26 is 22.31%

Overall, I would say that a performance degrade of 38% for table logging is hard to accept.

Further information on my previous comment.
The server was started with no particular options set. The option file only contains datadir,basedir, port, and PID_file.

The test without logging was taken without any other action.

The test with file logging was taken after issuing the command

set global general_log=0;
#
# removed the general log from the data directory, if any
#
set global log_output='FILE';
set global general_log=1;

The test with table logging was taken after issuing the following commands:

set global general_log=0;
truncate mysql.general_log;
set global log_output='TABLE';
set global general_log=1;

@Giuseppe -- I am suspicious of performance results based on Mac OS X. A while back Paul (of PBXT fame) published details on performance hotspots using it and I couldn't duplicate any of the results on Linux. Some things in Mac OS X are much slower than in Linux (mutexes, thread libraries, ...).

Noted in 5.5.7 changelog.

For the general query log and slow query log, logging to tables
incurred excessive overhead beginning with MySQL 5.1.21. This
overhead has been eliminated.