Slide 1
Slide 1 text
Dive into MySQL Error
第二雑学研究部、略してダイブ
2019/01/26
yoku0825
YAPC::Tokyo 2019
Slide 2
Slide 2 text
Dive into MySQL Error 第二雑学研究部、略してダイブ
“MySQLの” エラーの仕組みを考えるセッションです
“MySQLのエラー” をどう回避するか、ハンドルするか、という話は
出てきません
‐
本トークはPerl成分を含みません
変数の頭に $ がつかない言語にご注意ください
‐
1/83
Slide 3
Slide 3 text
Chiba.pmの
方から来まし
た
2/83
Slide 4
Slide 4 text
Chiba.pm
の “m” は
3/83
Slide 5
Slide 5 text
MySQL
の “m”！
4/83
Slide 6
Slide 6 text
※諸説あ
り
5/83
Slide 7
Slide 7 text
じゃあ…準備
はいいですか
ね？
6/83
Slide 8
Slide 8 text
せーの
7/83
Slide 9
Slide 9 text
＼こんに千葉！／
(c) @hokke_mirin
8/83
Slide 10
Slide 10 text
( ´-｀).oO（東
京の西側から来た
なんて言えない
9/83
Slide 11
Slide 11 text
＼こんに千葉！／ (c) @hokke_mirin
yoku0825＠とある企業のDBA
オラクれない
‐
ポスグれない
‐
マイエスキューエる
‐
Perl Monger!!
ytkit - Yoku-san no ToolKIT
Contributor of innotop
‐
生息域
Twitter: @yoku0825
‐
Blog: 日々の覚書
‐
日本MySQLユーザ会
‐
MySQL Casual
‐
10/83
Slide 12
Slide 12 text
MySQLのエ
ラーの話をし
ます
11/83
Slide 13
Slide 13 text
存分にダイブ
しましょう
12/83
Slide 14
Slide 14 text
MySQLのエラーってこんなやつ
ERROR 2002 (HY000): Can't connect to local MySQL server through
socket '/tmp/mysql.sock' (2)
13/83
Slide 15
Slide 15 text
MySQLのエラーってこんなやつ
DBIx::Sunny connect('database=isucon2;host=127.0.0.1;port=3306','
isucon2app',...) failed: Can't connect to MySQL server on '127.0.
0.1' (111) at /home/yoku0825/git/isucon2/webapp/perl/lib/Isucon2.
pm line 29.
14/83
Slide 16
Slide 16 text
「MySQLのエラー」と言ってもいくつかあって
MySQLサーバーの異常
MySQLサーバーからクライアントに返すネガティブな応答
クライアントライブラリーの異常
15/83
Slide 17
Slide 17 text
「MySQLのエラー」と言ってもいくつかあって
MySQLサーバーの異常
MySQLサーバーからクライアントに返すネガティブな応答
クライアントライブラリーの異常
16/83
Slide 18
Slide 18 text
MySQLサーバーからクライアントに返すネガティブな応
答
認証失敗
権限の不足
SQLシンタックスエラー
デッドロック検出
タイムアウト
..etc.
17/83
Slide 19
Slide 19 text
余談
“ER_LOCK_DEADLOCK”, 1213, “Deadlock found when
trying to get lock; try restarting transaction”
「デッドロックした」んじゃなくて、「デッドロックになり
そうな気配がしたのでロールバックした」という意味のネガ
ティブメッセージ
bugs.mysql.comとかで「デッドロック」というと「本当に
デッドロックしてタイムアウトするまで身動きが取れなく
なってるやつ」のこと
18/83
Slide 20
Slide 20 text
MySQLのエラーパケットの構成
19/83
Slide 21
Slide 21 text
エラーコード分類
range error_kbn
1..999 グローバルエラー
1000..1999 サーバーサイドエラー
2000..2999 クライアントサイドエラー (*)
3000..4999 サーバーサイドエラー
5000..5999 X Pluginのエラー
10000..49999 システムメッセージ
50000..51999 サードパーティ用
(*) libmysqlclient.soの場合
MySQL :: MySQL 8.0 Reference Manual :: B.1 Error
Message Sources and Components
20/83
Slide 22
Slide 22 text
( ´-｀).oO（どうせな
ら「リトライして成功す
る可能性のないエラー」
も体系にしてくれると嬉
しかったのに…
21/83
Slide 23
Slide 23 text
「MySQLのエラー」と言ってもいくつかあって(again)
MySQLサーバーの異常
MySQLサーバーからクライアントに返すネガティブな応答
クライアントライブラリーの異常
22/83
Slide 24
Slide 24 text
「MySQLのエラー」と言ってもいくつかあって(again)
MySQLサーバーの異常
プラグインやレプリケーションの “Initialization Failure” みたいな
のはある
‐
それ以外はAssertion FailureだったりSegmentation Faultだったり
でコア吐いたり、本物のデッドロックでストールしてたり
‐
MySQLサーバーからクライアントに返すネガティブな応答
概ね1000番台、5.7からたまに3000番台
‐
クライアントライブラリーの異常
概ね2000番台（libmysqlclient.soの場合）
‐
クライアントライブラリーの実装に依存
‐
23/83
Slide 25
Slide 25 text
最初につけられるアタリ
クライアントサイドのエラー(2000番台)なら、そもそも
サーバーに到達していない可能性がある
何らかの理由でサーバーが拒否ってるだけなら1000番台か3000番台
になるから
‐
ネットワーク経路的な問題が一番多い気がする
‐
クライアントサイドエラーでも、まれにサーバーがエラーに
絡んでいることもある
クライアントライブラリーの互換性の問題
‐
サーバー側からのコネクション強制切断
‐
24/83
Slide 26
Slide 26 text
2002: CR_CONNECTION_ERROR
ERROR 2002 (HY000): Can't connect to local MySQL server through
socket '/tmp/mysql.sock' (2)
25/83
Slide 27
Slide 27 text
2000番台エラーの特徴
サーバーから切られた以外の理由の場合、OSエラーコード
が載っていることが多い
例えばLinuxなら
#define ENOENT 2 /* No such file or directory */
#define ENOSPC 28 /* No space left on device */
#define ETIMEDOUT 110 /* Connection timed out */
#define ECONNREFUSED 111 /* Connection refused */
#define EHOSTUNREACH 113 /* No route to host */
26/83
Slide 28
Slide 28 text
2002: CR_CONNECTION_ERROR
ERROR 2002 (HY000): Can't connect to local MySQL server through s
ocket '/tmp/mysql.sock' (2)
$ perror 2
OS error code 2: No such file or directory
MySQL error code MY-000002: Error reading file '%s' (OS errno %d
- %s)
27/83
Slide 29
Slide 29 text
2000番台エラーの特徴
perror コマンドでは調べられ ない
パッケージ的にサーバーの付属ユーティリティーだから、だと思う
‐
MySQL :: MySQL 8.0 Reference Manual :: 4.8.2 perror —
Explain Error Codes
‐
OSエラーコードは perror コマンドで引ける
‐
OSエラーコードはたまにMySQLサーバーのエラーコードとカブるの
で見失わないように…
‐
perror についてはあとで詳しく
‐
28/83
Slide 30
Slide 30 text
2003: CR_CONN_HOST_ERROR
$ mysql -h10.0.0.1
ERROR 2003 (HY000): Can't connect to MySQL server on '10.0.0.1'
(110)
$ perror 2003 110
Illegal error code: 2003
OS error code 110: Connection timed out
29/83
Slide 31
Slide 31 text
同じ2003のタイムアウトでもどっちがタイムアウトさせ
るかによって違ったり
mysql_options(mysql, MYSQL_OPT_READ_TIMEOUT, 1);
mysql_real_connect(mysql);
2003: Can't connect to MySQL server on '192.168.225.201' (4)
$ perror 4
OS error code 4: Interrupted system call
30/83
Slide 32
Slide 32 text
2000番台でもサーバーの都合も含むもの
サーバー側のアイドルタイマー（wait_timeout）に引っか
かってサーバー側から一方的にコネクションを切断されたり
KILLステートメントで切断されたり
mysql80 11> SELECT NOW();
ERROR 2006 (HY000): MySQL server has gone away
mysql80 13> SELECT NOW();
ERROR 2013 (HY000): Lost connection to MySQL server during query
31/83
Slide 33
Slide 33 text
どこで切断されるかでエラー番号が変わる
mysql-client mysqld
TCP Handshake
Greeting Message/Mess
age Digest
User/Digest
Authentication
SELECT ..
Execute query
long_time
SELECT ..
Execute query
32/83
Slide 34
Slide 34 text
どこで切断されるかでエラー番号が変わる
mysql80 11> SELECT NOW();
ERROR 2006 (HY000): MySQL server has gone away
mysql80 13> SELECT NOW();
ERROR 2013 (HY000): Lost connection to MySQL server during query
33/83
Slide 35
Slide 35 text
2000番台でもサーバーの都合も含むもの
MySQL 8.0でみんなよくググるコレ
ERROR 2059 (HY000): Authentication plugin 'caching_sha2_password'
cannot be loaded: /usr/mysql/5.6.41/lib/plugin/caching_sha2_pass
word.so: cannot open shared object file: No such file or director
y
34/83
Slide 36
Slide 36 text
2059: CR_AUTH_PLUGIN_CANNOT_LOAD
クライアントが要求されたプラグインを見つけられないエ
ラー。
MySQL 8.0のサーバーに5.6のクライアントで接続しようと
すると出る
8.0のデフォルト認証プラグインは caching_sha2_password だが、こ
れは5.6の時代には実装されていなかったため、クライアントはそん
なプラグインを知らない。
‐
35/83
Slide 37
Slide 37 text
実はもう1種類ある
クライアントから送られてきたクライアントケーパビリ
ティーで「要求する認証プラグインにクライアントが対応し
ていないことがわかっちゃった」のでサーバーから接続を拒
否。
ERROR 1251 (08004): Client does not support authentication protoc
ol requested by server; consider upgrading MySQL client
36/83
Slide 38
Slide 38 text
どこで認証に失敗するかでエラー番号が変わる
mysql-client mysqld
TCP Handshake
Greeting Message/Mess
age Digest
User/Digest
Authentication
SELECT ..
Execute query
long_time
SELECT ..
Execute query
37/83
Slide 39
Slide 39 text
どこで認証に失敗するかでエラー番号が変わる
ERROR 2059 (HY000): Authentication plugin 'caching_sha2_password'
cannot be loaded: /usr/mysql/5.6.41/lib/plugin/caching_sha2_pass
word.so: cannot open shared object file: No such file or director
y
ERROR 1251 (08004): Client does not support authentication protoc
ol requested by server; consider upgrading MySQL client
38/83
Slide 40
Slide 40 text
libmysqlclient.so
製品名称は MySQL Connector/C
MySQLサーバーにバンドルされている
コイツをバインドしているのは PerlのDBD::mysql とか
Rubyのmysql2とか
PHPのmysqlnd, JavaのConnecor/J, PerlのNet::MySQL(!)とかは
独自実装
‐
39/83
Slide 41
Slide 41 text
2000番台エラーの応用（？）
レプリケーションスレーブ（のI/Oスレッド）はマスターか
ら見ると クライアント
しかも必ずlibmysqlclient.so実装のクライアント
‐
Last_IO_Error に2000番台のエラーが出ることがまれにだ
がよくある
ここで1000番台、2000番台の切り分けをスムーズにこなすとデキる
MySQLerっぽい
‐
40/83
Slide 42
Slide 42 text
Last_IO_ErrorはOSエラーコードが出てくれないのが
ちょっと痛い
少なくとも認証失敗（1000番台）でないことはわかる
Last_IO_Errno: 2003
Last_IO_Error: error connecting to master 'root@1
27.0.0.1:64057' - retry-time: 60 retries: 1
クライアントサイドエラーコードの一覧は include/
errmsg.h に
41/83
Slide 43
Slide 43 text
おまけ: Connector/J
“Communication link failure” って邪悪なやつがいて
src/com/mysql/jdbc/ConnectionImpl.java
‐
src/com/mysql/jdbc/ConnectionImpl.java
‐
更にすごいことには
src/com/mysql/jdbc/SQLError.java
‐
42/83
Slide 44
Slide 44 text
ひどい XD
個人の意見です
43/83
Slide 45
Slide 45 text
エラーコード分類
range error_kbn
1..999 グローバルエラー
1000..1999 サーバーサイドエラー
2000..2999 クライアントサイドエラー (*)
3000..4999 サーバーサイドエラー
5000..5999 X Pluginのエラー
10000..49999 システムメッセージ
50000..51999 サードパーティ用
(*) libmysqlclient.soの場合
MySQL :: MySQL 8.0 Reference Manual :: B.1 Error
Message Sources and Components
44/83
Slide 46
Slide 46 text
次ににつけられるアタリ
1000番台、3000番台ならサーバーが明示的に「エラー応答」を
返している
ERRパケットの中には「サーバーサイドエラーコード」「SQLス
テート」「エラーメッセージ」が入っている
45/83
Slide 47
Slide 47 text
たとえば
エラーコード1251
SQLステート08004
エラーメッセージが “Client does not ..”
ERROR 1251 (08004): Client does not support authentication protoc
ol requested by server; consider upgrading MySQL client
46/83
Slide 48
Slide 48 text
SQLステート
サーバーサイドエラーコードとSQLステートは1対多で結び
つく
なので、積極的にSQLステートを使うクライアントでなければエラー
コードの方が追いやすい
‐
Wikipediaさん後は頼んだ
SQLSTATE - Wikipedia
‐
47/83
Slide 49
Slide 49 text
エラーメッセージ
豆だけど実は日本語にできる
lc_messages=ja
‐
MySQL :: MySQL 5.6 リファレンスマニュアル :: 10.2 エラーメッ
セージ言語の設定
‐
48/83
Slide 50
Slide 50 text
誰得
mysql80 32> SELECT 1 FROM t1;
ERROR 1046 (3D000): No database selected
mysql80 32> SET lc_messages= 'ja_JP';
Query OK, 0 rows affected (0.01 sec)
mysql80 32> SELECT 1 FROM t1;
ERROR 1046 (3D000): データベースが選択されていません。
share/errmsg-utf8.txt から “jpn” で始まってる行を探すと
出てきます
最近増えたエラーコードは網羅されていないのでコントリビュート
チャンスですね :D
‐
49/83
Slide 51
Slide 51 text
perrorコマンド
$ perror 1046
MySQL error code MY-001046 (ER_NO_DB_ERROR): No database selected
$ perror ER_NO_DB_ERROR
MySQL error code MY-001046 (ER_NO_DB_ERROR): No database selected
50/83
Slide 52
Slide 52 text
perrorコマンド
さっきから何度か出てきている perror コマンド
パッケージ的には mysql-server 系に付属している
引数にエラーコードを受けて、エラーメッセージのフォー
マットを出力する
エラー番号からだけでもエラーメッセージを推測できる
‐
エラー番号からマクロ名が取り出せるのでgrepが捗る
‐
マクロ名しか書いてない（ことはまずないと思うけど）からエラー番
号とメッセージが取れる
‐
MySQL :: MySQL 5.6 リファレンスマニュアル :: 4.8.1
perror — エラーコードの説明
51/83
Slide 53
Slide 53 text
perrorコマンド
内部理解のために役に立つのは、 どこまでが決め打ちメッ
セージなのか がわかるフォーマットを見られること
たとえば 1593: ER_BINLOG_FATAL_ERROR は(5.7の場
合)
Slave I/O: The slave I/O thread stops because master and slave ha
ve equal MySQL server ids; these ids must be different for replic
ation to work (or the --replicate-same-server-id option must be u
sed on slave but this does not always make sense; please check th
e manual before using it), Error_code: 1593
Slave I/O: The slave I/O thread stops because SET @master_heartbe
at_period on master failed. Error: , Error_code: 1593
Slave SQL: Fatal error: Failed to initialize the master info stru
cture, Error_code: 1593
52/83
Slide 54
Slide 54 text
1593: ER_BINLOG_FATAL_ERROR
perrorで引くとほとんどが可変部分で、このエラーコードが
示すものは “Fatal error” しかない（あとは全部状況で変わ
る）
$ perror 1593
MySQL error code 1593 (ER_SLAVE_FATAL_ERROR): Fatal error: %s
53/83
Slide 55
Slide 55 text
じゃあどこでこのバリエーションが生まれるのか？
エラーマクロが分かってればgrepは簡単
$ grep -r -A1 ER_SLAVE_FATAL_ERROR .
...
./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR,
./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR),
./sql/log_event.cc- "Invalid character set for User var event");
--
./sql/rpl_slave.cc: mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR,
./sql/rpl_slave.cc: ER(ER_SLAVE_FATAL_ERROR),
./sql/rpl_slave.cc- "Failed to flush master info.");
--
./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR,
./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR),
./sql/log_event.cc- "Binlog version not supported");
...
54/83
Slide 56
Slide 56 text
慣れてくると
mi は master_info のことでI/Oスレッド関連
rli は relay_log_info のことでSQLスレッド関連
それぞれ report は SHOW SLAVE STATUS で表示されるような
バッファ（とエラーログ）に記録するためのメソッド
55/83
Slide 57
Slide 57 text
慣れてくると
$ grep -r -A1 ER_SLAVE_FATAL_ERROR .
...
./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR,
./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR),
./sql/log_event.cc- "Invalid character set for User var event");
--
./sql/rpl_slave.cc: mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR,
./sql/rpl_slave.cc: ER(ER_SLAVE_FATAL_ERROR),
./sql/rpl_slave.cc- "Failed to flush master info.");
--
./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR,
./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR),
./sql/log_event.cc- "Binlog version not supported");
...
56/83
Slide 58
Slide 58 text
C怖くないよ
2506 char query_buf[]= "SELECT @@GLOBAL.SERVER_UUID";
..
2535 if (!mysql_real_query(mysql, STRING_WITH_LEN(query_buf)) &&
2536 (master_res= mysql_store_result(mysql)) &&
2537 (master_row= mysql_fetch_row(master_res)))
2538 {
2539 if (!strcmp(::server_uuid, master_row[0]) &&
2540 !mi->rli->replicate_same_server_id)
2541 {
2542 errmsg= "The slave I/O thread stops because master and slave have equal
"
2543 "MySQL server UUIDs; these UUIDs must be different for "
2544 "replication to work.";
2545 mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ER(ER_SLAVE_FATAL_ERROR),
2546 errmsg);
2547 // Fatal error
2548 ret= 1;
2549 }
sql/rpl_slave.cc
57/83
Slide 59
Slide 59 text
$ がない以外
はほぼPerl :D
58/83
Slide 60
Slide 60 text
エラーフォーマットからエラーの意味を察する
可変部分は呼び出し元から文字列で渡されるので、1593な
ら “Fatal error:” の他の部分はソースコードから探しやすい
それに対して1046は可変部分がないのでエラーマクロで探
すしかない
$ perror 1046
MySQL error code 1046 (ER_NO_DB_ERROR): No database selected
$ perror 1593
MySQL error code 1593 (ER_SLAVE_FATAL_ERROR): Fatal error: %s
59/83
Slide 61
Slide 61 text
エラーフォーマットからエラーの意味を察する
これは grep -r "UUIDs must be different" . でもたどり着
ける
2506 char query_buf[]= "SELECT @@GLOBAL.SERVER_UUID";
..
2535 if (!mysql_real_query(mysql, STRING_WITH_LEN(query_buf)) &&
2536 (master_res= mysql_store_result(mysql)) &&
2537 (master_row= mysql_fetch_row(master_res)))
2538 {
2539 if (!strcmp(::server_uuid, master_row[0]) &&
2540 !mi->rli->replicate_same_server_id)
2541 {
2542 errmsg= "The slave I/O thread stops because master and slave have equal "
2543 "MySQL server UUIDs; these UUIDs must be different for "
2544 "replication to work.";
2545 mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ER(ER_SLAVE_FATAL_ERROR),
2546 errmsg);
2547 // Fatal error
2548 ret= 1;
2549 }
sql/rpl_slave.cc
60/83
Slide 62
Slide 62 text
エラーフォーマットからエラーの意味を察する
grep -r "No database selected" . だとテストケースとマ
クロの定義部分しか出てこない
それはそれで楽しいんですけどね :D
‐
...
./include/mysqld_ername.h:{ "ER_NO_DB_ERROR", 1046, "No database
selected" },
./mysql-test/r/alter_table.result:ERROR 3D000: No database select
ed
./mysql-test/r/create.result:ERROR 3D000: No database selected
./mysql-test/t/information_schema.test:# Bug#38916 Select from I_
S.ROUTINES results in "No database selected" error
./mysql-test/t/sp.test:# Bug#28551 "The warning 'No database sele
cted' is reported when calling
...
61/83
Slide 63
Slide 63 text
エラーに触れるつい
でにエラーログにつ
いても触れておこう
62/83
Slide 64
Slide 64 text
MySQLのエラーログとは実は
open_error_log でやっていることの実態は、 freopen を
使ってstderrとstdoutをエラーログに向けているだけ
1894 bool open_error_log(const char *filename, bool get_lock) {
...
1915 do {
1916 errors = 0;
1917 if (!my_freopen(filename, "a", stderr)) errors++;
1918 if (!my_freopen(filename, "a", stdout)) errors++;
1919 } while (retries-- && errors);
1920
sql/log.cc
63/83
Slide 65
Slide 65 text
lsofで開いているファイルディスクリプターを見るだけで
もわかったりする
$ lsof -p $(pidof mysqld)
..
mysqld 20980 yoku0825 0r CHR 1,3 0t0
1028 /dev/null
mysqld 20980 yoku0825 1w REG 253,0 52083
137048897 /usr/mysql/8.0.14/data/error.log
mysqld 20980 yoku0825 2w REG 253,0 52083
137048897 /usr/mysql/8.0.14/data/error.log
mysqld 20980 yoku0825 3u REG 253,0 65
149633590 /usr/mysql/8.0.14/data/bin.index
mysqld 20980 yoku0825 4u REG 253,0 4077
149596931 /usr/mysql/8.0.14/data/innodb_status.20980
..
64/83
Slide 66
Slide 66 text
stdoutとstderrが繋がっているだけなので
プラグインの中で fprintf(stderr, ..) とかやるとフツーに
エラーログに出る
printデバッグする機会があれば憶えておいて損はないはず ;)
‐
InnoDB Monitor( CREATE TABLE innodb_monitor とか SET
GLOBAL innodb_status_output = 1 )がなんでデフォルトで
エラーログに書かれるのか…
InnoDBからするとエラーログに書いてるつもりはなくて、単に標準
エラー出力に書いているだけ
‐
ロガープロセスみたいなのがいるわけではない
65/83
Slide 67
Slide 67 text
stdoutとstderrが繋がっているだけなので
おもむろにエラーログの書式をガン無視したInnoDBのログ
に遭遇したことってありません？
タイムスタンプとかログレベルとか一切ないやつ
‐
180731 13:29:08 [Note] InnoDB: 5.5.61 started; log sequence numbe
r 1625977
InnoDB: Error: page 1234 log sequence number
InnoDB: is in the future! Current system log sequence number 1625
977
InnoDB: Your database may be corrupt or you may have copied the I
nnoDB
InnoDB: tablespace but not the InnoDB log files. See"
InnoDB: https://dev.mysql.com/../forcing-innodb-recovery.html
InnoDB: for more information.
66/83
Slide 68
Slide 68 text
stdoutとstderrが繋がっているだけなので
8.0はもうかなり ib::error をちゃんと使うように書き換え
られているけれども
3925 ib::error(ER_IB_MSG_37) << "Has " << rec_get_n_fields_ol
d(rec, index)
3926 << " fields, should have " << n;
3927
3928 if (dump_on_error) {
3929 fputs("InnoDB: corrupt record ", stderr);
3930 rec_print_old(stderr, rec);
3931 putc('\n', stderr);
3932 }
3933 return (FALSE);
storage/innobase/btr/btr0btr.cc
67/83
Slide 69
Slide 69 text
プラガブルストレージエンジン
今でこそMySQLのストレージエンジンといえばInnoDBだけ
れども
かつてMySQLは “MySQL AB.” が
InnoDBは “Innobase Oy.” (後にOracleが買収) が
それぞれ別々に開発していた
68/83
Slide 70
Slide 70 text
InnoDBの余談
別の会社によって、別のリポジトリーで、別の製品として開
発されたInnoDB
バージョン体系も違っていて、5.1時代のInnoDB PluginはInnoDB
1.0.x
‐
MySQL 5.5のInnoDBはInnoDB 1.1.x
‐
OracleによるSun買収直後のリリースがMySQL 5.5だか
ら、Oracleになってから開発されたバージョンはMySQL
5.6から
5.6からはInnoDBにバージョン番号は振られていない
‐
69/83
Slide 71
Slide 71 text
閑話休題
70/83
Slide 72
Slide 72 text
プラガブルストレージエンジンのログ
別のファイルに吐く
1.
Mroongaストレージエンジン（ groonga.log ）
ISAMストレージエンジン (デバッグ用の log_isam オプショ
ンはなんと8.0にもまだある)
標準エラー出力に吐く
1.
InnoDBストレージエンジン
NDBCLUSTERストレージエンジン（データノードは独自ロ
グ）
71/83
Slide 73
Slide 73 text
mysqldのエラーロギングも進化している
MySQL 8.0でサーバーコアのコードはなんちゃってC++か
らほぼネイティブなC++に
ちゃんとしたメッセージフックが実装された
‐
MySQL 8.0からはエラーログフィルターとJSONコンポーネ
ントが追加できる
mysql80 10> SELECT @@log_error_services;
+-------------------------------------------------------+
| @@log_error_services |
+-------------------------------------------------------+
| log_filter_internal; log_sink_internal; log_sink_json |
+-------------------------------------------------------+
1 row in set (0.00 sec)
72/83
Slide 74
Slide 74 text
JSON形式のエラーログ
{
"log_type": 1,
"prio": 0,
"err_code": 10931,
"msg": "/usr/mysql/8.0.14/bin/mysqld: ready for connections. Ve
rsion: '8.0.14' socket: '/usr/mysql/8.0.14/data/mysql.sock' por
t: 64080 Source distribution.",
"time": "2019-01-25T14:15:23.491017Z",
"err_symbol": "ER_SERVER_STARTUP_MSG",
"SQL_state": "HY000",
"subsystem": "Server",
"label": "System"
}
73/83
Slide 75
Slide 75 text
エラーログで
ついでに思い
出した
74/83
Slide 76
Slide 76 text
有名なアレ
mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.
key_buffer_size=67108864
read_buffer_size=2093056
max_used_connections=0
max_connections=3000
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 30773
512 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
75/83
Slide 77
Slide 77 text
実はこのメッセージはハードコード
115 my_safe_printf_stderr("%s",
116 "This could be because you hit a bug.
It is also "
117 "possible that this binary\n"
118 "or one of the libraries it was linke
d against is "
119 "corrupt, improperly built,\n"
120 "or misconfigured. This error can als
o be caused by "
121 "malfunctioning hardware.\n");
sql/signal_handler.cc
76/83
Slide 78
Slide 78 text
未だに key_buffer_size がどうこう言うのも
単にハードコードされてるのを直してないだけ
innodb_buffer_pool_size が出てこないのも単に直してないだけ
‐
130 my_safe_printf_stderr("key_buffer_size=%lu\n",
131 (ulong)dflt_key_cache->key_cache_mem_
size);
sql/signal_handler.cc
77/83
Slide 79
Slide 79 text
handle_fatal_signal に対する雑な所感
signal 11(SIGSEGV)だと本物の（？）バグっぽさが上がる
signal 6(SIGABRT)はAssertionに引っかかってるケース
多くの場合、InnoDBのページ破損とかになるんじゃなかろうか
‐
この場合はバグじゃないからあの固定メッセージ出さなくて良い気
が…
‐
handle_fatal_signal が何も言わない時はsignal 9なので
OOM Killerさんの可能性が非常に高い
78/83
Slide 80
Slide 80 text
あと、何かの名残
5.1, 5.5, 5.6にはこんな分岐があった
未実装のまま5.7からは消えてる
‐
1160 switch (error_log_printer) {
1161 case LOG_FILE:
1162 error_log_handler_list[0]= file_log_handler;
1163 error_log_handler_list[1]= 0;
1164 break;
1165 /* these two are disabled for now */
1166 case LOG_TABLE:
1167 DBUG_ASSERT(0);
1168 break;
1169 case LOG_TABLE|LOG_FILE:
1170 DBUG_ASSERT(0);
1171 break;
1172 }
sql/log.cc
79/83
Slide 81
Slide 81 text
それを言い出すとmysqld_safeのエラーログ
これもシェルスクリプトの中で各コマンドの標準出力と標準
エラー出力をリダイレクトでファイルに向けているだけ
mysqldのログがsyslogに吐けるようになったのは最近だけ
どmysqld_safeのログが昔っから吐けたのは単にloggerコマ
ンドを使えば良かったから
mysqldの方はログを書き込む関数を呼ばずにあちこちまちまちに書
いてたのでそれを統合するところから始まったんだと思う
‐
そんなのもあってログ用の関数はメジャーバージョンのたびにガリガ
リ書き換わってるので、ストレージエンジンとかで真面目にそこを呼
んでいるお行儀の良いやつはマクロで大変な気がする
‐
80/83
Slide 82
Slide 82 text
おっと何
の話だ
81/83
Slide 83
Slide 83 text
まとめ
エラーにはクライアントサイドエラーとサーバーサイドエ
ラーがある
サーバーサイドエラーはものによって汎用的すぎるエラーが
あったり、特化しすぎたエラーがあったりでグレッパビリ
ティーが変わる
エラーログ駆動でソースコードを読むのは楽しい
See also, エラーログドリブン ソースコードリーディング(ただし
MySQLに限る) | GMOメディア エンジニアブログ
‐
82/83
Slide 84
Slide 84 text
Any Questions
and/or
Suggestions?
83/83