Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Dive into MySQL Error (YAPC::Tokyoバージョン)

yoku0825
January 26, 2019

Dive into MySQL Error (YAPC::Tokyoバージョン)

2019/01/26 YAPC::Tokyo 2019

yoku0825

January 26, 2019
Tweet

More Decks by yoku0825

Other Decks in Technology

Transcript

  1. Dive into MySQL Error
    第二雑学研究部、略してダイブ
    2019/01/26
    yoku0825
    YAPC::Tokyo 2019

    View Slide

  2. Dive into MySQL Error 第二雑学研究部、略してダイブ
    “MySQLの” エラーの仕組みを考えるセッションです
    “MySQLのエラー” をどう回避するか、ハンドルするか、という話は
    出てきません

    本トークはPerl成分を含みません
    変数の頭に $ がつかない言語にご注意ください

    1/83

    View Slide

  3. Chiba.pmの
    方から来まし

    2/83

    View Slide

  4. Chiba.pm
    の “m” は
    3/83

    View Slide

  5. MySQL
    の “m”!
    4/83

    View Slide

  6. ※諸説あ

    5/83

    View Slide

  7. じゃあ…準備
    はいいですか
    ね?
    6/83

    View Slide

  8. せーの
    7/83

    View Slide

  9. \こんに千葉!/
    (c) @hokke_mirin
    8/83

    View Slide

  10. ( ´-`).oO(東
    京の西側から来た
    なんて言えない
    9/83

    View Slide

  11. \こんに千葉!/ (c) @hokke_mirin
    yoku0825@とある企業のDBA
    オラクれない

    ポスグれない

    マイエスキューエる

    Perl Monger!!
    ytkit - Yoku-san no ToolKIT
    Contributor of innotop

    生息域
    Twitter: @yoku0825

    Blog: 日々の覚書

    日本MySQLユーザ会

    MySQL Casual

    10/83

    View Slide

  12. MySQLのエ
    ラーの話をし
    ます
    11/83

    View Slide

  13. 存分にダイブ
    しましょう
    12/83

    View Slide

  14. MySQLのエラーってこんなやつ
    ERROR 2002 (HY000): Can't connect to local MySQL server through
    socket '/tmp/mysql.sock' (2)
    13/83

    View Slide

  15. 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

    View Slide

  16. 「MySQLのエラー」と言ってもいくつかあって
    MySQLサーバーの異常
    MySQLサーバーからクライアントに返すネガティブな応答
    クライアントライブラリーの異常
    15/83

    View Slide

  17. 「MySQLのエラー」と言ってもいくつかあって
    MySQLサーバーの異常
    MySQLサーバーからクライアントに返すネガティブな応答
    クライアントライブラリーの異常
    16/83

    View Slide

  18. MySQLサーバーからクライアントに返すネガティブな応

    認証失敗
    権限の不足
    SQLシンタックスエラー
    デッドロック検出
    タイムアウト
    ..etc.
    17/83

    View Slide

  19. 余談
    “ER_LOCK_DEADLOCK”, 1213, “Deadlock found when
    trying to get lock; try restarting transaction”
    「デッドロックした」んじゃなくて、「デッドロックになり
    そうな気配がしたのでロールバックした」という意味のネガ
    ティブメッセージ
    bugs.mysql.comとかで「デッドロック」というと「本当に
    デッドロックしてタイムアウトするまで身動きが取れなく
    なってるやつ」のこと
    18/83

    View Slide

  20. MySQLのエラーパケットの構成
    19/83

    View Slide

  21. エラーコード分類
    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

    View Slide

  22. ( ´-`).oO(どうせな
    ら「リトライして成功す
    る可能性のないエラー」
    も体系にしてくれると嬉
    しかったのに…
    21/83

    View Slide

  23. 「MySQLのエラー」と言ってもいくつかあって(again)
    MySQLサーバーの異常
    MySQLサーバーからクライアントに返すネガティブな応答
    クライアントライブラリーの異常
    22/83

    View Slide

  24. 「MySQLのエラー」と言ってもいくつかあって(again)
    MySQLサーバーの異常
    プラグインやレプリケーションの “Initialization Failure” みたいな
    のはある

    それ以外はAssertion FailureだったりSegmentation Faultだったり
    でコア吐いたり、本物のデッドロックでストールしてたり

    MySQLサーバーからクライアントに返すネガティブな応答
    概ね1000番台、5.7からたまに3000番台

    クライアントライブラリーの異常
    概ね2000番台(libmysqlclient.soの場合)

    クライアントライブラリーの実装に依存

    23/83

    View Slide

  25. 最初につけられるアタリ
    クライアントサイドのエラー(2000番台)なら、そもそも
    サーバーに到達していない可能性がある
    何らかの理由でサーバーが拒否ってるだけなら1000番台か3000番台
    になるから

    ネットワーク経路的な問題が一番多い気がする

    クライアントサイドエラーでも、まれにサーバーがエラーに
    絡んでいることもある
    クライアントライブラリーの互換性の問題

    サーバー側からのコネクション強制切断

    24/83

    View Slide

  26. 2002: CR_CONNECTION_ERROR
    ERROR 2002 (HY000): Can't connect to local MySQL server through
    socket '/tmp/mysql.sock' (2)
    25/83

    View Slide

  27. 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

    View Slide

  28. 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

    View Slide

  29. 2000番台エラーの特徴
    perror コマンドでは調べられ ない
    パッケージ的にサーバーの付属ユーティリティーだから、だと思う

    MySQL :: MySQL 8.0 Reference Manual :: 4.8.2 perror —
    Explain Error Codes

    OSエラーコードは perror コマンドで引ける

    OSエラーコードはたまにMySQLサーバーのエラーコードとカブるの
    で見失わないように…

    perror についてはあとで詳しく

    28/83

    View Slide

  30. 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

    View Slide

  31. 同じ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

    View Slide

  32. 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

    View Slide

  33. どこで切断されるかでエラー番号が変わる
    mysql-client mysqld
    TCP Handshake
    Greeting Message/Mess
    age Digest
    User/Digest
    Authentication
    SELECT ..
    Execute query
    long_time
    SELECT ..
    Execute query
    32/83

    View Slide

  34. どこで切断されるかでエラー番号が変わる
    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

    View Slide

  35. 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

    View Slide

  36. 2059: CR_AUTH_PLUGIN_CANNOT_LOAD
    クライアントが要求されたプラグインを見つけられないエ
    ラー。
    MySQL 8.0のサーバーに5.6のクライアントで接続しようと
    すると出る
    8.0のデフォルト認証プラグインは caching_sha2_password だが、こ
    れは5.6の時代には実装されていなかったため、クライアントはそん
    なプラグインを知らない。

    35/83

    View Slide

  37. 実はもう1種類ある
    クライアントから送られてきたクライアントケーパビリ
    ティーで「要求する認証プラグインにクライアントが対応し
    ていないことがわかっちゃった」のでサーバーから接続を拒
    否。
    ERROR 1251 (08004): Client does not support authentication protoc
    ol requested by server; consider upgrading MySQL client
    36/83

    View Slide

  38. どこで認証に失敗するかでエラー番号が変わる
    mysql-client mysqld
    TCP Handshake
    Greeting Message/Mess
    age Digest
    User/Digest
    Authentication
    SELECT ..
    Execute query
    long_time
    SELECT ..
    Execute query
    37/83

    View Slide

  39. どこで認証に失敗するかでエラー番号が変わる
    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

    View Slide

  40. libmysqlclient.so
    製品名称は MySQL Connector/C
    MySQLサーバーにバンドルされている
    コイツをバインドしているのは PerlのDBD::mysql とか
    Rubyのmysql2とか
    PHPのmysqlnd, JavaのConnecor/J, PerlのNet::MySQL(!)とかは
    独自実装

    39/83

    View Slide

  41. 2000番台エラーの応用(?)
    レプリケーションスレーブ(のI/Oスレッド)はマスターか
    ら見ると クライアント
    しかも必ずlibmysqlclient.so実装のクライアント

    Last_IO_Error に2000番台のエラーが出ることがまれにだ
    がよくある
    ここで1000番台、2000番台の切り分けをスムーズにこなすとデキる
    MySQLerっぽい

    40/83

    View Slide

  42. Last_IO_ErrorはOSエラーコードが出てくれないのが
    ちょっと痛い
    少なくとも認証失敗(1000番台)でないことはわかる
    Last_IO_Errno: 2003
    Last_IO_Error: error connecting to master '[email protected]
    27.0.0.1:64057' - retry-time: 60 retries: 1
    クライアントサイドエラーコードの一覧は include/
    errmsg.h に
    41/83

    View Slide

  43. おまけ: 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

    View Slide

  44. ひどい XD
    個人の意見です
    43/83

    View Slide

  45. エラーコード分類
    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

    View Slide

  46. 次ににつけられるアタリ
    1000番台、3000番台ならサーバーが明示的に「エラー応答」を
    返している
    ERRパケットの中には「サーバーサイドエラーコード」「SQLス
    テート」「エラーメッセージ」が入っている
    45/83

    View Slide

  47. たとえば
    エラーコード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

    View Slide

  48. SQLステート
    サーバーサイドエラーコードとSQLステートは1対多で結び
    つく
    なので、積極的にSQLステートを使うクライアントでなければエラー
    コードの方が追いやすい

    Wikipediaさん後は頼んだ
    SQLSTATE - Wikipedia

    47/83

    View Slide

  49. エラーメッセージ
    豆だけど実は日本語にできる
    lc_messages=ja

    MySQL :: MySQL 5.6 リファレンスマニュアル :: 10.2 エラーメッ
    セージ言語の設定

    48/83

    View Slide

  50. 誰得
    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

    View Slide

  51. 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

    View Slide

  52. perrorコマンド
    さっきから何度か出てきている perror コマンド
    パッケージ的には mysql-server 系に付属している
    引数にエラーコードを受けて、エラーメッセージのフォー
    マットを出力する
    エラー番号からだけでもエラーメッセージを推測できる

    エラー番号からマクロ名が取り出せるのでgrepが捗る

    マクロ名しか書いてない(ことはまずないと思うけど)からエラー番
    号とメッセージが取れる

    MySQL :: MySQL 5.6 リファレンスマニュアル :: 4.8.1
    perror — エラーコードの説明
    51/83

    View Slide

  53. 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

    View Slide

  54. 1593: ER_BINLOG_FATAL_ERROR
    perrorで引くとほとんどが可変部分で、このエラーコードが
    示すものは “Fatal error” しかない(あとは全部状況で変わ
    る)
    $ perror 1593
    MySQL error code 1593 (ER_SLAVE_FATAL_ERROR): Fatal error: %s
    53/83

    View Slide

  55. じゃあどこでこのバリエーションが生まれるのか?
    エラーマクロが分かってれば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

    View Slide

  56. 慣れてくると
    mi は master_info のことでI/Oスレッド関連
    rli は relay_log_info のことでSQLスレッド関連
    それぞれ report は SHOW SLAVE STATUS で表示されるような
    バッファ(とエラーログ)に記録するためのメソッド
    55/83

    View Slide

  57. 慣れてくると
    $ 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

    View Slide

  58. 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

    View Slide

  59. $ がない以外
    はほぼPerl :D
    58/83

    View Slide

  60. エラーフォーマットからエラーの意味を察する
    可変部分は呼び出し元から文字列で渡されるので、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

    View Slide

  61. エラーフォーマットからエラーの意味を察する
    これは 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

    View Slide

  62. エラーフォーマットからエラーの意味を察する
    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

    View Slide

  63. エラーに触れるつい
    でにエラーログにつ
    いても触れておこう
    62/83

    View Slide

  64. 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

    View Slide

  65. 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

    View Slide

  66. stdoutとstderrが繋がっているだけなので
    プラグインの中で fprintf(stderr, ..) とかやるとフツーに
    エラーログに出る
    printデバッグする機会があれば憶えておいて損はないはず ;)

    InnoDB Monitor( CREATE TABLE innodb_monitor とか SET
    GLOBAL innodb_status_output = 1 )がなんでデフォルトで
    エラーログに書かれるのか…
    InnoDBからするとエラーログに書いてるつもりはなくて、単に標準
    エラー出力に書いているだけ

    ロガープロセスみたいなのがいるわけではない
    65/83

    View Slide

  67. 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

    View Slide

  68. 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

    View Slide

  69. プラガブルストレージエンジン
    今でこそMySQLのストレージエンジンといえばInnoDBだけ
    れども
    かつてMySQLは “MySQL AB.” が
    InnoDBは “Innobase Oy.” (後にOracleが買収) が
    それぞれ別々に開発していた
    68/83

    View Slide

  70. 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

    View Slide

  71. 閑話休題
    70/83

    View Slide

  72. プラガブルストレージエンジンのログ
    別のファイルに吐く
    1.
    Mroongaストレージエンジン( groonga.log )
    ISAMストレージエンジン (デバッグ用の log_isam オプショ
    ンはなんと8.0にもまだある)
    標準エラー出力に吐く
    1.
    InnoDBストレージエンジン
    NDBCLUSTERストレージエンジン(データノードは独自ロ
    グ)
    71/83

    View Slide

  73. 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

    View Slide

  74. 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

    View Slide

  75. エラーログで
    ついでに思い
    出した
    74/83

    View Slide

  76. 有名なアレ
    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

    View Slide

  77. 実はこのメッセージはハードコード
    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

    View Slide

  78. 未だに 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

    View Slide

  79. handle_fatal_signal に対する雑な所感
    signal 11(SIGSEGV)だと本物の(?)バグっぽさが上がる
    signal 6(SIGABRT)はAssertionに引っかかってるケース
    多くの場合、InnoDBのページ破損とかになるんじゃなかろうか

    この場合はバグじゃないからあの固定メッセージ出さなくて良い気
    が…

    handle_fatal_signal が何も言わない時はsignal 9なので
    OOM Killerさんの可能性が非常に高い
    78/83

    View Slide

  80. あと、何かの名残
    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

    View Slide

  81. それを言い出すとmysqld_safeのエラーログ
    これもシェルスクリプトの中で各コマンドの標準出力と標準
    エラー出力をリダイレクトでファイルに向けているだけ
    mysqldのログがsyslogに吐けるようになったのは最近だけ
    どmysqld_safeのログが昔っから吐けたのは単にloggerコマ
    ンドを使えば良かったから
    mysqldの方はログを書き込む関数を呼ばずにあちこちまちまちに書
    いてたのでそれを統合するところから始まったんだと思う

    そんなのもあってログ用の関数はメジャーバージョンのたびにガリガ
    リ書き換わってるので、ストレージエンジンとかで真面目にそこを呼
    んでいるお行儀の良いやつはマクロで大変な気がする

    80/83

    View Slide

  82. おっと何
    の話だ
    81/83

    View Slide

  83. まとめ
    エラーにはクライアントサイドエラーとサーバーサイドエ
    ラーがある
    サーバーサイドエラーはものによって汎用的すぎるエラーが
    あったり、特化しすぎたエラーがあったりでグレッパビリ
    ティーが変わる
    エラーログ駆動でソースコードを読むのは楽しい
    See also, エラーログドリブン ソースコードリーディング(ただし
    MySQLに限る) | GMOメディア エンジニアブログ

    82/83

    View Slide

  84. Any Questions
    and/or
    Suggestions?
    83/83

    View Slide