Hatena::ブログ(Diary)

ablog このページをアンテナに追加 RSSフィード

2018-04-27

MySQL の slow query log を Percona Toolkit の pt-query-digest で整形する

環境


インストール

% brew install percona-toolkit

使ってみる

  • pt-query-digest で slow query log を集計する。
% pt-query-digest mysql-slowquery.log.2018-04-27.09 > mysql-slowquery.log.2018-04-27.09-pt.txt
mysql-slowquery.log.2018-04-27.09:   9% 04:39 remain
mysql-slowquery.log.2018-04-27.09:  23% 03:16 remain
mysql-slowquery.log.2018-04-27.09:  45% 01:48 remain
mysql-slowquery.log.2018-04-27.09:  72% 00:44 remain
mysql-slowquery.log.2018-04-27.09:  93% 00:10 remain
  • 集計結果を確認する
% less  mysql-slowquery.log.2018-04-27.09-pt.txt
# 150.8s user time, 1.8s system time, 59.41M rss, 2.38G vsz
# Current date: Fri Apr 27 23:28:57 2018
# Hostname: ******
# Files: mysql-slowquery.log.2018-04-27.09
# Overall: 413.58k total, 977 unique, 114.91 QPS, 30.16x concurrency _____
# Time range: 2018-04-27 08:00:02 to 09:00:01
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time        108556s    38us     56s   262ms   640ms   814ms    51ms
# Lock time        129127208518408s       0 18446744073710s 312221233s    30ms 75048244001s    89us
# Rows sent         35.25M       0 169.78k   89.37   28.75   1.61k    0.99
# Rows examine      19.10G       0   9.28M  48.42k  97.04k 279.61k   19.46
# Query size       509.74M      24 742.43k   1.26k   2.38k  21.67k  381.65

# Profile
# Rank Query ID           Response time    Calls  R/Call  V/M   Item
# ==== ================== ================ ====== ======= ===== ==========
#    1 0x959A21D964B0B02E 10676.2713  9.8%   1538  6.9417  1.62 SELECT ...
#    2 0x7D68C5021733113C 10338.2087  9.5%   1537  6.7262  1.57 SELECT ...
#    3 0xF22F26C61E850C7F  9187.9306  8.5%  22197  0.4139  0.03 SELECT ...
#    4 0x864A6BD8BB56F3FC  7608.9758  7.0%  18397  0.4136  0.03 SELECT ....

見方

# 210ms user time, 40ms system time, 26.75M rss, 202.94M vsz
# Current date: Thu Mar 24 18:41:21 2016
# Hostname: xxxx
# Files: /usr/mysql/5.7.11/data/slow.log
# Overall: 119 total, 8 unique, 0 QPS, 0x concurrency ____________________
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          272ms     9us    32ms     2ms     2ms     3ms     2ms
# Lock time           21ms       0     8ms   177us    89us   865us    54us
# Rows sent            510       0     104    4.29       0   19.93       0
# Rows examine         510       0     104    4.29       0   19.93       0
# Query size        17.17k      10     164  147.74  158.58   41.54  158.58

最初のセクションはスローログ全体を俯瞰した様子です。Exec time(スローログ上ではQuery_time), Lock time, Rows sent, Rows examineなど、スローログに書き込まれている情報を集計した情報が書き出されています。

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0xCAEC22E79B0EFD3B  0.2041 75.2%   105 0.0019  0.00 INSERT t?
#    2 0x35AAC71503957920  0.0322 11.9%     1 0.0322  0.00 FLUSH
#    3 0x0C922D63DA1D917B  0.0216  8.0%     1 0.0216  0.00 CREATE TABLE t? `t1`
#    4 0x5722277F9D796D79  0.0107  3.9%     2 0.0053  0.01 DROP
# MISC 0xMISC              0.0029  1.1%    10 0.0003   0.0 <4 ITEMS>

次のセクションには、クエリー単位でノーマライズ・集計された結果が並びます。pt-query-digestはスローログを処理する際にリテラルノーマライズします。column1 = 1やcolumn1 = 2といった数値リテラルはcolumn1 = Nという形に丸められ、同じクエリーとして扱われます(カラム名の数字は丸められないため、数字が入っているカラム名を利用していてもカラムが違えば識別される)。

また、文字列リテラルや行リテラルノーマライズされますので、個々のクエリーのパラメーターの差異によらずに全体としての傾向を掴めます。このセクションでのクエリーはデフォルトでは「各ノーマライズされたクエリーごとのQuery_timeの和」の降順で並べられています。これは --order-by オプションで変更できます。

Response timeはQuery_timeの和とスローログ全体におけるそのクエリーの占めるパーセンテージが出力されます。Callsはクエリーが実行された回数、R/Callは Response time / Call (平均値)、V/Mは標準偏差です。Itemにはクエリーのサマリーが表示されます。時間がかかっている(R/Callが大きい)クエリーでも稀にしか実行されないものである場合、チューニング対象としてはちょっと不足気味です(たとえば、年に1回しか実行されないクエリーを10秒速くすることにあまり意味はない)。また、時間の累計(Response time)が大きいクエリーである場合でもR/Callが十分小さい場合はスピードアップは困難かも知れません(10秒のクエリーを10%速くすることと、10msのクエリーを10%速くすることでは後者の方が難易度が高い)。

実際のスローログを pt-query-digest に集計させた場合、結果サイズはそれなりに大きくなります。全てを見ていくにも時間がかかりますので、このセクションで目ぼしいクエリーにあたりをつけ、Query ID(ノーマライズされたステートメントから計算されるハッシュ値)を検索する方法がお勧めです。

# Query 1: 0 QPS, 0x concurrency, ID 0xCAEC22E79B0EFD3B at byte 2247 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         88     105
# Exec time     75   204ms     1ms     3ms     2ms     2ms   319us     2ms
# Lock time     32     7ms    37us   589us    64us    76us    57us    54us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    97  16.75k     160     164  163.33  158.58    0.00  158.58
# String:
# Databases    mysqlslap
# Hosts        localhost
# Time         2016-03-24... (1/0%), 2016-03-24... (1/0%)... 103 more
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `mysqlslap` LIKE 't1'\G
#    SHOW CREATE TABLE `mysqlslap`.`t1`\G
INSERT INTO t1 VALUES (1308044878,'50w46i58Giekxik0cYzfA8BZBLADEg3JhzGfZDoqvQQk0Akcic7lcJInYSsf9wqin6LDC1vzJLkJXKn5onqOy04MTw1WksCYqPl2Jg2eteqOqTLfGCvE4zTZwWvgMz')\G

3つ目のセクションからは、クエリー単位の個別の集計結果が表示されます。1行目にQuery IDが含まれているため、2つ目のセクションで表示されていたQuery IDを検索すると個別クエリーのセクションの先頭行に行けるようになっています。

筆者はここで Rows examine / Rows sent の値をよく計算します。GROUP BYを使っている場合を除けばRows examine / Rows sentの値が1に近い(小さい)ほど効率良くインデックスで WHERE 句を処理できているからです。1に近いほどインデックス以外の箇所でSQLチューニングしなければならないため時間がかかり、1から遠いほどインデックスの追加で劇的に速くなる可能性があるため、効率良くチューニングできる可能性が高まります。

またRows sentやRows examine、Exec timeに大きなバラつきがあり相関しているように見える場合、WHERE句の条件によって結果セットの大きさが大幅に変化していることが考えられます。転送された結果セットが本当に全てアプリケーション側で利用されているかを確認すると良いでしょう(本当に使われていた場合はどうしようもないが)。

Rows sent、Rows examine、Lock timeにバラつきが少ないにも関わらずExec timeにバラつきがある場合は、バッファプールのヒット率が悪いことなどが考えられます(MyISAMストレージエンジンのテーブルであればこの限りではない)。InnoDBバッファプールはSELECTのみでなくINSERTやDELETEの際にも利用されます。またInnoDBのテーブル圧縮を使用している場合、バッファプールミスヒットのコストは無圧縮状態に比べて非常に高くなるため注意が必要です。バッファプールの他にもテーブルキャッシュが足りなくなっていないかなども考慮する必要があります。

Timeの行は本来であれば「そのクエリーが最初に現れた時間」と「そのクエリーが最後に現れた時間」を表示しますが、残念ながらMySQL 5.7系列のスローログには対応していません。バッチなどによる一過性のスローログなのか、継続的なものか、あるいはもう既に修正されたもの(最後に現れた時間が十分過去)なのかをチェックしておきましょう。

最後の行は、このチェックサムのクエリーのうちサンプルとして1件、ノーマライズしていないクエリーを表示します。EXPLAINや実際に実行する時にそのままコピー&ペーストできます。

スローログの集計に便利な「pt-query-digest」を使ってみよう | Think IT(シンクイット)

参考

2018-03-25

MySQL のストレージエンジンとのインタフェース

どの当たりのコードか当たりをつけ中。


  • Interaction of the Core Modules
    • Figure 1-1. High-level view of MySQL modules

f:id:yohei-a:20180325184159p:image:w360

ABSTRACTED STORAGE ENGINE INTERFACE (TABLE HANDLER)

This module is actually an abstract class named handler and a structure called a handlerton. The handlerton structure was added in version 5.1 for plug-in integration. It provides a standardized interface to perform low-level storage and retrieval operations.

The table hander is defined in sql/handler.h and partially implemented in sql/handler.cc. The derived specific storage engine classes will have to implement all the pure virtual methods of this class. It will be discussed in greater detail in Chapter 9.

This module was introduced in version 3.23 to facilitate the integration of Berkeley DB tables. This move had far-reaching consequences: now a variety of low-level storage engines could be put underneath MySQL with a fair amount of ease. The code was further refined during the integration of InnoDB. The future of the module will largely depend on what new storage engines will be integrated into MySQL, and on the way the existing ones will change. For example, sometimes a new feature in some underlying storage engine may require an addition to the abstracted interface to make it available to the higher-level modules.

Shared Aspects of Architecture

While there is a great degree of freedom in the implementation of a storage engine, all storage engines must integrate with the main MySQL server code. As a result they have a few things in common. Aside from having to support the basic concepts of tables residing in a database, records, columns, keys, read and write operations, and other aspects stipulated by the storage engine interface requirements, each storage engine also inherits the features and properties from the core table manipulation code. In other words, they get some functionality and architecture regardless of whether they need it.

Regardless of the storage engine, all tables have one .frm file per table containing the table definition with the column names, their types and sizes, key information, and other table properties. A .frm file in essence gathers and stores the information from CREATE TABLE. Up until version 5.1 the filename was always the same as the name of the table, and it resided in a directory corresponding to the database name. Version 5.1 introduced a change. The table and database name are now encoded in build_ table_filename( ) in sql/sql_table.cc. Code reads and parses the files using openfrm( ) from sql/table.cc, and writes to them using create_frm( ) from the same source file.

Regardless of the storage engine, the server reads the table definition from the .frm file, and stores it in what is called a table cache. This way, the next time the table needs to be accessed, the server does not have to reread and reparse the .frm file, but rather can use the cached information.

MySQL server utilizes the mechanism of table locking. Thus, each storage engine can either take advantage of this feature, or politely ask the table lock manager to always grant a write lock, which bypasses the core code table locking. In that case, the storage engine itself becomes responsible for ensuring consistency during concurrent access.

2018-03-10

MySQL InnoDB で大きなトランザクションを見つける

SHOW ENGINE INNODB STATUS の

  • History list length が MySQL インスタンス全体の UNDO ページ数
  • undo log entries がトランザクション毎のUNDOレコード数

で、History list length が大きいとMySQLインスタンス全体での UNDO のサイズが大きくなりロールバックにかかる時間が長くなっており、undo log entries が大きいトランザクションが UNDO ページを大量に使っている犯人だと類推できる。undo log entries は insert/update/delete などを行った行数(未コミット)でサイズではない。

MariaDB 5.5.27以降10未満(XtraDB)では Information Schema の INNODB_UNDO_LOGS. SIZE で undo log が使っているサイズを確認できる。


  • テーブルを作成する
> create table undo_test(
	col1 char(255),
	col2 char(255),
	col3 char(255),
	col4 char(255),
	col5 char(255)
);
  • 1行 insert する
> start transaction;
> insert into undo_test(col1) values('1');
  • トランザクションが使っているUNDOの量を調べる
> show engine innodb stauts\G
(中略)
------------
TRANSACTIONS
------------
TRANSACTIONS
------------
Trx id counter 111207046
Purge done for trx's n:o < 111206999 undo n:o < 0 state: running but idle
History list length 719 ★ history list length がインスタンス全体のUNDOページ数
LIST OF TRANSACTIONS FOR EACH SESSION:
(中略)
---TRANSACTION 111207036, ACTIVE 2 sec ★2秒経過
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1 ★1行insertしたので、undo log が 1になっている
MySQL thread id 8697(★スレッドID), OS thread handle 0x2b9eb4b47700, query id 1400669 27.0.3.145(★接続元IP) awsuser(★ユーザー名) delayed send ok done
  • 5行 insert する
> start transaction;
> insert into undo_test(col1) values('2');
> insert into undo_test(col1) values('3');
> insert into undo_test(col1) values('4');
> insert into undo_test(col1) values('5');
  • 行数を確認する
> select count(1) from undo_test;
+----------+
| count(1) |
+----------+
|        5 |
+----------+
1 row in set (0.01 sec)
  • トランザクションが使っているUNDOの量を調べる
> show engine innodb stauts\G
(中略)
------------
TRANSACTIONS
------------
Trx id counter 111207337
Purge done for trx's n:o < 111206999 undo n:o < 0 state: running but idle
History list length 808
LIST OF TRANSACTIONS FOR EACH SESSION:
(中略)
---TRANSACTION 111207036, ACTIVE 58 sec ★58秒経過
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 5 ★5行insertしたので、undo log が 5 になっている
MySQL thread id 8697, OS thread handle 0x2b9ef9e43700, query id 1400956 27.0.3.145 awsuser cleaned up
Trx read view will not see trx with id >= 111207290, sees < 111207036
  • セッションを kill する
> call mysql.rds_kill(8697); ★show engine innodb stauts の TRANSACTIONS に表示されていた MySQL thread id 
  • トランザクションが終了していることを確認する
> show engine innodb status\G
(中略)
------------
TRANSACTIONS
------------
Trx id counter 111208582
Purge done for trx's n:o < 111206999 undo n:o < 0 state: running but idle
History list length 726
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 111208485, not started
MySQL thread id 8719, OS thread handle 0x2b9eb4a43700, query id 1402459 localhost rdsadmin cleaned up
---TRANSACTION 111205044, not started
MySQL thread id 8664, OS thread handle 0x2b9eb4bc9700, query id 1402491 27.0.3.145 awsuser System lock
show engine innodb status
---TRANSACTION 111208058, not started
MySQL thread id 11, OS thread handle 0x2b9eb37ed700, query id 1401866 localhost rdsadmin delayed send ok done
---TRANSACTION 111208576, not started
MySQL thread id 2, OS thread handle 0x2b9eb4a43700, query id 1402490 localhost rdsadmin delayed send ok done
★トランザクションがなくなっている

参考

Global history and purge operations

In addition to every record having a reference to its previous version, there is also a global view of the history of the entire database, called the “history list”. As each transaction is committed, its history is linked into this global history list in transaction serialization (commit) order. The history list is used primarily for cleaning up after a transaction, once no existing read view still needs its history (all other transactions have completed).

In the background, InnoDB runs a continuous “purge” process which is responsible for two things:

  • Actually deleting delete-marked records2, if the current version of the record in the index at the time of purge is still delete-marked and bears the same transaction ID. (That is, the record hasn’t been re-inserted.)
  • Freeing undo log pages and unlinking them from the global history list to make them available for re-use.

InnoDB exposes the total amount of history present in the system as a “History list length”, which can be seen in SHOW ENGINE INNODB STATUS. This is the count of all database modifications present in the undo logs, in units of undo logs (which may contain a single record modification or many).

The basics of the InnoDB undo logging and history system – Jeremy Cole

XtraDB は Information Schema の INNODB_UNDO_LOGS. SIZE(Size in pages of the segment) で undo log が使っているサイズが分かる。MariaDB 5.5.27 で入って、10では削除されてる。

Information Schema INNODB_UNDO_LOGS Table

The Information Schema INNODB_UNDO_LOGS table is a Percona enchancement, and is only available for XtraDB, not InnoDB (see XtraDB and InnoDB). It contains information about the the InnoDB undo log, with each record being an undo log segment. It was removed in MariaDB 10.0.

It has the following columns:

  • ColumnDescription
  • TRX_ID: Unique transaction ID number, matching the value from the information_schema.INNODB_TRX table.
  • RSEG_ID: Rollback segment ID, matching the value from the information_schema.INNODB_RSEG table.
  • USEG_ID: Undo segment ID.
  • SEGMENT_TYPE: Indicates the operation type, for example INSERT or UPDATE.
  • STATE: Segment state: one of ACTIVE (contains active transaction undo log), CACHED, TO_FREE (insert undo segment can be freed), TO_PURGE (update undo segment won't be re-used and can be purged when all undo data is removed) or PREPARED (segment of a prepared transaction).
  • SIZE: Size in pages of the segment.
Information Schema INNODB_UNDO_LOGS Table - MariaDB Knowledge Base

ソースコード

  • mysql-5.6.10/storage/innobase/lock/lock0lock.cc
/*********************************************************************//**
Prints info of locks for all transactions.
@return FALSE if not able to obtain lock mutex
and exits without printing info */
UNIV_INTERN
ibool
lock_print_info_summary(
/*====================*/
        FILE*   file,   /*!< in: file where to print */
        ibool   nowait) /*!< in: whether to wait for the lock mutex */
{
        /* if nowait is FALSE, wait on the lock mutex,
        otherwise return immediately if fail to obtain the
        mutex. */
        if (!nowait) {
                lock_mutex_enter();
        } else if (lock_mutex_enter_nowait()) {
                fputs("FAIL TO OBTAIN LOCK MUTEX, "
                      "SKIP LOCK INFO PRINTING\n", file);
                return(FALSE);
        }

        if (lock_deadlock_found) {
                fputs("------------------------\n"
                      "LATEST DETECTED DEADLOCK\n"
                      "------------------------\n", file);

                if (!srv_read_only_mode) {
                        ut_copy_file(file, lock_latest_err_file);
                }
        }

        fputs("------------\n"
              "TRANSACTIONS\n"
              "------------\n", file);

        fprintf(file, "Trx id counter " TRX_ID_FMT "\n",
                trx_sys_get_max_trx_id());

        fprintf(file,
                "Purge done for trx's n:o < " TRX_ID_FMT
                " undo n:o < " TRX_ID_FMT " state: ",
                purge_sys->iter.trx_no,
                purge_sys->iter.undo_no);

        /* Note: We are reading the state without the latch. One because it
        will violate the latching order and two because we are merely querying
        the state of the variable for display. */

        switch (purge_sys->state){
        case PURGE_STATE_EXIT:
        case PURGE_STATE_INIT:
                /* Should never be in this state while the system is running. */
                ut_error;

        case PURGE_STATE_DISABLED:
                fprintf(file, "disabled");
                break;

        case PURGE_STATE_RUN:
                fprintf(file, "running");
                /* Check if it is waiting for more data to arrive. */
                if (!purge_sys->running) {
                        fprintf(file, " but idle");
                }
                break;

        case PURGE_STATE_STOP:
                fprintf(file, "stopped");
                break;
        }

        fprintf(file, "\n");

        fprintf(file,
                "History list length %lu\n",
                (ulong) trx_sys->rseg_history_len);

#ifdef PRINT_NUM_OF_LOCK_STRUCTS
        fprintf(file,
                "Total number of lock structs in row lock hash table %lu\n",
                (ulong) lock_get_n_rec_locks());
#endif /* PRINT_NUM_OF_LOCK_STRUCTS */
        return(TRUE);
}
  • mysql-5.6.10/storage/innobase/trx/trx0trx.cc
/**********************************************************************//**
Prints info about a transaction.
Caller must hold trx_sys->mutex. */
UNIV_INTERN
void
trx_print_low(
/*==========*/
        FILE*           f,
                        /*!< in: output stream */
        const trx_t*    trx,
                        /*!< in: transaction */
        ulint           max_query_len,
                        /*!< in: max query length to print,
                        or 0 to use the default max length */
        ulint           n_rec_locks,
                        /*!< in: lock_number_of_rows_locked(&trx->lock) */
        ulint           n_trx_locks,
                        /*!< in: length of trx->lock.trx_locks */
        ulint           heap_size)
                        /*!< in: mem_heap_get_size(trx->lock.lock_heap) */
{
        ibool           newline;
        const char*     op_info;

        ut_ad(mutex_own(&trx_sys->mutex));

        fprintf(f, "TRANSACTION " TRX_ID_FMT, trx->id);

        /* trx->state cannot change from or to NOT_STARTED while we
        are holding the trx_sys->mutex. It may change from ACTIVE to
        PREPARED or COMMITTED. */
        switch (trx->state) {
        case TRX_STATE_NOT_STARTED:
                fputs(", not started", f);
                goto state_ok;
        case TRX_STATE_ACTIVE:
                fprintf(f, ", ACTIVE %lu sec",
                        (ulong) difftime(time(NULL), trx->start_time));
                goto state_ok;
        case TRX_STATE_PREPARED:
                fprintf(f, ", ACTIVE (PREPARED) %lu sec",
                        (ulong) difftime(time(NULL), trx->start_time));
                goto state_ok;
        case TRX_STATE_COMMITTED_IN_MEMORY:
                fputs(", COMMITTED IN MEMORY", f);
                goto state_ok;
        }
        fprintf(f, ", state %lu", (ulong) trx->state);
        ut_ad(0);
state_ok:

        /* prevent a race condition */
        op_info = trx->op_info;

        if (*op_info) {
                putc(' ', f);
                fputs(op_info, f);
        }

        if (trx->is_recovered) {
                fputs(" recovered trx", f);
        }

        if (trx->declared_to_be_inside_innodb) {
                fprintf(f, ", thread declared inside InnoDB %lu",
                        (ulong) trx->n_tickets_to_enter_innodb);
        }

        putc('\n', f);

        if (trx->n_mysql_tables_in_use > 0 || trx->mysql_n_tables_locked > 0) {
                fprintf(f, "mysql tables in use %lu, locked %lu\n",
                        (ulong) trx->n_mysql_tables_in_use,
                        (ulong) trx->mysql_n_tables_locked);
        }

        newline = TRUE;

        /* trx->lock.que_state of an ACTIVE transaction may change
        while we are not holding trx->mutex. We perform a dirty read
        for performance reasons. */

        switch (trx->lock.que_state) {
        case TRX_QUE_RUNNING:
                newline = FALSE; break;
        case TRX_QUE_LOCK_WAIT:
                fputs("LOCK WAIT ", f); break;
        case TRX_QUE_ROLLING_BACK:
                fputs("ROLLING BACK ", f); break;
        case TRX_QUE_COMMITTING:
                fputs("COMMITTING ", f); break;
        default:
                fprintf(f, "que state %lu ", (ulong) trx->lock.que_state);
        }

        if (n_trx_locks > 0 || heap_size > 400) {
                newline = TRUE;

                fprintf(f, "%lu lock struct(s), heap size %lu,"
                        " %lu row lock(s)",
                        (ulong) n_trx_locks,
                        (ulong) heap_size,
                        (ulong) n_rec_locks);
        }

        if (trx->has_search_latch) {
                newline = TRUE;
                fputs(", holds adaptive hash latch", f);
        }

        if (trx->undo_no != 0) {
                newline = TRUE;
                fprintf(f, ", undo log entries "TRX_ID_FMT, trx->undo_no);
        }

        if (newline) {
                putc('\n', f);
        }

        if (trx->mysql_thd != NULL) {
                innobase_mysql_print_thd(f, trx->mysql_thd, max_query_len);
        }
}
  • mysql-5.6.10/storage/innobase/handler/ha_innodb.cc
/************************************************************************//**
Implements the SHOW ENGINE INNODB STATUS command. Sends the output of the
InnoDB Monitor to the client.
@return 0 on success */
static
int
innodb_show_status(
/*===============*/
        handlerton*     hton,   /*!< in: the innodb handlerton */
        THD*            thd,    /*!< in: the MySQL query thread of the caller */
        stat_print_fn*  stat_print)
{
        trx_t*                  trx;
        static const char       truncated_msg[] = "... truncated...\n";
        const long              MAX_STATUS_SIZE = 1048576;
        ulint                   trx_list_start = ULINT_UNDEFINED;
        ulint                   trx_list_end = ULINT_UNDEFINED;

        DBUG_ENTER("innodb_show_status");
        DBUG_ASSERT(hton == innodb_hton_ptr);

        /* We don't create the temp files or associated
        mutexes in read-only-mode */

        if (srv_read_only_mode) {
                DBUG_RETURN(0);
        }

        trx = check_trx_exists(thd);

        trx_search_latch_release_if_reserved(trx);

        innobase_srv_conc_force_exit_innodb(trx);

        /* We let the InnoDB Monitor to output at most MAX_STATUS_SIZE
        bytes of text. */

        char*   str;
        ssize_t flen, usable_len;

        mutex_enter(&srv_monitor_file_mutex);
        rewind(srv_monitor_file);

        srv_printf_innodb_monitor(srv_monitor_file, FALSE,
                                  &trx_list_start, &trx_list_end);

        os_file_set_eof(srv_monitor_file);

        if ((flen = ftell(srv_monitor_file)) < 0) {
                flen = 0;
        }

        if (flen > MAX_STATUS_SIZE) {
                usable_len = MAX_STATUS_SIZE;
                srv_truncated_status_writes++;
        } else {
                usable_len = flen;
        }

        /* allocate buffer for the string, and
        read the contents of the temporary file */

        if (!(str = (char*) my_malloc(usable_len + 1, MYF(0)))) {
                mutex_exit(&srv_monitor_file_mutex);
                DBUG_RETURN(1);
        }

        rewind(srv_monitor_file);

        if (flen < MAX_STATUS_SIZE) {
                /* Display the entire output. */
                flen = fread(str, 1, flen, srv_monitor_file);
        } else if (trx_list_end < (ulint) flen
                   && trx_list_start < trx_list_end
                   && trx_list_start + (flen - trx_list_end)
                   < MAX_STATUS_SIZE - sizeof truncated_msg - 1) {

                /* Omit the beginning of the list of active transactions. */
                ssize_t len = fread(str, 1, trx_list_start, srv_monitor_file);

                memcpy(str + len, truncated_msg, sizeof truncated_msg - 1);
                len += sizeof truncated_msg - 1;
                usable_len = (MAX_STATUS_SIZE - 1) - len;
                fseek(srv_monitor_file, flen - usable_len, SEEK_SET);
                len += fread(str + len, 1, usable_len, srv_monitor_file);
                flen = len;
        } else {
                /* Omit the end of the output. */
                flen = fread(str, 1, MAX_STATUS_SIZE - 1, srv_monitor_file);
        }

        mutex_exit(&srv_monitor_file_mutex);

        stat_print(thd, innobase_hton_name, (uint) strlen(innobase_hton_name),

        my_free(str);

        DBUG_RETURN(0);
}

参考

2018-03-04

sysbench で MySQL のベンチマークをとる

sysbench をインストールして MySQL のベンチマークをとる手順をメモ。


インストール

$ curl -s https://packagecloud.io/install/repositories/akopytov/sysbench/script.rpm.sh | sudo bash
$ sudo yum -y install sysbench mysql

ベンチマーク

  • 初期データロード
$ sysbench /usr/share/sysbench/oltp_read_write.lua \
 --db-driver=mysql \
 --table-size=100000 \
 --mysql-host=aurora01.*********.ap-northeast-1.rds.amazonaws.com \
 --mysql-user=awsuser \
 --mysql-password=********* \
 --mysql-db=mydb \
 --db-ps-mode=disable \
 prepare
  • ベンチマークを実行する。
$ sysbench /usr/share/sysbench/oltp_read_write.lua \
 --db-driver=mysql \
 --table-size=100000 \
 --mysql-db=mydb \
 --mysql-host=aurora01.*********.ap-northeast-1.rds.amazonaws.com \
 --mysql-user=awsuser \
 --mysql-password=********* \
 --time=300 \
 --db-ps-mode=disable \
 --threads=16 \
 run

モニタリングする

  • トランザクションを開始する。
> use mydb;
> set autocommit=0;
> select @@global.autocommit,@@session.autocommit;
+---------------------+----------------------+
| @@global.autocommit | @@session.autocommit |
+---------------------+----------------------+
|                   1 |                    0 |
+---------------------+----------------------+
1 row in set (0.02 sec)

>  update members set name = 'aze';
Query OK, 0 rows affected (0.01 sec)
Rows matched: 1  Changed: 0  Warnings: 0

> select * from information_schema.innodb_trx;
  • History list length を確認する。
> pager egrep -A 5 '^TRANSACTIONS'
> show engine innodb status\G
TRANSACTIONS
------------
Trx id counter 70715803
Purge done for trx's n:o < 70591422 undo n:o < 0 state: running but idle
History list length 666
LIST OF TRANSACTIONS FOR EACH SESSION:
  • バイナリログを見る。
> show binary logs;
(中略)
| mysql-bin-changelog.000149 | 134264241 |
| mysql-bin-changelog.000150 | 134218252 |
| mysql-bin-changelog.000151 | 134218203 |
| mysql-bin-changelog.000152 |  24293043 |
| mysql-bin-changelog.000153 |  51085842 |
| mysql-bin-changelog.000154 | 108366756 |
| mysql-bin-changelog.000155 | 134218418 |
| mysql-bin-changelog.000156 |  18849396 |
| mysql-bin-changelog.000157 |       120 |
+----------------------------+-----------+
153 rows in set (0.02 sec)


参考

2018-03-03

MySQL のバイナリログとInnoDB ログ

MySQLのバイナリログはメディアリカバリに使うもので、ディスク障害などの際に mysqldump でエクスポートしておいたデータをインポートしてバイナリログでロールフォーワードする。Oracle Database で言うと、 インポートがリストアで、バイナリログでのロールフォーワードがアーカイブログとREDOログを使ったロールフォーワードに当たる。Oracle Database が物理的なブロックレベルで行う宇野に対して、MySQL は論理的にSQLベースで行う点が異なる。

InnoDBログはインスタンスダウンした時にクラッシュリカバリでロールフォーワードに使われる(ロールバックにはUNDOログが使われる)。Oracle Database がREDOログでロールフォーワードしてUNDO表領域のロールバックセグメントでロールバックするのと同じ。


  • バイナリログ


バイナリログを使っている場合、--innodb_support_xa を 1 に設定していると、InnoDBログとバイナリログの一貫性が保証される。sync_binlog が 1 の場合、クラッシュリカバリ時にバイナリログを走査して truncate して、マスターでロールバックしたトランザクションはバイナリログから削除するようだ。これが残っていると、マスターでDMLは発行されたけどロールバックされたトランザクションがスレーブに連携されて永遠にコミットされないトランザクションになるからではないかと思う。

For example, if you are using InnoDB tables and the MySQL server processes a COMMIT statement, it writes many prepared transactions to the binary log in sequence, synchronizes the binary log, and then commits this transaction into InnoDB. If the server crashes between those two operations, the transaction is rolled back by InnoDB at restart but still exists in the binary log. Such an issue is resolved assuming --innodb_support_xa is set to 1, the default. Although this option is related to the support of XA transactions in InnoDB, it also ensures that the binary log and InnoDB data files are synchronized. For this option to provide a greater degree of safety, the MySQL server should also be configured to synchronize the binary log and the InnoDB logs to disk before committing the transaction. The InnoDB logs are synchronized by default, and sync_binlog=1 can be used to synchronize the binary log. The effect of this option is that at restart after a crash, after doing a rollback of transactions, the MySQL server scans the latest binary log file to collect transaction xid values and calculate the last valid position in the binary log file. The MySQL server then tells InnoDB to complete any prepared transactions that were successfully written to the to the binary log, and truncates the binary log to the last valid position. This ensures that the binary log reflects the exact data of InnoDB tables, and therefore the slave remains in synchrony with the master because it does not receive a statement which has been rolled back.

MySQL :: MySQL 5.6 Reference Manual :: 5.4.4 The Binary Log

参考

Webエンジニアのための データベース技術[実践]入門 (Software Design plus)

Webエンジニアのための データベース技術[実践]入門 (Software Design plus)

P.155

バックアップ間隔とリカバリにかかる時間


UPDATE文であればデータファイル自体のサイズには大きな影響がないことが多いので、リストアにかかる時間は大差ありません。したがって、復旧時間の差はこのUPDATE文の実行時間の差に近くなるでしょう。1ヶ月分のUPDATE文を実行するとなると、膨大な時間がかかる可能性があることに注意が必要です。バックアップの間隔を空け過ぎていたため、バイナリログを全部当て終わるのに2日かかった、という失敗事例もありました。


http://h50146.www5.hpe.com/products/software/oe/linux/summary/reference/pdfs/MySQL-backup.pdf

SHOW ENGINE INNODB STATUS の History list length

SHOW ENGINE INNODB STATUS の History list length の見方をメモ。

mysql> show engine innodb status\G

(中略)
------------
  TRANSACTIONS
------------
Trx id counter 0 80157601
Purge done for trx's n:o <0 80154573 undo n:o <0 0 
History list length 6
Total number of lock structs in row lock hash table 0
  • Trx id counter: 現在のトランザクションID。トランザクションが発行されるとカウントアップされる。
  • Purge done for trx's n:o: このトランザクションIDまでパージ済。Trx id counter からこの値を引くと存在するMVCCの行のバージョン数になる。
  • undo n:o : パージ中のUNDOログのレコード数
  • History list length: InnoDB の UNDO スペースのページ数(InnoDBデフォルトのページサイズは 8KB、Aurora MySQL は16KB)。
  • 「Trx id counter」から「Purge done for trx's n:o」を引くと、MVCC の行のバージョン数になる。

参考

High Performance MySQL: Optimization, Backups, Replication, and More

High Performance MySQL: Optimization, Backups, Replication, and More

  • Appendix B. MySQL Server Status
    • SHOW ENGINE INNODB STATUS
      • TRANSACTIONS

TRANSACTIONS

This section contains a little summary information about InnoDB transactions, followed by a list of the currently active transactions. Here are the first few lines (the header):

1  ------------
2  TRANSACTIONS
3  ------------
4  Trx id counter 0 80157601
5  Purge done for trx's n:o <0 80154573 undo n:o <0 0
6  History list length 6
7  Total number of lock structs in row lock hash table 0

The output varies depending on the MySQL version, but it includes at least the following:

  • Line 4: the current transaction identifier, which is a system variable that increments for each new transaction.
  • Line 5: the transaction ID to which InnoDB has purged old MVCC row versions. You can see how many old versions haven’t yet been purged by looking at the difference between this value and the current transaction ID. There’s no hard and fast rule as to how large this number can safely get. If nothing is updating any data, a large number doesn’t mean there’s unpurged data, because all the transactions are actually looking at the same version of the database. On the other hand, if many rows are being updated, one or more versions of each row is staying in memory. The best policy for reducing overhead is to ensure that transactions commit when they’re done instead of staying open a long time, because even an open transaction that doesn’t do any work keeps InnoDB from purging old row versions.Also in line 5: the undo log record number InnoDB’s purge process is currently working on, if any. If it’s “0 0”, as in our example, the purge process is idle.
  • Line 6: the history list length, which is the number of pages in the undo space in InnoDB’s data files. When a transaction performs updates and commits, this number increases; when the purge process removes the old versions, it decreases. The purge process also updates the value in line 5.
  • Line 7: the number of lock structs. Each lock struct usually holds many row locks, so this is not the same as the number of rows locked.

で、私がいつも見ているのはこれ。

mysql> SHOW ENGINE INNODB STATUS\G
..
------------
TRANSACTIONS
------------
Trx id counter 22588
Purge done for trx's n:o < 22588 undo n:o < 0 state: running but idle
History list length 678
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2, OS thread handle 0x7f6bd0094700, query id 13 localhost root init
show engine innodb status
---TRANSACTION 22275, ACTIVE 1397 sec rollback
ROLLING BACK 542497 lock struct(s), heap size 64420280, 100542496 row lock(s), undo log entries 52636267
MySQL thread id 1, OS thread handle 0x7f6bd00d5700, query id 8 localhost root init
ROLLBACK
--------
FILE I/O
--------
..

これは今、手でROLLBACKを叩いてロールバックしているところですが、TRANSACTION 22275, ..の次の行に、undo log entriesの記載があります。

これが今、このトランザクション内の操作でUNDOセグメントに載っているレコードの数。UNDOセグメントからレコードを全部引っ張り出せばロールバックが終わるので、これが0に近付いていくのを見て、なんとなく進捗を知ります。

InnoDBのロールバックがあとどれくらいかかるかをなんとなく見積もる | GMOメディア エンジニアブログ
  • innodb_purge_threads
    • あまり意識している人はいない気がするパラメータ。5.6ではデフォルト1、5.7ではデフォルト4となっています。更新が多く、show engine innodb status\Gを見た場合に History list length [数字] の数字が肥大化していっている場合は増やす事が推奨されます。但しMySQLの再起動が必要です。History list lengthが増えているということはundo領域(デフォルトではibdata1と同居)が肥大化する要因となるため気を配ったほうが良いです。またHistory list lengthが大きくなっていくと基本的には性能が劣化する傾向があります。
    • 何か時間の超絶かかるSELECTとかが実行されている場合もHistory list lengthが増える事があります。その場合は増やしてもたいした効果はないと考えられます(だってpurge出来ないし)
    • なお、過去の記憶ですが、無駄に増やしすぎるとコンテキストスイッチが増加して少ない設定の時よりも性能が下がるので程ほどに設定して下さい。5.7なら殆どのケースでデフォルトで十分だと思います。
MySQL関連のパラメータ(主にInnoDB)について - hiroi10の日記

  • The InnoDB Shared Tablespace (ibdata1) is Growing in Spite of Using innodb_file_per_table (Document ID 1472410.1)
  • How to Investigate InnoDB Lock Issues? (Documnet ID 1531774.1)