Wednesday, January 6, 2016
Exploring Metadata Locks with gdb - Double Checking the Initial Results
(gdb) b MDL_request::init
Breakpoint 1 at 0x648f13: file /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc, line 1266.
Breakpoint 2 at 0x648e70: file /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc, line 1245.
warning: Multiple breakpoints were set.
Use the "delete" command to delete unwanted breakpoints.
(gdb) c
Continuing.
[Switching to Thread 0x7ff224c9f700 (LWP 2017)]
Breakpoint 2, MDL_request::init (this=0x7ff1fbe425a8,
mdl_namespace=MDL_key::TABLE, db_arg=0x7ff1fbe421c8 "test",
name_arg=0x7ff1fbe421d0 "t1", mdl_type_arg=MDL_SHARED_READ,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
MDL_SHARED_READ lock on the table is expected, we read it after all. Let's check with backtrace where this request happens:
(gdb) bt
#0 MDL_request::init (this=0x7ff1fbe425a8, mdl_namespace=MDL_key::TABLE,
db_arg=0x7ff1fbe421c8 "test", name_arg=0x7ff1fbe421d0 "t1",
mdl_type_arg=MDL_SHARED_READ, mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
#1 0x00000000006d3033 in st_select_lex::add_table_to_list (this=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_parse.cc:7479
#2 0x000000000077eb6d in MYSQLparse (YYTHD=0x7ff1fbb65000)
at /var/lib/jenkins/jobs/percona-server-5.6-source-tarballs/workspace/sql/sql_yacc.yy:10888
#3 0x00000000006decef in parse_sql (thd=0x7ff1fbb65000,
parser_state=0x7ff224c9e130, creation_ctx=0x0)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_parse.cc:9005
#4 0x00000000006df1b1 in mysql_parse (thd=0x7ff1fbb65000, rawbuf=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_parse.cc:6878
#5 0x00000000006e0d1f in dispatch_command (command=<value optimized out>,
thd=0x7ff1fbb65000, packet=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_parse.cc:1442
#6 0x00000000006ad692 in do_handle_one_connection (thd_arg=Unhandled dwarf expression opcode 0xf3
)
...
So, it happens as soon as we noted a table to read from while parsing the query text. What surprised me initially is no other MDL lock requests, nothing at schema level, for example. I expected that metadata locks should prevent dropping the schema when I read from some table there, but had not seen the schema-level lock for this.
To get more details on this and try to make sure I do not miss anything by studying a corner case, I've added a row to the table and then tried to do the same SELECT in explicit transaction, and (after SELECT completed, but transaction remained active) I tried to DROP DATABASE from the second session while this transaction was still active. (This test will also let us understand what metadata locks are requested for DROP DATABASE, by the way.) I've got the following in gdb:
[New Thread 0x7ff224c5e700 (LWP 2048)]
[Switching to Thread 0x7ff224c5e700 (LWP 2048)]
Breakpoint 2, MDL_request::init (this=0x7ff224c5a040,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) bt
#0 MDL_request::init (this=0x7ff224c5a040, mdl_namespace=MDL_key::GLOBAL,
db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
#1 0x00000000007d1ed7 in lock_schema_name (thd=0x7ff1fbbb5000,
db=0x7ff1e581d0b0 "test")
at /usr/src/debug/percona-server-5.6.27-76.0/sql/lock.cc:794
#2 0x00000000006b03d4 in mysql_rm_db (thd=0x7ff1fbbb5000,
db=0x7ff1e581d0b0 "test", if_exists=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_db.cc:787
...
---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c5a1f0,
mdl_namespace=MDL_key::BACKUP, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c5a3a0,
mdl_namespace=MDL_key::SCHEMA, db_arg=0x7ff1e581d0b0 "test",
name_arg=0xba2ae4 "", mdl_type_arg=MDL_EXCLUSIVE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) bt
#0 MDL_request::init (this=0x7ff224c5a3a0, mdl_namespace=MDL_key::SCHEMA,
db_arg=0x7ff1e581d0b0 "test", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_EXCLUSIVE, mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
#1 0x00000000007d1fb2 in lock_schema_name (thd=0x7ff1fbbb5000,
db=0x7ff1e581d0b0 "test")
at /usr/src/debug/percona-server-5.6.27-76.0/sql/lock.cc:801
#2 0x00000000006b03d4 in mysql_rm_db (thd=0x7ff1fbbb5000,
db=0x7ff1e581d0b0 "test", if_exists=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_db.cc:787
#3 0x00000000006daaa2 in mysql_execute_command (thd=0x7ff1fbbb5000)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_parse.cc:4371
#4 0x00000000006df518 in mysql_parse (thd=0x7ff1fbbb5000, rawbuf=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_parse.cc:6972
...
---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff1e58313b0,
mdl_namespace=MDL_key::TABLE, db_arg=0x7ff1e5831570 "test",
name_arg=0x7ff1e5831575 "t1", mdl_type_arg=MDL_EXCLUSIVE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) bt
#0 MDL_request::init (this=0x7ff1e58313b0, mdl_namespace=MDL_key::TABLE,
db_arg=0x7ff1e5831570 "test", name_arg=0x7ff1e5831575 "t1",
mdl_type_arg=MDL_EXCLUSIVE, mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
#1 0x00000000006b0857 in find_db_tables_and_rm_known_files (
thd=0x7ff1fbbb5000, db=0x7ff1e581d0b0 "test", if_exists=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_db.cc:1108
#2 mysql_rm_db (thd=0x7ff1fbbb5000, db=0x7ff1e581d0b0 "test", if_exists=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_db.cc:812
...
Now it's clear what happens, eventually we have to drop the table while dropping the schema, and here we surely hit a blocking metadata lock that SELECT set! Let's continue:
---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff1e581ece0,
mdl_namespace=MDL_key::SCHEMA, db_arg=0x7ff1e5831570 "test",
name_arg=0xba2ae4 "", mdl_type_arg=MDL_INTENTION_EXCLUSIVE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) bt
#0 MDL_request::init (this=0x7ff1e581ece0, mdl_namespace=MDL_key::SCHEMA,
db_arg=0x7ff1e5831570 "test", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
#1 0x000000000068da14 in lock_table_names (thd=0x7ff1fbbb5000,
tables_start=0x7ff1e5831010, tables_end=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:5033
#2 0x00000000006b05df in mysql_rm_db (thd=0x7ff1fbbb5000,
db=0x7ff1e581d0b0 "test", if_exists=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_db.cc:834
...
So, while our request for MDL_EXCLUSIVE lock for the table surely could not be satisfied, server continued with some further requests:
---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c5a1f0,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c5a3a0,
mdl_namespace=MDL_key::BACKUP, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
and only at this stage it hanged (waiting for the transaction where SELECT happened to complete). As soon as I committed there:
Breakpoint 2, MDL_request::init (this=0x7ff224c5a260,
mdl_namespace=MDL_key::TABLE, db_arg=0xb925ef "mysql",
name_arg=0xb94906 "proc", mdl_type_arg=MDL_SHARED_READ,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c5a360,
mdl_namespace=MDL_key::TABLE, db_arg=0xb925ef "mysql",
name_arg=0xb94906 "proc", mdl_type_arg=MDL_SHARED_WRITE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
So, we tried to read and then maybe change the mysql.proc table (to drop procedures created in this database, honestly I was not sure if there was any one there at the moment). Next:
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c59cb0,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c599c0,
mdl_namespace=MDL_key::BACKUP, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c5a250,
mdl_namespace=MDL_key::TABLE, db_arg=0xb925ef "mysql",
name_arg=0xc111a8 "event", mdl_type_arg=MDL_SHARED_WRITE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
That is, some lock requests and we try to delete events in this database from mysql.event table obviously. Let's continue:
Breakpoint 2, MDL_request::init (this=0x7ff224c59900,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) bt
#0 MDL_request::init (this=0x7ff224c59900, mdl_namespace=MDL_key::GLOBAL,
db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
#1 0x000000000068c13a in open_table (thd=0x7ff1fbbb5000,
table_list=0x7ff224c59eb0, ot_ctx=0x7ff224c59c10)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:2895
#2 0x0000000000694585 in open_and_process_table (thd=0x7ff1fbbb5000,
start=0x7ff224c59e48, counter=0x7ff224c59e50, flags=2048,
prelocking_strategy=0x7ff224c59ea0)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:4797
#3 open_tables (thd=0x7ff1fbbb5000, start=0x7ff224c59e48,
counter=0x7ff224c59e50, flags=2048, prelocking_strategy=0x7ff224c59ea0)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:5304
#4 0x0000000000694d74 in open_and_lock_tables (thd=0x7ff1fbbb5000,
tables=0x7ff224c59eb0, derived=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:5960
#5 0x000000000085039d in open_and_lock_tables (thd=0x7ff1fbbb5000, lock_type=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.h:477
#6 Event_db_repository::open_event_table (thd=0x7ff1fbbb5000, lock_type=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/event_db_repository.cc:619
#7 0x0000000000850bfc in Event_db_repository::drop_schema_events (this=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/event_db_repository.cc:1011---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c59610,
mdl_namespace=MDL_key::BACKUP, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) bt
#0 MDL_request::init (this=0x7ff224c59610, mdl_namespace=MDL_key::BACKUP,
db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
#1 0x00000000007d1dfe in Global_backup_lock::acquire_protection (
this=0x7ff1fbbb6a08, thd=0x7ff1fbbb5000, duration=MDL_STATEMENT,
lock_wait_timeout=31536000)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/lock.cc:1225
#2 0x000000000068ce20 in open_table (thd=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:3258
#3 0x0000000000694585 in open_and_process_table (thd=0x7ff1fbbb5000,
start=0x7ff224c59e48, counter=0x7ff224c59e50, flags=2048,
prelocking_strategy=0x7ff224c59ea0)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:4797
#4 open_tables (thd=0x7ff1fbbb5000, start=0x7ff224c59e48,
counter=0x7ff224c59e50, flags=2048, prelocking_strategy=0x7ff224c59ea0)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:5304
#5 0x0000000000694d74 in open_and_lock_tables (thd=0x7ff1fbbb5000,
tables=0x7ff224c59eb0, derived=Unhandled dwarf expression opcode 0xf3
)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/sql_base.cc:5960
...
---Type <return> to continue, or q <return> to quit---q
at /uQuit
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c5ab00,
mdl_namespace=MDL_key::BINLOG, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_EXPLICIT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
We ended up with writing to the binary log and DROP DATABASE was completed.
Let's summarize this experience. First of all, it seems in current implementation there is no need to set metadata locks at schema level to prevent dropping the database we read from with SELECT - table level metadata lock will eventually block the DROP DATABASE request. If we have many tables in the database this may happen not at the very first one, so we can drop some tables before getting blocked. This is something to study later. I'd really prefer DROP DATABASE to be atomic and do not even start if it can not complete at the moment. See Bug #79610 also.
We see table-level metadata lock requests for mysql.proc and mysql.events tables when DROP DATABASE is executed. This is expected and reasonable - we can NOT drop the database (schema) if there are some stored functions, procedures or events are defined there that are used.
We had also noted that even if some metadata lock is requested but can not be obtained, processing may continue for some time until stopped, and then processing resumes when we finally get the required metadata lock.
This is the code to study in sql/lock.cc:
760 /**
761 Obtain an exclusive metadata lock on a schema name.
762
763 @param thd Thread handle.
764 @param db The database name.
765
766 This function cannot be called while holding LOCK_open mutex.
767 To avoid deadlocks, we do not try to obtain exclusive metadata
768 locks in LOCK TABLES mode, since in this mode there may be
769 other metadata locks already taken by the current connection,
770 and we must not wait for MDL locks while holding locks.
771
772 @retval FALSE Success.
773 @retval TRUE Failure: we're in LOCK TABLES mode, or out of memory,
774 or this connection was killed.
775 */
776
777 bool lock_schema_name(THD *thd, const char *db)
778 {
779 MDL_request_list mdl_requests;
780 MDL_request global_request;
781 MDL_request backup_request;
782 MDL_request mdl_request;
783
784 if (thd->locked_tables_mode)
785 {
786 my_message(ER_LOCK_OR_ACTIVE_TRANSACTION,
787 ER(ER_LOCK_OR_ACTIVE_TRANSACTION), MYF(0));
788 return TRUE;
789 }
790
791 if (thd->global_read_lock.can_acquire_protection())
792 return TRUE;
793 global_request.init(MDL_key::GLOBAL, "", "", MDL_INTENTION_EXCLUSIVE,
794 MDL_STATEMENT);
795
796 if (thd->backup_tables_lock.abort_if_acquired())
797 return true;
798 thd->backup_tables_lock.init_protection_request(&backup_request,
799 MDL_STATEMENT);
800
801 mdl_request.init(MDL_key::SCHEMA, db, "", MDL_EXCLUSIVE, MDL_TRANSACTION) ;
802
803 mdl_requests.push_front(&mdl_request);
804 mdl_requests.push_front(&backup_request);
805 mdl_requests.push_front(&global_request);
806
807 if (thd->mdl_context.acquire_locks(&mdl_requests,
808 thd->variables.lock_wait_timeout))
809 return TRUE;
810
811 DEBUG_SYNC(thd, "after_wait_locked_schema_name");
812 return FALSE;
From this code we see that actually we acquire metadata locks in batches(!). This explaines why we had not stopped at our first "blocked" request immediately, and complicates tracing in gdb. We also see that we have some mdl_context object in THD structure, and we may use this later to study pending requests per thread. One day I'll start setting breakpoints at MDLcontext::acquire_locks as well.
It's also more or less clear what MDL_key::GLOBAL namespace is used for - this is a metadata lock requested by FLUSH TABLES WITH READ LOCK global lock, and thus we check it for any "write" operation, even before we try to do it. If I execute FLUSH TABLES WITH READ LOCK, I get the following in my gdb session with a breakpoint set:
[Switching to Thread 0x7ff224c9f700 (LWP 2017)]
Breakpoint 2, MDL_request::init (this=0x7ff224c9c9f0,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_SHARED, mdl_duration_arg=MDL_EXPLICIT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7ff224c9c9f0,
mdl_namespace=MDL_key::COMMIT, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_SHARED, mdl_duration_arg=MDL_EXPLICIT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
and then it's completed. Now, on UNLOCK TABLES nothing happens at MDL level.
The last topic I'd like to discuss in this post are metadata locks with namespace defined like this: mdl_namespace=MDL_key::BACKUP, "backup locks". Manual for 5.7 does not mention them, but they still exist in the code even there:
[openxs@centos ~]$ grep -rn MDL_key::BACKUP ~/git/mysql-server/*
[openxs@centos ~]$ echo $?
1
In MySQL we see the following in mdl.h:
enum enum_mdl_namespace { GLOBAL=0,
TABLESPACE,
SCHEMA,
TABLE,
FUNCTION,
PROCEDURE,
TRIGGER,
EVENT,
COMMIT,
USER_LEVEL_LOCK,
LOCKING_SERVICE,
/* This should be the last ! */
NAMESPACE_END };
So, backup locks is the unique feature of Percona Server, explained in the manual. It is implemented with MDL locks. As soon as we run LOCK TABLES FOR BACKUP, we see in gdb session:
Breakpoint 2, MDL_request::init (this=0x7ff224c9ca90,
mdl_namespace=MDL_key::BACKUP, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_SHARED, mdl_duration_arg=MDL_EXPLICIT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
This reminded me about the difference Percona Server can make, so I'll try to re-check my results with MySQL 5.6 next time as well. Stay tuned!
Tuesday, January 5, 2016
Exploring Metadata Locks with gdb - First Steps
Only since MySQL 5.7.3 (and only for a few months in GA releases since 5.7.9) we have an easy, official and documented way to check metadata locks set by different sessions using the metadata_locks table in Performance Schema. I've already explained how to use it in my blog post at Percona's blog. Still, most of MySQL servers in production are NOT 5.7.x today, so majority of MySQL users have to wonder what metadata locks are set and when, desperately killing old sessions in a hope to blindly find one holding the blocking metadata lock. In some cases the blocking session is easy to identify from SHOW PROCESSLIST or SHOW ENGINE INNODB STATUS, but if we have several long running sessions that executes nothing at the moment (or something that does not refer to the table we can not TRUNCATE or ALTER, and there are no table level locks mentioned in INNODB STATUS to help us as a hint), there is not so much one can do...
I was not ready to give up easily on this and just suggest to check/kill longest active transactions/sessions one by one, check for running mysqldump --single-transaction etc every time somebody asks why TRUNCATE TABLE is blocked on MySQL 5.5.x or 5.6.x. Based on my recent preferences of using gdb for every task that does not have official "SQL way" to complete, I decided last year to spend some time checking the source code (in mdl.cc and mdl.h) and try to use gdb to find out what metadata locks are set/requested and in what order when specific SQL statements are executed, how to "see" all the metadata locks if you are NOT on MySQL 5.7.x and, most importantly for real life cases, how to find out what exact session is holding the blocking metadata lock. It seems I've collected enough logs of debugging sessions and spent enough time reading the code to start sharing my findings that may become useful for wider audience. Hence this my first post in the series I plan to devote to metadata lock studies.
In this post I'll concentrate on how to check what metadata locks are requested and in what order. For this, we should concentrate on MDL_request class (yes, metadata locks are implemented in C++, with classes, methods, overloaded operators, friend classes etc), see mdl.h:
/**
A pending metadata lock request.
A lock request and a granted metadata lock are represented by
different classes because they have different allocation
sites and hence different lifetimes. The allocation of lock requests is
controlled from outside of the MDL subsystem, while allocation of granted
locks (tickets) is controlled within the MDL subsystem.
MDL_request is a C structure, you don't need to call a constructor
or destructor for it.
*/
class MDL_request
{
public:
/** Type of metadata lock. */
enum enum_mdl_type type; /** Duration for requested lock. */
enum enum_mdl_duration duration;
/**
Pointers for participating in the list of lock requests for this context.
*/
MDL_request *next_in_list;
MDL_request **prev_in_list;
/**
Pointer to the lock ticket object for this lock request.
Valid only if this lock request is satisfied.
*/
MDL_ticket *ticket;
/** A lock is requested based on a fully qualified name and type. */
MDL_key key;
public:
static void *operator new(size_t size, MEM_ROOT *mem_root) throw ()
{ return alloc_root(mem_root, size); }
static void operator delete(void *ptr, MEM_ROOT *mem_root) {}
void init(MDL_key::enum_mdl_namespace namespace_arg,
const char *db_arg, const char *name_arg,
enum_mdl_type mdl_type_arg,
enum_mdl_duration mdl_duration_arg); void init(const MDL_key *key_arg, enum_mdl_type mdl_type_arg,
enum_mdl_duration mdl_duration_arg);
...
};
I've highlighted class members that will be important for further checks. Metadata lock types are defined in mdl.h as follows (most comments were removed, read them in the source code!):
enum enum_mdl_type {
/*
An intention exclusive metadata lock. Used only for scoped locks.
Owner of this type of lock can acquire upgradable exclusive locks on
individual objects.
Compatible with other IX locks, but is incompatible with scoped S and
X locks.
*/
MDL_INTENTION_EXCLUSIVE= 0,
MDL_SHARED,
MDL_SHARED_HIGH_PRIO,
MDL_SHARED_READ,
MDL_SHARED_WRITE,
MDL_SHARED_UPGRADABLE,
MDL_SHARED_NO_WRITE,
/*
An exclusive metadata lock.
A connection holding this lock can modify both table's metadata and data.
No other type of metadata lock can be granted while this lock is held.
To be used for CREATE/DROP/RENAME TABLE statements and for execution of
certain phases of other DDL statements.
*/
MDL_EXCLUSIVE,
/* This should be the last !!! */
MDL_TYPE_END};
Metadata locks can be hold for different duration (till the end of statement, till the end of transactions -most of them), defined as follows:
enum enum_mdl_duration {
/**
Locks with statement duration are automatically released at the end
of statement or transaction.
*/
MDL_STATEMENT= 0,
/**
Locks with transaction duration are automatically released at the end
of transaction.
*/
MDL_TRANSACTION,
/**
Locks with explicit duration survive the end of statement and transaction.
They have to be released explicitly by calling MDL_context::release_lock().
*/
MDL_EXPLICIT,
/* This should be the last ! */
MDL_DURATION_END };
With this in mind, we are almost ready to start with gdb, the idea is to set breakpoint on MDL_request::init and then see what requests are made and in what order. This is how it's defined in mdl.cc:
/**
Initialize a lock request.
This is to be used for every lock request.
Note that initialization and allocation are split into two
calls. This is to allow flexible memory management of lock
requests. Normally a lock request is stored in statement memory
(e.g. is a member of struct TABLE_LIST), but we would also like
to allow allocation of lock requests in other memory roots,
for example in the grant subsystem, to lock privilege tables.
The MDL subsystem does not own or manage memory of lock requests.
@param mdl_namespace Id of namespace of object to be locked
@param db Name of database to which the object belongs
@param name Name of of the object
@param mdl_type The MDL lock type for the request.
*/
void MDL_request::init(MDL_key::enum_mdl_namespace mdl_namespace,
const char *db_arg,
const char *name_arg,
enum_mdl_type mdl_type_arg,
enum_mdl_duration mdl_duration_arg)
{
key.mdl_key_init(mdl_namespace, db_arg, name_arg);
type= mdl_type_arg;
duration= mdl_duration_arg;
ticket= NULL;
}
I've got a lot of "hints" from the above, up to the idea that MDL_keys can probably be created "manually" in gdb (not that it worked well). What we miss in the above is the list of metadata lock namespaces, so let's get back to mdl.h:
class MDL_key
{
public:
#ifdef HAVE_PSI_INTERFACE
static void init_psi_keys();
#endif
/**
Object namespaces.
Sic: when adding a new member to this enum make sure to
update m_namespace_to_wait_state_name array in mdl.cc!
Different types of objects exist in different namespaces
- TABLE is for tables and views.
- FUNCTION is for stored functions.
- PROCEDURE is for stored procedures.
- TRIGGER is for triggers.
- EVENT is for event scheduler events
Note that although there isn't metadata locking on triggers,
it's necessary to have a separate namespace for them since
MDL_key is also used outside of the MDL subsystem.
*/
enum enum_mdl_namespace { GLOBAL=0,
BACKUP,
SCHEMA,
TABLE,
FUNCTION,
PROCEDURE,
TRIGGER,
EVENT,
COMMIT,
USER_LOCK, /* user level locks. */
BINLOG,
/* This should be the last ! */
NAMESPACE_END };
...
As a side note, I quoted the code and worked with Percona Server 5.6.27, but this should not matter much - these parts of related code in 5.5.x and 5.6.x is more or less similar/same. In 5.7 there were many notable changes. For example, there is no BINLOG namespace, but there is one for the locking service...
So, with all these details in mind, let's try to use the gdb to find out what metadata locks are requested by a couple of simple statements, SELECT and TRUNCATE. I attached gdb to Percona Server 5.6.27 with binary log enabled (and debug symbols installed), and did the following:
[root@centos openxs]# gdb -p `pidof mysqld`
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-83.el6)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
...
Reading symbols from /usr/lib64/mysql/plugin/tokudb_backup.so...Reading symbols from /usr/lib/debug/usr/lib64/mysql/plugin/tokudb_backup.so.debug...done.
done.
Loaded symbols for /usr/lib64/mysql/plugin/tokudb_backup.so
0x00007feb2d145113 in poll () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.166.el6_7.3.x86_64 jemalloc-3.6.0-1.el6.x86_64 keyutils-libs-1.4-5.el6.x86_64 krb5-libs-1.10.3-42.el6.x86_64 libaio-0.3.107-10.el6.x86_64 libcom_err-1.41.12-22.el6.x86_64 libgcc-4.4.7-16.el6.x86_64 libselinux-2.0.94-5.8.el6.x86_64 libstdc++-4.4.7-16.el6.x86_64 nss-softokn-freebl-3.14.3-23.el6_7.x86_64 numactl-2.0.9-2.el6.x86_64 openssl-1.0.1e-42.el6_7.1.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) b MDL_request::init
Breakpoint 1 at 0x648f13: file /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc, line 1266.
Breakpoint 2 at 0x648e70: file /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc, line 1245.
warning: Multiple breakpoints were set.
Use the "delete" command to delete unwanted breakpoints.
(gdb) c
Continuing.
Now, in a separate session connected to the test database with simple (InnoDB) table t1, I did:
mysql> select * from t1;
and got the following in the gdb session:
[Switching to Thread 0x7feb2f44a700 (LWP 2319)]
Breakpoint 2, MDL_request::init (this=0x7feb064445a0,
mdl_namespace=MDL_key::TABLE, db_arg=0x7feb06444760 "test",
name_arg=0x7feb064441c8 "t1", mdl_type_arg=MDL_SHARED_READ,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
As soon as I continued, select returned me results. So, we see that SELECT had requested an MDL_SHARED_READ lock till the end of transaction for the table t1 in the database test. This already forces me to ask some followup questions to myself, but let's postpone them (and replies) to some later post. Let's try to do TRUNCATE TABLE:
mysql> truncate table t1;
I've got the following in the gdb session:
Breakpoint 2, MDL_request::init (this=0x7feb06444488,
mdl_namespace=MDL_key::TABLE, db_arg=0x7feb06444648 "test",
name_arg=0x7feb064440b0 "t1", mdl_type_arg=MDL_EXCLUSIVE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb06444660,
mdl_namespace=MDL_key::SCHEMA, db_arg=0x7feb06444648 "test",
name_arg=0xba2ae4 "", mdl_type_arg=MDL_INTENTION_EXCLUSIVE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb2f447720,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb2f4478d0,
mdl_namespace=MDL_key::BACKUP, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb06444808,
mdl_namespace=MDL_key::SCHEMA, db_arg=0x7feb06444648 "test",
name_arg=0xba2ae4 "", mdl_type_arg=MDL_INTENTION_EXCLUSIVE,
mdl_duration_arg=MDL_TRANSACTION)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb2f4472c0,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb2f447470,
mdl_namespace=MDL_key::BACKUP, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb2f447410,
mdl_namespace=MDL_key::GLOBAL, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_STATEMENT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb2f447a60,
mdl_namespace=MDL_key::COMMIT, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_EXPLICIT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
Breakpoint 2, MDL_request::init (this=0x7feb2f446900,
mdl_namespace=MDL_key::BINLOG, db_arg=0xba2ae4 "", name_arg=0xba2ae4 "",
mdl_type_arg=MDL_INTENTION_EXCLUSIVE, mdl_duration_arg=MDL_EXPLICIT)
at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:1245
1245 {
(gdb) c
Continuing.
and only after all these 10 (if I am not mistaking) MDL requests I've got TRUNCATE TABLE executed. Some of these requests are clear, like the very first MDL_EXCLUSIVE for the table we were truncating, or the next MDL_INTENTION_EXCLUSIVE one, for the test schema. Surely we need exclusive access to the table until the end of transaction, and if you read comments in mdl.h carefully it's clear that any active SELECT from the table will block TRUNCATE (this was a big surprise to many old MySQL users now upgrading to version 5.5+). Some other lock requests at the end (the one for COMMIT and BINLOG namespaces) also look reasonable - we do have to commit the TRUNCATE and write it to the binary log. Other requests may be far from clear.
We'll discuss them all eventually, but for now my goal was to show that the method of metadata locks study works (in a same way as it worked for studying InnoDB lock requests), we probably picked up a useful function to set a breakpoint on, to begin with, and that the method shows a very detailed information on what happens with metadata locks even if compared with what MySQL 5.7 officially provides via metadata_locks table in Performance Schema (where many requests can be missed with simple query, for example because they do not "live" for a long time and may be "gone" at the moment when we query the table).
More posts will appear in this series soon. Stay tuned!
Sunday, September 27, 2020
Metadata Locks Instrumentation in MariaDB 10.5
There are different ways to study metadata locks in MySQL and MariaDB, as I once described in details. Until recently MariaDB had not provided the performance_schema.metadata_locks table, but it was finally added in 10.5. So, now you can easily get the details in a way that became the easiest and most well known since MySQL 5.7. You just have to make sure performance_schema is enabled at startup:
openxs@ao756:~/dbs/maria10.5$ bin/mysqld_safe --no-defaults --port=3311 --socket=/tmp/mariadb105.sock --performance_schema=1 &
[1] 23626
openxs@ao756:~/dbs/maria10.5$ 200927 18:26:41 mysqld_safe Logging to '/home/openxs/dbs/maria10.5/data/ao756.err'.
200927 18:26:41 mysqld_safe Starting mariadbd daemon with databases from /home/openxs/dbs/maria10.5/data
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock
Welcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 3
Server version: 10.5.6-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 [(none)]> select @@performance_schema;
+----------------------+
| @@performance_schema |
+----------------------+
| 1 |
+----------------------+
1 row in set (0,000 sec)
MariaDB [(none)]> use performance_schema
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
Database changed
MariaDB [performance_schema]> show tables like '%metadata%';
+-------------------------------------------+
| Tables_in_performance_schema (%metadata%) |
+-------------------------------------------+
| metadata_locks |
+-------------------------------------------+
1 row in set (0,001 sec)
MariaDB [performance_schema]> select * from setup_instruments where name like '%metadata%';
+---------------------------------------------------------+---------+-------+
| NAME | ENABLED | TIMED |
+---------------------------------------------------------+---------+-------+
| wait/io/file/csv/metadata | YES | YES |
| stage/sql/Waiting for schema metadata lock | NO | NO |
| stage/sql/Waiting for table metadata lock | NO | NO |
| stage/sql/Waiting for stored function metadata lock | NO | NO |
| stage/sql/Waiting for stored procedure metadata lock | NO | NO |
| stage/sql/Waiting for stored package body metadata lock | NO | NO |
| stage/sql/Waiting for trigger metadata lock | NO | NO |
| stage/sql/Waiting for event metadata lock | NO | NO |
| memory/performance_schema/metadata_locks | YES | NO |
| wait/lock/metadata/sql/mdl | NO | NO |
+---------------------------------------------------------+---------+-------+
10 rows in set (0,034 sec)
So, the metadata_locks table is there and we just need to enable wait/lock/metadata/sql/mdl instrument:
MariaDB [performance_schema]> update setup_instruments set enabled = 'YES', timed='YES' where name like 'wait%mdl';
Query OK, 1 row affected (0,030 sec)
Rows matched: 1 Changed: 1 Warnings: 0
MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: performance_schema
OBJECT_NAME: metadata_locks
OBJECT_INSTANCE_BEGIN: 140032981253664
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 13
OWNER_EVENT_ID: 1
1 row in set (0,001 sec)
MariaDB [performance_schema]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
| 3 |
+-----------------+
1 row in set (0,000 sec)
MariaDB [performance_schema]> select * from threads where processlist_id = 3\G
*************************** 1. row ***************************
THREAD_ID: 13
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 3
PROCESSLIST_USER: openxs
PROCESSLIST_HOST: localhost
PROCESSLIST_DB: performance_schema
PROCESSLIST_COMMAND: Query
PROCESSLIST_TIME: 0
PROCESSLIST_STATE: Sending data
PROCESSLIST_INFO: select * from threads where processlist_id = 3
PARENT_THREAD_ID: 1
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: Socket
THREAD_OS_ID: 23719
1 row in set (0,018 sec)
The output above shows that one has to join to threads table on thread_id = metadata_locks.owner_thread_id to get the details for thread that set metadata lock:
MariaDB [performance_schema]> SELECT OBJECT_TYPE, OBJECT_SCHEMA, OBJECT_NAME, LOCK_TYPE, LOCK_STATUS, THREAD_ID, PROCESSLIST_ID, PROCESSLIST_INFO FROM performance_schema.metadata_locks INNER JOIN performance_schema.threads ON THREAD_ID = OWNER_THREAD_ID WHERE PROCESSLIST_ID <> CONNECTION_ID()\G
*************************** 1. row ***************************
OBJECT_TYPE: BACKUP
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
LOCK_TYPE: BACKUP_DDL
LOCK_STATUS: PENDING
THREAD_ID: 50
PROCESSLIST_ID: 21
PROCESSLIST_INFO: drop database test
1 row in set (0,001 sec)
In the cases above we see the lock, SHARED_READ, on the table we access, performance_schema.metadata_locks, set by thread that reads from the table. Then we see how to avoid seeing locks set by current connection and how to get current statement (or other SHOW PROCESSLIST details) for the thread associated with the lock.
I noted that SOURCE column in the metadata_locks table is empty. It seems to be the case for other locks too, like those caused by sysbench test running:
MariaDB [performance_schema]> select * from metadata_locks limit 5\G
*************************** 1. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
OBJECT_INSTANCE_BEGIN: 140032787904800
LOCK_TYPE: SHARED_WRITE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 34
OWNER_EVENT_ID: 1
*************************** 2. row ***************************
OBJECT_TYPE: BACKUP
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140032778203712
LOCK_TYPE: BACKUP_TRANS_DML
LOCK_DURATION: STATEMENT
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 34
OWNER_EVENT_ID: 1
*************************** 3. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
OBJECT_INSTANCE_BEGIN: 140033249782768
LOCK_TYPE: SHARED_WRITE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 33
OWNER_EVENT_ID: 1
*************************** 4. row ***************************
OBJECT_TYPE: BACKUP
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140033248057584
LOCK_TYPE: BACKUP_TRANS_DML
LOCK_DURATION: STATEMENT
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 33
OWNER_EVENT_ID: 1
*************************** 5. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: sbtest
OBJECT_NAME: sbtest1
OBJECT_INSTANCE_BEGIN: 140033449398688
LOCK_TYPE: SHARED_WRITE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 32
OWNER_EVENT_ID: 1
5 rows in set (0,001 sec)
MariaDB [performance_schema]>
I do not think that it is normal, as in MySQL 8.0.21, for example, I still see the reference to the line of source code where the lock is set:
openxs@ao756:~/dbs/8.0$ bin/mysql --socket=/tmp/mysql8.sock -uroot performance_schema
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 8
Server version: 8.0.21 Source distribution
Copyright (c) 2000, 2020, 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> flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)
mysql> select * from metadata_locks\G
*************************** 1. row ***************************
OBJECT_TYPE: GLOBAL
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
COLUMN_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139972651847648
LOCK_TYPE: SHARED
LOCK_DURATION: EXPLICIT
LOCK_STATUS: GRANTED
SOURCE: lock.cc:1033
OWNER_THREAD_ID: 49
OWNER_EVENT_ID: 112
*************************** 2. row ***************************
OBJECT_TYPE: COMMIT
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
COLUMN_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139972651711440
LOCK_TYPE: SHARED
LOCK_DURATION: EXPLICIT
LOCK_STATUS: GRANTED
SOURCE: lock.cc:1108
OWNER_THREAD_ID: 49
OWNER_EVENT_ID: 112
...
I reported this immediately as a bug, MDEV-23827 - "performance_schema.metadata_locks.source column is always empty".
The details in this table that are not covered by the MySQL manual require some investigation. You probably noted BACKUP_TRANS_DML as a lock type above. Another example (that you may get while mariabackup a.k.a mariadb-backup in 10.5 is running):
MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
OBJECT_TYPE: BACKUP
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140032980286816
LOCK_TYPE: BACKUP_START
LOCK_DURATION: EXPLICIT
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 44
OWNER_EVENT_ID: 1
...
I've investigated similar details in the past for MySQL and Percona Server, by code review and some gdb tests. I'd expect to see these values documented somewhere in the mdl.h file in the source code. Here is what we have:
openxs@ao756:~/git/server$ grep -rn BACKUP_TRANS_DML *
mysql-test/main/mdl.result:13:MDL_BACKUP_TRANS_DML Backup lock
mysql-test/main/mdl.result:19:MDL_BACKUP_TRANS_DML Backup lock
sql/mdl.h:295:#define MDL_BACKUP_TRANS_DML enum_mdl_type(8)
sql/mdl.cc:134: { C_STRING_WITH_LEN("MDL_BACKUP_TRANS_DML") },
sql/mdl.cc:490: MDL_BIT(MDL_BACKUP_TRANS_DML)));
sql/mdl.cc:1633: MDL_BIT(MDL_BACKUP_DML) | MDL_BIT(MDL_BACKUP_TRANS_DML) | MDL_BIT(MDL_BACKUP_SYS_DML) | MDL_BIT(MDL_BACKUP_DDL) | MDL_BIT(MDL_BACKUP_ALTER_COPY),
sql/mdl.cc:1634: MDL_BIT(MDL_BACKUP_DML) | MDL_BIT(MDL_BACKUP_TRANS_DML) | MDL_BIT(MDL_BACKUP_SYS_DML) | MDL_BIT(MDL_BACKUP_DDL) | MDL_BIT(MDL_BACKUP_ALTER_COPY) | MDL_BIT(MDL_BACKUP_COMMIT),
sql/sql_base.cc:2048: mdl_type= MDL_BACKUP_TRANS_DML;
storage/perfschema/table_helper.cc:636: case MDL_BACKUP_TRANS_DML:
storage/perfschema/table_helper.cc:637: PFS_engine_table::set_field_varchar_utf8(f, STRING_WITH_LEN("BACKUP_TRANS_DML"));
openxs@ao756:~/git/server$
This is what we have in sql/mdl.h in MariaDB 10.5:
258 /** Backup locks */
259
260 /**
261 Block concurrent backup
262 */
263 #define MDL_BACKUP_START enum_mdl_type(0)
264 /**
265 Block new write requests to non transactional tables
266 */
267 #define MDL_BACKUP_FLUSH enum_mdl_type(1)
268 /**
269 In addition to previous locks, blocks running requests to non trans tables
270 Used to wait until all DML usage of on trans tables are finished
271 */
272 #define MDL_BACKUP_WAIT_FLUSH enum_mdl_type(2)
273 /**
274 In addition to previous locks, blocks new DDL's from starting
275 */
276 #define MDL_BACKUP_WAIT_DDL enum_mdl_type(3)
277 /**
278 In addition to previous locks, blocks commits
279 */
280 #define MDL_BACKUP_WAIT_COMMIT enum_mdl_type(4)
281
282 /**
283 Blocks (or is blocked by) statements that intend to modify data. Acquired
284 before commit lock by FLUSH TABLES WITH READ LOCK.
285 */
286 #define MDL_BACKUP_FTWRL1 enum_mdl_type(5)
287
288 /**
289 Blocks (or is blocked by) commits. Acquired after global read lock by
290 FLUSH TABLES WITH READ LOCK.
291 */
292 #define MDL_BACKUP_FTWRL2 enum_mdl_type(6)
293
294 #define MDL_BACKUP_DML enum_mdl_type(7)
295 #define MDL_BACKUP_TRANS_DML enum_mdl_type(8)
296 #define MDL_BACKUP_SYS_DML enum_mdl_type(9)
...
I see creative re-use of the values from enum_mdl_type.
The last bug not the least, this is how the global read lock and the metadata lock wait look like:
MariaDB [performance_schema]> flush tables with read lock;
Query OK, 0 rows affected (0,090 sec)
MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
OBJECT_TYPE: BACKUP
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140033115590992
LOCK_TYPE: BACKUP_FTWRL1
LOCK_DURATION: EXPLICIT
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 56
OWNER_EVENT_ID: 1
...
MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
OBJECT_TYPE: BACKUP
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140033115590992
LOCK_TYPE: BACKUP_FTWRL1
LOCK_DURATION: EXPLICIT
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 56
OWNER_EVENT_ID: 1
*************************** 2. row ***************************
OBJECT_TYPE: BACKUP
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140032979653216
LOCK_TYPE: BACKUP_DDL
LOCK_DURATION: STATEMENT
LOCK_STATUS: PENDING
SOURCE:
OWNER_THREAD_ID: 50
OWNER_EVENT_ID: 1
*************************** 3. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: performance_schema
OBJECT_NAME: metadata_locks
OBJECT_INSTANCE_BEGIN: 140033113928032
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 56
OWNER_EVENT_ID: 1
3 rows in set (0,000 sec)
MariaDB [performance_schema]> select * from information_schema.metadata_lock_info\G
*************************** 1. row ***************************
THREAD_ID: 23
LOCK_MODE: MDL_BACKUP_FTWRL2
LOCK_DURATION: NULL
LOCK_TYPE: Backup lock
TABLE_SCHEMA:
TABLE_NAME:
1 row in set (0,001 sec)
The last statement above shows that the old way to check metadata locks, via metadata_lock_info plugin, had provided much less details. We could not even distinguish lock from lock wait (pending lock) with it!
| Are there any locks on that bridge? Go figure... |
Finally, even with metadata_locks table in place, finding the details about the exact blocking lock may be not trivial. See this blog post for some idea on how to do this based on assumption that blocking lock is surely set earlier than pending one.
Thursday, January 7, 2016
Exploring Metadata Locks with gdb - How One Can Use This?
I'll continue to use Percona Server 5.6.27 for now, just because I have it installed and have a source code at hand. So, MDL_context class is defined in sql/mdl.h file as follows:
/**
Context of the owner of metadata locks. I.e. each server
connection has such a context.
*/
class MDL_context
{
public:
typedef I_P_List<MDL_ticket,
I_P_List_adapter<MDL_ticket,
&MDL_ticket::next_in_context,
&MDL_ticket::prev_in_context> >
Ticket_list;
typedef Ticket_list::Iterator Ticket_iterator;
MDL_context();
...
bool try_acquire_lock(MDL_request *mdl_request);
bool acquire_lock(MDL_request *mdl_request, ulong lock_wait_timeout);
bool acquire_locks(MDL_request_list *requests, ulong lock_wait_timeout);...
unsigned long get_lock_owner(MDL_key *mdl_key);...
private:
THD *get_thd() const { return m_owner->get_thd(); }...
};
I've highlighted some of the functions that we may use later. Now, this is how MDL_context::aquire_locks() implementation looks like in mdl.cc:
/**
Acquire exclusive locks. There must be no granted locks in the
context.
This is a replacement of lock_table_names(). It is used in
RENAME, DROP and other DDL SQL statements.
@param mdl_requests List of requests for locks to be acquired.
@param lock_wait_timeout Seconds to wait before timeout.
@note The list of requests should not contain non-exclusive lock requests.
There should not be any acquired locks in the context.
@note Assumes that one already owns scoped intention exclusive lock.
@retval FALSE Success
@retval TRUE Failure
*/
bool MDL_context::acquire_locks(MDL_request_list *mdl_requests,
ulong lock_wait_timeout)
{
...
for (p_req= sort_buf; p_req < sort_buf + req_count; p_req++)
{
if (acquire_lock(*p_req, lock_wait_timeout))
goto err;
}
my_free(sort_buf);
return FALSE;
err:
/*
Release locks we have managed to acquire so far.
Use rollback_to_savepoint() since there may be duplicate
requests that got assigned the same ticket.
*/
rollback_to_savepoint(mdl_svp);
/* Reset lock requests back to its initial state. */
...
my_free(sort_buf);
return TRUE;
}
Comments make me think that for some metadata locks we may see some different function called, but let's deal with exclusive ones for now, those that can be blocked. Now, the MDL_context::aquire_lock() we eventually call for each request:
/**
Acquire one lock with waiting for conflicting locks to go away if needed.
@param mdl_request [in/out] Lock request object for lock to be acquired
@param lock_wait_timeout [in] Seconds to wait before timeout.
@retval FALSE Success. MDL_request::ticket points to the ticket
for the lock.
@retval TRUE Failure (Out of resources or waiting is aborted),
*/
bool
MDL_context::acquire_lock(MDL_request *mdl_request, ulong lock_wait_timeout)
{
MDL_lock *lock;
MDL_ticket *ticket= NULL;
struct timespec abs_timeout;
MDL_wait::enum_wait_status wait_status;
...
/*
Our attempt to acquire lock without waiting has failed.
As a result of this attempt we got MDL_ticket with m_lock
member pointing to the corresponding MDL_lock object which
has MDL_lock::m_rwlock write-locked.
*/
lock= ticket->m_lock;
lock->m_waiting.add_ticket(ticket);
/*
Once we added a pending ticket to the waiting queue,
we must ensure that our wait slot is empty, so
that our lock request can be scheduled. Do that in the
critical section formed by the acquired write lock on MDL_lock.
*/
m_wait.reset_status();
/*
Don't break conflicting locks if timeout is 0 as 0 is used
To check if there is any conflicting locks...
*/
if (lock->needs_notification(ticket) && lock_wait_timeout)
lock->notify_conflicting_locks(this);
mysql_prlock_unlock(&lock->m_rwlock);
will_wait_for(ticket);
/* There is a shared or exclusive lock on the object. */
DEBUG_SYNC(get_thd(), "mdl_acquire_lock_wait");
find_deadlock();
struct timespec abs_shortwait;
set_timespec(abs_shortwait, 1);
wait_status= MDL_wait::EMPTY;
while (cmp_timespec(abs_shortwait, abs_timeout) <= 0)
{
/* abs_timeout is far away. Wait a short while and notify locks. */
wait_status= m_wait.timed_wait(m_owner, &abs_shortwait, FALSE,
mdl_request->key.get_wait_state_name());
if (wait_status != MDL_wait::EMPTY)
break;
/* Check if the client is gone while we were waiting. */
if (! m_owner->is_connected())
{
/*
* The client is disconnected. Don't wait forever:
* assume it's the same as a wait timeout, this
* ensures all error handling is correct.
*/
wait_status= MDL_wait::TIMEOUT;
break;
}
mysql_prlock_wrlock(&lock->m_rwlock);
if (lock->needs_notification(ticket))
lock->notify_conflicting_locks(this);
mysql_prlock_unlock(&lock->m_rwlock);
set_timespec(abs_shortwait, 1);
}
...
So, here we check if our request is deadlocking and then we wait. It's clear that any session that is hanging while waiting for the metadata lock will have MDL_context::aquire_lock() in the backtrace.
To check this assumption let me set up a usual test with SELECT * FROM t1 executed in active transaction and TRUNCATE TABLE blocked. This is how it may look like in the SHOW PROCESSLIST:
mysql> show processlist;
+----+------+-----------+------+---------+------+---------------------------------+-------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+------+-----------+------+---------+------+---------------------------------+-------------------+-----------+---------------+
| 2 | root | localhost | test | Query | 121 | Waiting for table metadata lock | truncate table t1 | 0 | 0 |
| 3 | root | localhost | test | Sleep | 2 | | NULL | 1 | 0 |
| 4 | root | localhost | test | Query | 0 | init | show processlist | 0 | 0 |
+----+------+-----------+------+---------+------+---------------------------------+-------------------+-----------+---------------+
3 rows in set (0.00 sec)
In general (and in this case) we may NOT be able to find a thread that is executing some statement for longer than out blocked session is waiting for the metadata lock. So, which one is the blocking one?
Let's try to find a thread that mentions MDL_context::aquire_lock() in the backtrace:
[root@centos percona-server]# gdb -p `pidof mysqld` -ex "set pagination 0" -ex "thread apply all bt" -batch 2>/dev/null | grep 'MDL_context::acquire_lock'
#3 0x000000000064a74b in MDL_context::acquire_lock (this=0x7fc005ff5140, mdl_request=0x7fc00614e488, lock_wait_timeout=) at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:2380
#4 0x000000000064ae1b in MDL_context::acquire_locks (this=0x7fc005ff5140, mdl_requests=) at /usr/src/debug/percona-server-5.6.27-76.0/sql/mdl.cc:2500
[root@centos percona-server]#
Note that I've executed the command as root, because mysqld process is owned by root in this case.
So, we see exactly one backtrace with this call:
MDL_context::acquire_lock (this=0x7fc005ff5140, mdl_request=0x7fc00614e488, lock_wait_timeout=)
and from the code review we know that 0x7fc00614e488 is of type MDL_request *. We also know that 0x7fc005ff5140 is of type MDL_context * (this pointer in the method of that class). Now we can attach gdb to the mysqld running and try to see what we can do with that pointers:
[root@centos percona-server]# gdb -p `pidof mysqld`
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-83.el6)
...
(gdb) set $pmdlr=(MDL_request *)0x7fc00614e488
(gdb) p $pmdlr
$1 = (MDL_request *) 0x7fc00614e488
(gdb) p $pmdlr->key
$2 = {m_length = 9, m_db_name_length = 4,
m_ptr = "\003test\000t1", '\000' <repeats 378 times>,
static m_namespace_to_wait_state_name = {{m_key = 102,
m_name = 0xb9eb8c "Waiting for global read lock", m_flags = 0}, {
m_key = 103, m_name = 0xb9eba9 "Waiting for backup lock", m_flags = 0}, {
m_key = 104, m_name = 0xb9ed68 "Waiting for schema metadata lock",
m_flags = 0}, {m_key = 105,
m_name = 0xb9ed90 "Waiting for table metadata lock", m_flags = 0}, {
m_key = 106,
m_name = 0xb9edb0 "Waiting for stored function metadata lock",
m_flags = 0}, {m_key = 107,
m_name = 0xb9ede0 "Waiting for stored procedure metadata lock",
m_flags = 0}, {m_key = 108,
m_name = 0xb9ee10 "Waiting for trigger metadata lock", m_flags = 0}, {
m_key = 109, m_name = 0xb9ee38 "Waiting for event metadata lock",
m_flags = 0}, {m_key = 110, m_name = 0xb9ebc1 "Waiting for commit lock",
m_flags = 0}, {m_key = 79, m_name = 0xb9295a "User lock", m_flags = 0}, {
m_key = 111, m_name = 0xb9ebd9 "Waiting for binlog lock", m_flags = 0}}}
(gdb) p &($pmdlr->key)
$3 = (MDL_key *) 0x7fc00614e4a8
So, we can get a pointer to the MDL_key. Now, in MDL_context class we had seen the following method:
unsigned long get_lock_owner(MDL_key *mdl_key);
that returns the id of the owning thread, and lucky we are, we have a pointer to MDL_context, so we can refer to this function and call it if needed:
(gdb) set $pmdlc=(MDL_context *)0x7fc005ff5140
(gdb) p $pmdlc
$4 = (MDL_context *) 0x7fc005ff5140
(gdb) p $pmdlc->get_lock_owner(&($pmdlr->key))
$5 = 3
Now, what's that value printed, 3? It's the id of thread in the SHOW PROCESSLIST that holds the blocking metadata lock. So, we quit from gdb:
(gdb) q
A debugging session is active.
Inferior 1 [process 3003] will be detached.
Quit anyway? (y or n) y
Detaching from program: /usr/sbin/mysqld, process 3003
and then we know what thread to kill to release the blocking lock and let TRUNCATE to proceed:
mysql> show processlist;
+----+------+-----------+------+---------+------+---------------------------------+-------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+------+-----------+------+---------+------+---------------------------------+-------------------+-----------+---------------+
| 2 | root | localhost | test | Query | 1291 | Waiting for table metadata lock | truncate table t1 | 0 | 0 |
| 3 | root | localhost | test | Sleep | 1172 | | NULL | 1 | 0 |
| 4 | root | localhost | test | Query | 0 | init | show processlist | 0 | 0 |
+----+------+-----------+------+---------+------+---------------------------------+-------------------+-----------+---------------+
3 rows in set (0.00 sec)
mysql> kill 3;
Query OK, 0 rows affected (0.05 sec)
mysql> show processlist;
+----+------+-----------+------+---------+------+-------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+------+-----------+------+---------+------+-------+------------------+-----------+---------------+
| 2 | root | localhost | test | Sleep | 1305 | | NULL | 0 | 0 |
| 4 | root | localhost | test | Query | 0 | init | show processlist | 0 | 0 |
+----+------+-----------+------+---------+------+-------+------------------+-----------+---------------+
2 rows in set (0.00 sec)
So, from now on you know how to find out in MySQL 5.6 the blocking session/thread for any session that is waiting on metadata with just gdb and some grep.
This is not the only way, you can get the same result from different functions in different MDL-related classes. Your findings may depend on what part of the code you traced or read first, but essentially that's it: you can easily find a blocking thread for any waiting MDL lock request, using just a couple of gdb commands! No need to kill them one by one in a hope.
For any MySQL DBA gdb can be the tool useful in their routine work, NOT only while studying core dumps.
In the following blog posts in this series I'll get back to studying source code and will try to work with MySQL 5.7 in a similar way. Stay tuned!