Hatena::ブログ(Diary)

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

2018-06-10

MySQL の InnoDB テーブルの断片化状況を確認する

MySQLInnoDB テーブルの空き領域は INFORMATION_SCHEMA.TABLES の DATA_FREE カラムで確認でき、ALTER TABLE <テーブル名> ENGINE INNODB で断片化(フラグメンテーション)を解消することができる。なお、テーブルの断片化でI/O量が増えて性能劣化するのはフルテーブルスキャンで、インデックススキャンは影響を受けない。


前提


確認方法

select table_schema, table_name, data_free, table_rows
	from information_schema.tables
	where table_name='テーブル名';

  • テーブルを作成してデータをロードする
$ sysbench /usr/share/sysbench/oltp_read_write.lua \
 --db-driver=mysql \
 --table-size=10000 \
 --mysql-host=aurora01.******.ap-northeast-1.rds.amazonaws.com \
 --mysql-user=awsuser \
 --mysql-password=******** \
 --mysql-db=mydb \
 --db-ps-mode=disable \
 prepare
  • 1件を残して削除する
mysql> delete from sbtest1 where id < 10000;
Query OK, 9999 rows affected (0.16 sec)
  • テーブルの空き領域を確認する
mysql> select table_schema, table_name, data_free, table_rows
    -> from information_schema.tables
    -> where table_name='sbtest1';
+--------------+------------+-----------+------------+
| table_schema | table_name | data_free | table_rows |
+--------------+------------+-----------+------------+
| mydb         | sbtest1    |   6291456 |          1 |
+--------------+------------+-----------+------------+
1 row in set (0.00 sec)
mysql> alter table sbtest1 engine innodb;
Query OK, 0 rows affected (0.08 sec)
Records: 0  Duplicates: 0  Warnings: 0
mysql> select table_schema, table_name, data_free, table_rows
    -> from information_schema.tables
    -> where table_name='sbtest1';
+--------------+------------+-----------+------------+
| table_schema | table_name | data_free | table_rows |
+--------------+------------+-----------+------------+
| mydb         | sbtest1    |         0 |          1 |
+--------------+------------+-----------+------------+
1 row in set (0.00 sec)

参考

DATA_FREE カラムには、InnoDB テーブルの空き領域がバイト単位で表示されます。

no title

少し話がそれてしまったが、OPTIMIZEが必要になるのはどういう時だろうか?簡単にいうと、「行をDELETEのして無駄な領域がたくさん生じたとき」だけである。これによって、利用されていない領域が回収されることになる。そして、フラグメンテーションが解消するわけである。

実は、InnoDBにはOPTIMIZE TABLEに相当する機能は実装されておらず、代わりにALTER TABLEが実行される。OPTIMIZE TABLE t1は次のコマンドを実行するのと同じなのである。

mysql> ALTER TABLE t1 ENGINE INNODB;

このコマンドを実行すると、テーブルのデータが詰め直される。データの挿入は主キーの順番で行われるため、OPTIMIZE TABLEすると

という効果が期待できることになる。残念ながら、セカンダリインデックスセカンダリインデックスの順番で詰め直す方法はない。そのため、セカンダリインデックスの空間効率はあまりよくない場合があるので注意が必要である。

OPTIMIZE TABLEが内部的にALTER TABLEと同じということは、別に悪いことばかりではない。モノホンのOPTIMIZE TABLEだと実行中は参照も更新もブロックしてしまうことになるが、ALTER TABLEであればメンテナンス中も参照は可能なのである。

漢(オトコ)のコンピュータ道: 大人のためのInnoDBテーブルとの正しい付き合い方。

13.7.2.4 OPTIMIZE TABLE 構文

OPTIMIZE [NO_WRITE_TO_BINLOG | LOCAL] TABLE
    tbl_name [, tbl_name] ...

ストレージ領域を削減し、テーブルアクセス時の I/O 効率を向上させるために、テーブルデータとそれに関連付けられたインデックスデータの物理ストレージを再編成します。各テーブルに加えられる正確な変更は、そのテーブルによって使用されているストレージエンジンによって異なります。

OPTIMIZE TABLE は、テーブルのタイプに応じて次の場合に使用します。

  • innodb_file_per_table オプションが有効な状態で作成されたために独自の .ibd ファイル を含む InnoDB テーブルに対して大量の挿入、更新、または削除操作を行なったあと。テーブルとインデックスが再編成されるため、ディスク領域をオペレーティングシステムによる使用のために再利用できます。
  • InnoDB テーブル内の FULLTEXT インデックスの一部であるカラムに対して大量の挿入、更新、または削除操作を行なったあと。最初に、構成オプション innodb_optimize_fulltext_only=1 を設定します。インデックス保守期間を妥当な時間に維持するために、検索インデックスで更新するワード数を指定する innodb_ft_num_word_optimize オプションを設定し、検索インデックスが完全に更新されるまで OPTIMIZE TABLE ステートメントシーケンスを実行します。
  • MyISAM または ARCHIVE テーブルの大きな部分を削除するか、あるいは可変長行を含む MyISAM または ARCHIVE テーブル (VARCHAR、VARBINARY、BLOB、または TEXT カラムを含むテーブル) に多くの変更を行なったあと。削除された行はリンクリスト内に保持され、以降の INSERT 操作は古い行の位置を再利用します。OPTIMIZE TABLE を使用すると、未使用領域を再利用したり、データファイルをデフラグしたりできます。テーブルを大幅に変更したあとは、このステートメントにより、そのテーブルを使用するステートメントのパフォーマンスを (場合によっては大幅に) 向上させることができます。

(中略)

InnoDB の詳細

InnoDB テーブルの場合、OPTIMIZE TABLE は ALTER TABLE ... FORCE にマップされます。これは、インデックス統計を更新し、クラスタ化されたインデックス内の未使用領域を解放するためにテーブルを再構築します。これは、次に示すように、InnoDB テーブルに対して実行したときに OPTIMIZE TABLE の出力に表示されます。

no title

MySQL 5.0以降は、INFORMATION_SCHEMAという便利なシロモノがある。SHOW TABLE STATUSコマンドを利用する代わりに、INFOMATION_SCHEMA.TABLESテーブルを参照することで同様の情報を表示することが可能であり、innodb_file_per_tableオプション利用時は次のように利用することで、全てのテーブルに関する情報を一括表示することが可能だ。

mysql> SELECT TABLE_SCHEMA,TABLE_NAME,DATA_FREE
    -> FROM INFORMATION_SCHEMA.TABLES
    -> WHERE ENGINE='innodb';
mysql> SELECT TABLE_SCHEMA,SUM(DATA_FREE)
    -> FROM INFORMATION_SCHEMA.TABLES
    -> WHERE ENGINE='innodb'
    -> GROUP BY TABLE_SCHEMA WITH ROLLUP;

SHOWコマンドの出力は加工することは出来ないが、INFORMATION_SCHEMAは好きなようにWHERE句で絞り込みを行ったり集計したりすることができるので便利なのだ。

ところで、Data_freeの数値はInnoDBにおいてどの程度信頼できるのだろうか。

InnoDBのテーブルスペース内では、データは16KBのページ単位で管理されており、さらに64個の連続するページから成るエクステントにグループ化されている。InnoDBテーブルからデータを削除すると、対応するBツリーインデックスが縮小される。これによって、他のテーブルに対して空き領域が再利用できるかどうかは、削除のパターンがテーブルスペースの個々のページやエクステントを解放するかどうかによる。エクステントが解放された場合には、そのエクステントは他のテーブルによって再利用されるが、個々のページやページの一部だけが開放されただけの場合には他のテーブルによって再利用されることはない。つまり、Data_freeは使用されていないエクステントのサイズであり、ページ単位で見ると空き領域がある場合があるということだ。しかしながら、領域を再利用できるかどうかはエクステント全体が空いているかどうかで決まるため、Data_freeはほぼ正確な空き領域を示していると言える。

最後にちょっとだけ内部構造的な話。SHOW TABLE STATUSやINFORMATION_SCHEMAの情報は、最終的にはinnobase/fsp/fsp0fsp.c内のfsp_get_available_space_in_free_extents()関数によって値が取得される。関数引数はテーブルスペースのIDである。下記は関数の末尾からの抜粋である。

return((ullint)(n_free - reserve)
* FSP_EXTENT_SIZE
* (UNIV_PAGE_SIZE / 1024));

空き領域(n_free)から予約された領域(reserve)を引いたものに、一つのエクステントに含まれるページ数(FSP_EXTENT_SIZE=64)を掛けて、さらにページサイズ(UNIV_PAGE_SIZE/1024=16kb)を掛けたものを返しているというワケである。興味のある人はソースコードを覗いてみよう。

漢(オトコ)のコンピュータ道: InnoDBテーブルスペースの空き領域

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-19

Python スクリプトを cProfile でプロファイリングする

cProfile とは

cProfile と profile は 決定論的プロファイリング (deterministic profiling) を行います。 プロファイル (profile) とは、プログラムの各部分がどれだけ頻繁に呼ばれたか、そして実行にどれだけ時間がかかったかという統計情報です。 pstats モジュールを使ってこの統計情報をフォーマットし表示することができます。

Python 標準ライブラリは同じインターフェイスを提供するプロファイラの実装を3つ提供しています。

  • cProfile はほとんどのユーザーに推奨されるモジュールです。 C言語で書かれた拡張モジュールで、オーバーヘッドが少ないため長時間実行されるプログラムのプロファイルに適しています。 Brett Rosen と Ted Czotter によって提供された lsprof に基づいています。バージョン 2.5 で追加.
no title

使い方

$ python -m cProfile -s cumulative foo.py
引数意味
callscall count
cumulativecumulative time
cumtimecumulative time
filefile name
filenamefile name
modulefile name
ncallscall count
pcallsprimitive call count
lineline number
namefunction name
nflname/file/line
stdnamestandard name
timeinternal time
tottimeinternal time

参考

2018-03-12

less で - や + で始まるファイルを開く

- や + で始まるファイルを開こうとすると以下のようにエラーになるので、

$ less +ASM1_ora_19821.trc
Missing filename ("less --help" for help)

以下のように -- とオプションをつけるとよい。

$ less -- +ASM1_ora_19821.trc

参考

       --     A command line argument of "--" marks the end of option
              arguments.  Any arguments following this are interpreted as
              filenames.  This can be useful when viewing a file whose name
              begins with a "-" or "+".

2018-01-08

vmstat でタイムスタンプを表示する

vmstat: Support for timestamps with '-t' & fix for '-wd'

From now the vmstat can append a timestamp to each line in the

VMSTAT and DISKSTAT mode. You can achieve that with the '-t'

switch.

The '-w' switch now works in the DISKSTAT mode too.

vmstat: Support for timestamps with '-t' & fix for '-wd' (4fcd56bf) ? Commits ? procps-ng / procps ? GitLab

これ以降 vmstat は -t オプションでタイムスタンプを表示できるようになっている。

$ vmstat -V
procps version 3.2.8
$ vmstat -t 5
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ ---timestamp---
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 59579072 735596 280408    0    0     0     0   10    2  0  0 100  0  0	2018-01-08 07:33:15 UTC
 0  0      0 59579072 735596 280408    0    0     0     0   30   34  0  0 100  0  0	2018-01-08 07:33:20 UTC
 0  0      0 59578932 735596 280408    0    0     0     0   29   34  0  0 100  0  0	2018-01-08 07:33:25 UTC

この機能追加が入る前のバージョンの vmstat でも以下のように awk などでタイムスタンプを追加してやるとよい。

$ vmstat 5|awk '{print strftime("%Y-%m-%d %H:%M:%S"), $0}'
2018-01-08 07:35:47 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
2018-01-08 07:35:47  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
2018-01-08 07:35:47  1  0      0 59579072 735668 280420    0    0     0     0   10    2  0  0 100  0  0
2018-01-08 07:35:52  0  0      0 59579072 735668 280420    0    0     0     5   69   68  0  0 100  0  0
2018-01-08 07:35:57  0  0      0 59579072 735668 280420    0    0     0     0   32   38  0  0 100  0  0

なお、パイプで tee コマンドに渡すなどすると、awk がバッファリングしてすぐに表示されないので、"fflush()" でフラッシュしてやる。詳しくは下記 URL 参照。

$ vmstat 5|awk '{print strftime("%Y-%m-%d %H:%M:%S"), $0;fflush()}'|tee -a vmstat_20180109.log

vmstat を含む procps プロジェクトのソースコードprocps-ng / procps ? GitLab で読むことができる。


参考