MySQL Bugs: #37521: Row inserted through view not always visible in base table immediately after

Bug #37521	Row inserted through view not always visible in base table immediately after
Submitted:	19 Jun 2008 11:37	Modified:	9 Aug 2010 17:30
Reporter:	Vemund Østgaard	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	5.1.25-rc	OS:	Any
Assigned to:	Jon Olav Hauglid	CPU Architecture:	Any
Tags:	regression

Description:
The problem was discovered as instability in an upgrade test (from 5.1.24 to 5.1.25), I've created a simpler reproduction test case based on the original test that I will attack to this report after creation.

What basically happens in the test is:
1. A table is created and two rows inserted as root user.
2. A second user creates two views on the table.
3. A third user inserts three rows using the newly created views.
4. A fourth user selects * from the base table.

The expected result is to see 5 rows in the base table, the original two inserted in the base table and the three new ones inserted through the views.

The test however fails (but not very often) with the last row missing from the resultset.

The original upgrade test did fail in similar ways in several different places, I just picked the first failure for my reproduction case.

How to repeat:
The problem can be reproduced with the repro testcase that I will attach, but it only happens now and then so it's not very reliable. I have been reproducing this on two different machines that both have the same hardware and software (2 CPU RH4 64-bit 2Gig memory).

On 5.1.25 I saw it 12 times in 1000 runs
On 5.1.24 I saw it ~20 times in 100 runs

On 5.1.22 I did not see it at all in 10000 runs. This could indicate that it is a regression, but the test ran quite a bit slower on this version so if it is timing dependent that slowness could be hiding the problem.

On 5.0.62 I did not see it at all in 1000 runs. Here the test seemed to run just as fast as on the latest 5.1 versions.

reproduction testcase .test file

Attachment: REPRO-view1.test (application/octet-stream, text), 2.45 KiB.

Reproduction testcase .result file

Attachment: REPRO-view1.result (application/octet-stream, text), 1.82 KiB.

After connections of your users please make:
mysql> show grants;

and paste output here.

One important thing I forgot to mention in the report:
When I connect to the database from a separate client as root after the test is finished and select from the base table, I see all the rows that was inserted including the one not visible in the test.

Information from show grants follows below.

User creating the views:

Grants for view_create@localhost
GRANT USAGE ON *.* TO 'view_create'@'localhost' IDENTIFIED BY PASSWORD '*906B4414DFB7A82305EAAC8210CF5ADA9CCA3F88'
GRANT SELECT, CREATE VIEW ON `viewdb`.* TO 'view_create'@'localhost'
 
User inserting rows:

Grants for view_insert@localhost
GRANT USAGE ON *.* TO 'view_insert'@'localhost' IDENTIFIED BY PASSWORD '*B34BA5E90726FA529CF3A2C11186C5681E540DBA'
GRANT SELECT, INSERT ON `viewdb`.* TO 'view_insert'@'localhost'

User selecting rows:

It proved hard to reproduce the problem with the show grants; statement in between the user connecting and doing the select, so the show grants; was issued after the select was performed:

Grants for view_select@localhost                                                                                   
GRANT USAGE ON *.* TO 'view_select'@'localhost' IDENTIFIED BY PASSWORD '*A49821C5A4B04EDD612988117D840840FFBA77C2' |
GRANT SELECT ON `viewdb`.* TO 'view_select'@'localhost'

Thank you for the feedback.

You said:

> When I connect to the database from a separate client as root after the test is finished and select from the base table, I see all the rows that was inserted including the one not visible in the test.

Does this mean you run test like: ./mysql-test-run.pl --extern? Please specify mysql-test-run options and provide your server configuration file.

> Does this mean you run test like: ./mysql-test-run.pl --extern? Please
> specify mysql-test-run options and provide your server configuration
> file.

I am not very familiar with the testframework but it seems that at least when my test fails the database the test created is left running afterwards. i just run:

./mysql-test-run.pl REPRO-view1

when I run the reproduction testcase.

Setting to verified as I am able to reproduce this, although it happens rarely.

Possibly not a bug. 
Should be re-tested with myisam_concurrent_insert=off

I have not been able to reproduce the issue when running with the setting:

concurrent_insert=off

Seen from the perspective of the testclient the insert and select are not concurrent, although I realize they may be so from the perspective of the database server. Can we be sure that this is not a bug? The behavior in older 5.1 versions and in 5.0 versions is different, so something must have changed.

If you can't reproduce the issue with disabled concurrent inserts, it's fairly certain this is not a bug.
WRT earlier versions, what is the setting of concurrent_insert there?
Which version exactly do you have in mind?

As mentioned in the original description:

On 5.1.22 I did not see it at all in 10000 runs. 

On 5.0.62 I did not see it at all in 1000 runs. 

I checked these two versions, and the default for both is concurrent_inserts=1

See also Bug#29334

and Bug #36618

Bug#36618 has been closed as a duplicate of this one.

Bug#29334 has been closed as a duplicate of this one.

Bug #51329 "Inserts from one connection not immediately visible in second connection" was marked as duplicate of this bug report.

Changed risk/effort, more duplciates, please re-triage.

See Bug#41516

Bug reproduced on trunk-runtime by running the following statements:
        connection default;
        INSERT INTO t1 VALUES(1);
        connection con1;
        SELECT * FROM t1;
Sometimes the select will not retrieve the row inserted.

The following patch based on the patch Andrei Elkin posted on Bug#36618 fixes the problem:

=== modified file 'sql/sql_parse.cc'
--- sql/sql_parse.cc	2010-04-28 10:04:11 +0000
+++ sql/sql_parse.cc	2010-04-30 08:30:35 +0000
@@ -1443,13 +1443,13 @@ bool dispatch_command(enum enum_server_c
 
   thd->transaction.stmt.reset();
 
-  thd->protocol->end_statement();
-  query_cache_end_of_result(thd);
-
   thd->proc_info= "closing tables";
   /* Free tables */
   close_thread_tables(thd);
 
+  thd->protocol->end_statement();
+  query_cache_end_of_result(thd);
+
   if (!thd->is_error() && !thd->killed_errno())
     mysql_audit_general(thd, MYSQL_AUDIT_GENERAL_RESULT, 0, 0);

While the server with this patch does the same amount of work, it will delay notifying the client until after close_thread_tables(). This means that the execution of a statement will take longer seen from the point of the client.

To get an indication of the impact of the change, I've run the following
statements in a loop (same as above except different tables to prevent conflicting table locks from influencing the result):
        connection default;
        INSERT INTO t1 VALUES(1);
        connection con1;
        SELECT * FROM t2;

So far I've run 25 million iterations with the patch and 25 million without (split into runs of 1 million iterations each). This took 9% longer with the patch than without. The standard deviation for the tests without the patch is about 4%, with the patch about 5%.

Due to temporary brain malfunction, the above results were produced using a debug build. Redoing the above experiment on a release build (this time with 50 million iterations split into 1 million runs) gave a 3,5% performance reduction with the patch compared to not using the patch. Standard deviations about the same as earlier.

I've also run the sysbench insert and delete tests using 2 and 16 concurrent threads. Each combination with 60 million operations (split into runs of 2 mill). The results showed a performance reduction of less than 0,5% with standard deviations generally in the 1-2% range. (Client and server on the same machine.)

MTR test used:

--disable_warnings
drop table if exists t1, t2;
--enable_warnings

create table t1 (a int);
create table t2 (b int);
connect (con1, localhost, root);

let $try = 1000000;

while ($try)
{
        connection default;
        insert into t1 values(1);
        connection con1;
        select * from t2;
        dec $try;
}

drop table t1, t2;

run with ./mtr --mem --repeat=...

The patch is OK to push.
Detailed benchmarks by Ranger has shown that the patch actually improves the total execution time, since the average time to execute close_thread_tables() decreases.
Please make sure to mention all duplicates in the changeset comments (all effects of the patch).

To check impact of proposed patch I've instrumented every call with performance_schema objects. I've run several sysbench tests with 64 threads  and below are profile information from these runs:

OLTP_RO/MyISAM/original order of calls
--------------------------------------+------------+-----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT  | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+-----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    2871048 | 361721401441272 |          57114 |      125989325 |    17810153208 |
LOCK_4502_close_thread_time           |    2870415 |   1052659747260 |          75150 |         366727 |     7363813230 |
LOCK_4502_qc_end_of_result_time       |    2869341 |    454153345704 |          45090 |         158277 |     5463053298 |

OLTP_RO/MyISAM/modified order of calls
--------------------------------------+------------+-----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT  | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+-----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    2868867 | 324878831751000 |          51000 |      113242904 |    19070481000 |
LOCK_4502_close_thread_time           |    2870296 |    650587995000 |          78000 |         226662 |     8503071000 |
LOCK_4502_qc_end_of_result_time       |    2869473 |    439708929000 |          51000 |         153236 |     5789469000 |

OLTP_RO/InnoDB/original order of calls
--------------------------------------+------------+----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    2853363 | 29890922500962 |          60120 |       10475681 |    13809260394 |
LOCK_4502_close_thread_time           |    2864480 |   451726268238 |          66132 |         157699 |     5490495072 |
LOCK_4502_qc_end_of_result_time       |    2858151 |   320688211230 |          48096 |         112201 |     1335671010 |
OLTP_RO/InnoDB/modified order of calls
--------------------------------------+------------+----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    2842967 | 28823957280000 |          51000 |       10138688 |    13287543000 |
LOCK_4502_close_thread_time           |    2870592 |   369100836000 |          63000 |         128580 |     1048482000 |
LOCK_4502_qc_end_of_result_time       |    2858760 |   327405450000 |          48000 |         114527 |      665358000 |

OLTP_RW/MyISAM/original order of calls
--------------------------------------+------------+----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    1059896 | 13581837733554 |          57114 |       12814311 |     1485676422 |
LOCK_4502_close_thread_time           |    1059904 |   242179406028 |          69138 |         228491 |      362490534 |
LOCK_4502_qc_end_of_result_time       |    1059903 |   120452145444 |          48096 |         113644 |      105862302 |

OLTP_RW/MyISAM/modified order of calls
-------------------------------------+------------+----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    1069753 | 13783024485000 |          51000 |       12884305 |     1455789000 |
LOCK_4502_close_thread_time           |    1069889 |   156547902000 |          87000 |         146321 |      139539000 |
LOCK_4502_qc_end_of_result_time       |    1069702 |   121631688000 |          51000 |         113706 |       27390000 |

OLTP_RW/InnoDB/modified order of calls
--------------------------------------+------------+----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    3752039 | 51169874488020 |          54108 |       13637884 |    22938085602 |
LOCK_4502_close_thread_time           |    3762118 |   626162202756 |          63126 |         166438 |     1651815036 |
LOCK_4502_qc_end_of_result_time       |    3756409 |   438109905870 |          48096 |         116629 |     2219792724 |

OLTP_RW/InnoDB/modified order of calls
--------------------------------------+------------+----------------+----------------+----------------+----------------+
                                      | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
--------------------------------------+------------+----------------+----------------+----------------+----------------+
LOCK_4502_end_statement               |    3742833 | 51075593847108 |          51102 |       13646239 |    23489079390 |
LOCK_4502_close_thread_time           |    3770142 |   517670248950 |          63126 |         137307 |    14462256780 |
LOCK_4502_qc_end_of_result_time       |    3758369 |   460000998666 |          48096 |         122393 |     7852615884 |

Provided profile information allows to understand magnitude of every call. It's clear that most of time we're spending at end_statement() and time spent at close_threads()/qc_end_of_result() calls are significantly smaller. 

Another important observation is that by changing of order of calls we speedup/improve execution of end_statement()/close_threads() that makes this change completely safe from performance standpoint.

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/113028

3077 Jon Olav Hauglid	2010-07-07
      Bug #37521 Row inserted through view not always visible in base
                 table immediately after
      
      The problem was that rows inserted in a table by one connection was
      not immediately visible if another connection queried the table,
      even if the insert had committed.
      
      The reason for the problem was that the server sent a status reply
      to the client before it actually did the commit. Therefore it was
      possible to get an OK from the server before the changes were made
      permanent and visible to other connections.
      
      This patch fixes the problem by not sending status messages to the
      server until any changes made have been committed. No test case added
      as reproducing the error requires very specific timing betweeen the
      server and two or more clients.
      
      This patch also fixes the following (duplicate) bugs:
      Bug #29334 pseudo-finished SHOW GLOBAL STATUS
      Bug #36618 myisam insert not immediately visible to select from another client
      Bug #45864 insert on one connection, immediate query on another produces no result
      Bug #51329 Inserts from one connection not immediately visible in second
                 connection
      Bug #41516 Assertion fails when error returned from
                 handler::external_lock(thd, F_UNLCK)

Pushed to mysql-trunk-runtime (5.5.6).

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-next-mr (revid:alik@ibmvm-20100804081630-ntapn8bf9pko9vj3) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (pib:20)

Noted in 5.5.6, 5.6.0 changelogs.

Rows inserted in a table by one session were not immediately visible
to another session that queried the table, even if the insert had
committed.