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.



No comments:

Post a Comment