Saturday, December 22, 2018

How to Get Details About MyRocks Deadlocks in MariaDB and Percona Server

In my previous post on ERROR 1213 I noted that Percona Server does not support the SHOW ENGINE ROCKSDB TRANSACTION STATUS statement to get deadlock details in "text" form. I've got some clarifications in my related feature request, PS-5114. So I decided to write this followup post and show what is the way to get deadlock details for the ROCKSDB tables in current versions of MariaDB and Percona Server.

First of all, I'd like to check MariaDB's implementation of MyRocks. For this I'll re-create deadlock scenario from that my post with MariaDB 10.3.12 I have at hand. We should start with installing ROCKSDB plugin according to this KB article:
openxs@ao756:~/dbs/maria10.3$ bin/mysql --no-defaults --socket=/tmp/mariadb.sock -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 MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 8
Server version: 10.3.12-MariaDB Source distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

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


MariaDB [test]> install soname 'ha_rocksdb';
Query OK, 0 rows affected (36,338 sec)

MariaDB [test]> show engines;
+--------------------+---------+----------------------------------------------------------------------------------+--------------+------+------------+
| Engine             | Support | Comment                                                                          | Transactions | XA   | Savepoints |
+--------------------+---------+----------------------------------------------------------------------------------+--------------+------+------------+
| ROCKSDB            | YES     | RocksDB storage engine                                                           | YES          | YES  | YES        |
...
| CONNECT            | YES     | Management of External Data (SQL/NOSQL/MED), including many file formats         | NO           | NO   | NO         |
| Aria               | YES     | Crash-safe tables with MyISAM heritage                                           | NO           | NO   | NO         |
| InnoDB             | DEFAULT | Supports transactions, row-level locking, foreign keys and encryption for tables | YES          | YES  | YES        |
| PERFORMANCE_SCHEMA | YES     | Performance Schema                                                               | NO           | NO   | NO         |
| SEQUENCE           | YES     | Generated tables filled with sequential values                                   | YES          | NO   | YES        |
+--------------------+---------+----------------------------------------------------------------------------------+--------------+------+------------+
10 rows in set (8,753 sec)

MariaDB [test]> show plugins;
+-------------------------------+----------+--------------------+---------------+---------+
| Name                          | Status   | Type               | Library       | License |
+-------------------------------+----------+--------------------+---------------+---------+
| binlog                        | ACTIVE   | STORAGE ENGINE     | NULL          | GPL     |
| mysql_native_password         | ACTIVE   | AUTHENTICATION     | NULL          | GPL     |
| mysql_old_password            | ACTIVE   | AUTHENTICATION     | NULL          | GPL     |
| wsrep                         | ACTIVE   | STORAGE ENGINE     | NULL          | GPL     |
...
| CONNECT                       | ACTIVE   | STORAGE ENGINE     | ha_connect.so | GPL     |
| ROCKSDB                       | ACTIVE   | STORAGE ENGINE     | ha_rocksdb.so | GPL     |
...
| ROCKSDB_LOCKS                 | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_TRX                   | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_DEADLOCK              | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
+-------------------------------+----------+--------------------+---------------+---------+
68 rows in set (2,451 sec)
Note that in MariaDB just one simple INSTALL SONAME ... statement is enough to get ROCKSDB with all related plugins loaded. Do not mind time to execute statements - I am running them on a netbook that is busy compiling Percona Server 8.0.13 from GitHub concurrently, to post something about it later :)

Now, let me re-create the same deadlock scenario:

MariaDB [test]> create table t1(id int, c1 int, primary key(id)) engine=rocksdb;
Query OK, 0 rows affected (4,163 sec)

MariaDB [test]> insert into t1 values (1,1), (2,2);
Query OK, 2 rows affected (0,641 sec)
Records: 2  Duplicates: 0  Warnings: 0

MariaDB [test]> set global rocksdb_lock_wait_timeout=50;
Query OK, 0 rows affected (0,644 sec)

MariaDB [test]> set global rocksdb_deadlock_detect=ON;
Query OK, 0 rows affected (0,037 sec)

MariaDB [test]> show global variables like 'rocksdb%deadlock%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| rocksdb_deadlock_detect       | ON    |
| rocksdb_deadlock_detect_depth | 50    |
| rocksdb_max_latest_deadlocks  | 5     |
+-------------------------------+-------+
3 rows in set (0,022 sec)
We need two sessions. In the first one:
MariaDB [test]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|              11 |
+-----------------+
1 row in set (0,117 sec)

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0,000 sec)

MariaDB [test]> select * from t1 where id = 1 for update;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
+----+------+
1 row in set (0,081 sec)

In the second:
MariaDB [test]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|              12 |
+-----------------+
1 row in set (0,000 sec)

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0,000 sec)

MariaDB [test]> select * from t1 where id = 2 for update;
+----+------+
| id | c1   |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (0,001 sec)
Back in the first:

MariaDB [test]> select * from t1 where id=2 for update;
It hangs waiting for incompatible lock. In the second:

MariaDB [test]> select * from t1 where id=1 for update;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
Now, can we get any details about the deadlock that just happened using upstream SHOW ENGINE statement? Let's try:
MariaDB [test]> SHOW ENGINE ROCKSDB TRANSACTION STATUS\G
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'TRANSACTION STATUS' at line 1
Does not work, same as in Percona Server 5.7.x. Here is a related MariaDB task: MDEV-13859 - "Add SHOW ENGINE ROCKSDB TRANSACTION STATUS or its equivalent?". Still "Open" and without any target version set, not even 10.4.

The idea behind NOT supporting this statement by Percona, according to comments I've got in  PS-5114, is to rely on tables in the information_schema. That's what we have in the related tables, rocksdb_locks, rocksdb_trx and rocksdb_deadlock after deadlock above was detected:
MariaDB [test]> select * from information_schema.rocksdb_deadlock;
+-------------+------------+----------------+---------+------------------+-----------+------------+------------+-------------+
| DEADLOCK_ID | TIMESTAMP  | TRANSACTION_ID | CF_NAME | WAITING_KEY      | LOCK_TYPE | INDEX_NAME | TABLE_NAME | ROLLED_BACK |
+-------------+------------+----------------+---------+------------------+-----------+------------+------------+-------------+
|           0 | 1545481878 |              6 | default | 0000010080000002 | EXCLUSIVE | PRIMARY    | test.t1    |           0 |
|           0 | 1545481878 |              7 | default | 0000010080000001 | EXCLUSIVE | PRIMARY    | test.t1    |           1 |
+-------------+------------+----------------+---------+------------------+-----------+------------+------------+-------------+
2 rows in set (0,078 sec)

MariaDB [test]> select * from information_schema.rocksdb_trx;
+----------------+---------+------+-------------+------------+-------------+-------------+--------------------------+----------------+--------------+-----------+------------------------+----------------------+-----------+-------+
| TRANSACTION_ID | STATE   | NAME | WRITE_COUNT | LOCK_COUNT | TIMEOUT_SEC | WAITING_KEY | WAITING_COLUMN_FAMILY_ID | IS_REPLICATION | SKIP_TRX_API | READ_ONLY | HAS_DEADLOCK_DETECTION | NUM_ONGOING_BULKLOAD | THREAD_ID | QUERY |
+----------------+---------+------+-------------+------------+-------------+-------------+--------------------------+----------------+--------------+-----------+------------------------+----------------------+-----------+-------+
|              6 | STARTED |      |           0 |          2 |          50 |             |                        0 |              0 |            0 |         0 |                      1 |                    0 |        11 |       |
+----------------+---------+------+-------------+------------+-------------+-------------+--------------------------+----------------+--------------+-----------+------------------------+----------------------+-----------+-------+
1 row in set (0,001 sec)

MariaDB [test]> select * from information_schema.rocksdb_locks;
+------------------+----------------+------------------+------+
| COLUMN_FAMILY_ID | TRANSACTION_ID | KEY              | MODE |
+------------------+----------------+------------------+------+
|                0 |              6 | 0000010080000002 | X    |
|                0 |              6 | 0000010080000001 | X    |
+------------------+----------------+------------------+------+
2 rows in set (0,025 sec)
I was not able to find any really good documentation about these tables (I checked here, there and more), especially rocksdb_deadlock that is totally undocumented, so let me try to speculate and explain my ideas on how they are supposed to work and be used together. Information about up to rocksdb_max_latest_deadlocks is stored in the rocksdb_deadlock table, each deadlock is identified by deadlock_id and in case of MariaDB you can find out when it happened using the timestamp column that is a UNIX timestamp:
MariaDB [test]> select distinct deadlock_id, from_unixtime(timestamp) from information_schema.rocksdb_deadlock;+-------------+--------------------------+
| deadlock_id | from_unixtime(timestamp) |
+-------------+--------------------------+
|           0 | 2018-12-22 14:31:18      |
+-------------+--------------------------+
1 row in set (0,137 sec)

For each deadlock you have a row per lock wait for each transaction involved, identified by transaction_id. You can see for what key value (waited_key) in that index (index_name) of what table (table_name) the transaction was waited. Victim (transaction that was rolled back to prevent deadlock) of deadlock detection is identified by the value 1 in the rolled_back column. This is all the information that persists for any notable time, and I don't like it that much, as we can not see what lock(s) transactions had at the moment. We can guess conflicting lock based on what was the waiting_key, but I'd prefer InnoDB way of showing this clearly with all the details.

If you hurry up and query the rocksdb_trx table fast enough, you can get more details about those transaction(s) involved in deadlock that are NOT rolled back (and not yet committed). Join by the transaction_id column, obviously, to get the details up to current running query and processlist connection id (rocksdb_trx.thread_id column) involved. 

If you hurry up to query rocksdb_locks table also by the transaction_id of still active transaction, you can get a list of locks it holds and then guess which one was a blocking lock. If you are not fast enough and transaction is gone you have just to assume there was some blocking lock. One day gap locks may be added, and some lock would become not good enough guess.

I miss these rocks at Beaulieu-sur-Mer. MyRocks in all implementations but Facebook's, misses one useful way to get the details about deadlock(s) that happened in the past.

To summarize, while storing information about configurable number of last deadlocks in the table seems to be a good idea, in case of ROCKSDB in both Percona and MariaDB servers (as soon as all transactions involved in deadlock are completed one way or the other) we miss some details (like thread ids for sessions involved, exact locks that each transaction held etc) comparing to the text output provided by the original upstream statement (and SHOW ENGINE INNODB STATUS\G, surely). Even if we are lucky to query all tables in time, we still probably miss lock waits table (like innodb_lock_waits) and any built in way to store information in the error log about deadlocks that happened (and all locks involved). 

Note also lack of consistency in naming (rocksdb_locks, plural vs  rocksdb_deadlock, singular, in case of MariaDB), rocksdb_deadlock.lock_type with value EXCLUSIVE vs rocksdb_locks.mode with value X etc, and and very limited documentation available. In my opinion current state is unacceptable if we hope to see wide use of MyRocks by community users and DBAs outside of Facebook.

Saturday, December 15, 2018

Fun with Bugs #75 - On MySQL Bug Reports I am Subscribed to, Part XII

From the lack of comments to my previous post it seems everything is clear with ERROR 1213 in different kinds and forks of MySQL. I may still write a post of two about MyRocks or TokuDB deadlocks one day, but let's get back to my main topic of MySQL bugs. Today I continue my series of posts about community bug reports I am subscribed to with a review of bugs reported in November, 2018, starting from the oldest and skipping those MySQL 8 regression ones I've already commented on. I also skip documentation bugs that should be a topic for a separate post one day (to give more illustration to these my statements).

These are the most interesting bug reports from Community members in November 2018:
  • Bug #93139 - "mysqldump temporary views missing definer". This bug reported by Nikolai Ikhalainen from Percona looks like a regression (that can appear in a bit unusual case of missing root user) in all versions starting from 5.6. There is no regression tag, surely. Also for some reason I do not see 8.0.x as affected version, while from the text it seems MySQL 8 is also affected.
  • Bug #93165 - "Memory leak in sync_latch_meta_init() after mysqld shutdown detected by ASan". This bug was reported by Yura Sorokin from Percona, who also made important statement in his last comment (that I totally agree with):
    "In commit https://github.com/mysql/mysql-server/commit/e93e8db42d89154b37f63772ce68c1efda637609 you literally made 14 MTR test cases ignore ALL memory problems detected by ASan, not only those which you consider 'OK' when you terminate the process with the call to 'exit()'. In other words, new memory leaks introduced in FUTURE commits may not be detected because of those changes. Address Sanitizer is a very powerful tool and its coverage should be constantly extending rather than shrinking."
  • Bug #93196 - "DD crashes on assert if ha_commit_trans() returns error". It seems Vlad Lesin from Percona spent notable time testing everything related to new MySQL 8 data dictionary (maybe while Percona worked on their Percona Server for MySQL 8.0 that should have MyRocks also supported, should be able to provide native partitioning and proper integration with data dictionary). See also his Bug #93250 - "the result of tc_log->commit() is ignored in trans_commit_stmt()".
  • Bug #93241 - "Query against full text index with ORDER BY silently fails". Nice finding by Jonathan Balinski, with detailed test cases and comments added by Shane Bester. One more confirmation that FULLTEXT indexes in InnoDB are still problematic.
  • Bug #93276 - "Crash when calling mysql_real_connect() in loop". Nice regression in C API (since 8.0.4!) noted by Reggie Burnett and still not fixed.
  • Bug #93321 - "Assertion `rc == TYPE_OK' failed". The last but not the least, yet another debug assertion (and error in non-debug build) found in MySQL 8.0.13 by Roel Van de Paar from Percona. You already know where QA for MySQL happens to large extent, don't you?
  • Bug #93361 - "memory/performance_schema/table_handles have memory leak!". It's currently in "Need Feedback" status and may end up as not a bug, but I've never seen 9G of memory used for just one Performance Schema table so far. It's impressive.
  • Bug #93365 - "Query on performance_schema.data_locks causes replication issues". Probably the first case when it was proved that query to some Performance Schema table may block some important server activity. Nice finding by Daniël van Eeden.
  • Bug #93395 - "ALTER USER succeeds on master but fails on slave." Yet another way to break replication was found by Jean-François Gagné. See also his Bug #93397 - "Replication does not start if restart MySQL after init without start slave."
  • Bug #93423 - "binlog_row_image=full not always honored for binlog_format=MIXED". For some reason this bug (with a clear test case) reported by James Lawrie is still "Open".
  • Bug #93430 - "Inconsistent output of SHOW STATUS LIKE 'Handler_read_key';". This weird inconsistency was found by Przemysław Skibiński from Percona.
Thinking about the future of MySQL 8 somewhere in Greenwich...
To summarize this review:
  1. I obviously pay a lot of attention to bug reports from Percona engineers.
  2. It seems memory problems detected by ASan in some MTR test cases are deliberately ignored instead of being properly fixed.
  3. There are still many surprises waiting for early adopters of MySQL 8.0 GA :) 
That's all I have to say about specific MySQL bugs in 2018. Next "Fun with Bugs" post, if any, will appear only next year. I am already subscribed to 11 bugs reported in December 2018. Stay tuned!

Saturday, December 8, 2018

What May Cause MySQL ERROR 1213

Probably all of us, MySQL users, DBAs and developers had seen error 1213 more than once, in one context or the other:
mysql> select * from t1;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
The first thing that comes to mind in this case is: "OK, we have InnoDB deadlock, let's check the details", followed by the SHOW ENGINE INNODB STATUS check, like this:
mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2018-12-08 17:41:11 0x7f2f8b8db700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 12 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 59 srv_active, 0 srv_shutdown, 14824 srv_idle
srv_master_thread log flush and writes: 14882
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 326
OS WAIT ARRAY INFO: signal count 200
RW-shared spins 0, rounds 396, OS waits 195
RW-excl spins 0, rounds 120, OS waits 4
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 396.00 RW-shared, 120.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 14960
Purge done for trx's n:o < 14954 undo n:o < 0 state: running but idle
History list length 28
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421316960193880, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421316960192752, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
...
Now, what if you get the output like the one above? Without any LATEST DETECTED DEADLOCK section? I've seen people wondering how is it even possible and trying to find some suspicious bug somewhere...

Do not be in a hurry - time to recall that there are actually at least 4 quite common reasons to get error 2013 in modern (5.5+) version of MySQL, MariaDB and Friends:
  1. InnoDB deadlock happened
  2. Metadata deadlock happened
  3. If you are lucky enough to use Galera cluster, Galera conflict happened
  4. Deadlock happened in some other storage engine (for example, MyRocks)
I am not lucky enough to use MySQL's group replication yet, but I know that conflicts there are also possible. I am just not sure if error 1213 is also reported in that case. Feel free to check with a test case similar to the one I've used for Galera below.

I also suspect deadlocks with other engines are also possible. As a bonus point, I'll demonstrate the deadlock with MyRocks also.

Let's reproduce these 3 cases one by one and check how to get more information on them. In all cases it's enough to have at most 2 InnoDB tables with just two rows:
mysql> show create table t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `id` int(11) NOT NULL,
  `c1` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> show create table t2\G
*************************** 1. row ***************************
       Table: t2
Create Table: CREATE TABLE `t2` (
  `id` int(11) NOT NULL,
  `c1` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> select * from t1;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)

mysql> select * from t2;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)
We'll need two sessions, surely.

InnoDB Deadlock

With InnoDB and tables above it's really easy to end up with a deadlock. In the first session execute the following:
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t1 where id = 1 for update;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
+----+------+
1 row in set (0.00 sec)
In the second session execute:
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t1 where id = 2 for update;
+----+------+
| id | c1   |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (0.02 sec)
Now in the first session try to access the row with id=2 asking for incompatible lock:
mysql> select * from t1 where id = 2 for update;
This statement hangs waiting for a lock (up to innodb_lock_wait_timeout seconds). Try to access the row with id=1 asking for incompatible lock in the second session, and you'll get the deadlock error:
mysql> select * from t1 where id = 1 for update;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
at this moment SELECT in the first transaction returns data:
+----+------+
| id | c1   |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (5.84 sec)
It's that simple, one table and two rows is enough. We can get the details in the output of SHOW ENGINE INNODB STATUS:
...
------------------------
LATEST DETECTED DEADLOCK
------------------------
2018-12-08 18:32:59 0x7f2f8b8db700
*** (1) TRANSACTION:
TRANSACTION 15002, ACTIVE 202 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 8, OS thread handle 139842181244672, query id 8545 localhost root statistics
select * from t1 where id = 2 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 94 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 15002 lock_mode X locks rec but not gap waiting
*** (2) TRANSACTION:
TRANSACTION 15003, ACTIVE 143 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 9, OS thread handle 139842181510912, query id 8546 localhost root statistics
select * from t1 where id = 1 for update
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 94 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 15003 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 94 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 15003 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
...
In the case above I've used Percona Server  5.7.24-26 (why not). Details of output may vary depending on version (and bugs it has :).  If you use MariaDB 5.5+, in case of InnoDB deadlock special innodb_deadlocks status variable is also incremented.

Metadata Deadlock

Unlike with InnoDB deadlocks, chances that you've seen deadlocks with metadata locks involved are low. One may spend notable time trying to reproduce such a deadlock, but (as usual) quck check of MySQL bugs database may help to find an easy to reproduce case. I mean Bug #65890 - "Deadlock that is not a deadlock with transaction and lock tables".

So, let's try the following scenario with two sessions and out InnoDB tables, t1 and t2. In one session:
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t2 for update;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)
In another session:
mysql> lock tables t1 write, t2 write;
It hangs, waiting as long as lock_wait_timeout. We can check what happens with metadata locks using performance_schema.metadata_locks table (as we use MySQL or Percona Server 5.7+, more on setup, alternatives for MariaDB etc here and there). In the first session:
mysql> select * from performance_schema.metadata_locks;
+-------------+--------------------+----------------+-----------------------+----------------------+---------------+-------------+--------+-----------------+----------------+
| OBJECT_TYPE | OBJECT_SCHEMA      | OBJECT_NAME    | OBJECT_INSTANCE_BEGIN | LOCK_TYPE            | LOCK_DURATION | LOCK_STATUS | SOURCE | OWNER_THREAD_ID | OWNER_EVENT_ID |
+-------------+--------------------+----------------+-----------------------+----------------------+---------------+-------------+--------+-----------------+----------------+
| TABLE       | test               | t2             |       139841686765904 | SHARED_WRITE         | TRANSACTION   | GRANTED     |        |              45 |           2850 || GLOBAL      | NULL               | NULL           |       139841688088672 | INTENTION_EXCLUSIVE  | STATEMENT     | GRANTED     |        |              46 |            205 |
| SCHEMA      | test               | NULL           |       139841688088912 | INTENTION_EXCLUSIVE  | TRANSACTION   | GRANTED     |        |              46 |            205 |
| TABLE       | test               | t1             |       139841688088992 | SHARED_NO_READ_WRITE | TRANSACTION   | GRANTED     |        |              46 |            207 |
| TABLE       | test               | t2             |       139841688089072 | SHARED_NO_READ_WRITE | TRANSACTION   | PENDING     |        |              46 |            208 |
| TABLE       | performance_schema | metadata_locks |       139841686219040 | SHARED_READ          | TRANSACTION   | GRANTED     |        |              45 |           3003 |
+-------------+--------------------+----------------+-----------------------+----------------------+---------------+-------------+--------+-----------------+----------------+
6 rows in set (0.00 sec)
As soon as we try this in the first session:
mysql> select * from t1;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
we get the same deadlock error 1213 and LOCK TABLES in the second session completes. We can find nothing about this deadlock in the output of SHOW ENGINE INNODB STATUS (as shared at the beginning of this post). I am also not aware about any status variables to count metadata deadlocks.

You can find some useful information about metadata deadlocks in the manual.

Galera Conflict

For simplicity I'll use MariaDB 10.1.x and simple 2 nodes setup on the same box as I described here. I'll start first node as a new cluster and create tables for this test:
openxs@ao756:~/dbs/maria10.1$ bin/mysqld_safe --defaults-file=/home/openxs/galera/mynode1.cnf --wsrep-new-cluster &
[1] 13022
openxs@ao756:~/dbs/maria10.1$ 181208 20:40:52 mysqld_safe Logging to '/tmp/mysql-node1.err'.
181208 20:40:52 mysqld_safe Starting mysqld daemon with databases from /home/openxs/galera/node1

openxs@ao756:~/dbs/maria10.1$ bin/mysql  --socket=/tmp/mysql-node1.sock 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 MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 4
Server version: 10.1.34-MariaDB Source distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

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

MariaDB [test]> drop table t1, t2;
ERROR 1051 (42S02): Unknown table 'test.t2'
MariaDB [test]> create table t1(id int, c1 int, primary key(id));
Query OK, 0 rows affected (0.29 sec)

MariaDB [test]> create table t2(id int, c1 int, primary key(id));
Query OK, 0 rows affected (0.22 sec)

MariaDB [test]> insert into t1 values (1,1), (2,2);
Query OK, 2 rows affected (0.07 sec)
Records: 2  Duplicates: 0  Warnings: 0

MariaDB [test]> insert into t2 values (1,1), (2,2);
Query OK, 2 rows affected (0.18 sec)
Records: 2  Duplicates: 0  Warnings: 0
Then I'll start second node, make sure it joined the cluster and has the same data:
openxs@ao756:~/dbs/maria10.1$ bin/mysqld_safe --defaults-file=/home/openxs/galera/mynode2.cnf &
[2] 15110
openxs@ao756:~/dbs/maria10.1$ 181208 20:46:11 mysqld_safe Logging to '/tmp/mysql-node2.err'.
181208 20:46:11 mysqld_safe Starting mysqld daemon with databases from /home/openxs/galera/node2

openxs@ao756:~/dbs/maria10.1$ bin/mysql --socket=/tmp/mysql-node2.sock 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 MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 4
Server version: 10.1.34-MariaDB Source distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
MariaDB [test]> show status like 'wsrep_cluster%';
+--------------------------+--------------------------------------+
| Variable_name            | Value                                |
+--------------------------+--------------------------------------+
| wsrep_cluster_conf_id    | 4                                    |
| wsrep_cluster_size       | 2                                    |
| wsrep_cluster_state_uuid | b1d227b1-0211-11e6-8ce0-3644ad2b03dc |
| wsrep_cluster_status     | Primary                              |
+--------------------------+--------------------------------------+
4 rows in set (0.04 sec)

MariaDB [test]> select * from t2;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.02 sec)
Now we are ready to try to provoke Galera conflict. For this we have to try to update the same data in transactions on two different nodes. In one session connected to node1:
MariaDB [test]> select @@wsrep_node_name;
+-------------------+
| @@wsrep_node_name |
+-------------------+
| node1             |
+-------------------+
1 row in set (0.00 sec)

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0.00 sec)

MariaDB [test]> update test.t1 set c1 = 5 where id=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0


In another session connected to other node:

MariaDB [test]> select @@wsrep_node_name;
+-------------------+
| @@wsrep_node_name |
+-------------------+
| node2             |
+-------------------+
1 row in set (0.00 sec)

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0.00 sec)

MariaDB [test]> update test.t1 set c1 = 6 where id=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0
Now in the first we can COMMIT successfully:
MariaDB [test]> commit;
Query OK, 0 rows affected (0.12 sec)
But if we try to COMMIT in the second:
MariaDB [test]> commit;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
We get that same error 1213 about the deadlock. Surely you'll see nothing about this deadlock in INNODB STATUS output, as it was NOT an InnoDB deadlock, but Galera conflict. Check these status variables on the node2:
MariaDB [test]> show status like 'wsrep_local%';
+----------------------------+--------------------------------------+
| Variable_name              | Value                                |
+----------------------------+--------------------------------------+
| wsrep_local_bf_aborts      | 1                                    |
| wsrep_local_cached_downto  | 75                                   |
| wsrep_local_cert_failures  | 0                                    |
| wsrep_local_commits        | 0                                    |
| wsrep_local_index          | 0                                    |
| wsrep_local_recv_queue     | 0                                    |
| wsrep_local_recv_queue_avg | 0.000000                             |
| wsrep_local_recv_queue_max | 1                                    |
| wsrep_local_recv_queue_min | 0                                    |
| wsrep_local_replays        | 0                                    |
| wsrep_local_send_queue     | 0                                    |
| wsrep_local_send_queue_avg | 0.000000                             |
| wsrep_local_send_queue_max | 1                                    |
| wsrep_local_send_queue_min | 0                                    |
| wsrep_local_state          | 4                                    |
| wsrep_local_state_comment  | Synced                               |
| wsrep_local_state_uuid     | b1d227b1-0211-11e6-8ce0-3644ad2b03dc |
+----------------------------+--------------------------------------+
17 rows in set (0.01 sec)
If wsrep_local_bf_aborts > 0, you had conflicts and local transaction was rolled back to prevent them. We can see that remote one wins, on node2:
MariaDB [test]> select * from t1;
+----+------+
| id | c1   |
+----+------+
|  1 |    5 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)
To summarize, in Galera "first commit wins" and local transaction involved in conflict is always a looser. You can get a lot of information about conflicts in the error log if you enable conflict logging features through wsrep_log_conflicts and cert.log_conflicts. See this fine manual for details.

MyRocks Deadlock

We can easily check how deadlocks are processed by MyRocks by just loading the plugin for the engine, converting tables to MyRocks and trying the same InnoDB scenario with the same Percona Server we used initially. But first, if you use Percona binaries you have to install a separate package:
openxs@ao756:~$ dpkg -l | grep rocksdb
openxs@ao756:~$ sudo apt-get install percona-server-rocksdb-5.7
[sudo] password for openxs:
Reading package lists... Done
Building dependency tree
...
Unpacking percona-server-rocksdb-5.7 (5.7.24-26-1.trusty) ...
Setting up percona-server-rocksdb-5.7 (5.7.24-26-1.trusty) ...


 * This release of Percona Server is distributed with RocksDB storage engine.
 * Run the following script to enable the RocksDB storage engine in Percona Server:

        ps-admin --enable-rocksdb -u <mysql_admin_user> -p[mysql_admin_pass] [-S <socket>] [-h <host> -P <port>]
Percona's manual has a lot more details and relies on separate ps-admin script, but basically you have to INSTALL PLUGINs like this (check script's code):
mysql> INSTALL PLUGIN ROCKSDB SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.86 sec)

mysql> INSTALL PLUGIN ROCKSDB_CFSTATS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)

mysql> INSTALL PLUGIN ROCKSDB_DBSTATS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.08 sec)

mysql> INSTALL PLUGIN ROCKSDB_PERF_CONTEXT SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_PERF_CONTEXT_GLOBAL SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)

mysql> INSTALL PLUGIN ROCKSDB_CF_OPTIONS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_GLOBAL_INFO SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_COMPACTION_STATS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_DDL SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)

mysql> INSTALL PLUGIN ROCKSDB_INDEX_FILE_MAP SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_LOCKS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_TRX SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_DEADLOCK SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)
Then check that the engine is there and convert tables:
mysql> show engines;
+--------------------+---------+----------------------------------------------------------------------------+--------------+------+------------+
| Engine             | Support | Comment                                                                    | Transactions | XA   | Savepoints |
+--------------------+---------+----------------------------------------------------------------------------+--------------+------+------------+
| ROCKSDB            | YES     | RocksDB storage engine                                                     | YES          | YES  | YES        |
...

mysql> alter table t1 engine=rocksdb;
Query OK, 2 rows affected (0.64 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> alter table t2 engine=rocksdb;
Query OK, 2 rows affected (0.58 sec)
Records: 2  Duplicates: 0  Warnings: 0
Now we are ready to try the same InnoDB scenario. Just note that lock wait timeout for MyRocks is defined by the rocksdb_lock_wait_timeout that is small by default, 1 second, do you have have to increase it first. You also have to set rocksdb_deadlock_detect to ON (as it's OFF by default):
mysql> set global rocksdb_lock_wait_timeout=50;
Query OK, 0 rows affected (0.00 sec)

mysql> set global rocksdb_deadlock_detect=ON;
Query OK, 0 rows affected (0.00 sec)

mysql> \r
Connection id:    14
Current database: test

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

mysql> select * from t1 where id = 1 for update;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
+----+------+
1 row in set (0.00 sec)
Then in the second session:
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t1 where id = 2 for update;
+----+------+
| id | c1   |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (0.00 sec)
In the first:
mysql> select * from t1 where id = 2 for update;
and in the second we can get deadlock error:
mysql> select * from t1 where id = 1 for update;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
mysql> show global status like '%deadlock%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| rocksdb_row_lock_deadlocks | 1     |
+----------------------------+-------+
1 row in set (0.00 sec)
Note that MyRocks has status variable to count deadlocks. Note that Percona Server still does NOT seem to support SHOW ENGINE ROCKSDB TRANSACTION STATUS statement available upstream:
mysql> show engine rocksdb transaction status\G
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'transaction status' at line 1
I was not able to find a bug about this (sorry if I missed it), and just reported new task to Percona's JIRA: PS-5114 - "Add support for SHOW ENGINE ROCKSDB TRANSACTION STATUS".

That's probably more than enough for single blog post (that is mostly NOT about bugs). One day I'll refresh my knowledge of MyRocks etc and maybe write more about deadlocks troubleshooting there.

Do not be surprised if you can not find anything in INNODB STATUS when you get error 1213, just proceed with further steps. There are other reasons to explore. Venice hides a lot early in the morning...

To summarize, do not be surprised that after you got MySQL error 1213 you see no information about recent InnoDB deadlock - there are at least 3 more reasons for this error to be reported, as explained above. You should know your configuration and use several other commands and sources of information to pinpoint what exactly happened and why.

Sunday, December 2, 2018

Fun with Bugs #74 - On MySQL Bug Reports I am Subscribed to, Part XI

For some reason the Committee of FOSDEM 2019 MySQL, MariaDB & Friends Devroom of all my talks submitted picked up the one on how to create a useful MySQL bug report, so I have no options but continue to write about MySQL bugs, as long and MySQL Community wants and even prefers to listen and read about them... That's what I do, with pleasure.

Today I'll continue my series of posts about community bug reports I am subscribed to with the review of bugs reported since October 1, 2018, starting from the oldest and skipping those MySQL 8 regression ones I've already commented on:
  • Bug #92609 - "Upgrade to 8.0.12 fails". This bug reported by Frederic Steinfels is about upgrade from MySQL 5.7 that leads to crash. Nice workaround was found:
    "The work around is delete all .TRG file (or move them to out side of mysql data folder) then update. After success we can re-create the trigger."
    The bug is really fixed in MySQL 8.0.14 according to the last comment, but for some reason it is still "Verified". Probably will be closed when MySQL 8.0.14 is released.
  • Bug #92631 - "importing dump from mysqldump --all-databases breaks SYS schema due to routines". This bug affecting MySQL 5.7 (and not 8.0) was reported by Shane Bester. Workaround is actually documented in the manual - add sys schema explicitly while dumping and dump it separately, then re-create.
  • Bug #92661 - "SELECT on key partitioned enum reading all partitions instead of 1". Interesting corner case found by Frederic Steinfels. MariaDB 10.3.7 also seems affected:
    MariaDB [test]> explain partitions select id from product where outdated='0';
    +------+-------------+---------+------------+------+---------------+----------+-
    --------+-------+------+--------------------------+
    | id   | select_type | table   | partitions | type | possible_keys | key      |
    key_len | ref   | rows | Extra                    |
    +------+-------------+---------+------------+------+---------------+----------+-
    --------+-------+------+--------------------------+
    |    1 | SIMPLE      | product | p0,p1      | ref  | outdated      | outdated |
    1       | const |    2 | Using where; Using index |
    +------+-------------+---------+------------+------+---------------+----------+-
    --------+-------+------+--------------------------+
    1 row in set (0.002 sec)

    MariaDB [test]> explain partitions select id from product where outdated='1';
    +------+-------------+---------+------------+------+---------------+----------+-
    --------+-------+------+--------------------------+
    | id   | select_type | table   | partitions | type | possible_keys | key      |
    key_len | ref   | rows | Extra                    |
    +------+-------------+---------+------------+------+---------------+----------+-
    --------+-------+------+--------------------------+
    |    1 | SIMPLE      | product | p0,p1      | ref  | outdated      | outdated |
    1       | const | 2048 | Using where; Using index |
    +------+-------------+---------+------------+------+---------------+----------+-
    --------+-------+------+--------------------------+
    1 row in set (0.002 sec)
  • Bug #92809 - "Inconsistent ResultSet for different Execution Plans". The full test case is not public and it took a lot of arguing until this bug (reported by Juan Arruti) was finally "Verified". Based on the workaround, setting optimizer_switch='materialization=off', this feature of MySQL optimizer is still problematic.
  • Bug #92850 - "Bad select+order by+limit performance in 5.7". As Sveta Smirnova demonstrated, there are still cases when FORCE INDEX hints really needed to help optimizer to use proper plan, even in somewhat obvious case of single table and single proper index... What a surprise!
  • Bug #92882 - "MTS not replication crash-safe with GTID and all the right parameters." As  Jean-François Gagné proved, at least statement-based multi-threaded replication with GTIDs is not safe in case of OS crash. Good that there is an easy enough workaround: stop slave; reset slave; start slave; See also his Bug #93081 - "Please implement a better relay log recovery." that refers to several more known problems with relay log recovery.
  • Bug #92949 - "add auto_increment column as PK cause RBR replication inconsistent". This probably should never happen in production (adding primary key while data are already active changed concurrently), but still this is a nice corner case reported by Fungo Wang.
  • Bug #92996 - "ANALYZE TABLE still locks tables 10 years later". Domas Mituzas is trying hard to escalate this well known problem of blocking queries if ANALYZE TABLE was executed at some wrong time (when long running query against the table was in progress). The problem was resolved this year in Percona Server, see this blog post. See also my MDEV-15101 (fix is planned for version 10.4 in MariaDB).
  • Bug #93033 - "Missing info on partitioned tables in I_S.INNODB_COLUMNS after upgrade to 8.0". Yet another regression in MySQL 8 vs 5.7 was reported by Alexey Kopytov.
  • Bug #93049 - "ORDER BY pk, otherdata should just use PK". There is no reason to use filesort, as Domas Mituzas kindly noted. MariaDB is also, unfortunately, affected.
  • Bug #93083 - "InnoDB: Failing assertion: srv_read_only_mode || trx->in_depth > 0". This Severity 6 bug (only debug binaries are directly affected) was reported by Ramesh Sivaraman from Percona QA. At least it was verified instantly (I've subscribed to double check what happens to bugs with low severity levels).
I'll stop for now. More detailed review of remaining bugs reported in November is coming soon.

Sheep are everywhere in East Sussex and bugs are everywhere in MySQL. Not that many, but still they are visible.
To summarize my conclusions from this list:
  1. Sometimes it takes too much efforts to force proper bug report processing. I had written more about this here.
  2. Having materialization=on in optimizer_switch in MySQL 5.7+ may cause wrong results. Take care to double check.
  3. There still cases of single table SELECTs where optimizer can do a much better job. FORCE INDEX helps, sometimes.
  4. Multi-threaded statement-based replication in MySQL 5.6 and 5.7 is not crash safe, even with GTIDs, relay_log_info_repository-TABLE and relay_log_recovery=ON. A lot of improvements in relay log recovery are needed.
  5. Oracle engineers still care to document workarounds in active public bug reports. This is great!
  6. Percona still fixes some really important and annoying bugs way before other vendors.
  7. MySQL 8 is different in many small details, so regressions are to be expected.

Saturday, November 24, 2018

Fun with Bugs #73 - On MySQL Bug Reports I am Subscribed to, Part X

It's time to continue my review of MySQL bug reports that I considered interesting for some reason recently. I had not got any notable reaction from Oracle engineers to my previous post about recent regression bugs in MySQL 8.0.13, so probably this topic is not really that hot. In this boring post I'll just review some bugs I've subscribed to since August that are still not closed, starting from the oldest.

Let me start with a couple of bug reports that remain "Open":
  • Bug #91959 - "UBSAN: signed integer overflow in lock_update_trx_age". It's really unusual to see bug reported by Shane Bester himself just "Open" for months. As he noted, it's really strange to see age defined as 32-bit value here when age_updated two lines later is 64-bit. On the other hand, from comments in the code it seems the age value is supposed to be small enough and if it grows too much this is a problem.
  • Bug #92964 - "Slave performance degrades over time". As description says:
    "When mysql slave is running gtid based asynchronous multi threaded replication, performance degrades over time in significant way when session_track_gtids is set to OWN_GTID; "
    The bug is assigned, but there are no public comments, while the way to reproduce seem to be defined clearly.
Same as the weather at Seven Sisters Cliffs back on September 14, 2018, some recent MySQL bug reports do not add confidence to those few visitors who explore them...

Now let me continue with some "Verified" bugs:
  • Bug #91981 - "Inconsistent user@host definitions for definer/grantor/grantee columns". It seems consistency is not a high priority these days.
  • Bug #92020 - "Introduce new SQL mode rejecting queries with results depending on query plan". I already mentioned this report while reviewing recent MySQL optimizer bugs. I have nothing to add to my conclusion there:
    "So, current MySQL considers different results when different execution plans are used normal!"
  • Bug #92032 - "Restrict usage of session foreign_key_checks". It's a great request from Federico Razzoli and I am happy to see it verified as a bug, fast.
  • Bug #92093 - "Replication crash safety needs relay_log_recovery even with GTID." Recently Jean-François Gagné pays special attention to MySQL replication crash safety in his bug reports, talks and blog posts. This specific report ended up as a request for a more clear documentation that should not provoke (false) safety feelings. See also his Bug #92109 - "Please make replication crash safe with GTID and less durable setting (bis)." for the request to improve MySQL in this regard one day.
  • Bug #92131 - "ASan: Direct leak of 272 byte(s) in main.mysqlpump_partial_bkp MTR test case". This kind of reports make me nervous. They make me think that still there is no regular testing of ASan-enabled builds in Oracle. Lucky we are, Percona engineers (like Yura Sorokin) do this for Oracle.
  • Bug #92133 - "DICT_SYS mutex contention causes complete stall when running with 40 mill tables". Proper data dictionary in MySQL 8.0 was supposed to solve some performance problems for instances with a lot of tables. As this perfect bug report from Alexander Rubin shows, this is not yet the case. We can still push MySQL instance over the limits and single instance for thousands of different small databases is hardly usable.
  • Bug #92209 - "AVG(YEAR(datetime_field)) makes an error result because of overflow". Perfect analysis from Pin Lin. All recent MySQL (and MariaDB) versions are affected.
  • Bug #92252 - "Mysql generates gtid gaps because of option slave-skip-errors". Yet another bug report from Pin Lin
  • Bug #92364 - "events_transactions_summary_global_by_event_name not working as expected". This bug was reported by Przemyslaw Malkowski from Percona. We all know Performance Schema is near perfect, but it turned out that "...performance_schema.events_transactions_summary_global_by_event_name behavior for instrumenting transactions seems completely broken.".
  • Bug #92398 - "point in time recovery using mysqlbinlog broken with temporary table -> errors". Let me quote Shane Bester:
    "Running a multi-threaded workload involving temporary and non-temporary tables leads to binary log playback giving errors."
  • Bug #92421 - "Queries with views and operations over local variables don't use indexes". This is a kind of regression in MySQL 5.7. MySQL 8 allows to workaround the problem properly using ROW_NUMBER() function.
  • Bug #92540 - "Comparison between DATE and DECIMAL does not round nanoseconds". This bug was reported by Alexander Barkov from MariaDB. MariaDB 10.3.x is not affected based on my tests.
To summarize:
  1. It seems ASan-enabled builds are not tested by Oracle engineers on a regular basis.
  2. Percona engineers help a lot with regular MySQL QA and testing for various extreme use cases.
  3. There is a lot to do to make GTID-based replication crash-safe and working fast in common use cases.
 More bug review are coming soon, so stay tuned.



Sunday, November 18, 2018

Fun with Bugs #72 - On MySQL Bug Reports I am Subscribed to, Part IX

I've subscribed to more than 60 new bug reports since my previous post in this series. It means that I'd need 4-5 posts to cover all new subscriptions and reasons behind them. I still plan to write about most of the bug reports I was interested in recently, but for this post I decided to pick up only MySQL 8.0 regression bugs and pay special attention to those that could be handled better or faster by Oracle engineers, as well as those handled perfectly.

The initial reason for this special attention originally was Bug #93085 - "Stall when concurrently execute create/alter user with flush privilege", that caused a lot of interesting Twitter discussions. It took some time, comments (in the bug report and in social media) and pressure from MySQL Community (including yours truly) to get it accepted as a real (regression!) bug to work on, and got "Verified". Unfortunately too often recently I see more time spent on arguing that something is not a bug or can not be reproduced, or is an example of improper usage of some MySQL feature etc instead of simply checking how things worked before MySQL 8.0 and how this changed, to worse.

Another example of "interesting" approach to bugs in MySQL 8.0 is Bug #93102 - "I_S queries don't return column names in the same case as requested.". It's indeed a duplicate of old and well known Bug #84456 - "column names in metadata appearing as uppercase when selecting from I_S" reported at early 8.0 development stage by Shane Bester from Oracle and community user (see Bug #85947). Still, it was decided NOT to fix it and tell users to rely on workaround, while this breaks application compatibility and is a regression.

Take a look at Bug #92998 - "After finishing the backup with mysqldump, mysql crashes and restarts" also. It ended up in "Unsupported" status, with some statements that "Dumping and restoring data between different 8.0 releases is not supported". This can be classified as a regression by itself. What I miss is a link to the manual saying it's not supported (was not able to find it in 5 minutes) any explanation of crash and restart - supported or not, running mysqldump should NOT cause server restarts in a general case. I think this bug report could end up in many statuses, but of them all "Unsupported" is hardly correct.

This my photo is far from ideal and can be criticized from different points of view, but there is no point to argue with the fact that it shows clouds in the sky. I wish the fact that MySQL 8.0 GA releases still have regression bugs is accepted with less arguing and more attention.

Now let me continue with a list of recently reported regression bugs in MySQL 8.0 that were handled mostly properly:

  • Bug #93215 - "Case statement use in conditional with sub_part index regression in 8.0". MySQL of versions < 8.0 (and MariaDB 10.3.7) work as expected also. The bug was verified fast, but it still misses explicit "regression" tag.
  • Bug #93214 - "LIMIT is applied before HAVING when you have a subquery". The bug was "Verified" quickly, but I still miss the exact 8.0.x version(s) affected and the results of checking with older versions. I strongly suspect it's a regression, as MariaDB 10.3.7 provides expected result:
MariaDB [test]> CREATE TABLE test (id INT PRIMARY KEY, value INT);
Query OK, 0 rows affected (0.510 sec)
MariaDB [test]> INSERT INTO test VALUES (1, 99), (2,98), (3, 97);
Query OK, 3 rows affected (0.057 sec)
Records: 3  Duplicates: 0  Warnings: 0
MariaDB [test]> SELECT t1.id, (SELECT t2.value FROM test t2 WHERE t1.id = t2.id) AS sub_value FROM test t1 HAVING sub_value = 99 ORDER BY value LIMIT 1;
+----+-----------+
| id | sub_value |
+----+-----------+
|  1 |        99 |
+----+-----------+
1 row in set (0.116 sec)
            • Bug #93170 - "undo truncation in 8.0.13 is not crash safe". The bug was quickly verified (after all, it's a failure of existing innodb_undo.truncate_recover MTR test case), but had not got "regression" tag. I am still not sure how it was missed during regular testing and ended up in the MySQL 8.0.13 release.
            • Bug #93147 - "Upgrade to 8.0.13 from 8.0.11 fails". In pre-8.0 releases there was no strict need to update to every intermediate minor version, so it's also a regression of a kind for any production DBA.
            • Bug #92979 - "MySQL 8.0 performance degradation on INSERT with foreign_key_checks=0". This is a verified performance regression comparing to MySQL 5.7, but "regression" tag is still missing. 

            To summarize, there are some regressions noted by community users recently in MySQL 8.0 GA releases. Some of them were demonstrated with simple test cases, so it's strange they were not noted by Oracle's QA. What's worse, it seems some of Oracle engineers are not ready to accept the fact that the best ever MySQL 8.0 GA release they worked on may get some things done incorrectly and worse than before, so they seem to waste time on useless discussions that everything is OK, work as expected and nothing can be done differently.  I also see some processed and verified bug reports without detailed check for regressions presented to users or even with "regression" tag NOT added when needed.

            I hope this is not going to become a new trend. I wish all community bug reports and features of MySQL get as much attention and detailed study from Oracle employees as (far from perfect) JSON support in MariaDB...

            Sunday, November 4, 2018

            On New Severity Levels for MySQL Bugs

            Four weeks ago while working on a blog post about half baked XA transactions feature of MySQL server I've noted that there are new severity levels added by Oracle for MySQL bug reports. Previously we had 5 levels:

            • S1 (Critical) - mostly for all kinds of crashes, DoS attack vectors, data corruptions etc
            • S2 (Serious) - mostly for wrong results bugs, broken replication etc
            • S3 (Non-critical) - all kinds of minor but annoying bugs, from unexpected results in some corner cases to misleading or wrong error messages, inefficient or unclear code etc
            • S4 (Feature requests) - anything that should work or be implemented based on common sense, but is not documented in the manual and was not required by the original specification or implementation of some feature.
            • S5 (Performance) - everything works as expected and documented, but the resulting performance is bad or less than expected. Something does not scale well, doesn't return results fast enough in some cases, or could be made faster or some specific platform using some different code or library. This severity level was also probably added at Oracle times, at least it was not there in 2005 when I started to work on MySQL bugs.

            Informal descriptions above are mine and may be incorrect or different from definitions Oracle engineers currently use. I tried to search for Oracle definitions that apply to MySQL, but was not able to find anything immediately useful (any help with public URL is appreciated). 

            In general, severity is defined as the degree of impact a bug has on the operation or use of some software, so less severity assumes less impact on common MySQL operations. One may also expect that bugs with higher severity are fixed first (have higher internal priority). It may not be that simple (and was not during my days in MySQL, when many more inputs were taken into account while setting priority for the bug fix), but it's a valid assumption for any community member.

            By default when searching for bugs you got all bugs of severity levels S1, S2, S3 and S5. You had to specifically care to get feature requests in search results while using bugs database search interface.

            If you try to search bugs today, you'll see two more severity levels added, S6 (Debug Builds) and S7 (Test Cases):

            Now we have 7 Severity levels for MySQL bug reports
            S6 severity level seems to be used for assertion failures and other bugs that affect only debug builds and can not be reproduced literally with non-debug binaries. S7 severity level is probably used for bug reports about failing MTR test cases, assuming that failure does NOT show a regression in MySQL software, but rather some non-determinism, platform dependencies, timing assumptions or other defects of the test case itself.

            By default bug reports with these severity levels are NOT included in search (they are not considered "Production Bugs"). So, one has to care to see them. This, as well as normal common sense based assumption that lower severity eventually means to lower priority for the fix, caused some concerns. It would be great for somebody from Oracle to explain the intended use and reasons for introduction of these severity levels with some more text than a single tweet, to clarify possible FUD people may have. If applied formally, these new severity values may lead to low priority for quite important problems. Most debug assertions are in the code for really good reason, as many weird things (up to crashes and data corruption) may happen in non-debug binaries somewhere later in cases when debug-only assertion fails.

            I was surprised to find out that at the moment we have 67 active S6 bug reports, and 32 active S7 bug reports. The latter list obviously includes reports that should not be S7, like Bug #92274 - "Question of mysql 8.0 sysbench oltp_point_select test" that is obviously about a performance regression noted in MySQL 8 (vs MySQL 5.7) by the bug reporter.

            Any comments from Oracle colleagues on the reasons to introduce new severity levels, their formal definitions and impact on community bug reports processing are greatly appreciated.