Saturday, April 15, 2017

How To Find What Thread Had Executed FTWRL

This week one of MariaDB Support customers asked how to find what thread had executed FLUSH TABLES WITH READ LOCK (FTWRL) and thus blocked all changes to data. I decided to list several ways to find this out (as eventually customer wanted to know how to find this out not only in MariaDB 10.1, but also in MySQL 5.6 etc).

Let me start with a quick summary. I know the following ways (other that having all queries logged in general query log, slow log, by some audit plugin or at client side, and checking the log) to find the thread that executed FLUSH TABLES WITH READ LOCK successfully:
  1. In MariaDB starting from 10.0.7 you can use METADATA_LOCK_INFO plugin.
  2. In MySQL starting from 5.7 you can use performance_schema.metadata_locks table.
  3. In MySQL starting from 5.6 (or MariaDB 10.x.y) you can use performance_schema.events_statements_history table.
  4. In all versions of MySQL or MariaDB you can attach gdb and check threads one by one (and I explain one of the ways to do this in the post).
Now, time to present the details. Unfortunately, when FTWRL is executed successfully, it is not visible neither in SHOW PROCESSLIST nor in related INFORMATION_SCHEMA table:
MariaDB [test]> select version();
+-----------------+
| version()       |
+-----------------+
| 10.1.18-MariaDB |
+-----------------+
1 row in set (0.00 sec)

MariaDB [test]> flush tables with read lock;
Query OK, 0 rows affected (0.06 sec)

MariaDB [test]> show full processlist\G
*************************** 1. row ***************************
      Id: 10
    User: root
    Host: localhost
      db: test
 Command: Query
    Time: 0
   State: init
    Info: show full processlist
Progress: 0.000
*************************** 2. row ***************************
      Id: 11
    User: root
    Host: localhost
      db: test
 Command: Query
    Time: 743
   State: Waiting for global read lock
    Info: delete from t0
Progress: 0.000
2 rows in set (0.00 sec)

MariaDB [test]> select * from information_schema.processlist\G*************************** 1. row ***************************
           ID: 11
         USER: root
         HOST: localhost
           DB: test
      COMMAND: Query
         TIME: 954
        STATE: Waiting for global read lock
         INFO: delete from t0
      TIME_MS: 954627.587
        STAGE: 0
    MAX_STAGE: 0
     PROGRESS: 0.000
  MEMORY_USED: 67464
EXAMINED_ROWS: 0
     QUERY_ID: 1457
  INFO_BINARY: delete from t0
          TID: 8838
*************************** 2. row ***************************
           ID: 10
         USER: root
         HOST: localhost
           DB: test
      COMMAND: Query
         TIME: 0
        STATE: Filling schema table
         INFO: select * from information_schema.processlist
      TIME_MS: 0.805
        STAGE: 0
    MAX_STAGE: 0
     PROGRESS: 0.000
  MEMORY_USED: 84576
EXAMINED_ROWS: 0
     QUERY_ID: 1461
  INFO_BINARY: select * from information_schema.processlist
          TID: 8424
2 rows in set (0.02 sec)
There is usually nothing useful in the INNODB STATUS also:
MariaDB [test]> show engine innodb status\G
...
------------
TRANSACTIONS
------------
Trx id counter 20439
Purge done for trx's n:o < 20422 undo n:o < 0 state: running but idle
History list length 176
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 11, OS thread handle 0x7f7f5cdb8b00, query id 1457 localhost root Waiting for global read lock
delete from t0
---TRANSACTION 0, not started
MySQL thread id 10, OS thread handle 0x7f7f5ce02b00, query id 1462 localhost root init
show engine innodb status
--------
...
No wonder, global read lock that FTWRL sets is not an InnoDB lock.

In this case we have just 2 user threads connected, so it's easy to find out what thread could set the global read lock we are waiting for. With dozens or hundreds of threads connected one has to guess which one it can be (often those that sleep for a longest time are blamed), unless he knows for sure how to find the exact one. So, let me list some of the ways to find this out.

I'd like to start with MariaDB 10.x.y. It provides a special METADATA_LOCK_INFO plugin. Surely you can not install it when FTWRL is already executed (as plugin ends up recorded in mysql.plugins table when installed):
MariaDB [test]> INSTALL SONAME 'metadata_lock_info';
ERROR 1223 (HY000): Can't execute the query because you have a conflicting read lock
MariaDB [test]> unlock tables;
Query OK, 0 rows affected (0.00 sec)

MariaDB [test]> INSTALL SONAME 'metadata_lock_info';
Query OK, 0 rows affected (0.37 sec)

MariaDB [test]> select * from mysql.plugin;
+--------------------+-----------------------+
| name               | dl                    |
+--------------------+-----------------------+
| BLACKHOLE          | ha_blackhole.so       |
| METADATA_LOCK_INFO | metadata_lock_info.so |
+--------------------+-----------------------+
2 rows in set (0.00 sec)
But when plugin is installed, we can get the information we need from the information_schema.metadata_lock_info table:
MariaDB [test]> flush tables with read lock;
Query OK, 0 rows affected (0.01 sec)

MariaDB [test]> select * from information_schema.metadata_lock_info;
+-----------+------------+---------------+------------------+--------------+------------+
| THREAD_ID | LOCK_MODE  | LOCK_DURATION | LOCK_TYPE        | TABLE_SCHEMA | TABLE_NAME |
+-----------+------------+---------------+------------------+--------------+------------+
|        10 | MDL_SHARED | NULL          | Global read lock |              |            |
|        10 | MDL_SHARED | NULL          | Commit lock      |              |            |
+-----------+------------+---------------+------------------+--------------+------------+
2 rows in set (0.00 sec)

MariaDB [test]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|              10 |
+-----------------+
1 row in set (0.01 sec)

MariaDB [test]> show processlist;
+----+------+-----------+------+---------+------+------------------------------+------------------+----------+
| Id | User | Host      | db   | Command | Time | State                        | Info             | Progress |
+----+------+-----------+------+---------+------+------------------------------+------------------+----------+
| 10 | root | localhost | test | Query   |    0 | init                         | show processlist |    0.000 |
| 12 | root | localhost | test | Query   |   47 | Waiting for global read lock | delete from t0   |    0.000 |
+----+------+-----------+------+---------+------+------------------------------+------------------+----------+
2 rows in set (0.00 sec)
We are looking for a row where lock_type is "Global read lock":
MariaDB [test]> select thread_id from information_schema.metadata_lock_info where lock_type = 'Global read lock';
+-----------+
| thread_id |
+-----------+
|        10 |
+-----------+
1 row in set (0.00 sec)
Now, let me proceed to MySQL 5.7. It had introduced the performance_schema.metadata_locks table, and we can use it as follows (I've used Percona Server 5.7.17 for this example, but it's not any different from upstream MySQL 5.7 in this regard):
openxs@ao756:~/dbs/maria10.1$ mysql -uroot -proot test
mysql: [Warning] Using a password on the command line interface can be insecure.
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 12
Server version: 5.7.17-13-log Percona Server (GPL), Release '13', Revision 'fd33d43'

Copyright (c) 2009-2016 Percona LLC and/or its affiliates
Copyright (c) 2000, 2016, 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 @@performance_schema;
+----------------------+
| @@performance_schema |
+----------------------+
|                    1 |
+----------------------+
1 row in set (0.00 sec)

mysql> UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME = 'global_instrumentation';
Query OK, 0 rows affected (0.18 sec)
Rows matched: 1  Changed: 0  Warnings: 0

mysql> UPDATE performance_schema.setup_instruments SET ENABLED = 'YES' WHERE NAME = 'wait/lock/metadata/sql/mdl';
Query OK, 1 row affected (0.04 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> flush tables with read lock;
Query OK, 0 rows affected (0.06 sec)

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 |
+-------------+--------------------+----------------+-----------------------+-------------+---------------+-------------+-------------------+-----------------+----------------+
| GLOBAL      | NULL               | NULL           |       139917187957472 | SHARED      | EXPLICIT      | GRANTED     | lock.cc:1128      |              39 |             10 || COMMIT      | NULL               | NULL           |       139917300586224 | SHARED      | EXPLICIT      | GRANTED     | lock.cc:1212      |              39 |             10 |
| TABLE       | performance_schema | metadata_locks |       139917192091536 | SHARED_READ | TRANSACTION   | GRANTED     | sql_parse.cc:6406 |              39 |             11 |
+-------------+--------------------+----------------+-----------------------+-------------+---------------+-------------+-------------------+-----------------+----------------+
3 rows in set (0.01 sec)

mysql> show processlist;
+----+----------+--------------------+------+---------+------+----------+------------------+-----------+---------------+
| Id | User     | Host               | db   | Command | Time | State    | Info             | Rows_sent | Rows_examined |
+----+----------+--------------------+------+---------+------+----------+------------------+-----------+---------------+
| 11 | maxscale | 192.168.1.37:55399 | NULL | Sleep   |    4 |          | NULL             |         0 |             0 |
| 12 | root     | localhost          | test | Query   |    0 | starting | show processlist |         0 |             0 |
+----+----------+--------------------+------+---------+------+----------+------------------+-----------+---------------+
2 rows in set (0.02 sec)
In this case we are looking for the value "GLOBAL" in OBJECT_TYPE column and "SHARED" in LOCK_TYPE column. In this row we see OWNER_TREAD_ID, but the value, 39, is not present in the SHOW PROCESSLIST output. We need to search for the proper thread id in the performance_schema.threads table, like this:
mysql> select t.processlist_id from performance_schema.threads t join performance_schema.metadata_locks ml on ml.owner_thread_id = t.thread_id where ml.object_type='GLOBAL' and ml.lock_type='SHARED';
+----------------+
| processlist_id |
+----------------+
|             12 |
+----------------+
1 row in set (0.03 sec)
Now, what if we run older MySQL 5.6.x that does not have metadata_locks table? If we make sure that the history of statements executed by each thread is maintained in performance_schema, we can easily search the history for the FTWRL statement in the performance_schema.events_statements_history table! Steps are also simple:
mysql> update performance_schema.setup_consumers set enabled = 'YES' where NAME = 'events_statements_history';
ERROR 1223 (HY000): Can't execute the query because you have a conflicting read lock
mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)

mysql> update performance_schema.setup_consumers set enabled = 'YES' where NAME = 'events_statements_history';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0

mysql> flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from performance_schema.events_statements_history where sql_text like 'flush tables%'\G
*************************** 1. row ***************************
              THREAD_ID: 39
               EVENT_ID: 21
           END_EVENT_ID: 21
             EVENT_NAME: statement/sql/flush
                 SOURCE: socket_connection.cc:95
            TIMER_START: 94449505549959000
              TIMER_END: 94449505807116000
             TIMER_WAIT: 257157000
              LOCK_TIME: 0
               SQL_TEXT: flush tables with read lock
                 DIGEST: 03682cc3e0eaed3d95d665c976628d02
            DIGEST_TEXT: FLUSH TABLES WITH READ LOCK
...
    NESTING_EVENT_LEVEL: 0
1 row in set (0.00 sec)
 Again, if we need thread id for the processlist, we have to join with performance_schema.threads:
mysql> select t.processlist_id from performance_schema.threads t join performance_schema.events_statements_history h on h.thread_id = t.thread_id where h.digest_text like 'FLUSH TABLES%';
+----------------+
| processlist_id |
+----------------+
|             12 |
+----------------+
1 row in set (0.01 sec)
Note that using digest_text while searching in history is a bit more reliable, as the text is already normalized, so you do not need to care about extra spaces etc. On the other hand, it requires statements_digest consumer to be enabled:

mysql> select * from performance_schema.setup_consumers where enabled = 'YES';
+---------------------------+---------+
| NAME                      | ENABLED |
+---------------------------+---------+
| events_statements_current | YES     |
| events_statements_history | YES     |
| global_instrumentation    | YES     |
| thread_instrumentation    | YES     |
| statements_digest         | YES     |
+---------------------------+---------+
5 rows in set (0.00 sec)
Now, what if you do not have performance_schema enabled (or compiled in), use older MySQL version or it's too late to run any updates or install any plugins? As usual, gdb to the rescue!

We already know that global shared metadata lock is set, so one can try to apply the approach I've already written about in this post. It looks a bit complicated though, so I decided to try something easier and just traverse the linked list of all MySQL threads in gdb in a way similar to what Shane Bester did years ago while looking for SQL statements executed by thread in the core file.

So, in MariaDB 10.1 with performance_schema disabled I, again, executed the following (surely, delete was executed in another session after FTWRL):
openxs@ao756:~/dbs/maria10.1$ bin/mysql -uroot --socket=/tmp/mariadb.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 13
Server version: 10.1.18-MariaDB MariaDB Server

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

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

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

MariaDB [test]> flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)

MariaDB [test]> show processlist;
+----+------+-----------+------+---------+------+------------------------------+------------------+----------+
| Id | User | Host      | db   | Command | Time | State                        | Info             | Progress |
+----+------+-----------+------+---------+------+------------------------------+------------------+----------+
| 13 | root | localhost | test | Query   |    0 | init                         | show processlist |    0.000 |
| 14 | root | localhost | test | Query   |    9 | Waiting for global read lock | delete from t0   |    0.000 |
+----+------+-----------+------+---------+------+------------------------------+------------------+----------+
2 rows in set (0.00 sec)
and then found the PID for MariaDB server and attached gdb to the process:
openxs@ao756:~$ ps aux | grep 'mysqld ' | grep maria
openxs    7444  0.1  5.7 748028 220744 ?       Sl   кві14   1:47 /home/openxs/dbs/maria10.1/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/maria10.1 --datadir=/home/openxs/dbs/maria10.1/data --plugin-dir=/home/openxs/dbs/maria10.1/lib/plugin --log-error=/home/openxs/dbs/maria10.1/data/ao756.err --pid-file=ao756.pid --socket=/tmp/mariadb.sock --port=3307
openxs@ao756:~$ sudo gdb -p 7444
...
Loaded symbols for /home/openxs/dbs/maria10.1/lib/plugin/metadata_lock_info.so
0x00007f7f5a2f084d in poll () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) p threads
$1 = {<base_ilist> = {first = 0x7f7f3fbf3008, last = {
      _vptr.ilink = 0x7f7f5cea3510 <vtable for ilink+16>,
      prev = 0x7f7f3ffa1018, next = 0x0}}, <No data fields>}
As you can see, we have a global variable threads. threads->first is a pointer to (the structure that describes) the first thread (of THD * type) in the double linked list of all MySQL threads, so we can do the following:
(gdb) set $thd=(THD *)(threads->first)
(gdb) p $thd
$3 = (THD *) 0x7f7f3fbf3008
(gdb) p $thd->thread_id$4 = 14
(gdb) p $thd->global_read_lock
$5 = {m_state = Global_read_lock::GRL_NONE, m_mdl_global_shared_lock = 0x0,
  m_mdl_blocks_commits_lock = 0x0}
I had not checked any version before MySQL 5.6 yet, but I assume that all of them have list of threads, each thread's structure has a thread_id item and I suppose to see global_read_lock item as well, if not as a structure with related MDL information, then with something else (to be studied later).

In the case above, I clearly see that thread with 14 in the processlist had not set global read lock. Now, let me proceed to the next thread:
(gdb) set $thd=(THD *)($thd->next)
(gdb) p $thd
$6 = (THD *) 0x7f7f3ffa1008
(gdb) p $thd->thread_id
$7 = 13
(gdb) p $thd->global_read_lock
$8 = {m_state = Global_read_lock::GRL_ACQUIRED_AND_BLOCKS_COMMIT,
  m_mdl_global_shared_lock = 0x7f7f2e90e080,
  m_mdl_blocks_commits_lock = 0x7f7f2e90e180}
So, it is thread with id 13 that had executed FTWRL and had not yet released the global read lock. I was lucky to find it fast, but I can repeat steps above to move on to the next list item until the next is 0x0. Shane had written a similar code as a Python macro for gdb is his post I mentioned. One day I may grow up and write something similar for this case.

Other approach was invented and described by in his blog post on the same topic of getting SQL statements from core files. One can just create a big enough input file for gdb that will switch to process threads one by one and try to get information from MySQL thread structure there, assuming it was created (and ignoring errors), like this:
(gdb) thread 1[Switching to thread 1 (Thread 0x7f7f5ce6d7c0 (LWP 7444))]
#0  0x00007f7f5a2f084d in poll () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) p do_command::thd->thread_id
No frame is currently executing in block do_command(THD*).
(gdb) thread 2
[Switching to thread 2 (Thread 0x7f7f5ce02b00 (LWP 9232))]
#0  pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
238     ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S: No such file or directory.
(gdb) p do_command::thd->thread_id
$9 = 14
(gdb) p do_command::thd->global_read_lock
$10 = {m_state = Global_read_lock::GRL_NONE, m_mdl_global_shared_lock = 0x0,
  m_mdl_blocks_commits_lock = 0x0}
(gdb) thread 3
[Switching to thread 3 (Thread 0x7f7f5cd6eb00 (LWP 9230))]
#0  0x00007f7f5a2f084d in poll () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) p do_command::thd->thread_id
$11 = 13
(gdb) p do_command::thd->global_read_lock
$12 = {m_state = Global_read_lock::GRL_ACQUIRED_AND_BLOCKS_COMMIT,
  m_mdl_global_shared_lock = 0x7f7f2e90e080,
  m_mdl_blocks_commits_lock = 0x7f7f2e90e180}

...
And so on, for 1000 threads or more, if we expect that many. With some smart use of shell and tools like grep and awk on the resulting output we can probably eventually get just what we need - thread id of the thread that did FTWRL and is still keeping global read lock.

One day I may work on this kind of scripts, but for now I just wanted to show how gdb can help you to get this information.

Tuesday, April 11, 2017

Fun with Bugs #52 - On Some Bugs Fixed in MySQL 5.7.18

I had not reviewed MySQL 5.7 release notes for quite a some time in this series. Last time I checked it was MySQL 5.7.15. So, as soon as I noted new release, 5.7.18, I decided to check the release notes for any interesting fixed bug (reported by Community users in public) in the areas I am interested in: InnoDB, replication, optimizer and few others.

Note that recently most of the bugs fixed are internal only, found by Oracle engineers that never cared (or are not allowed, who knows) to report them in public, so this blog post is not even remotely a full review of what's fixed in MySQL 5.7.18 and is not a replacement for reading the detailed release notes.

So, here is the result. I've noted the following InnoDB bugs from Community users are fixed (as usual, I explicitly state who reported and verified the bug):
  • Bug #83245 - "Log parsing buffer overflow". This regression bug was reported by my former colleague from Percona, Tomislav Plavcic (based on the original findings by Peter Zaitsev), and verified by Umesh Shastry.
  • Bug #82968 "InnoDB's estimate for rows-in-table can return rows=1 due to a race condition", was reported by my colleague Sergey Petrunya while working on my MariaDB bug report, MDEV-10649 (based, in turn, on a problem one of our key customers hit in production). The bug was kindly verified by Sinisa Milivojevic.
  • Bug #80060 - "Concurrent TRUNCATE TABLEs cause stalls". It's great to see this case reported by Domas Mituzas fixed at least in 5.7.x. But it's even better to just read all the comments and arguments in that great and funny discussion he had with Sinisa Milivojevic who was working on verification...
  • Bug #80580 - "count(*) much slower on 5.7 than 5.6". This regression (not tagged as such!) bug was reported by Qi Xiaobin as optimizer one (but it turned out to be in InnoDB), and verified by  Umesh Shastry. Simple public test case there was provided by me.
  • Bug #84202 is not public, so let me simply quote (after telling you again that I hate such cases):
    "InnoDB: The row_search_mvcc() function unnecessarily traversed the entire table for a range query, which occurred when the record was not in the transaction read view. (Bug #84202, Bug #23481444, Bug #25251375)"
These bugs reported by Community users were fixed in replication:
  • Bug #83537 - "WAIT_UNTIL_SQL_THREAD_AFTER_GTIDS timeout value handles some inputs badly". It was reported by Dan Reif and verified by Umesh Shastry. Now fractional and negative timeouts are processed in a reasonable and expected way.
  • Bug #84674 - "Having an unresolvable hostname in group_repl should not block group replication", by Kenny Gryp. I've already reviewed active group replication bugs in a separate post some time ago. Nice to see some of them fixed. The bug was probably verified by Nuno Carvalho.
  • Bug #83918 - "RBR: Wrong field length in error message". It was reported by Luis Soares from Oracle,  who probably fixed it himself. Nice example when Oracle engineers do not hesitate to report bugs in public!
  • Bug #83270 - "Performance degradation when the server has many gtids", was reported by Daniël van Eeden and quickly verified by Umesh Shastry.
The following interesting bugs in other categories were also fixed:
  • Bug #84786 - "--performance-schema-digests-size=1 leads to SIGSEGV". It was reported by Roel Van de Paar and promptly verified by Miguel Solorzano.
  • Bug #84263 - "mysql.server (MySQL Server Startup Script) can not work,and export some error.". This bug was reported by Song Boomballa. See also this my related bug report, Bug #84173 - "mysqld_safe --no-defaults & silently does NOT work any more". Nice to know this regression is finally fixed. 
  • Bug #84172 - "The pid-file value is ignored in the /etc/my.cnf option file". This nice packaging bug/difference was noted and reported by Monty Solomon.
  • Bug #83253 - "performance_schema digests the same query to multiple different digests", was reported by my former colleague Justin Swanhart. The bug was verified and probably fixed by Mayank Prasad.
  • Bug #83110 - "found_rows() returns 1 when no rows found". This nice regression bug was found and reported by Yamada Isami, and verified by Umesh Shastry
  • Bug #83005 - "When the Optimiser is using index for group-by it often gives wrong results", was reported by Yoseph Phillips and verified, again by Umesh Shastry. Somehow this regression affecting versions 5.6+ was not noted for a long time.
  • Bug #82313 - "Wrong result for EXPLAIN SELECT COUNT(*) FROM TABLE;". This is yet another optimizer regression bug in 5.7 found by Justin Swanhart. I wonder if MySQL 8 (that seemed to be affected) would include the fix... Release notes fro 8.0.1 are empty at the moment!
  • Bug #81854 - "Force index is skipped while executing select count(*)", was reported by Zhai Weixiang and verified by Umesh Shastry.
  • Bug #78244 - "SELECT DISTINCT, wrong results combined with use_index_extensions=off". It was reported by Daniel G and verified by Miguel Solorzano.
  • Bug #41908 - "Trying to start MySQL while another instance is starting: confusing error messag". The bug was reported by  Roel Van de Paar more than 8 years ago! It was verified by Sveta Smirnova. Somehow it seems that 5.7.18 had introduced a lot of changes into the way mysqld_safe works...
That's all fixed bugs that I've considered relevant for myself and this post. I've just built MySQL 5.7.18 from source on my Ubuntu 14.04 netbook while I write this post, so I do not have any personal experience with this new release, yet. But I know it works:
openxs@ao756:~/dbs/5.7$ bin/mysqld_safe --no-defaults --port=3308 --socket=/tmp/mysql57.sock --basedir=/home/openxs/dbs/5.7 --datadir=/home/openxs/dbs/5.7/data &
[1] 5202
openxs@ao756:~/dbs/5.7$ 2017-04-11T10:51:24.224518Z mysqld_safe Logging to '/home/openxs/dbs/5.7/data/ao756.err'.
2017-04-11T10:51:24.264873Z mysqld_safe Starting mysqld daemon with databases from /home/openxs/dbs/5.7/data

openxs@ao756:~/dbs/5.7$ bin/mysql -uroot --socket=/tmp/mysql57.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.7.18 MySQL Community Server (GPL)

Copyright (c) 2000, 2017, 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>
Time to start testing and looking for something new...

Sunday, April 9, 2017

Accessing Oracle tables via MariaDB CONNECT engine and ODBC

In my previous working environment it was typical to consider MariaDB Server as just a set of "random" storage engines mixed together, sometimes for unclear reasons and with questionable extra value. But even at that times I was already impressed by some features of one of the engines supported only by MariaDB, CONNECT. PIVOT table type specifically was of interest in a couple of customer cases I had to work on, but I quickly found out that the engine does not work with Oracle's MySQL or Percona Server, and thus had to forget about it for some time.

Recently while working in MariaDB I've got several more chances to deal with some new CONNECT use cases (and some related problems, that ended up mostly minor or caused by ignorance). This engine can be (and is, widely) used to access tables from virtually any other database management system or data source, as long as there is an ODBC or JDBC driver for it. I had to set up a testing environment to reproduce some of the problems noted while accessing remote tables in Oracle RDBMS, and eventually decided to document setup steps, mistakes and findings for myself and my readers.

I think the topic may require a series of posts, and in this first one I plan to concentrate on creating a basic testing environment to access Oracle RDBMS via ODBC driver and CONNECT engine on my main testing box running Fedora 25, and resolving simplest access issues, like those I described in MDEV-12355 (ended as not a bug thanks to quick help and clarifications from engine creator, Olivier Bertrand).

For pure testing purposes I had not planned to spend time installing and setting up Oracle RDBMS on that Fedora 25 box directly (later I tried and failed), but decided to rely on some existing Docker image. So, I started with installing Docker and dependencies (see this article for some hints, if needed):
[openxs@fc23 ~]$ sudo dnf install docker
...
Installed:
  container-selinux.noarch 2:2.10-1.fc25
  docker.x86_64 2:1.12.6-6.gitae7d637.fc25
  docker-common.x86_64 2:1.12.6-6.gitae7d637.fc25
  oci-register-machine.x86_64 0-2.7.gitbb20b00.fc25
  oci-systemd-hook.x86_64 1:0.1.6-1.gitfe22236.fc25
  skopeo-containers.x86_64 0.1.17-1.dev.git2b3af4a.fc25

Complete!

[openxs@fc23 ~]$ sudo systemctl start docker
I am going to skip details on images that had not worked well (not a topic for this blog). Eventually I ended up working with https://hub.docker.com/r/sath89/oracle-12c/:
[openxs@fc23 server]$ sudo docker run -d -p 8080:8080 -p 1521:1521 -e ORACLE_ALLOW_REMOTE=true sath89/oracle-12c:latest
4515bc4a6fb4804ac8d714115de12e47a9e8f9baabb2300cde672aedb4843c2b
[openxs@fc23 server]$ sudo docker ps
CONTAINER ID        IMAGE                      COMMAND             CREATED             STATUS              PORTS                                            NAMES
4515bc4a6fb4        sath89/oracle-12c:latest   "/entrypoint.sh "   14 seconds ago      Up 8 seconds        0.0.0.0:1521->1521/tcp, 0.0.0.0:8080->8080/tcp   adoring_turing

[openxs@fc23 server]$ sudo docker logs -f 4515bc4a6fb4
ls: cannot access /u01/app/oracle/oradata: No such file or directory
Database not initialized. Initializing database.
Starting tnslsnr
Copying database files
1% complete
3% complete
11% complete
18% complete
26% complete
37% complete
Creating and starting Oracle instance
40% complete
45% complete
50% complete
55% complete
56% complete
60% complete
62% complete
Completing Database Creation
66% complete
70% complete
73% complete
85% complete
96% complete
100% complete
Look at the log file "/u01/app/oracle/cfgtoollogs/dbca/xe/xe.log" for further details.
Configuring Apex console
Database initialized. Please visit http://#containeer:8080/em http://#containeer:8080/apex for extra configuration if needed
Starting web management console
PL/SQL procedure successfully completed.
Starting import from '/docker-entrypoint-initdb.d':
found file /docker-entrypoint-initdb.d//docker-entrypoint-initdb.d/*
[IMPORT] /entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
Import finished
Database ready to use. Enjoy! ;)
^C
This image initializes new database by default (unless you pass a volume on host, then it is initialized for the first time if the database is not there), so you have to wait (maybe for many minutes) and check the logs before trying to access the database. Note that container's port 1521 is mapped to host's port 1521 (and my Fedora 25 IP address, 192.168.1.85, is then used later below to access "remote" Oracle server on this port).

So, my "Oracle server" is ready (probably). Now, my Fedora 25 host will work as a client, so I had downloaded and installed basic Oracle client software RPMs (including ODBC driver and SQL*Plus) from OTN:
[openxs@fc23 maria10.1]$ rpm -q -a | grep oracle
oracle-instantclient11.2-sqlplus-11.2.0.4.0-1.x86_64
oracle-xe-11.2.0-1.0.x86_64
oracle-instantclient11.2-basic-11.2.0.4.0-1.x86_64
oracle-instantclient11.2-odbc-11.2.0.4.0-1.x86_64
I also installed unixODBC (including -devel, as I built MariaDB from source and one needs unixODBC-devel to have CONNECT engine build properly) as fine manual stated at the beginning:
[openxs@fc23 maria10.1]$ rpm -q -a | grep unixODBC
unixODBC-2.3.4-3.fc25.x86_64
unixODBC-devel-2.3.4-3.fc25.x86_64
One has to set up tnsnames.ora for Oracle client to work with (remote) instance, and /etc/odbcinst.ini + /etc/odbc.ini to inform unixODBC about the known drivers and system data sources (this discussion had some useful hints):
[openxs@fc23 maria10.1]$ cat /etc/oracle/tnsnames.ora
XE =
 ( DESCRIPTION =
  (ADDRESS_LIST =
  (ADDRESS =
  (PROTOCOL = TCP)
  (Host = 192.168.1.85)
  (Port = 1521)
  )
 )
 (CONNECT_DATA = (SID = XE)
 )
)

[openxs@fc23 maria10.1]$ cat /etc/odbcinst.ini
...

[OracleODBC]
Description = Oracle ODBC driver for Oracle 11g
Driver64 = /usr/lib/oracle/11.2/client64/lib/libsqora.so.11.1
FileUsage = 1
Driver Logging = 7

[openxs@fc23 maria10.1]$ cat /etc/odbc.ini
[oracle]
Driver = OracleODBCDSN = OracleODBC
ServerName = XE
UserID = system
Password = oracle
 Surely, I tried to access my Oracle server in Docker container via sqlplus command first:
[openxs@fc23 server]$ /usr/lib/oracle/11.2/client64/bin/sqlplus system/oracle@localhost:1521/xe.oracle.docker/usr/lib/oracle/11.2/client64/bin/sqlplus: error while loading shared libraries: libsqlplus.so: cannot open shared object file: No such file or directory
[openxs@fc23 server]$ ldd /usr/lib/oracle/11.2/client64/bin/sqlplus
        linux-vdso.so.1 (0x00007ffe8813b000)
        libsqlplus.so => not found
        libclntsh.so.11.1 => not found
        libnnz11.so => not found
        libdl.so.2 => /lib64/libdl.so.2 (0x00007f0aadc93000)
        libm.so.6 => /lib64/libm.so.6 (0x00007f0aad98a000)
        libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f0aad76a000)
        libnsl.so.1 => /lib64/libnsl.so.1 (0x00007f0aad551000)
        libc.so.6 => /lib64/libc.so.6 (0x00007f0aad18b000)
        /lib64/ld-linux-x86-64.so.2 (0x0000563b14bfb000)
This is what happens when one does not care to read all the details and forgets to set some environment variables and inform dynamic loader about libraries location. So, I did the following to resolve the problem:
[openxs@fc23 server]$ export ORACLE_HOME=/usr/lib/oracle/11.2/client64
[openxs@fc23 server]$ export LD_LIBRARY_PATH=$LD_LIBRARY_PATH:$ORACLE_HOME/lib
[openxs@fc23 server]$ export PATH=$PATH:$ORACLE_HOME/bin
[openxs@fc23 server]$ sudo ldconfig
[openxs@fc23 server]$ ldd /usr/lib/oracle/11.2/client64/bin/sqlplus
        linux-vdso.so.1 (0x00007ffd31b50000)
        libsqlplus.so => /usr/lib/oracle/11.2/client64/lib/libsqlplus.so (0x00007f88f680f000)
        libclntsh.so.11.1 => /usr/lib/oracle/11.2/client64/lib/libclntsh.so.11.1 (0x00007f88f3ea0000)
        libnnz11.so => /usr/lib/oracle/11.2/client64/lib/libnnz11.so (0x00007f88f3ad3000)
        libdl.so.2 => /lib64/libdl.so.2 (0x00007f88f38b2000)
        libm.so.6 => /lib64/libm.so.6 (0x00007f88f35a9000)
        libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f88f3389000)
        libnsl.so.1 => /lib64/libnsl.so.1 (0x00007f88f3170000)
        libc.so.6 => /lib64/libc.so.6 (0x00007f88f2daa000)
        libaio.so.1 => /lib64/libaio.so.1 (0x00007f88f2ba8000)
        /lib64/ld-linux-x86-64.so.2 (0x000056123639a000)

[openxs@fc23 server]$ sqlplus system/oracle@localhost:1521/xe.oracle.docker    
SQL*Plus: Release 11.2.0.4.0 Production on Fri Mar 24 11:00:21 2017

Copyright (c) 1982, 2013, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Standard Edition Release 12.1.0.2.0 - 64bit Production

SQL> select count(*) from scott.emp;

  COUNT(*)
----------
        14

SQL> create table scott.t1(c1 number(30));

Table created.

SQL> insert into scott.t1 values (12345);

1 row created.

SQL> desc scott.t1;
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 C1                                                 NUMBER(30)

SQL>

SQL> exit
Disconnected from Oracle Database 12c Standard Edition Release 12.1.0.2.0 - 64bit Production
So, SQL*Plus (that I still miss sometimes, after using it maybe only 10 times over last 12 years) client works. Let's try to access Oracle via ODBC and isql now:
[openxs@fc23 server]$ isql -v oracle
[08004][unixODBC][Oracle][ODBC][Ora]ORA-12154: TNS:could not resolve the connect identifier specified

[ISQL]ERROR: Could not SQLConnect
Surely, one more environment variable is not set, the one pointing out the location of tnsnames.ora file:
[openxs@fc23 server]$ export TNS_ADMIN=/etc/oracle
[openxs@fc23 server]$ isql -v oracle
+---------------------------------------+
| Connected!                            |
|                                       |
| sql-statement                         |
| help [tablename]                      |
| quit                                  |
|                                       |
+---------------------------------------+
SQL> select * from scott.t1;
+---------------------------------+
| C1                              |
+---------------------------------+
| 12345                           |
+---------------------------------+
SQLRowCount returns -1
1 rows fetched
SQL> select count(*) from scott.emp;+-----------------------------------------+
| COUNT(*)                                |
+-----------------------------------------+
| 14                                      |
+-----------------------------------------+
SQLRowCount returns -1
1 rows fetched
SQL> quit
[openxs@fc23 server]$

Looks like now we should be able to use ODBC table type of CONNECT storage engine of MariaDB (that was already loaded with INSTALL SONAME 'ha_connect.so'; check the details here) to access remote Oracle table:
MariaDB [test]> create table oracle_t1 engine=connect table_type=ODBC tabname='t1' dbschema='scott' connection='dsn=oracle';
ERROR 1105 (HY000): Cannot get columns from t1
MariaDB [test]> show warnings\G
*************************** 1. row ***************************
  Level: Error
   Code: 1105
Message: Cannot get columns from t1
*************************** 2. row ***************************
  Level: Error
   Code: 1030
Message: Got error 122 "Internal (unspecified) error in handler" from storage engine CONNECT
2 rows in set (0.00 sec)
Do not be like me and do not report bugs when you see these messages! Go read the fine manual that explicitly mentions Oracle as being case sensitive and converting identifiers to upper case unless they are quoted.

As soon as you use proper case in tabname (and dbname) settings, everything works as expected, at least for my primitive use case:
MariaDB [test]> create table t1_oracle engine=connect table_type=ODBC tabname='t1' dbname='scott' connection='dsn=oracle';
ERROR 1105 (HY000): Cannot get columns from t1
MariaDB [test]> create table t1_oracle engine=connect table_type=ODBC tabname='T1' dbname='scott' connection='dsn=oracle';ERROR 1105 (HY000): Cannot get columns from T1
MariaDB [test]> create table t1_oracle engine=connect table_type=ODBC tabname='T1' dbname='SCOTT' connection='dsn=oracle';Query OK, 0 rows affected (1.29 sec)

MariaDB [test]> select * from t1_oracle;
+-------+
| C1    |
+-------+
| 12345 |
+-------+
1 row in set (0.07 sec)

MariaDB [test]> create table t2_oracle engine=connect table_type=ODBC tabname='SCOTT.T1' connection='dsn=oracle';
Query OK, 0 rows affected (3.54 sec)

MariaDB [test]> select * from t2_oracle;
+-------+
| C1    |
+-------+
| 12345 |
+-------+
1 row in set (0.06 sec)
To summarize, with some initial setup efforts (that should include reading the official CONNECT manual) it is easy to access Oracle tables from MariaDB server via ODBC driver. It may be very useful if you plan to migrate or use some data from Oracle RDBMS.

As a side note, Docker really rocks sometimes. I spent maybe 15+ years installing Oracle RDBMS (starting from version 7.0.16 or so) on all kinds of OSes dozens of times, and I do not miss this experience and do not mind to have it up and running with one simple command any time (rarely) I need it.

Wednesday, April 5, 2017

My First Steps with MariaDB 10.2 and RocksDB Storage Engine

Last year I started to explore MyRocks, that is, RocksDB used as a storage engine with MySQL. So far I had to use Facebook's MySQL 5.6 to do this. I could try to use some specific development branches of MariaDB (or maybe even Percona Server) for this, but I preferred to wait until the engine is included into a main branch by the company I work for. Recently this happened, and now you can get RocksDB loaded and working in main MariaDB 10.2 branch. In this blog post I am going to explain how to build it from source and do some basic checks.

I was updating my MariaDB local repository on my Ubuntu 14.04 netbook, with 10.2 branch already checked out (do git checkout 10.2 if you see other marked with *, 10.1 is used by default):
openxs@ao756:~/git/server$ git branch  10.0
  10.1
* 10.2
  bb-10.2-marko
and noted the following at the end of output produced by git pull:
...
 create mode 100644 storage/rocksdb/unittest/test_properties_collector.cc
 create mode 100644 storage/rocksdb/ut0counter.h
So, I realized what I considered just talks, plans and rumors really happened - we have RocksDB in the main branch of MariaDB! I immediately proceeded with the following commands to get submodule for the engine up to date:
openxs@ao756:~/git/server$ git submodule init
Submodule 'storage/rocksdb/rocksdb' (https://github.com/facebook/rocksdb.git) registered for path 'storage/rocksdb/rocksdb'
openxs@ao756:~/git/server$ git submodule update
Submodule path 'libmariadb': checked out 'd1387356292fb840c7736aeb8f449310c3139087'
Cloning into 'storage/rocksdb/rocksdb'...
remote: Counting objects: 49559, done.
remote: Compressing objects: 100% (70/70), done.
remote: Total 49559 (delta 31), reused 1 (delta 1), pack-reused 49485
Receiving objects: 100% (49559/49559), 97.77 MiB | 3.45 MiB/s, done.
Resolving deltas: 100% (36642/36642), done.
Checking connectivity... done.
Submodule path 'storage/rocksdb/rocksdb': checked out 'ba4c77bd6b16ea493c555561ed2e59bdc4c15fc0'
openxs@ao756:~/git/server$ git log -1
commit 0d34dd7cfb700b91f11c59d189d70142ed652615
...
Then I applied my usual cmake command line and build commands:
openxs@ao756:~/dbs/maria10.2$ fc -l
2001     cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=bundled -DMYSQL_MAINTAINER_MODE=0 -DENABLED_LOCAL_INFILE=1 -DWITH_JEMALLOC=system -DWITH_INNODB_DISALLOW_WRITES=ON -DCMAKE_INSTALL_PREFIX=/home/openxs/dbs/maria10.2
...
2003     time make -j 2
2004     make install && make clean
2005     cd
2006     cd dbs/maria10.2
2007     bin/mysqld_safe --no-defaults --port=3307 --socket=/tmp/mariadb.sock --rocksdb &
The last command above was my lame attempt to add RocksDB support in the same way it is done in MySQL 5.6 from Facebook. The option is not recognized and instead you just have to start as usual and install plugin:
install soname 'ha_rocksdb.so';
Then you'll see a lot of new rows in the output of SHOW PLUGINS:
...
| ROCKSDB                       | ACTIVE   | STORAGE ENGINE     | ha_rocksdb.so | GPL     |
| ROCKSDB_CFSTATS               | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_DBSTATS               | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_PERF_CONTEXT          | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_PERF_CONTEXT_GLOBAL   | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_CF_OPTIONS            | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_COMPACTION_STATS      | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_GLOBAL_INFO           | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_DDL                   | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_INDEX_FILE_MAP        | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_LOCKS                 | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
| ROCKSDB_TRX                   | ACTIVE   | INFORMATION SCHEMA | ha_rocksdb.so | GPL     |
+-------------------------------+----------+--------------------+---------------+---------+
64 rows in set (0.00 sec)

MariaDB [test]> show engines;
+--------------------+---------+----------------------------------------------------------------------------------+--------------+------+------------+
| Engine             | Support | Comment                                                                          | Transactions | XA   | Savepoints |
+--------------------+---------+----------------------------------------------------------------------------------+--------------+------+------------+
| ROCKSDB            | YES     | RocksDB storage engine                                                           | YES          | YES  | YES        |
| CSV                | YES     | CSV storage engine                                                               | NO           | NO   | NO         |
| MyISAM             | YES     | MyISAM storage engine                                                            | NO           | NO   | NO         |
| MEMORY             | YES     | Hash based, stored in memory, useful for temporary tables                        | NO           | NO   | NO         |
| MRG_MyISAM         | YES     | Collection of identical MyISAM tables                                            | NO           | NO   | NO         |
| CONNECT            | YES     | Management of External Data (SQL/MED), including many file formats               | NO           | NO   | NO         |
| SEQUENCE           | YES     | Generated tables filled with sequential values                                   | YES          | NO   | YES        |
| 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         |
+--------------------+---------+----------------------------------------------------------------------------------+--------------+------+------------+
10 rows in set (0.00 sec)
Now I can create ROCKSDB tables and work with them:
MariaDB [test]> create table tmariarocks(id int primary key, c1 int) engine=rocksdb;
Query OK, 0 rows affected (0.14 sec)

MariaDB [test]> insert into tmariarocks values(1,1);
Query OK, 1 row affected (0.04 sec)

MariaDB [test]> select version(), t.* from tmariarocks t;
+----------------+----+------+
| version()      | id | c1   |
+----------------+----+------+
| 10.2.5-MariaDB |  1 |    1 |
+----------------+----+------+
1 row in set (0.00 sec)

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

MariaDB [test]> select engine, count(*) from information_schema.tables group by engine;
+--------------------+----------+
| engine             | count(*) |
+--------------------+----------+
| Aria               |       11 |
| CSV                |        2 |
| InnoDB             |        8 |
| MEMORY             |       74 |
| MyISAM             |       25 |
| PERFORMANCE_SCHEMA |       52 |
| ROCKSDB            |        1 |
+--------------------+----------+
7 rows in set (0.03 sec)
Moreover, I can still work with InnoDB tables and even mix them with ROCKSDB ones in the same transaction (at least to some extent):
MariaDB [test]> create table t1i(id int primary key) engine=InnoDB;
Query OK, 0 rows affected (0.24 sec)

MariaDB [test]> create table t1r(id int primary key) engine=ROCKSDB;
Query OK, 0 rows affected (0.13 sec)

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

MariaDB [test]> insert into t1r select * from t1i;
Query OK, 3 rows affected (0.04 sec)
Records: 3  Duplicates: 0  Warnings: 0

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

MariaDB [test]> insert into t1i values(5);
Query OK, 1 row affected (0.00 sec)

MariaDB [test]> insert into t1r values(6);
Query OK, 1 row affected (0.00 sec)

MariaDB [test]> commit;
Query OK, 0 rows affected (0.14 sec)

MariaDB [test]> select * from t1i;
+----+
| id |
+----+
|  1 |
|  2 |
|  3 |
|  5 |
+----+
4 rows in set (0.00 sec)

MariaDB [test]> select * from t1r;
+----+
| id |
+----+
|  1 |
|  2 |
|  3 |
|  6 |
+----+
4 rows in set (0.00 sec)
In the error log I see:
openxs@ao756:~/dbs/maria10.2$ tail data/ao756.err
2017-04-05 13:59:51 140157875193600 [Note]   cf=default
2017-04-05 13:59:51 140157875193600 [Note]     write_buffer_size=67108864
2017-04-05 13:59:51 140157875193600 [Note]     target_file_size_base=67108864
2017-04-05 13:59:52 140157875193600 [Note] RocksDB: creating a column family __system__
2017-04-05 13:59:52 140157875193600 [Note]     write_buffer_size=67108864
2017-04-05 13:59:52 140157875193600 [Note]     target_file_size_base=67108864
2017-04-05 13:59:52 140157875193600 [Note] RocksDB: Table_store: loaded DDL data for 0 tables
2017-04-05 13:59:52 140157875193600 [Note] RocksDB: global statistics using get_sched_indexer_t indexer
2017-04-05 13:59:52 140157875193600 [Note] RocksDB instance opened
2017-04-05 14:03:13 140157875193600 [ERROR] Invalid (old?) table or database name '.rocksdb'
So, not 100% clean integration, it's probably still at alpha stage, but now it is easy to build, migrate, mix, test, benchmark and compare InnoDB from MySQL 5.7 with latest RocksDB, all on the same MariaDB 10.2 code base!

I think a really great job was done by Sergei Petrunia, my colleagues from MariaDB, Facebook engineers and other interested MyRocks community members. I'd like to thank them all for their hard work on MyRocks and making it available in MariaDB. Maria Rocks!

Sunday, March 26, 2017

Fun with Bugs #51 - My Bug Reports that Oracle doesn't Want to Fix

This week I noticed (yet another) customer issue related to the output produced by mysqladmin debug command (or when mysqld process gets SIGHUP signal). I mean the output generated by the mysql_print_status() function. In this issue the content of the output was misinterpreted. I've seen this in the past more than once, and requested to document the output properly, but it never happened for a reason that there is an internal feature request to put this information elsewhere, in Performance Schema or Information Schema. The bug ended up with "Won't fix" status.

Surely I complained in a comment and on Facebook, and then decided to check if there are any other my bug reports and documentation request that Oracle explicitly decided not to fix after accepting the fact that there is a problem.

I've ended up with the following short list:
  • Bug #69399 - "Inconsistency in crash report". Here I've got a perfect reason to keep things as they are currently implemented. Functions called from signal handlers must be async signal safe, and time() is like that, but it always outputs in UTC. It would be great to print time in UTC in some messages as well, so that timezone difference is 100% clear, but it's truly not a big deal.
  • Bug #71300 - "Manual does not explain that statement/abstract/* instruments appeared in 5.6.15". This change in naming that happened in 5.6.15 is, indeed, explained in the manual, even if there is no highlighted statements about incompatible change etc. I can live with that.
  • Bug #71303 - "Manual page on P_S build configuration does not provide enough details". I really missed the details at that time on how to instrument individual buffer's mutexes/rwlocks, after getting a hint during my talk that I had no chance to see real most important waits in Bug #68079  with Performance Schema without recompiling it properly. I've got a useful comment at the end of the bug report, but I truly do not understand why this detail ("The only way to enable it is by removing the line which defines PFS_SKIP_BUFFER_MUTEX_RWLOCK in storage/innobase/include/sync0sync.h. Seems to be no compiler flags to enable or disable the above mentioned symbol.") was not added to the small enough page as a note.
  • Bug #71304 - "Manual does not provide enough details about automatic sizing of P_S parameters ". Here my suggestions were refused. Go figure yourself, check the output of mysqld --verbose --help 2>/dev/null | grep performance | grep "\-1" to find out what parameters are auto-sized and go read the code to find out how exactly, if you care. They don't.
  • Bug #71274 - "Manual does not provide enough details about background threads in P_S.threads". All I've got in reply is: "The purpose of the page is to describe the table structure, not enumerate the (subject to change) set of background threads." You may be satisfied with this remark, but I am not.
  • Bug #71346 - "Manual does not provide details on mysqladmin debug output". As you can check here, even for MySQL 8 the command is still there, but all we have about the output is: "Tell the server to write debug information to the error log. Format and content of this information is subject to change. This includes information about the Event Scheduler."
  • Bug #75366 - "mysql_install_db requires explicit --lc-messages-dir if non-default PREFIX used". This was reported at early MySQL 5.7.x development stage, and I've got a recommendation to use mysqld --initialize instead. I do so now, but sometimes some related problem still happen, see Bug #84173 and Bug #80351. I think that even deprecated commands must be properly documented, including any incompatible changes in behavior, options, binaries location etc, until they still exist in GA and supported versions of MySQL.
  • Bug #78822 - "Materialized table from semijoin may change join order and lead to bad plan". In MySQL 5.7 the problem must be fixed, and for 5.6 the following obvious workaround was suggested: set optimizer_switch="semijoin=off";
  • Bug #80601 - "Manual is wrong/not clear while explaining kill flag check for ALTER TABLE".  Even though it was stated that "this is an implementation detail subject to change", some clarifications happened in the manual.
To summarize, out of 310 bug reports I've created since 2005, Oracle decided not to fix just 9, and in many cases provided proper explanations about the reasons to do this, or made some changes in the manual. The remaining cases all are related to MySQL manual and mostly happened in 2014, when nice people found a way to shut me up (temporary) on the topic of MySQL bugs...

Wednesday, March 22, 2017

Fun with Bugs #50 - On Bugs Tagged as "missing manual"

Back in January 2014, some time after many nice people kindly asked me to shut up stop writing about MySQL bugs on Facebook several times per day, I decided to start reading the fine MySQL Manual more carefully than before and report not only typos there, but also any topic or detail not properly explained. Usually these reports, tagged as "missing manual", were the result of careful study of the documentation based on real user question or customer issue. So, most of these reports came from real life, and missing information badly affected poor MySQL users.

Today, for this issue #50 in my series of posts about MySQL bugs, I decided to list and summarize 20 currently active (of 66 total) bugs (mostly documentation requests) tagged as "missing manual", starting from the oldest:
  • Bug #71293 - "Manual page for P_S.FILE_INSTANCES table does not explain EVENT_NAME values". Performance Schema was one of my favorite topics back then, as I was working on my second talk and presentation about it. No single comment since the bug was verified by Umesh Shastry.
  • Bug #71294 - "Manual page for P_S.FILE_INSTANCES table does not explain '~' in FILE_NAME". The bug was re-classified as server one, but still no further activity since then. Go figure what does this output may mean:

    mysql> select * from performance_schema.file_instances where event_name like '%parse%';
    +-----------------------------+------------------------------+------------+
    | FILE_NAME                   | EVENT_NAME                   | OPEN_COUNT |
    +-----------------------------+------------------------------+------------+
    | /var/lib/mysql/test/ti.TRG  | wait/io/file/sql/file_parser |          0 |
    | /var/lib/mysql/test/v2.frm~ | wait/io/file/sql/file_parser |          0 |
    +-----------------------------+------------------------------+------------+
    2 rows in set (0,00 sec)
  • Bug #71521 - "Manual does not list all valid values for innodb_flush_method". Actually, it seems the manual now lists them all, but the bug was not properly closed.
  • Bug #71732 - "Garbage value in output when MASTER_LOG_FILE='' is set". The bug was re-classified as Replication one, but I doubt that current state is documented in details.
  • Bug #71808 - "Manual does not explain what TICK timer is and why it's different on Windows". Still waiting for something... Had not checked if anything was documented, but TICK timer still exists in 5.7.17.
  • Bug #72368 - "Empty/zero statistics for imported tablespace until explicit ANALYZE TABLE". This is the InnoDB bug, and it seems there was some work performed on it internally, but the only information in the manual about the need to run ANALYZE is in user comment dated October, 2014. Had I already informed you that I hate persistent InnoDB statistics, the way it is implemented, for many reasons (including this bug)? Now you know. Statistics must be stored, engine-independent and re-estimated only upon explcit DBA request, if you ask me...
  • Bug #73299 - "DEFAULT value for PRIMARY KEY column depends on the way to declare it PRIMARY". It's probably a server bug, but maybe, until it is fixed, manual should explain current server's behavior in some note?
  • Bug #73305 - "Manual does not explain all cases when SHOW VIEW privilege is needed". SHOW VIEW privilege may be needed to run EXPLAIN against query referring the view. See Bug #73306 also ("Manual does not explain what privileges are needed for EXPLAIN explainable_stmt"). I still remember user's confusion that led to these report...
  • Bug #73413 - "Manual does not explain MTS implementation in details". Try to find out in the manual what threads are created for multi-threaded slave, what are their typical statuses, does replication event format (ROW vs STATEMENT) matter for MTS or not...
  • Bug #76563 - "Manual does not explain when exactly AUTO-INC lock is set for "bulk inserts"". There are reasons to think that when target table is different from the source one, AUTO-INC lock is set on the target table after reading the first row from the source one. Check my old blog post for more details. This is the first still "Verified" bug in this list that is explicitly devoted to InnoDB locking. You'll see several more below.
  • Bug #77390 - "Manual does not explain a "deadlock" case of online ALTER". Trust me, online ALTER sets metadata lock at early stage, but it is not exclusive. Check some of my posts about MDL and this documentation request: Bug #84004 - "Manual misses details on MDL locks set and released for online ALTER TABLE".
  • Bug #79665 - "Manual does not explain locks set by INSERT ... ON DUPLICATE KEY UPDATE properly". It wouldbe great to see  the manual describing all the locks set by INSERT ... ON DUPLICATE KEY UPDATE carefully and properly, covering both the duplicate on PRIMARY key case and duplicate on secondary UNIQUE key case.
  • Bug #80067 - "Index on BIT column is not used when column name only is used in WHERE clause". It's a pure optimizer bug/problem, but while it is not resolved it would be nice for the manual to describe current behavior.
  • Bug #82127 - "Deadlock with 3 concurrent DELETEs by UNIQUE key". Manual does not explain locks set on secondary indexes properly, for too many cases, including this one. InnoDB does work as designed, and you can find some explanations (by my colleague Jan Lindström) of this design and reasons behind it in MDEV-10962. Check Bug #83640 - "Locks set by DELETE statement on already deleted record" also for the idea of how one may (mis-)interpret what really happens in similar cases. This is because InnoDB's implementation of locking is not properly explained, including implicit locks (see some details and links here), locking of secondary indexes etc. This missing information leads to all kinds of misunderstanding and speculations about "lock upgrading" etc, for decades already.
  • Bug #82212 - "mysqlbinlog can produce events larger than max_allowed_packet for mysql". This is a server problem, but, as I put it, please, describe "safe" setting of max_allowed_packet in case of row-based replication in the manual clearly, as well as any workarounds for the case when max_allowed_packet was 1G on the server that produced binary long with huge row based event that one needs to restore now.
  • Bug #83024 - "Internals manual does not explain COM_SLEEP in details". One may argue that this is truly irrelevant for most users, but it's hard to explain slow log content sometimes:
    SET timestamp=1473712798;
    # administrator command: Sleep;
    # Time: 160912 20:39:59
    # User@Host: user[host] @ [192.168.1.51]
    # Thread_id: 36310042 Schema: somedb QC_hit: No
    # Query_time: 17.201526 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
    
    without this.
  • Bug #85557 - "Manual does not explain locks set by UPDATE with subquery referring other table". I had to report it yesterday, as some users considers current behavior (proper, but not documented at all) a bug and complained. My dear friend Sinisa Milivojevic verified it promptly.
I understand that it's hard to keep the quality of MySQL manual, and some of the documentation requests mentioned above stay active for years just because it's really a lot of work to document things properly. Documentation team is, probably, concentrated on desribing new and shiny features of MySQL 8.0 (one day I'll start to read its manual) or InnoDB clusters/Group replication.

If the team needs somebody to help, please, get in touch with me as I may have a suggestion whom you can hire. (It's not me, I am not qualified as I am not a native speaker. I'd better report problems and missing details here and there...)