Fun with Bugs #35 - Bugs fixed in MySQL 5.6.24

I had not reviewed bug fixes in MySQL 5.6 for quite a some time, so I decided to check what bugs reported by MySQL Community were fixed in recently released MySQL 5.6.24. I'll mention both a bug reporter and engineer who verified the bug in the list below, because I still think that in MySQL world names should matter.

So, MySQL 5.6.24 includes fixes for the following bugs from http://bugs.mysql.com. I'd start with InnoDB and memcached-related fixes:

• Bug #72080 - truncate temporary table crash: !DICT_TF2_FLAG_IS_SET(table, DICT_TF2_TEMPORARY). Reported by Doug Warner and verified by Shane Bester after a lot of testing. Note how fast it was fixed after verification!
• Bug #75755 - Fulltext search behaviour with MyISAM vs. InnoDB (wrong result with InnoDB). Reported by Elena Stepanova from MariaDB and confirmed by my former boss Miguel Solorzano, this wrong results bug was also promptly fixed.
• Bug #70055 - Expiration time ignored. This memcached-related bug was reported by Miljenko Brkic and verified by Umesh. 
• Bug #74956 - Can not stop mysql with memcached plugin. This regression bug was reported by my colleague Nilnandan Joshi and verified by Umesh. 
• Bug #75200 - MySQL crashed because of append operation. Reported by
  by already famous bug reporter (and developer) Zhai Weixiang, it was verified by Umesh and fixed fast enough.
  As you can see MySQL 5.6.24 fixed several more memcached-related bugs (reported internally), so if you use memcached it really makes sense to upgrade.
• Bug #73361 - mutex contention caused by dummy table/index creation/free. Reported by Zhai Weixiang (who also suggested a patch) and verified by my dear friend and teacher Sinisa Milivojevic.  

Let's move on to partitioning. Just a couple of fixes there that fixed a long list of bugs reported by Percona QA engineers:

•  Bug #74841 - handle_fatal_signal (sig=11) in cmp_rec_and_tuple | sql/sql_partition.cc:7610. This was reported by Percona's recent QA super star, Ramesh Sivaraman, and verified by Miguel Solorzano.
• Bug #74860 - handle_fatal_signal (sig=11) in generate_partition_syntax. This was reported by Percona's all times QA superstar, Roel Van de Paar, and verified by Umesh.
• Bug #74869 - handle_fatal_signal (sig=11) in ha_partition::handle_opt_partitions. It was reported by Ramesh Sivaraman, and verified by Miguel Solorzano.
• Bug #74288 - Assertion `part_share->partitions_share_refs->num_parts >= m_tot_parts' failed. Reported by Roel Van de Paar and verified by Umesh.
• Several other bugs mentioned remain private and not visible to us: Bug #74451, Bug #74478, Bug #74491, Bug #74560, Bug #74746, Bug #74634. I am not sure why they are private (or why the previous ones are still public, and for how long). Let's assume they were reported as private (and/or security ones) by my colleagues.

Now, only one replication bug reported at http://bugs.mysql.com was fixed, but serious one:

• Bug #74607 - slave io_thread may get stuck when using GTID and low slave_net_timeouts. This bug was reported by Santosh Praneeth Banda and verified by Umesh.

There were several other bugs fixed in several categories:

• Bug #74037 - group_concat_max_len=18446744073709547520 not accepted in my.cnf. It was reported by Leandro Morgado from Oracle and verified by himself probably. I am always to happy to see Oracle engineers reporting bugs in public.
• Bug #73373 - Warning message shows old variable name. This was reported by Tsubasa Tanaka and verified by Miguel Solorzano.
• Bug #71634 - P_S digest looks wrong for system variables, shown as @ @ variable... Reported by Simon Mudd and verified by the author of PERFORMANCE_SCHEMA, Marc Alff.
• Bug #69744 - ssl.cmake silently chooses bundled yassl instead of erroring for old openssl ver. Good old build problem reported and verified by Shane Bester.
• Bug #69423 - Double close() on the same file descriptor inside mysql_real_connect(). Reported by Yao Deng and verified by Igor Solodovnikov.
• Bug #60782 - Audit plugin API: no MYSQL_AUDIT_GENERAL_LOG notifications with general log off. This one was reported by Olle Nilsson and verified (as a feature request) by ...yours truly almost 4 years ago.

A couple of issues were also fixed by introducing new server behavior:

• Bug #74917 - Failed restarts contain no version details. Reported by my Oracle colleague Shawn Green and probably verified by him as well. Now server version is mentioned in the new error log file with the first message.
• Bug #72997 - "fast" ALTER TABLE CHANGE on enum column triggers full table rebuild. Reported by famous Oracle customer Simon Mudd and verified by even more famous Shane Bester. The (temporary?) fix introduced two new variables, avoid_temporal_upgrade to control conversion to new "temporal" columns format (and rebuilding the table for any ALTER as a result), and show_old_temporals to control adding comments about old format of "temporal" column in SHOW CREATE TABLE output and corresponding INFORMATION_SCHEMA.COLUMNS.COLUMN value. Both variables are immediately declared as deprecated, so they may disappear in 5.7 (or 5.8? I am a bit lost with recent deprecation practices of Oracle).

That's all fixes for bugs reported at http://bugs.mysql.com in 5.6.24. Stay tuned, maybe one day we'll discuss MySQL 5.7.7 as well.

Using gdb to understand what locks (and when) are really set by InnoDB. Part II.

In the previous post we checked lock requests while executing INSERT INTO t ... SELECT FROM tt where there is an auto_increment column for which the value is generated in the destination table with default innodb_autoinc_lock_mode=1. Based on it I've reported Bug #76563 that is already verified.

Let's continue to study a special case of the statement mentioned above, INSERT INTO t ... SELECT FROM t, that is, when source and destination table is the same. We again start with table t having just 4 rows:

mysql> rollback;
Query OK, 0 rows affected (0.01 sec)
 
mysql> select * from t;
+----+------+
| id | val  |
+----+------+
|  1 |    1 |
|  2 |    2 |
|  3 |    3 |
|  4 |    4 |
+----+------+
4 rows in set (0.00 sec)

mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t(val) select 100 from t;


Tracing in gdb with the same breakpoints set shows the following:

[Switching to Thread 0x7fd74cf79700 (LWP 1866)]

Breakpoint 1, lock_table (flags=0, table=0x7fd7233f69e8, mode=LOCK_IS, thr=0x7fd7233de6f0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:4426
4426            if (flags & BTR_NO_LOCKING_FLAG) {
(gdb) p table->name
$41 = 0x7fd7383feac0 "test/t"
So, we start with IS lock on the table. Probably we plan to read some rows. Let's continue:

(gdb) c
Continuing.

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249af000, heap_no=2, index=0x7fd7233f7b68, thr=0x7fd7233de6f0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:2329
2329            switch (lock_rec_lock_fast(impl, mode, block, heap_no, index, thr)) {
(gdb) p index->table_name
$42 = 0x7fd7383feac0 "test/t"
(gdb) c
Continuing.

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249af000, heap_no=3, index=0x7fd7233f7b68, thr=0x7fd7233de6f0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:2329
2329            switch (lock_rec_lock_fast(impl, mode, block, heap_no, index, thr)) {
(gdb) c
Continuing.

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249af000, heap_no=4, index=0x7fd7233f7b68, thr=0x7fd7233de6f0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:2329
2329            switch (lock_rec_lock_fast(impl, mode, block, heap_no, index, thr)) {
(gdb) c
Continuing.

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249af000, heap_no=5, index=0x7fd7233f7b68, thr=0x7fd7233de6f0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:2329
2329            switch (lock_rec_lock_fast(impl, mode, block, heap_no, index, thr)) {
(gdb) c
Continuing.

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249af000, heap_no=1, index=0x7fd7233f7b68, thr=0x7fd7233de6f0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:2329
2329            switch (lock_rec_lock_fast(impl, mode, block, heap_no, index, thr)) {

We set S (mode=2) locks on each row in the "source" (t) table and supremum record there, to begin with. We read all rows that we plan to insert into the temporary table before inserting them. One could assume this just from checking the plan:

mysql> explain insert into t(val) select 100 from t\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: t
         type: index
possible_keys: NULL
          key: PRIMARY
      key_len: 4
          ref: NULL
         rows: 4
        Extra: Using index; Using temporary
1 row in set (0.00 sec)

Note that this stage, selecting all rows into the temporary table, may take a long time for a big table t. During all this time there is NO AUTO-INC lock set. Probably it explains what happened in cases discussed in the original Bug #72748.

(gdb) c
Continuing.

Breakpoint 3, row_lock_table_autoinc_for_mysql (prebuilt=0x7fd7233e3068) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/row/row0mysql.cc:1146
1146            if (trx == table->autoinc_trx) {
(gdb) c
Continuing.

Breakpoint 1, lock_table (flags=0, table=0x7fd7233f69e8, mode=LOCK_AUTO_INC, thr=0x7fd7233e3780) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:4426
4426            if (flags & BTR_NO_LOCKING_FLAG) {
(gdb) p table->name
$43 = 0x7fd7383feac0 "test/t"
Only now we set AUTO-INC lock on the "destination" table (again t in this case) and proceed with expected insertion:

(gdb) c
Continuing.

Breakpoint 1, lock_table (flags=0, table=0x7fd7233f69e8, mode=LOCK_IX, thr=0x7fd7233e3780) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:4426
4426            if (flags & BTR_NO_LOCKING_FLAG) {
(gdb) p table->name
$44 = 0x7fd7383feac0 "test/t"
(gdb) c
Continuing.

Breakpoint 3, row_lock_table_autoinc_for_mysql (prebuilt=0x7fd7233e3068) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/row/row0mysql.cc:1146
1146            if (trx == table->autoinc_trx) {
(gdb) c
Continuing.

Breakpoint 3, row_lock_table_autoinc_for_mysql (prebuilt=0x7fd7233e3068) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/row/row0mysql.cc:1146
1146            if (trx == table->autoinc_trx) {
(gdb) c
Continuing.
...
Our UPDATE completes finally:

...
Query OK, 4 rows affected, 1 warning (5 min 45.02 sec)
Records: 4  Duplicates: 0  Warnings: 1

mysql> show warnings\G*************************** 1. row ***************************
  Level: Note
   Code: 1592
Message: Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave.
1 row in set (0.00 sec)

mysql> select * from t;
+----+------+
| id | val  |
+----+------+
|  1 |    1 |
|  2 |    2 |
|  3 |    3 |
|  4 |    4 |
| 12 |  100 |
| 13 |  100 |
| 14 |  100 |
| 15 |  100 |
+----+------+
8 rows in set (0.00 sec)
To summarize, the following locks are set (and in the following order) while executing INSERT INTO t ... SELECT FROM t where there is an auto_increment column for which the value is generated (with default innodb_autoinc_lock_mode=1 and using default REPEATABLE READ transaction isolation level) according to our tracing in gdb:

1. IS lock on the table (t)
2. S locks on each row in t we read with SELECT
3. S lock on the supremum record in t
4. AUTO-INC lock on t
5. IX lock on t
6. Probably implicit X lock on each row inserted (we had not seen this in gdb clearly). We read these rows from the temporary table we've created

I see two potential problems here.

There is a real chance to run (and commit) fast concurrent INSERT (that uses AUTO-INC lock) into the table t while we read all rows from it before we request AUTO-INC lock on the destination. As a result, some of rows inserted may be read during SELECT stage and lead to more rows inserted than we could expect.

Also, there is no explicit explanation for this (corner) case of INSERT ... SELECT in the manual. I plan to file a documentation bug later.