Sunday, May 31, 2015

Fun with Bugs #36 - Bugs fixed in MySQL 5.6.25

Two days ago Oracle had released MySQL 5.6.25, so it's time to check what bugs reported by MySQL Community are fixed there. As usual, I'll mention both a bug reporter and engineer who verified the bug. Please, pay attention to fixes in replication and partitioning - if you use these features (or queries to INFORMATION_SCHEMA with a lot of complex tables in your database), please, consider upgrading ASAP.

The following InnoDB related bugs were fixed:
  • Bug #69990 - CREATE_TIME and UPDATE_TIME are wrong for partitioned tables. Finally this bug reported by my colleague Justin Swanhart and verified by Umesh (almost immediately after it was reported) is fixed!
  • Bug #75790 - memcached SET command accepts negative values for expire time. This bug (that Oracle put into InnoDB section in the release notes) was reported and verified by Umesh
  • Bug #74686  - Wrong relevance ranking for InnoDB full text searches under certain conditions. This bug was reported by Tim McLaughlin and verified by Miguel Solorzano.
  • The last but not the least, new innodb_stress test suite by Mark Callaghan is included now, thanks to the Bug #76347 reported by Viswanatham Gudipati.
Oracle had fixed several more memcached and InnoDB-related bugs in 5.6.25, but as they were reported only internally, they are out of the scope of my posts.

A set of related bugs in Partitioning category was fixed:
  • Bug #74288 - Assertion `part_share->partitions_share_refs->num_parts >= m_tot_parts' failed. It was reported by my colleague Roel Van de Paar and verified by Umesh.
  • Bug #74634 - this bug is still private, so we do not see the details.
  • Bug #74451 - this bug is also private. We can probably assume that in case of private bug we had assertion failures or crashes on non-debug builds. So, if you use partitioning a lot, please, consider upgrading to 5.6.25 ASAP.
A lot of replication related bugs were fixed in 5.6.25:
  • Bug #75879 - memory consumed quickly while executing loop in procedure. It was reported by Zhai Weixiang (who had also provided a patch) and verified by Shane Bester. If you ask me, based on the contributions over last 2 years it's about time for Percona to hire Zhai Weixiang into our development team, or Oracle may approach him faster. He is a really brilliant engineer!
  • Bug #75781 - log lock may not be unlocked if add_logged_gtid failed. It was reported by Fangxin Flou (who had provided a patch as well) and verified by Sinisa Milivojevic.
  • Bug #75769 - this bug is still private. Release notes describes the problem as follows: "A slave running MySQL 5.6.24 or earlier could not connect to a master running MySQL 5.7.6 and later that had gtid_mode=OFF_PERMISSIVE or gtid_mode=ON_PERMISSIVE." I wonder why such a bug can be private. Either it was reported like that or we do not see all the details about the impact.
  • Bug #75574 - Can not execute change master after Error occurred in MTS mode. It was reported by Zhang Yingqiang and verified by Sveta Smirnova (while she still worked in Oracle).
  • Bug #75570 - semi-sync replication performance degrades with a high number of threads. The problem was studied in details and reported by Rene' Cannao' and verified by Umesh.
  • Bug #74734  - mysqlbinlog can't decode events > ~1.6GB. It was reported by Hartmut Holzgraefe and verified by Umesh.
  • Bug #69848 - mysql 5.6 slave out of memory error. It was reported by  Jianjun Yang and verified by Sveta SmirnovaBug #72885 (where Shane Bester had clearly identified the memory leak)was declared a duplicate. If you use master-info-repository = TABLE on your 5.6.x slaves, please, consider upgrading to 5.6.25 ASAP.
  • Bug #70711 - mysqlbinlog prints invalid SQL from relay logs when GTID is enabled. This bug was reported by Yoshinori Matsunobu and probably verified formally by Luis Soares.
 There are several fixes in other categories:
  • Bug #75740 - Fix errors detected by ASan at runtime. It was reported and verified by Anitha Gopi based on request from WebScaleSQL team. 
  • Bug #76612 - would like ability to throttle firewall ACCESS DENIED messages in error log. This feature was requested by Shane Bester. Should I tell you again how much I am happy when I see public bug reports from Oracle employees?
  • Bug #76552 - Cannot shutdown MySQL using JDBC driver. This regression bug was reported by Davi Arnaut (who provided a patch as well) and verified by Umesh.
  • Bug #76019 is private. Release notes say: "Inappropriate -Werror options could appear in mysql_config --cflags output." Why on the Earth anyone could set or leave this bug as private is beyond my imagination.
  • Bug #74517 - thread/sql/main doesn't change state/info after startup. PERFORMANCE_SCHEMA was meant to be perfect already, but still some fixes are needed. The bug was reported by Kolbe Kegel and verified by Umesh.
  • Bug #72322 - Query to I_S.tables and I_S.columns leads to huge memory usage. Now I am impressed and I want to check the fix ASAP (as release notes do not say much)! If this bug (reported by my colleague Przemyslaw Malkowski just few weeks ago, on April 11, and verified by Umesh) is really fixed, it's a huge step forward in making INFORMATION_SCHEMA usable.
  • Bug #69638 - Wrong results when running a SELECT that includes a HAVING based on a function. The only optimizer bug from Community fixed in this version was reported by Roger Esteban and verified by Umesh.
  • Bug #69453 - Prepared statement is written to general query log after its execution is finish. It was reported by my colleague Sergei Glushchenko and verified by Umesh.
  • Bug #68999 - SSL_OP_NO_COMPRESSION not defined. It was reported by Remi Colletand verified probably by Georgi Kodinov.
To summarize, 24 or so bug reports from public bugs database were fixed in 5.6.25, of them fixes for replication, partitioned tables and INFORMATION_SCHEMA look really important and impressive. At least 10 of these bug reports were verified by Umesh. 4 bugs remain private, and I think it's probably wrong.
  

Tuesday, April 14, 2015

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.

Wednesday, April 8, 2015

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.



Tuesday, March 31, 2015

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

There is a story behind this post. To make it short, the detailed study presented here started when I noted old Bug #72748 in "No feedback" status few days ago. I considered this status totally wrong and started a discussion on Facebook about it (yes, this is what I usually do, I discuss handling of MySQL bugs in public).

The technical topic of this discussion (blaming aside) was the way AUTO-INC locks are set by InnoDB with default innodb_autoinc_lock_mode=1. Manual defines "bulk inserts" concept:
  • Bulk inserts
    Statements for which the number of rows to be inserted (and the number of required auto-increment values) is not known in advance. This includes INSERT ... SELECT, REPLACE ... SELECT, and LOAD DATA statements, but not plain INSERT. InnoDB will assign new values for the AUTO_INCREMENT column one at a time as each row is processed.
 and then says:
  • innodb_autoinc_lock_mode = 1 (consecutive lock mode)
    This is the default lock mode. In this mode, bulk inserts use the special AUTO-INC table-level lock and hold it until the end of the statement. This applies to all INSERT ... SELECT, REPLACE ... SELECT, and LOAD DATA statements. Only one statement holding the AUTO-INC lock can execute at a time.
I suspected (based on test case presented by my colleague Peiran last year) that this may not be case in reality, or at least the process is a bit more complicated. In the process of technical discussion, to make my points clear and highlight the underlying problem, I've reported another bug, Bug #76533, with simple test case and some speculations (that were not entirely correct as I soon found out).

After re-reading my report and re-checking results I was really surprised to see the result that can not be explained by the manual page mentioned above (yes, after all my bug reports for the manual I still consider it correct until the opposite is clearly proved, but that can be reproduced on MySQL 5.5, 5.6 and 5.7.

Once when I was in doubts I've got a nice advice from my dear friend Sinisa, "Read the Source, Luke!". But one has probably to spend few days at least to understand enough details to say for sure what happens when one executes INSERT INTO T ... SELECT FROM T (same table) comparing to INSERT INTO T ... SELECT FROM S (other table). So, I gave good advice myself (that I actually used to give others at FOSDEM 2015): "Use gdb, Luke!". It was even easier to follow that way after reading this great post by Annamalai.

So, I set up simple test, like this:

[openxs@centos ~]$ mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.23-72.1-log Percona Server (GPL), Release 72.1, Revision 0503478

Copyright (c) 2009-2015 Percona LLC and/or its affiliates
Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select @@innodb_autoinc_lock_mode, @@log_bin, @@binlog_format;
+----------------------------+-----------+-----------------+
| @@innodb_autoinc_lock_mode | @@log_bin | @@binlog_format |
+----------------------------+-----------+-----------------+
|                          1 |         1 | STATEMENT       |
+----------------------------+-----------+-----------------+
1 row in set (0.01 sec)

mysql> select @@innodb_locks_unsafe_for_binlog;
+----------------------------------+
| @@innodb_locks_unsafe_for_binlog |
+----------------------------------+
|                                0 |
+----------------------------------+
1 row in set (0.00 sec)
 

mysql> create table t(id int auto_increment primary key, val int);
Query OK, 0 rows affected (0.21 sec)

mysql> create table tt(id int auto_increment primary key, val int);
Query OK, 0 rows affected (0.14 sec)

mysql> insert into t(val) values (1), (2), (3), (4);
Query OK, 4 rows affected (0.02 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> insert into tt(val) values (1), (2), (3), (4);
Query OK, 4 rows affected (0.02 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> select * from t;
+----+------+
| id | val  |
+----+------+
|  1 |    1 |
|  2 |    2 |
|  3 |    3 |
|  4 |    4 |
+----+------+
4 rows in set (0.00 sec)

mysql> select * from tt;
+----+------+
| id | val  |
+----+------+
|  1 |    1 |
|  2 |    2 |
|  3 |    3 |
|  4 |    4 |
+----+------+
4 rows in set (0.01 sec)

That is, on Percona Server 5.6.23 I've created two InnoDB tables with auto_increment PRIMARY key and one other integer column. I've inserted the same 4 rows into both tables. Now, I wonder what locks are set while executing each the following statements, in the same single session, and in what order they are set:

insert into t(val) select 100 from tt;
insert into t(val) select 100 from t;

as I suspect there is a difference that is not clearly documented. I decided to use gdb to set breakpoints on the following functions:

lock_table()
lock_rec_lock()
row_lock_table_autoinc_for_mysql()

Don't ask me why these, it's topic for a separate discussion (but you can guess based on the names and/or code review and/or this great post I've already mentioned).

I've made sure there is debug info for the official RPM binaries I've used:

[root@centos ~]# rpm -qa | grep -i percona
...

Percona-Server-server-56-5.6.23-rel72.1.el6.x86_64
Percona-Server-56-debuginfo-5.6.23-rel72.1.el6.x86_64
...


So, I've attached gdb to mysql process running and set breakpoints:

[root@centos ~]# gdb -p `pidof mysqld`
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-75.el6)
...

 Loaded symbols for /usr/lib64/mysql/plugin/ha_tokudb.so
0x00007fd74b0970d3 in poll () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.149.el6_6.5.x86_64 jemalloc-3.6.0-1.el6.x86_64 keyutils-libs-1.4-5.el6.x86_64 krb5-libs-1.10.3-33.el6.x86_64 libaio-0.3.107-10.el6.x86_64 libcom_err-1.41.12-21.el6.x86_64 libgcc-4.4.7-11.el6.x86_64 libselinux-2.0.94-5.8.el6.x86_64 libstdc++-4.4.7-11.el6.x86_64 nss-softokn-freebl-3.14.3-22.el6_6.x86_64 openssl-1.0.1e-30.el6_6.7.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) set pagination 0
(gdb) b lock_table
Breakpoint 1 at 0x91c940: file /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc, line 4426.
(gdb) b lock_rec_lock
Breakpoint 2 at 0x91de04: file /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc, line 2329.
(gdb) b row_lock_table_autoinc_for_mysql
Breakpoint 3 at 0x984504: file /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/row/row0mysql.cc, line 1146.
(gdb) c
Continuing.


Then in the session where I created my tables I've started transaction to check the first statement:

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

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


and immediately hit one of breakpoints in gdb:

[Switching to Thread 0x7fd74cf79700 (LWP 1866)]

Breakpoint 1, lock_table (flags=0, table=0x7fd7233f7de8, mode=LOCK_IS, thr=0x7fd7233e29e8) 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
$1 = 0x7fd7383feae8 "test/tt"

So, we had a request for IS lock for the tt table.  I had source code at hand to check for some details that may be useful while interpreting data:

-- this is from  storage/innobase/include/lock0types.h
/* Basic lock modes */
enum lock_mode {
        LOCK_IS = 0,    /* intention shared */
        LOCK_IX,        /* intention exclusive */
        LOCK_S,         /* shared */
        LOCK_X,         /* exclusive */
        LOCK_AUTO_INC,  /* locks the auto-inc counter of a table
                        in an exclusive mode */
        LOCK_NONE,      /* this is used elsewhere to note consistent read */
        LOCK_NUM = LOCK_NONE, /* number of lock modes */
        LOCK_NONE_UNSET = 255
};


-- this is from storage/innobase/include/lock0lock.h
#define LOCK_WAIT       256     /*!< Waiting lock flag; when set, it
                                means that the lock has not yet been
                                granted, it is just waiting for its
                                turn in the wait queue */
/* Precise modes */
#define LOCK_ORDINARY   0       /*!< this flag denotes an ordinary
                                next-key lock in contrast to LOCK_GAP
                                or LOCK_REC_NOT_GAP */
#define LOCK_GAP        512     /*!< when this bit is set, it means that the
                                lock holds only on the gap before the record;
                                for instance, an x-lock on the gap does not
                                give permission to modify the record on which
                                the bit is set; locks of this type are created
                                when records are removed from the index chain
                                of records */
#define LOCK_REC_NOT_GAP 1024   /*!< this bit means that the lock is only on
                                the index record and does NOT block inserts
                                to the gap before the index record; this is
                                used in the case when we retrieve a record
                                with a unique key, and is also used in
                                locking plain SELECTs (not part of UPDATE
                                or DELETE) when the user has set the READ
                                COMMITTED isolation level */
#define LOCK_INSERT_INTENTION 2048 /*!< this bit is set when we place a waiting
                                gap type record lock request in order to let
                                an insert of an index record to wait until
                                there are no conflicting locks by other
                                transactions on the gap; note that this flag
                                remains set when the waiting lock is granted,
                                or if the lock is inherited to a neighboring
                                record */

if gdb would not be kind enough to do this for me (it 's, for enum, as you can see).

Now, let's check how we ended up here:

(gdb) bt
#0  lock_table (flags=0, table=0x7fd7233f7de8, mode=LOCK_IS, thr=0x7fd7233e29e8) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:4426
#1  0x0000000000999bdd in row_search_for_mysql (buf=0x7fd71bfed410 "\375\004", mode=1, prebuilt=0x7fd7233e2068, match_mode=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/row/row0sel.cc:4083
#2  0x00000000008e8b41 in ha_innobase::index_read (this=0x7fd71bf9d610, buf=0x7fd71bfed410 "\375\004", key_ptr=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/handler/ha_innodb.cc:8232
#3  0x00000000008dc090 in ha_innobase::index_first (this=0x7fd71bf9d610, buf=0x7fd71bfed410 "\375\004") at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/handler/ha_innodb.cc:8629
#4  0x000000000059a3ee in handler::ha_index_first (this=0x7fd71bf9d610, buf=0x7fd71bfed410 "\375\004") at /usr/src/debug/percona-server-5.6.23-72.1/sql/handler.cc:3057
#5  0x00000000006b491d in join_read_first (tab=0x7fd72332dc60) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_executor.cc:2540
#6  0x00000000006b3c0d in sub_select (join=0x7fd72332cf40, join_tab=0x7fd72332dc60, end_of_records=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_executor.cc:1256
#7  0x00000000006b2ea8 in do_select (this=0x7fd72332cf40) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_executor.cc:933
#8  JOIN::exec (this=0x7fd72332cf40) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_executor.cc:194
#9  0x00000000006fc3c5 in mysql_execute_select (thd=0x7fd71c354000, tables=0x7fd72332c888, wild_num=0, fields=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_select.cc:1100
#10 mysql_select (thd=0x7fd71c354000, tables=0x7fd72332c888, wild_num=0, fields=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_select.cc:1221
#11 0x00000000006fcc25 in handle_select (thd=0x7fd71c354000, result=0x7fd72332ce00, setup_tables_done_option=1073741824) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_select.cc:110
#12 0x00000000006d977b in mysql_execute_command (thd=0x7fd71c354000) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_parse.cc:3965
#13 0x00000000006db7e8 in mysql_parse (thd=0x7fd71c354000, rawbuf=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_parse.cc:6922
#14 0x00000000006dcf59 in dispatch_command (command=<value optimized out>, thd=0x7fd71c354000, packet=0x7fd72330f001 "insert into t(val) select 100 from tt", packet_length=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_parse.cc:1434
#15 0x00000000006aa772 in do_handle_one_connection (thd_arg=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_connect.cc:1532
#16 0x00000000006aa860 in handle_one_connection (arg=0x7fd71c354000) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_connect.cc:1443
#17 0x0000000000adc113 in pfs_spawn_thread (arg=0x7fd71c3443e0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/perfschema/pfs.cc:1860
#18 0x00007fd74c9869d1 in start_thread () from /lib64/libpthread.so.0
#19 0x00007fd74b0a08fd in clone () from /lib64/libc.so.6


So, we started with SELECT part and set IS lock on the table we read from tt. This is expected, as manual says:
"INSERT INTO T SELECT ... FROM S WHERE ... sets an exclusive index record lock (without a gap lock) on each row inserted into T. If the transaction isolation level is READ COMMITTED, or innodb_locks_unsafe_for_binlog is enabled and the transaction isolation level is not SERIALIZABLE, InnoDB does the search on S as a consistent read (no locks). Otherwise, InnoDB sets shared next-key locks on rows from S. InnoDB has to set locks in the latter case:"
Our case is REPEATABLE READ and innodb_locks_unsafe_for_binlog is not enabled, so some kind of S locks will be set on rows, and it means we need IS lock on the table (again, by the manual). Let's continue:

(gdb) c
Continuing.

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249ae700, heap_no=2, index=0x7fd7233f82e8, thr=0x7fd7233e29e8) 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
$2 = 0x7fd7383feae8 "test/tt"
(gdb) p index->name
$3 = 0x7fd7233f8480 "PRIMARY"


So, we clearly see an attempt to set a record lock on some row (heap_no=2) in the PRIMARY key of the table tt (this is a row of data, surely). mode=2 means LOCK_S in the enum. So this is an attempt to set S lock on the row ("shared next-key lock" as manual explained above, one day I'll explain how to distinguish it from other kinds of shared locks if needed). Let's continue:

(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) p trx
$4 = <value optimized out>
(gdb) p table->name
value has been optimized out

(gdb) p table
$5 = <value optimized out>

(gdb) bt
#0  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
#1  0x00000000008e8dcc in ha_innobase::innobase_lock_autoinc (this=0x7fd71bf9cc10) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/handler/ha_innodb.cc:7084
#2  0x00000000008e9128 in innobase_get_autoinc (this=0x7fd71bf9cc10, offset=1, increment=1, nb_desired_values=1, first_value=0x7fd74cf767c0, nb_reserved_values=0x7fd74cf767d0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/handler/ha_innodb.cc:13890
#3  ha_innobase::get_auto_increment (this=0x7fd71bf9cc10, offset=1, increment=1, nb_desired_values=1, first_value=0x7fd74cf767c0, nb_reserved_values=0x7fd74cf767d0) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/handler/ha_innodb.cc:13961
#4  0x000000000059ad18 in handler::update_auto_increment (this=0x7fd71bf9cc10) at /usr/src/debug/percona-server-5.6.23-72.1/sql/handler.cc:3472
#5  0x00000000008f06e9 in ha_innobase::write_row (this=0x7fd71bf9cc10, record=0x7fd71bfec810  <incomplete sequence \375>) at /usr/src/debug/percona-server-5.6.23-72.1/storage/innobase/handler/ha_innodb.cc:7271

...
#19 0x00000000006dcf59 in dispatch_command (command=<value optimized out>, thd=0x7fd71c354000, packet=0x7fd72330f001 "insert into t(val) select 100 from tt", packet_length=Unhandled dwarf expression opcode 0xf3
) at /usr/src/debug/percona-server-5.6.23-72.1/sql/sql_parse.cc:1434
...

I had not checked the code in time, so attempts to print something I see had not helped, but top lines of backtrace clearly show: we want to get auto_increment value for the row we are planning to write somewhere (to the table t). So, we set IS lock on table read from, we set S lock on the first row we tried to read from it via SELECT and then we try to insert the row into the target table t, and we need auto_increment value for it. Let's continue:

(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
$6 = 0x7fd7383feac0 "test/t"
(gdb) p thr
$7 = (que_thr_t *) 0x7fd7233e3780
(gdb) p *thr
$8 = {common = {type = 9, parent = 0x7fd7233e36b8, brother = 0x0, val = {data = 0x0, ext = 0, len = 0, type = {prtype = 0, mtype = 0, len = 0, mbminmaxlen = 0}}, val_buf_size = 0}, magic_n = 8476583, child = 0x7fd7233e3548, graph = 0x7fd7233e36b8, state = 1, is_active = 1, run_node = 0x7fd7233e3548, prev_node = 0x7fd7233e3548, resource = 0, lock_state = 0, slot = 0x0, thrs = {prev = 0x0, next = 0x0}, trx_thrs = {prev = 0x0, next = 0x0}, queue = {prev = 0x0, next = 0x0}, fk_cascade_depth = 0}

So,  we clearly see the attempt to set LOCK_AUTO_INC on the table t. This happens only after we read some row from the table tt and now inserting it into the target table, t.
 

(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
$9 = 0x7fd7383feac0 "test/t"
(gdb) p *table
$10 = {id = 65, heap = 0x7fd71c3514a0, name = 0x7fd7383feac0 "test/t", dir_path_of_temp_table = 0x0, data_dir_path = 0x0, space = 51, flags = 1, flags2 = 80, ibd_file_missing = 0, cached = 1, to_be_dropped = 0, n_def = 5, n_cols = 5, can_be_evicted = 1, corrupted = 0, drop_aborted = 0, cols = 0x7fd71c371868, col_names = 0x7fd71c3718f0 "id", name_hash = 0x0, id_hash = 0x0, indexes = {count = 1, start = 0x7fd7233f7b68, end = 0x7fd7233f7b68}, foreign_set = std::set with 0 elements, referenced_set = std::set with 0 elements, table_LRU = {prev = 0x7fd74902cb68, next = 0x7fd7233f7de8}, fk_max_recusive_level = 0, n_foreign_key_checks_running = 0, def_trx_id = 84487, query_cache_inv_trx_id = 84497, big_rows = 0, stats_latch_created = 2, stats_latch = 0x7fd71c3efb80, stat_initialized = 1, memcached_sync_count = 0, stats_last_recalc = 1427781732, stat_persistent = 0, stats_auto_recalc = 0, stats_sample_pages = 0, stat_n_rows = 4, stat_clustered_index_size = 1, stat_sum_of_other_index_sizes = 0, stat_modified_counter = 0, stats_bg_flag = 0 '\000', autoinc_lock = 0x7fd71c3718a8, autoinc_mutex = {event = 0x7fd71c3ef600, lock_word = 0 '\000', waiters = 0, list = {prev = 0x7fd7233f7f50, next = 0x7fd71c370f28}, count_os_wait = 0, cmutex_name = 0xc3cb37 "&table->autoinc_mutex", pfs_psi = 0x0}, autoinc = 6, n_waiting_or_granted_auto_inc_locks = 1, autoinc_trx = 0x7fd71c370c68, fts = 0x0, quiesce = QUIESCE_NONE, n_rec_locks = 0, n_ref_count = 1, locks = {count = 1, start = 0x7fd71c3718a8, end = 0x7fd71c3718a8}, is_corrupt = 0}
(gdb) p table->autoinc_lock
$11 = (ib_lock_t *) 0x7fd71c3718a8
(gdb) p *(table->autoinc_lock)
$12 = {trx = 0x7fd71c370c68, trx_locks = {prev = 0x7fd71c373530, next = 0x0}, type_mode = 20, hash = 0x0, index = 0x0, un_member = {tab_lock = {table = 0x7fd7233f69e8, locks = {prev = 0x0, next = 0x0}}, rec_lock = {space = 140561986054632, page_no = 0, n_bits = 0}}}


 Now, we set IX lock on table T (no wonder, we need to inserts rows there). According to the comments in the code:

-- this is from storage/innobase/include/lock0priv.h 
static const byte lock_compatibility_matrix[5][5] = {
 /**         IS     IX       S     X       AI */
 /* IS */ {  TRUE,  TRUE,  TRUE,  FALSE,  TRUE},
 /* IX */ {  TRUE,  TRUE,  FALSE, FALSE,  TRUE},
 /* S  */ {  TRUE,  FALSE, TRUE,  FALSE,  FALSE},
 /* X  */ {  FALSE, FALSE, FALSE, FALSE,  FALSE},
 /* AI */ {  TRUE,  TRUE,  FALSE, FALSE,  FALSE}
};

...

/* STRONGER-OR-EQUAL RELATION (mode1=row, mode2=column)
 *    IS IX S  X  AI
 * IS +  -  -  -  -
 * IX +  +  -  -  -
 * S  +  -  +  -  -
 * X  +  +  +  +  +
 * AI -  -  -  -  +
 * See lock_mode_stronger_or_eq().
 */
static const byte lock_strength_matrix[5][5] = {
 /**         IS     IX       S     X       AI */
 /* IS */ {  TRUE,  FALSE, FALSE,  FALSE, FALSE},
 /* IX */ {  TRUE,  TRUE,  FALSE, FALSE,  FALSE},
 /* S  */ {  TRUE,  FALSE, TRUE,  FALSE,  FALSE},
 /* X  */ {  TRUE,  TRUE,  TRUE,  TRUE,   TRUE},
 /* AI */ {  FALSE, FALSE, FALSE, FALSE,  TRUE}
};


IX lock is compatible with AI (and AI is hold by this same transaction anyway), so let's assume we got it and continue:

(gdb) c
Continuing.

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249ae700, heap_no=3, index=0x7fd7233f82e8, thr=0x7fd7233e29e8) 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
$13 = 0x7fd7383feae8 "test/tt"
(gdb) p index->name
$14 = 0x7fd7233f8480 "PRIMARY"


Now we set S lock (mode=2) on the next row (heap_no=3) we read in SELECT. We continue reading...

(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.

So, request for auto_increment value again (we ask for the lock that we already have), to get it for the row we plan to insert. All clear, so we continued and got this:

[Switching to Thread 0x7fd716bf7700 (LWP 1718)]

Breakpoint 1, lock_table (flags=0, table=0x7fd74902cb68, mode=LOCK_IX, thr=0x7fd71c1db638) at /usr/src/debug/percona-serverinnodb_table-5.6.23-72.1/storage/innobase/lock/lock0lock.cc:4426
4426            if (flags & BTR_NO_LOCKING_FLAG) {
(gdb) p table->name
$15 = 0x7fd730396c60 "mysql/innodb_table_stats"


So, other thread stepped in to set IX lock on innodb_table_stats table. This is a background update of table statistics and there will be many hits for our breakpoints because of this. I'll skip them all from now on, to keep concentrated on one main topic. For our tables in question we later had already well know sequences:

...
Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249ae700, heap_no=5, index=0x7fd7233f82e8, thr=0x7fd7233e29e8) 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
$17 = 0x7fd7383feae8 "test/tt"
(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.

...

that is, requests for S lock on yet another row in the source table (tt) and then request for the auto_increment. It ends up like this (changes to persistent statistics tables skipped):

Breakpoint 2, lock_rec_lock (impl=0, mode=2, block=0x7fd7249ae700, heap_no=1, index=0x7fd7233f82e8, thr=0x7fd7233e29e8) 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
$20 = 0x7fd7383feae8 "test/tt"
(gdb) p block
$21 = (const buf_block_t *) 0x7fd7249ae700
(gdb) p *block
$22 = {page = {space = 52, offset = 3, buf_fix_count = 1, io_fix = 0 '\000', state = 5 '\005', flush_type = 1, buf_pool_index = 0, zip = {data = 0x0, m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 0}, hash = 0x0, list = {prev = 0x7fd7249cf280, next = 0x0}, newest_modification = 129192199, oldest_modification = 0, LRU = {prev = 0x7fd7249ae580, next = 0x7fd7249ae880}, old = 0, freed_page_clock = 0, access_time = 1852500389, is_corrupt = 0}, frame = 0x7fd72c438000 "\333s\257\247", unzip_LRU = {prev = 0x0, next = 0x0}, mutex = {event = 0x7fd72400e900, lock_word = 0 '\000', waiters = 0, list = {prev = 0x7fd7249ae900, next = 0x7fd7249ae600}, count_os_wait = 0, cmutex_name = 0xc375cd "&block->mutex", pfs_psi = 0x0}, lock = {lock_word = 1048575, waiters = 0, recursive = 0, writer_thread = 140561776342784, event = 0x7fd72400e980, wait_ex_event = 0x7fd72400ea00, list = {prev = 0x7fd7249ae940, next = 0x7fd7249ae640}, pfs_psi = 0x0, count_os_wait = 0, lock_name = 0xc375db "&block->lock", last_s_file_name = 0xc281a0 "/mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.23-72.1/storage/innobase/row/row0sel.cc", last_x_file_name = 0xc34650 "/mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.23-72.1/storage/innobase/btr/btr0btr.cc", writer_is_wait_ex = 0, last_s_line = 3226, last_x_line = 741}, lock_hash_val = 39242, check_index_page_at_flush = 1, modify_clock = 1, n_hash_helps = 0, n_fields = 1, n_bytes = 0, left_side = 1, curr_n_fields = 0, curr_n_bytes = 0, curr_left_side = 0, index = 0x0}
(gdb) c
Continuing.



Note heap_no=1 above. This is a supremum record. I've also checked some details you can get for the block (page in the buffer pool) in the process. At this moment we've finally got rows inserted:

mysql> insert into t(val) select 100 from tt;
Query OK, 4 rows affected, 1 warning (31 min 9.51 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 (34.72 sec)

As you can assume for the above (time to execute show warnings)  we hit some breakpoints as InnoDB continues to update persistent statistics for the table t. I've later executed the following:

mysql> show engine innodb status\G
...

------------
TRANSACTIONS
------------
Trx id counter 84515
Purge done for trx's n:o < 84514 undo n:o < 0 state: running
History list length 371
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 84514, ACTIVE 223 sec
2 lock struct(s), heap size 360, 2 row lock(s), undo log entries 2---TRANSACTION 84511, ACTIVE 2394 sec
3 lock struct(s), heap size 360, 5 row lock(s), undo log entries 4
MySQL thread id 1, OS thread handle 0x7fd74cf79700, query id 18 localhost root init
show engine innodb status
--------
...
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
2 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
2 out of 1000 descriptors used
Main thread process no. 1681, id 140561818302208, state: sleeping
Number of rows inserted 12, updated 0, deleted 0, read 12
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s


So, you see transaction that made 2 changes in the background thead (this is reated to persitent statistics table), and our transaction that made 4 changes (inserted 4 rows). You see 5 row locks (and surely will NOT see AUTO-INC table one no matter how you try, as statement is completed, but it was there). These are 5 S locks set on the tt table we read (4 rows read and supremum record). But where our X locks on rows inserted into the t table (transaction is still active)? Here they are:

mysql> select * from t;
+----+------+
| id | val  |
+----+------+
|  1 |    1 |
|  2 |    2 |
|  3 |    3 |
|  4 |    4 |
|  5 |  100 |
|  6 |  100 |
|  7 |  100 |
|  8 |  100 |
+----+------+
8 rows in set (0.00 sec)


They exist, but they are implicit. You've probably noted that there was no call for X record lock mentioned, and they had NOT happened. Implicit locks do not have accociated lock object with them, they are present just because the trx_id for the transaction that changed (inserted, in this case) the row. Annamalai explained them well here.

Probably it's time to stop, as this post is already big enough. To summarize, the following locks are set (and in the following order) 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_aunoinc_lock_mode=1 according to our tracing in gdb:
  1. IS lock on the source table (tt)
  2. S lock on the first row in tt we read with SELECT
  3. AUTO-INC lock on the destination table (t)
  4. IX lock on the destination table (t)
  5. Probably implicit X lock on the row inserted (we had not seen this in gdb clearly)
  6. S lock on the next row in tt we read with SELECT
  7. Probably implicit X lock on the row inserted (we had not seen this in gdb clearly)
  8. ...
  9. S lock on the supremum in tt we read with SELECT
I see three potential problems here.

There is a small chance to run fast concurrent INSERT (that uses AUTO-INC lock) into the destination table after we read the first row from the source table, but before we request AUTO-INC lock on the destination.

Also, try to find explanation for this case in the manual. It says nothing on when AUTO-INC lock is set.

The last but not the least, I do not see any explanation of implicit X locks in the manual. I had not try hard yet.

For these (and more) I'll report bugs. The story will be continued in the next blog post(s) in this series. As for that "day" when I plan ot tell you more about InnoDB locks, it's predefined. Please, visit this talk at Percona Live 2015. There Nilnanadan and me (let's hope) will tell you notably more based on our findings and experience.

Sunday, September 28, 2014

Fun with Bugs #34 - Who has fun to verify your bugs (based on 5.6.21)

This time I decided not just to review all community bugs fixed in recent MySQL 5,6 GA release, 5.6.21, but also to mention who reported them (Morgan does this recently) and, most important for this post - who verified them.

As I've explained long time ago, verification is an important part of a bugs life cycle in MySQL. We need some MySQL engineer to check the bug and make sure there is a repeatable test case for it or it is at least clear what is the real problem behind the report. Bug must be "Verified" (confirmed internally) before developers start to work on the fix.

Usually this engineer is somebody from the bugs verification team where I worked for 7 years. But we later agreed that if a bug is reported by MySQL Support Engineer or Developer, it's accepted to set it to "Verified" immediately, without waiting on somebody else from bugs verification team to pay attention and double check.

So, while reporting and fixing are, surely, important stages, verification is also important as it helps developers to concentrate on real bugs only and isolate them from most false positives and user complains. I've noted (at was surprised) that it seems more than 45% of all bugs recently fixed were actually verified by one my former colleague in Oracle since 2011 (who used to work as a regular support engineer during EMEA hours mostly), Umesh Shastry (that you may know as "Umesh Umesh" in the bugs database for the reason only him and Oracle probably knows about).

This is what we have in MySQL 5.6.21 with regards to bugs from http://bugs.mysql.com:
  • Bug #70641 - 5.6 partitions use much more memory than 5.1. Reported by famous Yoshinori Matsunobu and verified by Umesh (no details shared in public). As a side note: I think it was me who introduced a habit not just to write "verified" in a comment, but also to share all the details and steps, just copy/pasting outputs from mysql command line client or terminal. (I've got this habit while following famous Oracle guru Tom Kyte.) So, I am always sad when details about the exact steps performed and versions used are no shared...
  • Bug #73650 is still private and we can see no details. We can only rely on public description in the release notes: "An ALTER TABLE ... ADD FOREIGN KEY operation could cause a serious error." I know what the bug is about as I've reported a duplicate of it based on Percona Server bug report (that is public as far as I remember). many community users know all the details about the crash (let's use proper words, it was a crash). Bug is fixed. But we see nothing, neither about test case, nor about the fix (even though it's visible when one checks what changed since last version in bzr/source code repository). If you ask me, this Oracle policy is applied in a wrong way to open source software, to put it into polite words. One day I'll write long text about this approach and historical reasons for it...
  • Bug #72453 - InnoDB Memcached Plugin "gets" command. Reported by qixiu xiao and verified by Umesh.
  • Bug #72586 - memcached daemon crashes and restarts on second ADD operation. Reported by David Schwartz and verified by Umesh.
  • Bug #72594 - InnoDB in-place ALTER failures block future ALTERs. Reported by famous code contributor, InnoDB guru and great conference speaker, Jeremy Cole. Recently we see his name in all release notes. This bug was verified by Miguel Solorzano, who was my team manager and trainer since day one in MySQL. Nice to see that he still not only manages a successful (and key!) team in Oracle MySQL Support, but also finds time to do real work.  
  • Bug #72137 - inaccurate handling of srv_activity_count. Reported by famous InnoDB guru Inaam Rana and verified by Sveta Smirnova. There is no much need to explain who is Sveta and what she does - she speaks, writes and works for herself, and her work is recognized and awarded in Oracle. Check her sessions at MySQL Connect 2013, if you wonder, or read her book. I am just happy to find out that she still works on bugs processing.
  • Bug #67718 - InnoDB drastically under-fills pages in certain conditions. Reported by Jeremy Cole and verified by Sinisa Milivojevic. I am happy to call Sinisa my teacher, in diplomatic skills if not in bugs processing or reading the code. If any of my former colleagues from MySQL asked what I am doing in Percona, I'd reply that I play a role of Sinisa here, "ideal" Sinisa as I wanted him to be, not the "real" one. I am not good enough in playing the role of real one, as I lack diplomatic skills, to begin with.
  • Bug #71695 - Concatenation of mysqlbinlog output does not work with GTID. Reported by Sadao Hiratsuka and verified by Umesh.
  • Bug #70327 - Assertion error when setting future binlog file/pos with semisync. Reported by Yoshinori Matsunobu and verified by yet another my former colleague since MySQL AB times, Mikiya Okuno. Nice to see many MySQL engineers contributing to bugs processing, not just members of bugs verification team.
  • Bug #69873 - Replication stop with "Error in Xid_log_event: Commit could not be completed". Reported by Alexander Du and verified by Umesh.
  • Bug #71047 - shutdown hang if semisync is enabled and slave abort. Reported by a great community contributor to MySQL, zhai weixiang. Verified by Umesh.
  • Bug #72788 - HASH_SCAN seems broken: Can't find record in 't1' Error_code: 1032. Reported by Shane Bester, who probably works more on community bugs reports than all other engineers outside bugs verification team together. As I mentioned more than once, Shane is a QA department for MySQL by himself, and it had always been the case, no matter what company he worked at. Bug was verified, surprise surprise, by Umesh.
  • Bug #72313 - stop sql_thread, start sql_thread causes a trx to log with a different GTID. Reported by Santosh Praneeth Banda. Not sure who verified it, but probably the reporter himself.
  • Bug #72578 - Duplicate slave server_uuid in replication forum gives no specific error message. Reported by Hartmut Holzgraefe, former my colleague at MySQL AB and Sun. He helped me a lot during my first days in MySQL and he still reports a lot of bugs. Bug was verified by Umesh.
  • Bug #72901 - Keep CLIENT_REMEMBER_OPTIONS for compressed connections. Bug was reported by Ramil Kalimullin, whom I miss a lot since MySQL developers conference in Riga, 2008 (as many others, it was last team meeting or conference for me till I quite from Oracle). He verified the bug himself it seems.
  • Bug #73324 - Client flags are getting discarded due to incorrect assignment operator. Reported by Sujatha Sivakumar. She then verified and fixed the bug herself it seems. I am always happy to see Oracle employees and customers using public bugs database. You know why, I hope...
  • Bug #72610 - Out of memory replicating using RBR and slave having different data types. Reported by Jean-Francois Gagn and verified by Umesh.
  • Bug #70429 - list handling incorrect in mysql_prune_stmt_list(). Reported and verified by yet another former colleague from MySQL Support, Andrew Dalgleish.
  • Bug #47641 - LIKE doesn't match when cp932_bin/sjis_bin collations are used. Reported and verified by Mikiya Okuno.
    Bug #73507 - On EL7, installation of MySQL from RPM packages could fail if postfix had previously been installed using yum. It is still private, even though I fail to see what "security implications" it may have, based on that description, comparing to any other public bug report about upgrade being screwed up. There are many, public ones...
  • Bug #72066 - mysql_upgrade duplicate key error for mysql.user for 5.5.35+, 5.6.15+, 5.7.3+. Reported and verified by Jesper wisborg Krogh, again, former colleague who still works in Oracle.
  • Bug #67088 - When the general_log is a socket and the reader goes away, mysql quits working. Reported by Rolf Martin-Hoster and verified by Sveta Smirnova.
  • Bug #71433 - recreate+analyze OPTIMIZE TABLE T and online ALTER TABLE T may deadlock. Reported by my colleagues from Percona and great code contributor, Laurynas Biveinis. Recently he reached 100 as a number of public MySQL bugs reported. Time to review and update my list of famous bug reporters, it seems... Bug was verified by Umesh.
  • Bug #72547 - Query cache not invalidated on cascade delete if db name has special symbols. Reported by Elena Stepanova, whom I met first in Riga, 2008. He contribution to QA in both MariaDB and upstream MySQL is outstanding - we can see her name in every issue of community release notes by Morgan. Bug was verified by Umesh.
So, out of 24 community bug reports 11 were surely verified by Umesh Shastry. This is almost 46% of them all. Now you know who seems to play the most important role in community bugs processing. I hope I am not the only one who noted that I am now successfully replaced in my former main job role, by a single person (whom I trained to some extent while we still worked together in Oracle).

One can probably make more conclusions based on above. For example, it looks like that most "community" bugs fixed are actually from former or current MySQL support engineers and developers, not just "users"... But let me stop on highlighting names at the moment. I am sure that some of these names were rarely mentioned in public before.

Saturday, May 31, 2014

Fun with Bugs #33 - bugs fixed in MySQL 5.6.19

It seems Oracle released MySQL 5.6.19 yesterday. So, it's time to check what community bug reports are fixed there.

Let's start with InnoDB. We have the following bugs fixed:
  • Bug #72079, "Upgrade from 5.6.10 to 5.6.16 crashes and leaves unusable DB". Honestly I had not noted this bug, even though I upgrade several instances on Windows to each and every release since 5.6.8. Probably because I had no need to use FTS indexes till recently...
  • Bug #71014, about two extra memset calls that are now removed. I hope the patch bug report provided was just used.
  • Bug #69641, "Crash when enabling innodb_table_monitor (assertion: ib_table->stat_initialized)". Good to see one more crash fixed.
  • Bug #62534, "off by one error in innodb_max_dirty_pages_pct logic". Reported by Domas and fixed by Facebook long time ago. But it seems current fix from Oracle is somewhat more complex than just replacing ">" with ">="... Maybe my comment about Informix having decimal (instead of integer) as a data type for similar variable helped :)
The following replication bugs are fixed in 5.6.19:
  • Bug #71070, "kill of truncate table will lead to binary log written while rows remains". I am really happy to this it fixed finally!
  • Bug #71376, "restart of slave instance fail in GTID replication if we use replicate-ignore-db". Also great to see this fixed. Note that to add more confusion, Bug #71326 is mentioned instead as replication bug that is fixed, but this is actually a MySQL Workbench bug. I tried to guess what other community bug it could really be, and ended up with this one. Let's home release notes will be fixed soon accordingly.
  • Bug #71179, "CREATE TABLE .. SELECT produces invalid structure, breaks RBR". Replication is just one of the areas affected though. Let me quote details of the fix (added by Laurynas Biveinis, he does this for each and every community bug fixed. I wonder why Oracle does NOT care to do that themselves?):

      This fix changes the DIV operation implementation to correctly
      evaluate the display width of its result. We check if DIV's
      results estimated width crosses maximum width for integer
      value (21) and if yes set it to this maximum value.
  • Bug #70891 is also listed as fixed, but it is still private, so we can only guess what exactly it was about or just trust release notes... 
 On top of that, few old bugs from other categories were also fixed:
  • Bug #66803, "Allow compilation using Clang in C++11 mode". Clang is becoming popular. Still not sure why it took so much time to fix the problem when original bug report had a patch.
  • Bug #71089, "CMake warning when generating Makefile". No more warning for new CMake versions.
  • Bug #51840, "infinite hang with 100% cpu usage with load data local and import errors". Reported by Shane more than 4 years ago, it was fixed only in 5.6.19. This fix may be the only really good reason to upgrade to 5.6.19, by the way!
  • Bug #69683, "Optimize after a delete returns error 0 can't get stat of MYD file". Actually, it was a problem for MyISAM tables with .MYD files larger than 4GB on Windows. If you care about Windows and MyISAM (really?), then you have one more good reason to upgrade.
  • Bug #69684, "The update and select behave differently under the same conditions". Probably the only fix from the Optimizer team in this release.
That's all, folks! Just 13 community bugs fixed over 2 months, according to the official Release Notes (that has a bug...). I am not impressed and I see a reason to upgrade only if you care about top INSERT performance for InnoDB, or if you use GTID and/or row-based replication setup, or may get LOAD DATA LOCAL statements for files with uncontrolled content. Other fixed are for some rare/corner cases or compilation problems, and I'd happily wait for 5.6.20 to fix some more bugs I so much care about...

Wednesday, April 2, 2014

Fun with Bugs #32 - some bugs I've reported in March

Comparing to the previous month I was not really productive bug reporter in March 2014 (partially because I spent few days at a nice FLOSS UK conference where I tried to give a session on PERFORMANCE_SCHEMA). Just 12 reports, of them 5 documentation requests are already closed. There are some interesting reports among other 7 to write about though.

But let me start with good (or not entirely good) news about my older report, Bug #71858 (easy way to crash MySQL with single SELECT statement, at least on Windows and maybe everywhere). The bug seems to be fixed by Oracle, but the fix will appear in 5.5.38, 5.6.18, and 5.7.5, not in recent official releases.

Off all the documentation requests I'd like to highlight this one, Bug #71916, "Manual does NOT explain locks set for UPDATE ... WHERE PK='const' properly". I was so much surprised to see even basic details about InnoDB locks ad monitoring them not entirely or correctly documented thatI even decided to submit a talk about this of next Oracle's MySQL Connect event (and I tried once, but then probably clicked at some wrong place and my submission disappeared).... Do you think this makes any sense, or should we better just wait for MySQL Documentation team to explain it all eventually?

Another important cases of the "missing manual"are presented by my Bug #72047, "Manual does not explain names for indexes generated for FOREIGN keys properly", that I've reported while trying to study what happens when MySQL creates index for the foreign key implicitly and then InnoDB "switches" to a new suitable index that is explicitly created later (more on this to be written one day...), and by the latest my report, Bug #72133, "Manual does not provide enough details about InnoDB FTS implementation".

While working on a (usual) customer issue about ibdata1 growing even with innodb_file_per_table=1 in MySQL 5.6 I've noted more serious missing detail about FTS implementation represented by a sever bug report, Bug #72132, "Auxiliary tables for InnoDB FTS indexes are always created in shared tablespace". Had you even noted tables like these?

mysql> select name, space from information_schema.innodb_sys_tables where name like 'test/FTS%';
+----------------------------------------------------+-------+
| name                                               | space |
+----------------------------------------------------+-------+
| test/FTS_000000000000002e_0000000000000059_INDEX_1 |     0 |
| test/FTS_000000000000002e_0000000000000059_INDEX_2 |     0 |
| test/FTS_000000000000002e_0000000000000059_INDEX_3 |     0 |
| test/FTS_000000000000002e_0000000000000059_INDEX_4 |     0 |
| test/FTS_000000000000002e_0000000000000059_INDEX_5 |     0 |
| test/FTS_000000000000002e_0000000000000059_INDEX_6 |     0 |
| test/FTS_000000000000002e_BEING_DELETED            |    35 |
| test/FTS_000000000000002e_BEING_DELETED_CACHE      |    36 |
| test/FTS_000000000000002e_CONFIG                   |    37 |
| test/FTS_000000000000002e_DELETED                  |    33 |
| test/FTS_000000000000002e_DELETED_CACHE            |    34 |
... 

Not only they are not documented anywhere outside this old article, but those *_INDEX_* ones are always created in shared tablespace! I consider this a server bug to fix, not just something to document.

Probably I am not the first one, but I consider this mysql client problem, Bug #72108, related to libedit now used by Oracle mysql client instead of readline really annoying... Some users even claim that other versions/forks of MySQl are already good enough just because they still use readline :)

Finally, one of my reports ended up as "Not a bug": Bug #71978, "Server silently allows to set PERFORMANCE_SCHEMA as default_storage_engine". I've got a kind and polite offer like this:
"Please double-check the documentation available at http://dev.mysql.com/doc/ and the instructions on how to report a bug at http://bugs.mysql.com/how-to-report.php"
that I probably has to be insulted by, as a person who had not only reported many dozens of good "Verified" valid bugs, but also the one who had a chance to use the same boilerplate standard reply for 7+ years and hardly used it more than maybe 10 times over these years... What's even more interesting, for a bug that was "Verified" by Oracle engineer (and my former manager in bugs verification team) originally I've got explanations (that I am thankful for) and kind offer:
"So your request is at best a feature request (and feel free to re-open as such). But I see little value in implementing this, specially since you're getting a meaningful error message."
So, I did that. I still wonder why the decision to make feature request out of it was not made without original reporter involved...