MySQL Bugs: #68573: 50ms query cache lock timeout not applied to SELECT statements correctly

Bug #68573	50ms query cache lock timeout not applied to SELECT statements correctly
Submitted:	5 Mar 2013 12:57	Modified:	7 Jul 2017 9:08
Reporter:	Przemysław Ołtarzewski	Email Updates:
Status:	Won't fix	Impact on me:	None
Category:	MySQL Server: Query Cache	Severity:	S3 (Non-critical)
Version:	5.5.25a, 5.6.17	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	50ms, lock timeout, query cache

Description:
In MySQL 5.5.1, a 50ms timeout was introduced for SELECT statement to aquire a query cache lock. According to changelog:

"When the query cache is fragmented, the size of the free block lists in the memory bins grows, which causes query cache invalidation to become slow. There is now a 50ms timeout for a SELECT statement waiting for the query cache lock. If the timeout expires, the statement executes without using the query cache."

Profiling SELECT statements that trigger the query lock shows that this feature doesn't work correctly.

Consider the two examples below 1-ok, 2-invalid. Pay special attention to paragraph (2.2.):

1. No load on database, no wait on query cache lock:

1.1. SELECT statement issued first time:

mysql> SELECT `ID`, `SUBSCRIBER_MSISDN`, `EXPIRY_DATE`, `TARIFF_ID`, `IN_SUBACCOUNT_ID` FROM `outpayment_account` WHERE  ( (`SUBSCRIBER_MSISDN` LIKE '48604868674%')  AND  (`IN_SUBACCOUNT_ID` = '3') ) AND ( (1=1)  AND  (1=1) );
Empty set (0.00 sec)

mysql> show profile for query 13;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000013 |
| checking query cache for query | 0.000043 |
| Opening tables                 | 0.000009 |
| System lock                    | 0.000004 |
| Table lock                     | 0.000025 |
| init                           | 0.000022 |
| optimizing                     | 0.000013 |
| statistics                     | 0.000123 |
| preparing                      | 0.000012 |
| executing                      | 0.000003 |
| Sending data                   | 0.046477 |
| end                            | 0.000010 |
| query end                      | 0.000004 |
| freeing items                  | 0.000060 |
| storing result in query cache  | 0.000093 |
| logging slow query             | 0.000007 |
| cleaning up                    | 0.000008 |
+--------------------------------+----------+

Notice that there was no wait on query cache lock and the result was stored in query cache correctly.

1.2. SELECT statement issued second time:

mysql> SELECT `ID`, `SUBSCRIBER_MSISDN`, `EXPIRY_DATE`, `TARIFF_ID`, `IN_SUBACCOUNT_ID` FROM `outpayment_account` WHERE  ( (`SUBSCRIBER_MSISDN` LIKE '48604868674%')  AND  (`IN_SUBACCOUNT_ID` = '3') ) AND ( (1=1)  AND  (1=1) );
Empty set (0.00 sec)

mysql> show profile for query 14;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000024 |
| checking query cache for query | 0.000013 |
| checking privileges on cached  | 0.000009 |
| sending cached result to clien | 0.000045 |
| logging slow query             | 0.000004 |
| cleaning up                    | 0.000005 |
+--------------------------------+----------+

Notice that cached result was correctly found and sent to client.

2. Load on database, wait on query cache lock triggered:

2.1. Issued SELECT statement

SELECT `ID`, `SUBSCRIBER_MSISDN`, `EXPIRY_DATE`, `TARIFF_ID`, `IN_SUBACCOUNT_ID` FROM `outpayment_account` WHERE  ( (`SUBSCRIBER_MSISDN` LIKE '48604868674%')  AND  (`IN_SUBACCOUNT_ID` = '3') ) AND ( (1=1)  AND  (1=1) );

+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000052 |
| Waiting for query cache lock   | 0.039997 |
| checking query cache for query | 0.000070 |
| checking permissions           | 0.000023 |
| Opening tables                 | 0.000023 |
| System lock                    | 0.000020 |
| Waiting for query cache lock   | 0.123580 |
| init                           | 0.000056 |
| optimizing                     | 0.000023 |
| statistics                     | 0.066764 |
| preparing                      | 0.000045 |
| executing                      | 0.000016 |
| Sending data                   | 0.000125 |
| end                            | 0.000024 |
| query end                      | 0.000018 |
| closing tables                 | 0.000018 |
| freeing items                  | 0.000020 |
| Waiting for query cache lock   | 0.165541 |
| freeing items                  | 0.000058 |
| Waiting for query cache lock   | 0.879688 |
| freeing items                  | 0.000055 |
| logging slow query             | 0.000017 |
| cleaning up                    | 0.000015 |
+--------------------------------+----------+

2.2. Notice the following facts:

2.2.1. There were four attempts to acquire the query cache lock, that summed up to 1208.806 ms. That invalidates the whole idea of 50ms timeout for query cache.

Multiple attempts to acquire the lock may take less than 50ms, but add up to a whole that is significantly longer than 50ms, generating performance hit.

2.2.2. Every attempt except for the first one was significantly longer then 50ms:

A1 ~ 40 ms
A2 ~ 123 ms
A3 ~ 165 ms
A4 ~ 880 ms

This implies that the 50ms timeout does not work as expected. A thread waiting for query cache should quit after about 50ms. It seems that instead it waits as long as it takes to obtain the lock, then measures time it took to obtain it, and quits if the time was greater than 50ms.

2.2.3. The fact that attempt A2 took longer than 50ms was simply ignored and attempts A3, A4 were still executed. According to changelog, query cache should not be used beyond A2.

2.2.4. After such a long time spent waiting for the query cache lock, the result was not stored (as it was in 1.1), but discarded. Perhaps the fact that the query cache lock timeout was exceeded is recorded and then used to decide whether the result should be stored. This generates more performance hit as the result of a very expensive operation is not being stored.

How to repeat:
Use the following table:

CREATE TABLE `outpayment_account` (
  `ID` int(11) DEFAULT NULL,
  `SUBSCRIBER_MSISDN` varchar(50) NOT NULL,
  `EXPIRY_DATE` datetime DEFAULT NULL,
  `TARIFF_ID` int(11) DEFAULT NULL,
  `IN_SUBACCOUNT_ID` varchar(50) DEFAULT NULL,
  `LAST_UPDATE` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  UNIQUE KEY `UQ_ACCOUNT_MSISDN_SUBACCOUNT` (`SUBSCRIBER_MSISDN`,`IN_SUBACCOUNT_ID`),
  KEY `IDX_ACCOUNT_EXPIRY_DATE` (`EXPIRY_DATE`),
  KEY `SUBSCRIBER_MSISDN` (`SUBSCRIBER_MSISDN`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

Supply about 25000000 random rows. Use 32M query_cache_size. Generate a load on table with select statements similar to:

SELECT `ID`, `SUBSCRIBER_MSISDN`, `EXPIRY_DATE`, `TARIFF_ID`, `IN_SUBACCOUNT_ID` FROM `outpayment_account` WHERE  ( (`SUBSCRIBER_MSISDN` LIKE '48604868674%')  AND  (`IN_SUBACCOUNT_ID` = '3') ) AND ( (1=1)  AND  (1=1) );

Query was generated by FEDERATED engine - that is why the conditions in WHERE clause are a bit odd.

Enable profiling in your mysql session and issue queries similar to ongoing load - manually. Inspect results with SHOW PROFILE FOR QUERY ... . Some of the attempts should show described behavior. The number of query lock waits and time spent will vary from one query to another.

Suggested fix:
3. Fix:

3.1. Query cache lock timeout should be measured for the aggregate time of all attempts to obtain the lock - otherwise it is pointless (see 2.2.1.)

3.2. The time spent by the thread waiting for lock should be measured before the lock is acquired and it should take about 50ms (as described in documentation) for the thread to resign from obtaining the lock (see 2.2.2.)

3.3. No further attempts to acquire the lock should be made after one of them times out (see 2.2.3.)

3.4. Only if 3.1-3.3 are satisfied the result should not be saved in cache (as in 2.2.4.)

4. Workaround:

Disable the query cache completely.

Set:

query_cache_type=0
query_cache_size=0

in my.cnf

Hello Przemysław,

Thank you for the report.
Verified as described on reported and later versions.

Thanks,
Umesh

How to repeat:

// MySQLD startup

bin/mysqld_safe --no-defaults --skip-gr --skip-na --console --core-file  --basedir=/data/ushastry/server/mysql-5.5.32 --datadir=/tmp/69044_5532 --port=5532 --socket=/tmp/mysql.sock --query-cache-type=1 --query-cache-size=32M --innodb-flush-log-at-trx-commit=0 --innodb-buffer-pool-size=1000M --innodb-log-file-size=512M --innodb-file-per-table --innodb-support-xa=0 --innodb-checksums=0 --innodb-doublewrite=0 --user=mysql

// Schema and load script

use test;
DROP TABLE IF EXISTS outpayment_account;

CREATE TABLE `outpayment_account` (
  `ID` int(11) DEFAULT NULL,
  `SUBSCRIBER_MSISDN` varchar(50) NOT NULL,
  `EXPIRY_DATE` datetime DEFAULT NULL,
  `TARIFF_ID` int(11) DEFAULT NULL,
  `IN_SUBACCOUNT_ID` varchar(50) DEFAULT NULL,
  `LAST_UPDATE` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  UNIQUE KEY `UQ_ACCOUNT_MSISDN_SUBACCOUNT` (`SUBSCRIBER_MSISDN`,`IN_SUBACCOUNT_ID`),
  KEY `IDX_ACCOUNT_EXPIRY_DATE` (`EXPIRY_DATE`),
  KEY `SUBSCRIBER_MSISDN` (`SUBSCRIBER_MSISDN`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

set @id:=0;
set @msisdn:=48604868674;
set @tarrif_id:=0;

 insert into `outpayment_account` values (@id:=@id+1,@msisdn:=@msisdn+1,now(),@tarrif_id:=@tarrif_id+1,3,now()),(@id:=@id+1,@msisdn:=@msisdn+1,now(),@tarrif_id:=@tarrif_id+1,3,now()),(@id:=@id+1,@msisdn:=@msisdn+1,now(),@tarrif_id:=@tarrif_id+1,3,now()),(@id:=@id+1,@msisdn:=@msisdn+1,now(),@tarrif_id:=@tarrif_id+1,3,now());

 insert into `outpayment_account`
 select @id:=@id+1,@msisdn:=@msisdn+1,now(),@tarrif_id:=@tarrif_id+1,3,now()
 from `outpayment_account` oa1
     ,`outpayment_account` oa2
     ,`outpayment_account` oa3
     ,`outpayment_account` oa4
     ,`outpayment_account` oa5
     ,`outpayment_account` oak6
     ,`outpayment_account` oa7
     ,`outpayment_account` oa8
     ,`outpayment_account` oa9
     ,`outpayment_account` oa10
     ,`outpayment_account` oa11
     ,`outpayment_account` oa12
     ,`outpayment_account` oa13
     ,`outpayment_account` oa14 limit 25000000;  

/// Stress test query cache 
// Shane has written a script and shall pass on to you if you need 
     
///      5.5.32

 SELECT `ID`, `SUBSCRIBER_MSISDN`, `EXPIRY_DATE`, `TARIFF_ID`, `IN_SUBACCOUNT_ID` FROM `outpayment_account` WHERE  ( (`SUBSCRIBER_MSISDN` LIKE '486048%')  AND  (`IN_SUBACCOUNT_ID` = '3') ) AND ( (1=1)  AND  (1=1) );
 
 
mysql> show profile for query 8;
| Waiting for query cache lock | 0.000008 |
| Waiting for query cache lock | 0.000008 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000009 |
| Waiting for query cache lock | 0.000011 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000010 |
| Waiting for query cache lock | 0.000009 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.001107 |
| Waiting for query cache lock | 0.023118 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000007 |
| Waiting for query cache lock | 0.000014 |
| Waiting for query cache lock | 0.083513 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000011 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.066186 |
| Waiting for query cache lock | 0.000010 |
| Waiting for query cache lock | 0.000010 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.000007 |
| Waiting for query cache lock | 0.013664 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.058520 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.000205 |
| Waiting for query cache lock | 0.077533 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.048046 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000011 |
| Waiting for query cache lock | 0.000005 |
| Waiting for query cache lock | 0.000009 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.091037 | <-----------
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000010 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000009 |
100 rows in set (0.00 sec)

Just to confirm that it is repeatable on 5.5.25a and on 5.5.32

Latest 5.6 is also affected..

mysql> SHOW PROFILE FOR QUERY 5;
| Waiting for query cache lock | 0.000007 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.092091 |
| Waiting for query cache lock | 0.000007 |
| Waiting for query cache lock | 0.000016 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.062547 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.108135 |
| Waiting for query cache lock | 0.000007 |
| Waiting for query cache lock | 0.001809 |
| Waiting for query cache lock | 0.000011 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000007 |
| Waiting for query cache lock | 0.000015 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000014 |
| Waiting for query cache lock | 0.000014 |
| Waiting for query cache lock | 0.000013 |
| Waiting for query cache lock | 0.048075 |
| Waiting for query cache lock | 0.016696 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000015 |
| Waiting for query cache lock | 0.000474 |
| Waiting for query cache lock | 0.066495 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.036373 |
| Waiting for query cache lock | 0.082277 |
| Waiting for query cache lock | 0.004116 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.069118 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000013 |
| Waiting for query cache lock | 0.000012 |
| Waiting for query cache lock | 0.123210 |
| Waiting for query cache lock | 0.000012 |
| Waiting for query cache lock | 0.071339 |
| Waiting for query cache lock | 0.000011 |
| Waiting for query cache lock | 0.000006 |
| Waiting for query cache lock | 0.000013 |
| Waiting for query cache lock | 0.000011 |
| Waiting for query cache lock | 0.000015 |
| Waiting for query cache lock | 0.000007 |
| Waiting for query cache lock | 0.000014 |
| Waiting for query cache lock | 0.063197 |
| Waiting for query cache lock | 0.000013 |
| Waiting for query cache lock | 0.000006 |
100 rows in set, 1 warning (0.00 sec)

MySQL will no longer invest in the query cache, see:

http://mysqlserverteam.com/mysql-8-0-retiring-support-for-the-query-cache/