MySQL Bugs: #12447: Query cache not being invalidated during concurrent SELECT, INSERT

Bug #12447	Query cache not being invalidated during concurrent SELECT, INSERT
Submitted:	8 Aug 2005 22:28	Modified:	26 Sep 2005 20:18
Reporter:	Steve Meyers	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S2 (Serious)
Version:	4.1.13	OS:	Linux (RHEL 3)
Assigned to:		CPU Architecture:	Any

Description:
My program runs an insert select on the master database, and then starts checking to see when that value shows up on the slave.  Occasionally (at least three times that I've seen), the value never seems to show up on the slave.  Here is a copy/paste from the CLI demonstrating it:

******************************************************************
mysql> select * from checksum_tables where name='minglemail_bodies_05';
Empty set (0.00 sec)

mysql> select * from checksum_tables where name='minglemail_bodies_05' and 1=1;
+----------------------+-----------------+--------+
| name                 | checksum        | rows   |
+----------------------+-----------------+--------+
| minglemail_bodies_05 | 303416492571750 | 141433 |
+----------------------+-----------------+--------+
1 row in set (0.00 sec)

mysql> select * from checksum_tables where name='minglemail_bodies_05';
Empty set (0.00 sec)
******************************************************************

As you can see, the data was there, but the query cache was wrong.

How to repeat:
I haven't been able to reliably duplicate it, but I've seen it happen at least three times.  I tried to write a fairly simple (yet still 50-lines long) program that would duplicate it, but had no such luck.  It's gotta be a timing issue, and I can't get the timing just right.

Suggested fix:
My suspicion is that it has to do with the fact that MyISAM tables allow concurrent INSERTs and SELECTs.  I believe that the INSERT ... SELECT ... statement being executed by the replication SQL thread occurs at the same time the SELECT statement is done.  The SELECT returns nothing, but while the SELECT was occurring, the INSERT ... SELECT ... happened.  So the query cache believes there's no result, but the table was updated while the SELECT was going on.

Does that make sense?

First program for reproducing the bug (requires two programs)

Attachment: repl_bug_test.php (application/octet-stream, text), 1.73 KiB.

Second program to reproduce bug

Attachment: repl_bug_test2.php (application/octet-stream, text), 667 bytes.

I have added two PHP scripts that can reproduce the bug.  To reproduce it, run repl_bug_test.php (from the command line), and wait until it tells you to start the second process.  Then start repl_bug_test2.php in another terminal.  When I have run it, it has always reproduced the bug during the first loop.

You'll need to edit the $host, $database, $mysql_username, and $mysql_password fields in each file as appropriate.

Replication is NOT necessary to duplicate this bug.

changed synopsis

Thank you for taking the time to report a problem.  Unfortunately
you are not using a current version of the product your reported a
problem with -- the problem might already be fixed. Please download
a new version from http://www.mysql.com/downloads/

If you are able to reproduce the bug with one of the latest versions,
please change the version on this bug report to the version you
tested and change the status back to "Open".  Again, thank you for
your continued support of MySQL.

Additional info:

Have you thried your 2 php scripts on a newer versions (4.1.14)? Is this problem still demonstrated by them?

Wrong version number when submitted.  Testing on 4.1.14 now.

I am trying to repeat with your PHP scripts and today's 4.1.15-BK build on my Fedora Core 1, but with no luck.

First script gave me:

[openxs@Fedora 4.1]$ ./repl_bug_test.php
Content-type: text/html
X-Powered-By: PHP/4.3.3

Start second process now!
5
4
3
2
1
Running inserts...
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|
.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|.|

So, it worked and finished (after a couple of hours). The second one is still working (I ran it just when prompted, at tick 2):

[openxs@Fedora 4.1]$ bin/mysql -uroot
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3 to server version: 4.1.15-debug

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> show processlist;
+----+------+--------------+------+---------+------+----------------+-----------
--------------------------------+
| Id | User | Host         | db   | Command | Time | State          | Info
                                |
+----+------+--------------+------+---------+------+----------------+-----------
--------------------------------+
|  2 | root | Fedora:32803 | test | Query   |    0 | Writing to net | select * f
rom test_table where keyid=1000 |
|  3 | root | localhost    | NULL | Query   |    0 | NULL           | show proce
sslist                          |
+----+------+--------------+------+---------+------+----------------+-----------
--------------------------------+
2 rows in set (0,07 sec)

(looks like it is locked on this id=1000, because it does not move on)

And according to top:

  PID USER     PRI  NI  SIZE  RSS SHARE STAT %CPU %MEM   TIME CPU COMMAND
 9264 openxs    17   0 19404  14M  2156 S    64,6  6,4 208:40   0 mysqld
 9417 openxs    15   0  4428 3548  3416 S    34,5  1,5  26:42   0 repl_bug_test

it still uses all the CPU resources, together with mysqld.

So, I can not see anything useful or strange during the first loop. Or I am wrong in my testing/interpretation? What you expected me to see from this test?

Could not duplicate in 4.1.14