Tuesday, January 5, 2016

Exploring Metadata Locks with gdb - First Steps

Metadata locks are used in MySQL since version 5.5.3 and are available in GA MySQL versions for 6 years already. Still they are far from clearly documented (even less their implementation is documented in details - try to find anything about metadata locks in current MySQL Internals manual) and often causes "unexpected" problems for users.

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!

3 comments: