日々の覚書: 2月 2015

2015/02/27

#dsmasakari でMySQLにマサカリ投げてきた

昨夜開催された Datastore Masakari Talks でMySQLにマサカリ投げてきました。

DS masakari talks from yoku0825

会社の用事で前半分くらいは聞けなかったんですが、みんな、特に分散DBなみなさんはつらい話をつらそうに話してたので、つらいつらい言っても笑って話せるMySQLは可愛いなぁと思う次第です。

しゃべってる人たちが「この人ホントこのデータストア大好きなんだなぁ」という感じでいいイベントでした。@tagomoris さん++

2015/02/25

MySQL 5.7の暗黙のデフォルトに対するプロポーザルその2

日々の覚書: MySQL 5.7で暗黙のデフォルトが変わりそうなはなしの時に紹介したのと同じく、Morgan Tockerがまた5.7のデフォルト値のプロポーザルを発表しています。

Proposal to change additional defaults in MySQL 5.7 (February Edition) http://t.co/kWKwFAZHtB
— morgo (@morgo) 2015, 2月 24

前回がトランザクション周りやInnoDB周り(これは、彼の2つのポストを俺が1つにまとめちゃったからだけど)だったのに対し、今回はそれ以外、スローログ関連とか多いですね。

原文は Proposal to change additional defaults in MySQL 5.7 (February Edition) | Master MySQL こちらです。

* log_slow_admin_statements
* 有効にするとALTER TABLEとかも閾値を上回った時にスローログに出るようになる（デフォルトでは、ALTER TABLEステートメントはどれだけ時間がかかってもスローログには出ない）
* ドキュメントに "This variable was added in MySQL 5.7.1." とか書いてあってﾌｧｯてなる(5.6系は5.6.11からって書いてある) けど、これはもとはオプションでしか提供されていなかったこの機能がサーバー変数として与えられたのがこのバージョン、ということ。
* 5.5だと、SHOW GLOBAL VARIABLESで見えないしオンラインで変更できないけど、5.6.11 & 5.7.1以降は見えるしSET GLOBALで変えられる。

* log_slow_slave_statements
* 有効にすると、レプリケーションのSQLスレッドが閾値を超えた場合にもスローログに出るようになる（デフォルトではSQLスレッドの処理したSQLはどれだけ時間がかかってもスローログには出ない)
* こいつも 5.6.11 & 5.7.1 からサーバー変数に昇格 :)

* long_query_time
* 言わずもがな。長い長いと言われてきたデフォルトが10から2へ。

* log_queries_not_using_indexes
* デフォルトでONに。
* クエリーのうち、"WHERE句に(?)" インデックスが使われていないものを、long_query_timeを無視してスローログに書き出す(min_examined_row_limitの影響は受ける)
* 手元の5.6.23だとORDER BY *だけ* を狙ったキーで打つと出力される。WHEREを一部引っ掛けつつメインはORDER BY狙い、みたいなキーなら出力されない。

* min_examined_row_limit
* 0から1000へ
* long_query_timeを超えた、またはlog_queries_not_uxing_indexesにマッチしたクエリーでも、この値よりもExaminedが少ない場合はログに記録しない。よって0は(前提条件にマッチすれば)全記録。

min_examined_row_limitは「long_query_timeより時間かかってるのに何故か出力されない！！１」とかいう人が(今ですら)たまにいるので、採用されたら結構出てくるんじゃないか疑惑。

これを書いててそんな気がしたので、別途まとめておいた。
日々の覚書: MySQLのスローログ関連のパラメーターが評価される順番

* mysqlコマンドラインクライアントのshow-warningsオプション
* デフォルトでONに
* クエリーの結果がWARNINGを持って返ってくると、自動でshow warningsを叩いてくれるやつ。

150225 11:08:55     5 Query     SET sql_mode= ''
150225 11:08:56     5 Query     create table t2 (num int) engine= moga
                    5 Query     show warnings

別に内部でステキなことをしているわけじゃなく、本当にshow warningsをmysql_real_queryで押し込んでるだけ。LOAD DATA INFILEとかの時にデータが切り詰められたりすると大量に画面が埋め尽くされたりするヤーツ。

* group_concat_max_len
* 1024から1Mへ。ずいぶんでかくなったな。
* GROUP_CONCAT関数の結果がこの値を超えた場合、先頭のこの文字数だけが結果に載って残りは切り詰められる。

mysql56> SELECT @@group_concat_max_len;
+------------------------+
| @@group_concat_max_len |
+------------------------+
|                   1024 |
+------------------------+
1 row in set (0.04 sec)

mysql56> SELECT d, CHARACTER_LENGTH(val) FROM (SELECT num % 10000 AS d, GROUP_CONCAT(val) AS val FROM t1 GROUP BY 1) AS dummy LIMIT 3;
+------+-----------------------+
| d    | CHARACTER_LENGTH(val) |
+------+-----------------------+
|    0 |                  1024 |
|    1 |                  1024 |
|    2 |                  1024 |
+------+-----------------------+
3 rows in set, 10000 warnings (4.75 sec)

mysql56> SHOW WARNINGS LIMIT 3;
+---------+------+----------------------------------+
| Level   | Code | Message                          |
+---------+------+----------------------------------+
| Warning | 1260 | Row 32 was cut by GROUP_CONCAT() |
| Warning | 1260 | Row 64 was cut by GROUP_CONCAT() |
| Warning | 1260 | Row 96 was cut by GROUP_CONCAT() |
+---------+------+----------------------------------+
3 rows in set (0.00 sec)

mysql56> SET SESSION group_concat_max_len= 1 * 1024 * 1024;
Query OK, 0 rows affected (0.00 sec)

mysql56> SELECT d, CHARACTER_LENGTH(val) FROM (SELECT num % 10000 AS d, GROUP_CONCAT(val) AS val FROM t1 GROUP BY 1) AS dummy LIMIT 3;
+------+-----------------------+
| d    | CHARACTER_LENGTH(val) |
+------+-----------------------+
|    0 |                  3299 |
|    1 |                  3299 |
|    2 |                  3299 |
+------+-----------------------+
3 rows in set (4.58 sec)

こんなかんじ。

* max_allowed_packet
* 4Mから64Mへ

* symbolic-links
* OFFへ
* これがあるとdatadirからファイルを移動してシンボリックリンクを張っておけば今までどおり使えるよ、というやつ。そういえばそんなのあったね。

* temp-pool
* OFFに
* 昔のLinuxではテンポラリーファイル名を作るときにメモリーリークの可能性があったから、テンポラリーファイル名をあらかじめ作っておく、みたいなオプションらしい。実はずいぶん昔からある。初めて知った。

* table_open_cache_instance
* 1から16に
* 16ってRDSといっしょですね :)
* 16コア以上なら8から16が推奨ってもともと書いてあったしね :-P

mix_examined_row_limitだけ手で0にしたい所存、それ以外はいいんじゃないですかねって感想。
プロポーザルなので、意見がある人は本人のブログまでどうぞ :)

Proposal to change additional defaults in MySQL 5.7 (February Edition) | Master MySQL

MySQLのスローログ関連のパラメーターが評価される順番

別のエントリー書いてたら、前に誰かに聞かれたなと思ったのでメモ。

スローログが出力されるかどうかの判定は、

1. スローログが有効化されていること
2. log_slow_admin_statements = 0 で除外されるステートメントではないこと
3. (long_query_time以上の時間がかかっている) OR (log_queries_not_using_indexes にマッチする) クエリーであること
4. クエリーのExaminedが min_examined_row_limit 以上であること
5. log_queries_not_using_indexesにマッチしていることが決まっている場合、log_throttle_queries_not_using_indexes で設定された以上の時間が経っているかどうか

意外と4. が知られてなくて、どんなに時間がかかってもmin_examined_row_limitより下のやつはログされない。
5. は5.6からの新機能で、「log_queries_not_using_indexes = 1にした時にスローログどばー問題」を抑制するためのサーバー変数。単位は分で、「前回のインデックス使ってないスローログからx分経過するまでは、次にインデックス使ってないスローログは出力しない」という感じ。

具体的には、long_query_time= 1, min_examined_row_limit= 0, log_queries_not_using_indexes= 1, log_throttle_queries_not_using_index= 1の場合に、

# Time: 150225 10:32:03
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 0.000371  Lock_time: 0.000175 Rows_sent: 1  Rows_examined: 1
SET timestamp=1424827923;
SELECT * FROM t1;
# Time: 150225 10:33:03
# User@Host: [] @  []  Id:     4
# Query_time: 0.013910  Lock_time: 0.006933 Rows_sent: 1  Rows_examined: 1
SET timestamp=1424827983;
throttle:         39 'index not used' warning(s) suppressed.;
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 0.001051  Lock_time: 0.000199 Rows_sent: 1  Rows_examined: 1
SET timestamp=1424827983;
SELECT * FROM t1;

こんな風(真ん中のエントリー)になる。

ただしこれ、long_query_timeを超過している && インデックスが使えてないクエリーの場合はカウントされるので、

# Time: 150225 10:35:20
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 1.000613  Lock_time: 0.000209 Rows_sent: 1  Rows_examined: 1
SET timestamp=1424828120;
SELECT *, sleep(1) FROM t1;
# Time: 150225 10:36:21
# User@Host: [] @  []  Id:     4
# Query_time: 59.052891  Lock_time: 0.011360 Rows_sent: 1  Rows_examined: 1
SET timestamp=1424828181;
throttle:         59 'index not used' warning(s) suppressed.;
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 1.001240  Lock_time: 0.000198 Rows_sent: 1  Rows_examined: 1
SET timestamp=1424828181;
SELECT *, sleep(1) FROM t1;

long_query_time超えてるんだから出力してほしい気がするけど、今のところこんな仕様。

MySQL :: MySQL 5.6 Reference Manual :: 5.2.5 The Slow Query Log

2015/02/12

innodb_fast_shutdownとInnoDBの停止/起動にかかる時間とか

InnoDBの停止にやたら時間がかかる、と相談された時に調べたものメモ。

残念ながら試したのはMySQL 5.1.60の ビルトインInnoDB なので、InnoDB PluginやMySQL 5.5以降なら違う結果が出るかも知れない。

まずそもそも、innodb_fast_shutdownの振る舞いについて。
MySQL :: MySQL 5.1 Reference Manual :: 14.6.7 InnoDB Startup Options and System Variables

InnoDBは停止/起動時に大まかに3つのことをやっていて、

InnoDBログのフラッシュ
InnoDBバッファプールのダーティーページをibdata1にフラッシュ
ibdata1からのパージとインサートバッファのマージ(普段完全に非同期でやってるやつ)

これをそれぞれ停止/起動時のどこでやるかをinnodb_fast_shutdownの値で制御できる。

innodb-fast-shutdown	InnoDBログのフラッシュ	ダーティーページのフラッシュ	バックグラウンド非同期処理
0	シャットダウン時	シャットダウン時	シャットダウン時
1(default)	シャットダウン時	シャットダウン時	次のスタートアップ以降、非同期
2	シャットダウン時	次のスタートアップ時(クラッシュリカバリー)	次のスタートアップ以降、非同期

InnoDBログファイルさえ適切にフラッシュされていれば一貫性は保障されるので、トラフィック流したままinnodb_fast_shutdown= 2の状態で停止しても一貫性は変わらない。もしそれでロストするとしたらInnoDBのバグだ。

さて、これでテキトーにDirty pageを増やしたあとにinnodb_fast_shutdownの値を比べてみる。

# ./tpcc_start -w 200 -r 0 -l 900 -c 1 -u tpcc -d tpcc -p test ; ps auxww | grep mysqld ; mysql -Ee "show engine innodb status" | grep -i modified ; time mysqladmin shutdown

結果はこんな感じ。ちなみに物理メモリーは1GB割り当てなので、innodb_buffer_pool_size= 1Gするとたぶんページキャッシュほとんど食われてる。

innodb-buffer-pool-size	innodb-fast-shutdown	Dirty Pages	shutdown-time	startup-time
1G	0	25103	4:17	0:01
1G	1(default)	24796	1:10	0:01
1G	2	24700	0:01	4:18

シャットダウンと起動にかかる時間を足すと、1 >> 0 == 2という感じ。0と2がほぼ同じなのは直感的に判るとして(シャットダウンの時にやるのを起動時に回しているだけだから…という。↓間違ってるんだけどねこの直感)、1が頭ひとつ飛び抜けている。

これには罠があって、0と1の差である「パージとインサートバッファのマージ」は、起動時にまた非同期で走るのだ。というわけで、innodb_fast_shutdown= 1で停止した後に起動すると、しばらくの間I/Oが走りまくる(非同期でパージとマージを再開する)ので、これを完全に待つとなると話はまた変わってくるはず。つまり、2もその分を加味すれば0より遅いはず。

あと、「InnoDBバッファプールをswap outさせた時にどうなるか」というのも調べないといけなかったのでそれも。
割り当てメモリーは1GBしかないので、10GBの割り当てはモロにswapに行っている(いや、Free Pagesも残ってるけれど)

innodb-buffer-pool-size	innodb-fast-shutdown	Dirty Pages	shutdown-time	startup-time
10G	0	49716	11:45	0:03
10G	1	49767	7:22	0:04
10G	2	49067	0:01	3:30

こっちは 2 >> 1 >> 0。

0と1は「ダーティーページをフラッシュするためにバッファプールをスキャンしないといけない」ので、バッファプールをスキャンするためにスラッシングが発生する。2の場合はダーティーページの回復はクラッシュリカバリー処理に任せてしまうので、InnoDBログファイルとibdata1をスキャンして比較すればいいので、起動時に時間がかかるとはいえお釣りが返ってきている…と考えればいいのかなぁ。

大事なことなのでもう一度言います。 MySQL 5.1.60のビルトインInnoDBです 。

2015/02/10

Docker時代にMySQLのserver-idを自動で振りたい

やってることはつまり昔から語られているアレです。

MySQLのserver-idの振り方 - blog.nomadscafe.jp

本番環境に突っ込むときはセットアップスクリプトがよしなにやってくれるようにしてあるんですが、DockerだとCMDでセットアップスクリプトを毎回流すの…？とかなってもんにょりしたのでmysqld_safeにパッチを書きました。結構前ですが。

Docker_image_for_MySQL_Fabric_aware/mysqld_safe.patch at master · yoku0825/Docker_image_for_MySQL_Fabric_aware

[mysqld_safe]セクションにauto-server-idを渡すと、IPアドレスの3バイト目と4バイト目からserver-idを計算してmysqldに渡してくれます。report-hostをくっつけるのは完全に単なる趣味ですが、report-hostはデフォルトでくっつけてくれてもいいんじゃないかなぁ。

このパッチを適用したmysqld_safeを使うと、

bash-4.1# ip a
592: lo:  mtu 16436 qdisc noqueue state UNKNOWN
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
593: eth0:  mtu 1500 qdisc pfifo_fast state UP qlen 1000
    link/ether 02:42:ac:11:00:6b brd ff:ff:ff:ff:ff:ff
    inet 172.17.0.107/16 scope global eth0

# bin/mysqld_safe --no-defaults --auto-server-id &
[1] 6
bash-4.1# 150210 13:19:48 mysqld_safe Logging to '/var/lib/mysql/b283bcd9b8b9.err'.
150210 13:19:48 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql

bash-4.1# ps auxww | grep mysqld
root         6  0.0  0.1  11304  1472 ?        S    13:19   0:00 /bin/sh bin/mysqld_safe --no-defaults --auto-server-id
mysql       97 14.0 44.0 1127276 448972 ?      Sl   13:19   0:00 /usr/sbin/mysqld --no-defaults --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --server-id=107 --report-host=b283bcd9b8b9 --user=mysql --log-error=/var/lib/mysql/b283bcd9b8b9.err --pid-file=/var/lib/mysql/b283bcd9b8b9.pid
root       121  0.0  0.0   6380   648 ?        S+   13:19   0:00 grep mysqld

mysql> SELECT @@server_id;
+-------------+
| @@server_id |
+-------------+
|         107 |
+-------------+
1 row in set (0.00 sec)

こうなります。 DockerでMySQL Fabricをさっくり試すための整備をしたつもりのときに作ってたんですが、Oracleが公式にDocker HubにMySQLのイメージを作るとか言ってるので、ゆるい感じでFeature Requestを出してみました。便利なので。

MySQL Bugs: #75832: Add function to mysqld_safe for setting server-id automatically.

( ´-｀).oO（FR出したあとに、思いっきりbash特有の書き方だったことに気付いた。。

2015/02/04

MySQL 5.7.5 on Windowsでskip-name-resolveするとrootでログインできなくなる

ことの発端はこのバグレポート。

MySQL Bugs: #75656: 5.7.5 skip_name_resolve stops all connection attempts

なんでかよくわからないけれど、調べてみようと思った。そしたらば。

mysql57> SELECT user, host FROM mysql.user;
+------+-----------+
| user | host      |
+------+-----------+
| root | localhost |
+------+-----------+
1 row in set (0.00 sec)

mysql_install_dbして起動しただけでコレ。これじゃあ--skip-name-resolveしたらつながらなくなるだろうという感じ。

日々の覚書: user@localhostとuser@127.0.0.1は別人？

MySQL Bugs: #68436: user@127.0.0.1 is authorized partly as user@localhost.

* Linuxでは--protocolを指定しない場合は暗黙で--protocol=socketになるんですが、Windowsでは指定しない場合は暗黙で--protocol=tcpになるんです。豆知識。
* 名前解決が有効な時は接続元: 127.0.0.1を接続元: localhostにリバースマップしてくれて--protocol=tcpでも認証が通るんですが、skip-name-resolveしてるとこの逆引きを一切してくれないので、127.0.0.1 ≠ localhostという単純な比較がなされて認証に失敗します。

$ bin/mysql_install_db --basedir=./ --datadir=data --verbose=1
2015-02-04 17:13:08 [NOTE]    Creating data directory data
2015-02-04 17:13:08 [NOTE]    Generating random password to /home/yoku0825/.mysql_secret...done.
2015-02-04 17:13:08 [NOTE]    Executing /usr/mysql/5.7.5/bin/mysqld --no-defaults --bootstrap --datadir=data --lc-messages-dir=./share --lc-messages=en_US --basedir=.
2015-02-04 17:13:11 [NOTE]    Creating system tables...done.
2015-02-04 17:13:11 [NOTE]    Filling system tables with data...done.
2015-02-04 17:13:12 [NOTE]    Filling help table with data...done.
2015-02-04 17:13:12 [NOTE]    Creating default user root@localhost
2015-02-04 17:13:12 [NOTE]    Creating default proxy root@localhost
2015-02-04 17:13:13 [NOTE]    Success!

mysql-5.7.5-m15/client/mysql_install_db.cc を参照すると(MySQL 5.7.5からmysql_install_dbはC++で書かれているのだ)

296 struct Sql_user
297 {
..
348 void to_sql(string *cmdstr)
349 {
350 stringstream set_oldpasscmd,ss;
351 ss << "INSERT INTO mysql.user VALUES (" 352 << "'" << escape_string(host) << "','" << escape_string(user) << "',"; ..

ユーザーを作るためのINSERTステートメントはこのへんで組み立てていて、

940 class Process_writer
941 {
942 public:
943 Process_writer(Sql_user *user, const string &opt_sqlfile) : m_user(user),
944 m_opt_sqlfile(opt_sqlfile) {}
945 bool operator()(int fh)
946 {
..
1003 info << "Creating default user " << m_user->user << "@" 1004 << m_user->host
1005 << endl; 1006 string create_user_cmd; 1007 m_user->to_sql(&create_user_cmd);
1008 write(fh, create_user_cmd.c_str(), create_user_cmd.length());
..

それを読んでるのはここで1回のみ。その元になるのはどこから来るかというと、ぐるぐる探し迷った末に

122 {"admin-user", 0, "Username part of the default admin account.",
123 &opt_adminuser, 0, 0, GET_STR_ALLOC, REQUIRED_ARG,
124 (longlong)&default_adminuser, 0, 0, 0, 0, 0},
125 {"admin-host", 0, "Hostname part of the default admin account.",
126 &opt_adminhost, 0, 0, GET_STR_ALLOC,REQUIRED_ARG,
127 (longlong)&default_adminhost, 0, 0, 0, 0, 0},

ここにたどり着いた。

$ ./bin/mysql_install_db --basedir=./ --datadir=data --admin-user=root --admin-host=127.0.0.1 --verbose=1
2015-02-04 18:46:29 [NOTE]    Creating data directory data
2015-02-04 18:46:29 [NOTE]    Generating random password to /home/yoku0825/.mysql_secret...done.
2015-02-04 18:46:29 [NOTE]    Executing /usr/mysql/5.7.5/bin/mysqld --no-defaults --bootstrap --datadir=data --lc-messages-dir=./share --lc-messages=en_US --basedir=.
2015-02-04 18:46:31 [NOTE]    Creating system tables...done.
2015-02-04 18:46:31 [NOTE]    Filling system tables with data...done.
2015-02-04 18:46:32 [NOTE]    Filling help table with data...done.
2015-02-04 18:46:32 [NOTE]    Creating default user root@127.0.0.1
2015-02-04 18:46:32 [NOTE]    Creating default proxy root@127.0.0.1
2015-02-04 18:46:33 [NOTE]    Success!

大正解。--admin-hostで指定してやればOKぽいので、

*** client/mysql_install_db.cc  2014-09-18 22:36:41.000000000 +0900
--- client/mysql_install_db.cc.new      2015-02-04 18:49:16.113066355 +0900
***************
*** 65,71 ****
  char *opt_sqlfile= 0;
  char default_adminuser[]= "root";
  char *opt_adminuser= 0;
! char default_adminhost[]= "localhost";
  char *opt_adminhost= 0;
  char default_authplugin[]= "mysql_native_password";
  char *opt_authplugin= 0;
--- 65,75 ----
  char *opt_sqlfile= 0;
  char default_adminuser[]= "root";
  char *opt_adminuser= 0;
! #ifdef __WIN__
!   char default_adminhost[]= "127.0.0.1";
! #else
!   char default_adminhost[]= "localhost";
! #endif
  char *opt_adminhost= 0;
  char default_authplugin[]= "mysql_native_password";
  char *opt_authplugin= 0;

Windowsだったら127.0.0.1にするとか、こんなパッチでいいのかな？ (ウインドーズでMySQLビルドしたことないからよくわからない。。) とりあえずBugsは更新しておいた。ワークアラウンドとパッチと。

登録: 投稿 ( Atom )

GA