MySQL Bugs: #38551: RBR/MBR + Query Cache + "invalidating query cache entries (table)" => slow slave

Bug #38551	RBR/MBR + Query Cache + "invalidating query cache entries (table)" => slow slave
Submitted:	4 Aug 2008 22:08	Modified:	1 Dec 2009 16:07
Reporter:	Neel Nadgir	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Query Cache	Severity:	S5 (Performance)
Version:	5.1, 6.0	OS:	Any
Assigned to:	Kristofer Pettersson	CPU Architecture:	Any
Tags:	performance

Description:
Since the Query cache hurts some workloads, we turn if off by setting query_cache_size=0. However, the Query Cache still does some work before finding out that query_cache_size is 0 and returning.

For example, QueryCache::invalidate() builds up a list of tables used, and calls QueryCache::invalidate_table(). QueryCache::invalidate_table locks the query cache, invalidates the QC if query_cache_size > 0, unlocks QC and returns.  The current code actually locks/unlocks the query_cache lock twice when the query_cache_size is zero!. This can all be bypassed if the check for query_cache_size is done without holding the QC lock as in Query_cache::store_query

The CPU time wasted is very less, however, in benchmark situations, every cpu cycle counts.

How to repeat:
Run a sysbench read-write benchmark with lots of threads. Measure the time spent in QueryCache::invalidate()

Bug #38207 seems to be related to this bug here.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/53515

2735 Kristofer Pettersson	2008-09-08
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
      
      When the query cache size is zero, all query cache functionallity should be
      skipped. Since query_cache_size is protected from any changes by the
      barrier in Query_cache::resize() we can safely add a test at the begining
      of the invalidate* functions to avoid having mutexes locked when
      the query cache is ment to be disabled.

..of course to be fully protected we can't by pass the QC in case of a flush by must hold.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/55912

2768 Kristofer Pettersson	2008-10-09
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
                  
      When the query cache size is zero, all query cache functionallity should be
      skipped.
            
      By checking query_cache_size before attempting to invalidate a table or
      db we avoid grabbing the query cache mutex. If the rare cases the query cache
      size would change so we get a false read the cache has either been cleared or

progress report: There is a confusion about the visibility and atomicity which can be expected. This makes it difficult to make a good decision without showing the concrete performance consequences to each decision. Currently nobody wants: 1) a blocking mutex 2) a client barrier on a write. 3) Only be able to disable query cache at compile time/startup time. What is left to investigate is if it really is possible to read query_cache_size in a concurrent environment and if the rare but occasional lack of consistence when the query_cache_size change is an issue for the overall system performance.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/56418

2666 Kristofer Pettersson	2008-10-16
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
                    
      When the query cache is disabled, the server shouldn't attempt to take the 
      query cache mutex.
              
      By using the command line option --query_cache_type=0, the user can disable
      the query cache permanently and avoid taking the query cache mutex.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57125

2742 Kristofer Pettersson	2008-10-27
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
                          
      When the query cache is disabled, the server shouldn't attempt to take the 
      query cache mutex.
                    
      By using the command line option --query_cache_type=0, the user can disable
      the query cache permanently and avoid taking the query cache mutex.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57127

2743 Kristofer Pettersson	2008-10-27
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
      
      Adding additional test case.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57199

2742 Kristofer Pettersson	2008-10-28
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
                                
      When the query cache is disabled, the server shouldn't attempt to take the 
      query cache mutex.
                          
      By using the command line option --query_cache_type=0, the user can disable
      the query cache permanently and avoid taking the query cache mutex.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57302

2742 Kristofer Pettersson	2008-10-29
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
                                      
      When the query cache is disabled, the server shouldn't attempt to take the 
      query cache mutex.
                               
      By using the command line option --query_cache_type=0, the user can disable
      the query cache permanently and avoid taking the query cache mutex.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57327

2742 Kristofer Pettersson	2008-10-29
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
                                      
      When the query cache is disabled, the server shouldn't attempt to take the 
      query cache mutex.
                            
      By using the command line option --query_cache_type=0, the user can disable
      the query cache permanently and avoid taking the query cache mutex.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58178

2917 Kristofer Pettersson	2008-11-07
      Bug#38551 query cache can still consume [very little] cpu time even when it is off.
                                            
      When the query cache is disabled, the server shouldn't attempt to take the 
      query cache mutex.
                                  
      By using the command line option --query_cache_type=0, the user can disable
      the query cache permanently and avoid taking the query cache mutex.

Pushed into 6.0.9-alpha  (revid:kristofer.pettersson@sun.com-20081107140159-6unylckzptcal73g) (version source revid:kristofer.pettersson@sun.com-20081107140159-6unylckzptcal73g) (pib:5)

Noted in 6.0.9 changelog.

The server unnecessarily acquired a query cache mutex even with the
query cache disabled, resulting in a small performance decrement.

This would be easy to backport to 5.0. Are there plans for that?

I'd like an answer to Mark's question too.  What's the backport plan for this?

At this time there is no plan to backport the fix to a stable release as it changes the behavior of the query_cache_type command line option. Also, if query cache is not used at all, one can build (or request a build) with query cache disabled (see --without-query-cache).

Pushed into 5.4.4-alpha (revid:alik@sun.com-20090916063112-8hjmu6wkxfx5qxf4) (version source revid:guilhem@mysql.com-20090708213845-36vjraclcpz7mwlq) (merge vers: 5.4.4-alpha) (pib:11)

Updated changelog entry:

The server unnecessarily acquired a query cache mutex even with the
query cache disabled, resulting in a small performance decrement. Now
if the server is started with query_cache_type set to 0, it does not
acquire the query cache mutex. This has the implication that the
query cache cannot be enabled at runtime.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

http://lists.mysql.com/commits/88574

2900 Kristofer Pettersson 2009-10-29
Bug#38551 query cache can still consume [very little] cpu time even when it is off.

When the query cache is disabled, the server shouldn't attempt to take the
query cache mutex.

By using the command line option --query_cache_type=0, the user can disable

(backport from mysql-pe)
@ mysql-test/t/query_cache_disabled-master.opt
* added test case for bug38551
@ mysql-test/t/query_cache_disabled.test
* added test case for bug38551
@ sql/set_var.cc
* Added before-trigger to verify that query_cache_type wasn't turned off or on during
runtime.
@ sql/set_var.h
* Changed order on how the enumeration is processed. By first projecting the
character representation of the variable to a temporary integer we can have
one function instead of two to check if the value is valid.
@ sql/share/errmsg-utf8.txt
* Added error message for query cache disabled state
@ sql/sql_cache.cc
* If the query cache is disabled at start up, shorten the execution path and avoid
grabbing the query cache mutex each time the invalidate interface methods are called.
@ sql/sql_cache.h
* Added new methods to set the query cache into a disabled state.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091102151658-j9o4wgro47m5v84d) (version source revid:alik@sun.com-20091102151658-j9o4wgro47m5v84d) (merge vers: 6.0.14-alpha) (pib:13)

Already fixed in earlier 6.0.x release.

Pushed into 5.5.0-beta (revid:alik@sun.com-20091110093229-0bh5hix780cyeicl) (version source revid:mikael@mysql.com-20091103113702-p61dlwc6ml6fxg18) (merge vers: 5.5.0-beta) (pib:13)

Noted in 5.5.0 changelog.

Paul, please update the release note to:

The server unnecessarily acquired a query cache mutex even with the query cache disabled, resulting in a small performance decrement which could show up as threads often in state "invalidating query cache entries (table)", particularly on a replication slave with row-based replication. Now if the server is started with query_cache_type set to 0, it does not acquire the query cache mutex. This has the implication that the query cache cannot be enabled at runtime.

This is to note where we're commonly seeing customers encountering this issue and to give them an explicit clue that this fix will solve their problem. See bug #38207 for the symptom I've described being associated with this bug.

Please also add the performance tag for this fix, because of the impact on CPU use for RBR.

James, done, thanks.

Is this going to be put into 5.1?  I see a request to backport to 5.1, and I see pushes to 6.0, 5.5 and 5.4, but no fix for 5.1...

I am having the problem described in http://bugs.mysql.com/bug.php?id=38207 on:

mysql> select @@version;
+------------------+
| @@version        |
+------------------+
| 5.1.41-community |
+------------------+
1 row in set (0.00 sec)

binlog format is MIXED, and there are loads are to MyISAM files.  Replication is the only process running on this machine, and it can't keep up due to this bug.

Here's SHOW PROCESSLIST:

mysql> show processlist;
+-------+-------------+--------------------------------------+------+---------+--------+------------------------------------------+------------------+
| Id    | User        | Host                                 | db   | Command | Time   | State                                    | Info             |
+-------+-------------+--------------------------------------+------+---------+--------+------------------------------------------+------------------+
|  5252 | system user |                                      | NULL | Connect |  80756 | Waiting for master to send event         | NULL             |
|  5253 | system user |                                      | NULL | Connect | 101583 | invalidating query cache entries (table) | NULL             |
| 10893 | avail3      | localhost:44662                      | NULL | Query   |      0 | NULL                                     | show processlist |
+-------+-------------+--------------------------------------+------+---------+--------+------------------------------------------+------------------+
3 rows in set (0.00 sec)

The SQL thread of replication also shows "freeing items" frequently as well.

The query cache is off (size is 0, but type is 0 too just in case)

mysql> SHOW GLOBAL VARIABLES LIKE 'query_cache%';
+------------------------------+---------+
| Variable_name                | Value   |
+------------------------------+---------+
| query_cache_limit            | 1048576 |
| query_cache_min_res_unit     | 4096    |
| query_cache_size             | 0       |
| query_cache_type             | OFF     |
| query_cache_wlock_invalidate | OFF     |
+------------------------------+---------+
5 rows in set (0.00 sec)

Sheeri, this is an incompatible change for 5.1 and we aren't generally keen on the idea of breaking compatibility for a performance fix unless it's very widespread. The change is that it's currently possible in 5.1 to modify the query cache type at runtime if it starts at 0. With this improvement that is no longer possible if it's started at type 0. So we can do this change in the 5.4/5.5 and later versions but not in 5.1.

We are tracking how many customers are affected by this so that we can get some idea of how often people are encountering it. If there's a pattern of it being a serious issue without decent workaround then the decision might change if the risk is judged to be low enough.

The best workaround for the situation you have may be mixed mode. Or if the slave gets behind only for some bulk operations you might use row-based for most work and change to mixed as SUPER just for a session that is doing the bulk operations. A bulk operation like updating a column in half the rows of a large table would be a good candidate for statement-based replication.

If you see this, also check whether you may be affected by bug #53375, slow deletes or updates on a table without a primary key. If you are, adding a primary key to the table is the best workaround and can make a dramatic difference.

To diagnose bug #53375 as a possible cause:

---TRANSACTION 0 1799, ACTIVE 731 sec, OS thread id 3672 fetching rows
mysql tables in use 1, locked 1
153 lock struct(s), heap size 30704, 78278 row lock(s), undo log entries 10045
MySQL thread id 5, query id 16 Reading event from the relay log

Number of rows inserted 78130, updated 0, deleted 10045, read 370899004
0.00 inserts/s, 0.00 updates/s, 16.20 deletes/s, 600754.85 reads/s

Observe 78,278 row locks but only 10,045 undo log entries, so many more rows being scanned than changed. Also observer 16 row deletes per second but 600,754 row reads per second, same mismatch between counts suggesting unindexed accesses are happening.

Updating the title of this bug to make it easier for people to locate it using Google and otherwise.

Old title for reference: "query cache can still consume [very little] cpu time even when it is off."

We have the same problem as Sheers described in 5.1 that is impacting us. It would be great to fix it in 5.1.

Hello,
I am having same problem where:
MASTER:
mysql> show global variables like "binlog_format";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW   |
+---------------+-------+
1 row in set (0.00 sec)

mysql> select @@version;
+----------------------+
| @@version            |
+----------------------+
| 5.1.51-community-log |
+----------------------+
1 row in set (0.00 sec)

SLAVE:
mysql> show processlist;
+----+-------------+-----------+------+---------+-------+------------------------------------------+------------------+
| Id | User        | Host      | db   | Command | Time  | State                                    | Info             |
+----+-------------+-----------+------+---------+-------+------------------------------------------+------------------+
|  1 | system user |           | NULL | Connect |  1677 | Waiting for master to send event         | NULL             |
|  2 | system user |           | NULL | Connect | 12077 | invalidating query cache entries (table) | NULL             |
|  3 | root        | localhost | NULL | Query   |     0 | NULL                                     | show processlist |
+----+-------------+-----------+------+---------+-------+------------------------------------------+------------------+
3 rows in set (0.00 sec)

mysql> select@@version;
+----------------------+
| @@version            |
+----------------------+
| 5.1.51-community-log |
+----------------------+
1 row in set (0.00 sec)

mysql> show global variables like 'query_cache%';
+------------------------------+---------+
| Variable_name                | Value   |
+------------------------------+---------+
| query_cache_limit            | 1048576 |
| query_cache_min_res_unit     | 4096    |
| query_cache_size             | 0       |
| query_cache_type             | OFF     |
| query_cache_wlock_invalidate | OFF     |
+------------------------------+---------+
5 rows in set (0.00 sec)

This impacts our prod machines with their slaves. The master servers have ~1k Updates/s by PK and ~100 Inserts/s also by PK. We are using RBR.

It will be good to have that fixed for 5.1.

Regards,