LOAD DATA LOCAL INFILE ~ REPLACE INTO と時々ロックでしっかり沼った

はじめに
- 書きながら思ったこと
- 検証環境
検証する
おわりに

はじめに

どうも、最近よく主要人物が闇落ちする映像作品を薦められがちなけんつです。最近色々あって LOAD DATA LOCAL INFILE ~ REPLACE INTO ~ を呼んだときにどういった処理が走るのか、特に metadata lock 周りが気になったのでそれについて書きます。大層ご立派なことを書いているが、完全にメモである。ブログ書きながら読める分量じゃなかった。
そして余談だが、どこで何のロックがかかっているのかを知りたい時が最近多すぎる。

書きながら思ったこと

本当は InnoDB まで見ようと思ったが思いの外手強かったので metadata lock 周りが中心になりそう。むしろ metadata lock も全部読めているか怪しい。

検証環境

Ubuntu 22.04
MySQL 8.0.33

検証する

前提

LOAD DATA INFILE を実行した場合に通過するコードパスがわからなかったので、以下の test, result ファイルを用意して mtr を実行し debug trace を取得する。

create table t1(id int)Engine=InnoDB;
insert into t1(id) values(1),(2),(3),(4);
load data infile '../../std_data/hoge.csv' replace into table t1 fields terminated by ',';
drop table t1;

create table t1(id int)Engine=InnoDB;
insert into t1(id) values(1),(2),(3),(4);
load data infile '../../std_data/hoge.csv' replace into table t1 fields terminated by ',';
drop table t1;

また std_data 以下に適当な名前の csv ファイルを追加し、以下の内容とする。

1
2
3

コードパスを掴む

コードパスがわからないとどこを見れば良いかわからないので debug trace, gdb とにらめっこしながらどこを通過するのか、ということからまず調べる必要がある。
debug trace を見ていると以下のような処理がいくつか流れていることがわかる。

...
T@11: | | | | >Sql_cmd_load_table::execute_inner
T@11: | | | | | >THD::set_current_stmt_binlog_format_row_if_mixed
T@11: | | | | | <THD::set_current_stmt_binlog_format_row_if_mixed
T@11: | | | | | >open_and_lock_tables
T@11: | | | | | | >open_tables
T@11: | | | | | | | THD::enter_stage: 'Opening tables' /home/lrf141/mysqlProject/mysql-server/sql/sql_base.cc:5795
T@11: | | | | | | | >PROFILING::status_change
T@11: | | | | | | | <PROFILING::status_change
T@11: | | | | | | | >open_and_process_table
T@11: | | | | | | | | >debug_sync
T@11: | | | | | | | | | debug_sync_point: hit: 'open_and_process_table'
T@11: | | | | | | | | <debug_sync
T@11: | | | | | | | | tcache: opening table: 'test'.'file_tbl'  item: 0x7f3d4c29f008
T@11: | | | | | | | | >ha_innobase::update_thd
T@11: | | | | | | | | | ha_innobase::update_thd: user_thd: 0x7f3d4c5a9a30 -> 0x7f3d4c5a9a30
T@11: | | | | | | | | | >innobase_trx_init
T@11: | | | | | | | | | <innobase_trx_init
T@11: | | | | | | | | <ha_innobase::update_thd
T@11: | | | | | | | <open_and_process_table
T@11: | | | | | | | >debug_sync
T@11: | | | | | | | | debug_sync_point: hit: 'open_tables_after_open_and_process_table'
T@11: | | | | | | | <debug_sync
T@11: | | | | | | | open_tables: returning: 0
T@11: | | | | | | <open_tables
T@11: | | | | | | >lock_tables
...

コードパスはわからないとしても write_row は通過するはずと、ha_innobase::write_row にブレークポイントを貼って更に実行する。
すると以下の back trace となる。

(gdb) bt
#0  ha_innobase::write_row (this=0x7fff3c125620, record=0x7fff3c00f1f0 "\375\001")
    at /home/lrf141/mysqlProject/mysql-server/storage/innobase/handler/ha_innodb.cc:8972
#1  0x000055555917c6f2 in handler::ha_write_row (this=0x7fff3c125620, 
    buf=0x7fff3c00f1f0 "\375\001")
    at /home/lrf141/mysqlProject/mysql-server/sql/handler.cc:7953
#2  0x0000555559529e78 in write_record (thd=0x7fff3c001050, table=0x7fff3c0f54d0, 
    info=0x7fffd85f2ef0, update=0x0)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_insert.cc:1811
#3  0x0000555559534cc4 in Sql_cmd_load_table::read_sep_field (this=0x7fff3c11ed28, 
    thd=0x7fff3c001050, info=..., table_list=0x7fff3c11ee60, read_info=..., enclosed=..., 
    skip_lines=0) at /home/lrf141/mysqlProject/mysql-server/sql/sql_load.cc:1109
#4  0x0000555559532d19 in Sql_cmd_load_table::execute_inner (this=0x7fff3c11ed28, 
    thd=0x7fff3c001050, handle_duplicates=DUP_REPLACE)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_load.cc:570
#5  0x00005555595390df in Sql_cmd_load_table::execute (this=0x7fff3c11ed28, 
    thd=0x7fff3c001050) at /home/lrf141/mysqlProject/mysql-server/sql/sql_load.cc:2147
#6  0x0000555558d4edfb in mysql_execute_command (thd=0x7fff3c001050, first_level=true)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:3683
#7  0x0000555558d5491d in dispatch_sql_command (thd=0x7fff3c001050, 
    parser_state=0x7fffd85f49f0)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:5363
#8  0x0000555558d49da3 in dispatch_command (thd=0x7fff3c001050, com_data=0x7fffd85f5340, 
    command=COM_QUERY) at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:2050
#9  0x0000555558d47c0d in do_command (thd=0x7fff3c001050)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:1439
#10 0x0000555558f94937 in handle_connection (arg=0x55556093e800)
    at /home/lrf141/mysqlProject/mysql-server/sql/conn_handler/connection_handler_per_thread.cc:302
#11 0x000055555b22f9fe in pfs_spawn_thread (arg=0x555560dde4b0)
    at /home/lrf141/mysqlProject/mysql-server/storage/perfschema/pfs.cc:3042
#12 0x00007ffff7294ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#13 0x00007ffff7326a40 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Sql_cmd_load_table::execute_inner から先はメソッド名を見るに、各 field を読み込みながらストレージエンジンの write_row を呼び出すという流れになっていると読み取れる。
次に、念の為 ha_innobase::write_row を通過するときに引数として渡ってくるバイナリ列を見る。

(gdb) b ha_innobase::write_row
Breakpoint 3 at 0x55555a614e14: file /home/lrf141/mysqlProject/mysql-server/storage/innobase/handler/ha_innodb.cc, line 8972.
(gdb) c
Continuing.
InnoDB: ###### Diagnostic info printed to the standard error stream

Thread 48 "connection" hit Breakpoint 3, ha_innobase::write_row (this=0x7fff3c125620, record=0x7fff3c00f1f0 "\375\001") at /home/lrf141/mysqlProject/mysql-server/storage/innobase/handler/ha_innodb.cc:8972
8972	{

// 一回目の write_row
(gdb) p *(record)
$9 = 253 '\375'
(gdb) p *(record + 1)
$10 = 1 '\001'

// 二回目の write_row
(gdb) p *(record + 0)
$12 = 253 '\375'
(gdb) p *(record + 1)
$13 = 2 '\002'

// 三回目の write_row
(gdb) p *(record + 0)
$14 = 253 '\375'
(gdb) p *(record + 1)
$15 = 3 '\003'

handler::write_row の引数で渡ってくるバイト列は Row Format になっていて、この場合先頭 1 byte は null bitmap で次の 4 byte が test, result ファイルで宣言した INT カラムの値となっている。
また、ここで四回止まるなら最初に 1~4 を INSERT している部分であるが、三回しか止まらないので前もって用意した csv ファイルの中身が insert される瞬間であるということがわかる。

というわけで Sql_cmd_load_table::execute_inner から先を読んでいけば良いということがわかった。

ちょっと気合を入れて読んでいく

というわけでこのあたりから元気に読んでいく。
https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_load.cc#L192-L201

まず最初に気になるのはここ。

  /*
    Bug #34283
    mysqlbinlog leaves tmpfile after termination if binlog contains
    load data infile, so in mixed mode we go to row-based for
    avoiding the problem.
  */
  thd->set_current_stmt_binlog_format_row_if_mixed();

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_load.cc#L226-L232

これの中身を追っていくと、ここにたどり着く

    if ((variables.binlog_format == BINLOG_FORMAT_MIXED) && (in_sub_stmt == 0))
      set_current_stmt_binlog_format_row();

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_class.h#L3396-L3397

inline void set_current_stmt_binlog_format_row() {
    DBUG_TRACE;
    current_stmt_binlog_format = BINLOG_FORMAT_ROW;
    return;
  }

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_class.h#L3401-L3405

binlog_format が MIXED になっている場合で、trigger か stored function の場合は ROW を設定している。
これは
MySQL Bugs: #34283: mysqlbinlog leaves tmpfile after termination if binlog contains load data infile
このバグが関連していて、mysqlbinlog が生成する tmp ファイルが残らないようにするための措置っぽい雰囲気を感じる。が、今はこれは主題ではないのでこのぐらいにする。2008 年頃からずっとあるみたいだし。

これの後は LOAD DATA INFILE で与えられているセパレータなどの文字列が ascii かどうかを確認しているが、これも今回見たいことではないので一旦飛ばす。
もし具体的にどんな値が渡されているかをみたい時は is_ascii() が呼び出されている各変数の m_ptr を参照すれば見ることができる。

次はいよいよ面白くなってきて lock 周りに突入するこの部分。

  if (open_and_lock_tables(thd, table_list, 0)) return true;

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_load.cc#L248

これを追っていくと、以下の関数にたどり着く。ここではテーブルを開いてロックをかけるという流れになっているので、それぞれ見ていく。

/**
  Open all tables in list, locks them and optionally process derived tables.

  @param thd		      Thread context.
  @param tables	              List of tables for open and locking.
  @param flags                Bitmap of options to be used to open and lock
                              tables (see open_tables() and mysql_lock_tables()
                              for details).
  @param prelocking_strategy  Strategy which specifies how prelocking algorithm
                              should work for this statement.

  @note
    The thr_lock locks will automatically be freed by close_thread_tables().

  @note
    open_and_lock_tables() is not intended for open-and-locking system tables
    in those cases when execution of statement has started already and other
    tables have been opened. Use open_trans_system_tables_for_read() instead.

  @retval false  OK.
  @retval true   Error
*/

bool open_and_lock_tables(THD *thd, Table_ref *tables, uint flags,
                          Prelocking_strategy *prelocking_strategy) {

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_base.cc#L6542-L6565

この関数をざっと読んでいくと open_table, lock_table という実にそれらしい関数を呼び出しているので、その２つを重点的に読んでいく。
まずは open_table から。

open_table に関する実装をデバッグしながら読んでいくと、まずは以下の実装にたどり着く。

      Table_ref *table;
      if (lock_table_names(thd, *start, thd->lex->first_not_own_table(),
                           ot_ctx.get_timeout(), flags)) {
        error = true;
        goto err;
      }
      for (table = *start; table && table != thd->lex->first_not_own_table();
           table = table->next_global) {
        if (table->mdl_request.is_ddl_or_lock_tables_lock_request() ||
            table->open_strategy == Table_ref::OPEN_FOR_CREATE)
          table->mdl_request.ticket = nullptr;
      }

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_base.cc#L5825-L5836

なんとなく metadata lock に関するであろう処理がいくつかあるが、ここで重要になるのは lock_table_names。
何故かというと lock_table_names を読んでいると LOCK TABLES か DDL によって発生する metadata lock を取得するとあるため。

/**
  Acquire "strong" (SRO, SNW, SNRW) metadata locks on tables used by
  LOCK TABLES or by a DDL statement.

  Acquire lock "S" on table being created in CREATE TABLE statement.

  @note  Under LOCK TABLES, we can't take new locks, so use
         open_tables_check_upgradable_mdl() instead.

  @param thd               Thread context.
  @param tables_start      Start of list of tables on which locks
                           should be acquired.
  @param tables_end        End of list of tables.
  @param lock_wait_timeout Seconds to wait before timeout.
  @param flags             Bitmap of flags to modify how the tables will be
                           open, see open_table() description for details.
  @param schema_reqs       When non-nullptr, pointer to array in which
                           pointers to MDL requests for acquired schema
                           locks to be stored. It is guaranteed that
                           each schema will be present in this array
                           only once.

  @retval false  Success.
  @retval true   Failure (e.g. connection was killed)
*/
bool lock_table_names(THD *thd, Table_ref *tables_start, Table_ref *tables_end,

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_base.cc#L5357-L5382

ここのコメントはとてもよく書かれていて、以下の手順でロックを取得する

対象テーブルの一意な Schema Set を作成する
Schema Set に対して Insert Intention Lock を設定する
ここまでに設定したロックを取得する
tablespace 名をロックする

最初の手順は良いとしても、その後にやってくる３つの手順に関しては実装を読みながらでないと自分で書いていても何を言っているかわからなくなる。
ざっくりとまとめるなら 2, 3 はある意味ではひとまとまりになっていて、2 が IX を各オブジェクトに設定し、3 で実際にロックを取得するという流れになっている。
そして最もよくわからなかった 4 についてだが、これは tablespace 名をロックしたいがそれには data dictionary を参照する必要があり、data dictionary を参照するには schema の metadata lock が必要になる、という事情があるらしい。

  /*
    Phase 4: Lock tablespace names. This cannot be done as part
    of the previous phases, because we need to read the
    dictionary to get hold of the tablespace name, and in order
    to do this, we must have acquired a lock on the table.
  */
  return get_and_lock_tablespace_names(thd, tables_start, tables_end,
                                       lock_wait_timeout, flags);

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_base.cc#L5506-L5512

この部分はこの程度で終わらせてしまっても良いが延々とコメントを引用しただけになってしまうので、忘れないために metadata lock を実装ではどうやって取得するかに少しだけ言及する。
まずここまでに挙げた実装を眺めると、やたら MDL_ という文字列を見かけるがこれは大体 metadata lock に関する情報を扱うデータ構造だったりする。
そして特に自分が理解するのに必要だったのは Phase 2 で、特に以下の部分。

    for (const Table_ref *table_l : schema_set) {
      MDL_request *schema_request = new (thd->mem_root) MDL_request;
      if (schema_request == nullptr) return true;
      MDL_REQUEST_INIT(schema_request, MDL_key::SCHEMA, table_l->db, "",
                       MDL_INTENTION_EXCLUSIVE, MDL_TRANSACTION);
      mdl_requests.push_front(schema_request);
      if (schema_reqs) schema_reqs->push_back(schema_request);
    }

https://github.com/mysql/mysql-server/blob/mysql-8.0.33/sql/sql_base.cc#L5454-L5465

mdl_requests というのは要求したい metadata lock のリストとなっている。ここに突っ込んだ情報を元に Phase 3 で metadata lock が取得される。
そして次に面白かったのが MDL_REQUEST_INIT という謎マクロ。特にその引数は面白かった。
何が面白いかというと、MDL_INTENTION_EXCLUSIVE が IX を示していて、MDL_TRANSACTION が設定されているのでトランザクションの終了と共に自動で metadata lock が開放されるという風になっていること。思ったよりロックの寿命が長かった。だいぶ長かった。

というわけでこの後はいつものテーブルを元気に開くやつがやってくる。ここでも metadata lock 周りでなんかやっている雰囲気はあるが、一旦放置で。
信じられないことにここまでが open_table の内容である…。

この後は open_table と対になっている lock_table がやってくる。ここを読み切る気力はもうすでに失われたので、将来の自分のために backtrace だけ貼っておく。
読み切る気力がなくなったのは metadata lock の読解でもうだいぶカロリーを使った上に lock_table がやっているのは ha_innobase::external_lock を呼び出すことなので次回に持ち越し。どのみち自作ストレージエンジンのために一度は読む必要があるので。

(rr) bt
#0  ha_innobase::external_lock (this=0x7fc0b04587c0, thd=0x7fc0b0025f70, lock_type=1)
    at /home/lrf141/mysqlProject/mysql-server/storage/innobase/handler/ha_innodb.cc:18583
#1  0x000055f86b1e815a in handler::ha_external_lock (this=0x7fc0b04587c0, 
    thd=0x7fc0b0025f70, lock_type=1)
    at /home/lrf141/mysqlProject/mysql-server/sql/handler.cc:7884
#2  0x000055f86b46a167 in lock_external (thd=0x7fc0b0025f70, tables=0x7fc0b04545d8, count=1)
    at /home/lrf141/mysqlProject/mysql-server/sql/lock.cc:393
#3  0x000055f86b469de5 in mysql_lock_tables (thd=0x7fc0b0025f70, tables=0x7fc0b06f6290, 
    count=1, flags=0) at /home/lrf141/mysqlProject/mysql-server/sql/lock.cc:337
#4  0x000055f86ac975a4 in lock_tables (thd=0x7fc0b0025f70, tables=0x7fc0b06f5830, count=1, 
    flags=0) at /home/lrf141/mysqlProject/mysql-server/sql/sql_base.cc:6899
#5  0x000055f86ac96b84 in open_and_lock_tables (thd=0x7fc0b0025f70, tables=0x7fc0b06f5830, 
    flags=0, prelocking_strategy=0x7fc089be6d60)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_base.cc:6593
#6  0x000055f86abec248 in open_and_lock_tables (thd=0x7fc0b0025f70, tables=0x7fc0b06f5830, 
    flags=0) at /home/lrf141/mysqlProject/mysql-server/sql/sql_base.h:470
#7  0x000055f86b59d818 in Sql_cmd_load_table::execute_inner (this=0x7fc0b06f56f8, 
    thd=0x7fc0b0025f70, handle_duplicates=DUP_REPLACE)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_load.cc:248
#8  0x000055f86b5a50df in Sql_cmd_load_table::execute (this=0x7fc0b06f56f8, 
    thd=0x7fc0b0025f70) at /home/lrf141/mysqlProject/mysql-server/sql/sql_load.cc:2147
#9  0x000055f86adbadfb in mysql_execute_command (thd=0x7fc0b0025f70, first_level=true)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:3683
#10 0x000055f86adc091d in dispatch_sql_command (thd=0x7fc0b0025f70, 
    parser_state=0x7fc089be89f0)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:5363
#11 0x000055f86adb5da3 in dispatch_command (thd=0x7fc0b0025f70, com_data=0x7fc089be9340, 
    command=COM_QUERY) at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:2050
#12 0x000055f86adb3c0d in do_command (thd=0x7fc0b0025f70)
    at /home/lrf141/mysqlProject/mysql-server/sql/sql_parse.cc:1439
#13 0x000055f86b000937 in handle_connection (arg=0x55f87418e1b0)
    at /home/lrf141/mysqlProject/mysql-server/sql/conn_handler/connection_handler_per_thread.cc:302
#14 0x000055f86d29b9fe in pfs_spawn_thread (arg=0x55f874192080)
    at /home/lrf141/mysqlProject/mysql-server/storage/perfschema/pfs.cc:3042
#15 0x00007fc0c8c94ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#16 0x00007fc0c8d25bf4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100

おわりに

というわけでハイパー駆け足になったが metadata lock を中心に理解が深まった部分がいくつかある。特に metadata lock がどういう処理で取得されているか、取得までに必要な諸々のデータ構造についてわかったのはでかい。
そしてまだちゃんとデバッグしたわけではないが LOAD DATA LOCAL INFILE ~ REPLACE INTO は普通に data_locks を眺めていると

インテンションロックの取得
InnoDB でギャップロック取得
1. write_row が指定したファイルの行数分呼ばれているのでおそらく普通の INSERT と同じ挙動をしている

という風になっている。はず。

というわけで次回作にご期待ください。

それが僕には楽しかったんです。

僕と MySQL と時々 MariaDB