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:
- In MariaDB starting from 10.0.7 you can use METADATA_LOCK_INFO plugin.
- In MySQL starting from 5.7 you can use performance_schema.metadata_locks table.
- In MySQL starting from 5.6 (or MariaDB 10.x.y) you can use performance_schema.events_statements_history table.
- 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).
MariaDB [test]> select version();There is usually nothing useful in the INNODB STATUS also:
+-----------------+
| 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)
MariaDB [test]> show engine innodb status\GNo wonder, global read lock that FTWRL sets is not an InnoDB lock.
...
------------
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
--------
...
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';But when plugin is installed, we can get the information we need from the information_schema.metadata_lock_info table:
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)
MariaDB [test]> flush tables with read lock;We are looking for a row where lock_type is "Global 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)
MariaDB [test]> select thread_id from information_schema.metadata_lock_info where lock_type = 'Global read lock';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):
+-----------+
| thread_id |
+-----------+
| 10 |
+-----------+
1 row in set (0.00 sec)
openxs@ao756:~/dbs/maria10.1$ mysql -uroot -proot testIn 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: [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)
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';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:
+----------------+
| processlist_id |
+----------------+
| 12 |
+----------------+
1 row in set (0.03 sec)
mysql> update performance_schema.setup_consumers set enabled = 'YES' where NAME = 'events_statements_history';Again, if we need thread id for the processlist, we have to join with performance_schema.threads:
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)
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%';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:
+----------------+
| processlist_id |
+----------------+
| 12 |
+----------------+
1 row in set (0.01 sec)
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 testand then found the PID for MariaDB server and attached gdb to the process:
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)
openxs@ao756:~$ ps aux | grep 'mysqld ' | grep mariaAs 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:
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>}
(gdb) set $thd=(THD *)(threads->first)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).
(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}
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)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.
(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}
Other approach was invented and described by Roel Van de Paar 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))]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.
#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}
...
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.
Thanks for your share!
ReplyDelete