2016年5月16日月曜日

MySQL Routerの接続でMySQL Fabricのlogテーブルがあふれた(event_schedulerをOFFにするとあぶない)

MySQL Fabricには /etc/mysql/fabric.cfg の [logging]セクションの他にもログを取る部分が仕込まれていて、


mysql> SELECT * FROM fabric.log;
+---------------------------+----------------------------+------------------------------+-----------------------------------------------------------------------+----------+------+
| subject                   | reported                   | reporter                     | message                                                               | category | type |
+---------------------------+----------------------------+------------------------------+-----------------------------------------------------------------------+----------+------+
| 0                         | 2016-05-16 06:48:47.000000 | mysql.fabric.services.manage | Fabric node version (1.5.6) started.                                  |        0 |    0 |
| manage.ping               | 2016-05-16 06:48:52.000000 | mysql.fabric.command         | Started command (manage, ping).                                       |        1 |    0 |
| manage.ping               | 2016-05-16 06:48:52.000000 | mysql.fabric.command         | Finished command (manage, ping).                                      |        1 |    1 |
..
| dump.servers              | 2016-05-16 06:55:53.000000 | mysql.fabric.command         | Finished command (dump, servers).                                     |        1 |    1 |
| dump.sharding_information | 2016-05-16 06:55:53.000000 | mysql.fabric.command         | Started command (dump, sharding_information).                         |        1 |    0 |
| dump.sharding_information | 2016-05-16 06:55:53.000000 | mysql.fabric.command         | Finished command (dump, sharding_information).                        |        1 |    1 |
+---------------------------+----------------------------+------------------------------+-----------------------------------------------------------------------+----------+------+
1297 rows in set (0.02 sec)

なんというか、どぱーと吐いている。

( ´-`).oO(こんなトランザクションで保護される必要もなさそうな間っ平なログをMySQLに突っ込むとか、何考えてるのか小一時間問い詰めたい。


そしてなんか周辺の流れを見ても、何のフィルターもなく毎回INSERTされてるように見える。マジか(Python詳しい人誰か)

https://github.com/mysql/mysql-fabric/blob/release/1.5.5/lib/mysql/fabric/handler.py#L305-L307



$ mysqlbinlog -R -uroot -h 172.17.0.4 --stop-never -vv --start-position=182893 bin.000001 | grep "^#"
..

# at 285377
#160516 15:55:53 server id 1  end_log_pos 285408 CRC32 0x7f70413b       Xid = 5500
# at 285408
#160516 15:55:53 server id 1  end_log_pos 285473 CRC32 0xb35843f4       Anonymous_GTID  last_committed=772      sequence_number=773
# at 285473
#160516 15:55:53 server id 1  end_log_pos 285555 CRC32 0xd3de3d80       Query   thread_id=4     exec_time=0     error_code=0
# at 285555
#160516 15:55:53 server id 1  end_log_pos 285614 CRC32 0x12ff61e4       Table_map: `fabric`.`log` mapped to number 110
# at 285614
#160516 15:55:53 server id 1  end_log_pos 285734 CRC32 0x3c061fb3       Write_rows: table id 110 flags: STMT_END_F
### INSERT INTO `fabric`.`log`
### SET
###   @1='dump.servers' /* VARSTRING(120) meta=120 nullable=0 is_null=0 */
###   @2=1463349353.000000 /* TIMESTAMP(6) meta=6 nullable=0 is_null=0 */
###   @3='mysql.fabric.command' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @4='Finished command (dump, servers).' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
###   @5=1 /* INT meta=0 nullable=0 is_null=0 */
###   @6=1 /* INT meta=0 nullable=0 is_null=0 */
# at 285734
#160516 15:55:53 server id 1  end_log_pos 285765 CRC32 0x39af684e       Xid = 5508
# at 285765
#160516 15:55:53 server id 1  end_log_pos 285830 CRC32 0xe449e1fe       Anonymous_GTID  last_committed=773      sequence_number=774
# at 285830
#160516 15:55:53 server id 1  end_log_pos 285912 CRC32 0x239e9184       Query   thread_id=4     exec_time=0     error_code=0
# at 285912
#160516 15:55:53 server id 1  end_log_pos 285971 CRC32 0xe2235101       Table_map: `fabric`.`log` mapped to number 110
# at 285971
#160516 15:55:53 server id 1  end_log_pos 286116 CRC32 0xf5cc5f55       Write_rows: table id 110 flags: STMT_END_F
### INSERT INTO `fabric`.`log`
### SET
###   @1='dump.sharding_information' /* VARSTRING(120) meta=120 nullable=0 is_null=0 */
###   @2=1463349353.000000 /* TIMESTAMP(6) meta=6 nullable=0 is_null=0 */
###   @3='mysql.fabric.command' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @4='Started command (dump, sharding_information).' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
###   @5=1 /* INT meta=0 nullable=0 is_null=0 */
###   @6=0 /* INT meta=0 nullable=0 is_null=0 */

MySQL Routerを起動している間中、ずっとこれが来る。
それぞれのmysqlrouterから1秒に3リクエストずつ来ているらしく、そんな感じで倍々ゲームになっている:(;゙゚'ω゚'):

さてどうしようか。


【2016/05/17 13:46】

event_schedulerをOFFにしてたのがいけなかったのか!!!!

mysql> SELECT * FROM events\G
*************************** 1. row ***************************
       EVENT_CATALOG: def
        EVENT_SCHEMA: fabric
          EVENT_NAME: prune_log
             DEFINER: mikasa_fabric@127.0.0.1
           TIME_ZONE: SYSTEM
          EVENT_BODY: SQL
    EVENT_DEFINITION: DELETE FROM log WHERE TIMEDIFF(UTC_TIMESTAMP(), reported) > MAKETIME(3600,0,0)
          EVENT_TYPE: RECURRING
          EXECUTE_AT: NULL
      INTERVAL_VALUE: 3600
      INTERVAL_FIELD: SECOND
            SQL_MODE: NO_ENGINE_SUBSTITUTION
              STARTS: 2016-04-04 15:49:10
                ENDS: NULL
              STATUS: ENABLED
       ON_COMPLETION: NOT PRESERVE
             CREATED: 2016-04-04 15:49:10
        LAST_ALTERED: 2016-04-04 15:49:10
       LAST_EXECUTED: NULL
       EVENT_COMMENT:
          ORIGINATOR: 33893
CHARACTER_SET_CLIENT: utf8
COLLATION_CONNECTION: utf8_general_ci
  DATABASE_COLLATION: utf8_general_ci
*************************** 2. row ***************************
       EVENT_CATALOG: def
        EVENT_SCHEMA: fabric
          EVENT_NAME: prune_error_log
             DEFINER: mikasa_fabric@127.0.0.1
           TIME_ZONE: SYSTEM
          EVENT_BODY: SQL
    EVENT_DEFINITION: DELETE FROM error_log WHERE TIMEDIFF(UTC_TIMESTAMP(), reported) > MAKETIME(3600,0,0)
          EVENT_TYPE: RECURRING
          EXECUTE_AT: NULL
      INTERVAL_VALUE: 3600
      INTERVAL_FIELD: SECOND
            SQL_MODE: NO_ENGINE_SUBSTITUTION
              STARTS: 2016-04-04 15:49:11
                ENDS: NULL
              STATUS: ENABLED
       ON_COMPLETION: NOT PRESERVE
             CREATED: 2016-04-04 15:49:11
        LAST_ALTERED: 2016-04-04 15:49:11
       LAST_EXECUTED: NULL
       EVENT_COMMENT:
          ORIGINATOR: 33893
CHARACTER_SET_CLIENT: utf8
COLLATION_CONNECTION: utf8_general_ci
  DATABASE_COLLATION: utf8_general_ci
2 rows in set (0.00 sec)

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


MySQL Bugs: #73206: MySQL Fabric should report a warning when MySQL Event Scheduler is disabled




1. logテーブルをBlackhole化する

mysql> use fabric
mysql> ALTER TABLE log Engine= Blackhole;

一番最初にこれが出てくるのもなんだかななんだけど、なんとこれ無事に動く。
mysqlfabricデーモンを再起動してもフツーに動いた。マジか。


2. ロギングをすっ飛ばすようにMySQL Fabric側をゴニョる

$ diff -C1 /usr/lib/python2.6/site-packages/mysql/fabric/handler.py handler.py
*** /usr/lib/python2.6/site-packages/mysql/fabric/handler.py    2015-09-11 14:31:50.000000000 +0900
--- handler.py  2016-05-16 16:51:12.000000000 +0900
***************
*** 209,214 ****
          """
-         persister.exec_stmt(_INSERT_FABRIC_LOG,
-             {"params": (subject, reported, reporter, info, info_category,
-             info_type)}
-         )

--- 209,210 ----

これでももちろんMySQL Routerはちゃんと動く。


3. 定期的にlogテーブルからレコードをパージする

至極当たり前すぎる。
何故かすごくごちゃごちゃとインデックスが張ってあるので、reportedで期間を切って定期的に消すのはそんなに難しくないはずだ。
(最近のMySQLはOPTIMIZE TABLEもオンラインでできるのでー。。)

mysql> SHOW CREATE TABLE log\G
*************************** 1. row ***************************
       Table: log
Create Table: CREATE TABLE `log` (
  `subject` varchar(40) NOT NULL,
  `reported` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
  `reporter` varchar(64) NOT NULL,
  `message` text,
  `category` int(11) NOT NULL,
  `type` int(11) NOT NULL,
  KEY `key_subject_reported` (`subject`,`reported`),
  KEY `key_reporter` (`reporter`),
  KEY `key_reported` (`reported`),
  KEY `key_category` (`category`),
  KEY `key_type` (`type`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)


これ、実際に運用してる人はどうしてるんでしょうか。
お客様の中にMySQL Fabricを運用している方はいらっしゃいませんか?


…いらっしゃいませんね。

2016年5月9日月曜日

innotopが最近息してないなーと思ったんだ

使っている人口がどれくらいいるかわからないですが、 innotop というtopライクにMySQLの状況を表示してくれる便利スクリプトが世の中には存在しています。

日々の覚書: innotopがすごく便利

もともとGoogle Codeにホスティングされてたんだけど、Google Codeはサービス終了しちゃったから(いつからか知らないけど)GitHubに移行してて、ひょっとしたらこのまま(移行だけしてメンテナンスされなくなって)息を引き取るんじゃないか疑惑が当時から俺の中にあったりなかったり。


原因がそれかどうかは全く知らないけれど、 innotopは5.6までは問題なく使える(5.6で使えなくなった時にちゃんと対応された)んだけど、5.7だと `SHOW ENGINE INNODB STATUS` をパースできなくなっていて(それ以外は何とか使える)、随分前からこれはIssueに上がってるんだけど、全然直される気配がない。

App crash on the "T" and "L" pages · Issue #109 · innotop/innotop


というか、 "Support MySQL 5.7" と銘打たれたコミットがひどすぎて、テストすら通らない(何故マージされたし)

Support MySQL 5.7 by potto007 · Pull Request #114 · innotop/innotop


ちまちま直してったら、こんな転け方もした。日付が違う? 馬鹿な。

$ perl t/InnoDBParser.t
1..5
ok 1 - /home/yoku0825/git/innotop/t/innodb-status-007
ok 2 - /home/yoku0825/git/innotop/t/innodb-status-001
ok 3 - /home/yoku0825/git/innotop/t/innodb-status-002
not ok 4 - /home/yoku0825/git/innotop/t/innodb-status-009
#   Failed test '/home/yoku0825/git/innotop/t/innodb-status-009'
#   at InnoDBParser.t line 2193.
#     Structures begin differing at:
#          $got->{IB_timestring} = '2015-06-09 13:52:05'
#     $expected->{IB_timestring} = '2013-06-19 13:47:37'
ok 5 - /home/yoku0825/git/innotop/t/innodb-status-008
ok 6 - /home/yoku0825/git/innotop/t/innodb-status-006
# Looks like you planned 5 tests but ran 6.
# Looks like you failed 1 test of 6 run.


という訳でまずテストを直すPRした。これがマージされれば Issue #109のやつも頑張るかも知れない。これがマージされないようなら、 innotop は死んだんであろう(というか、死んだと思ってForkしてゴニョったやつをrpmbuildしたらテストが通らないのに気が付いた。。)

Fix broken test for 5.7 by yoku0825 · Pull Request #135 · innotop/innotop


出来れば死なずにメンテナンスされ続けて欲しいなーと思いつつ、今後どうなるかなぁ。。
(多少なら自分で使う分くらいは頑張れると思うんだけど、全面的にメンテナンスは無理だなきっと。。)


【2016/05/11 00:20】

2016年5月2日月曜日

はじめてのMySQLへのPull-Request体験談

の前に、いくつかMySQLへのContributeの前提を。

MySQLへのコードの寄贈は

1. Oracleプロファイルを持っていないといけない。ダウンロードする時に "No thanks" に気付かないと作らされるアレ。
2. Oracle Contributor Agreement にサインしないといけない(OCAにサインしたかどうかがOracleプロファイルに紐付けられる…ので、Oracleプロファイルが必要みたい)

が前提になる。


【2016/05/06 23:35】

ちなみにMariaDBの場合も似たようなもので

If you want the code to be part of the main MariaDB tree, you also have to give the MariaDB Foundation a shared copyright to your code. This is needed so that the foundation can offer the code to other projects (like MySQL).

You do this by either:

1. Signing the MariaDB Contributor Agreement (MCA) and then scanning and sending it to the foundation.
2. Sending an email to maria-developers where you say that your patch and all fixes to it are provided to the MariaDB Foundation under the MCA.
3. Licensing your code using the BSD license.
Contributing Code - MariaDB Knowledge Base

MCAにサインするか、パッチのライセンスを明示的にBSDにする必要がある。


これなしでいきなりPull-Requestしても多分蹴られる(ってか手違いで蹴られた)


前提について詳しくはこのへんの記事が読みやすくて良いと思う。




で、取り敢えず バグレポート を上げて、GitHubでも Pull-Request を出してみた。

予想としては
Hi, thank you for your contribution. Please confirm this code is submitted under the terms of the OCA (Oracle's Contribution Agreement) you have previously signed by cutting and pasting the following text as a comment:
"I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it."
Thanks

bug 79747: crc32 optimizations by grooverdan · Pull Request #68 · mysql/mysql-server

こんな感じで、「これコピペしてね」って言われると思ってたんだけどさにあらず。



Hi, thank you for submitting this pull request. In order to consider your code we need you to sign the Oracle Contribution Agreement (OCA). Please review the details and follow the instructions at http://www.oracle.com/technetwork/community/oca-486395.html
Please make sure to include your MySQL bug system user (email) in the returned form.
Thanks

Fix Bug#80833 by yoku0825 · Pull Request #102 · mysql/mysql-sys


(;・3・) アルェー、コピペしようにもコピペするべき文章が見当たらないぞー。

mysql/mysql-server と mysql/mysql-sys でbotが違うのかなぁと思いつつ、かるーく 梅ッシュ 最近のVerifiedおじさんことUmeshに「GitHubでPull-Request出したけど大丈夫ですかね?」的なジャブをかましてみるも、「大丈夫じゃね?」的な返答。

そして待つことしばし。


Hi, there was no response to our request to sign an OCA or confirm the code is submitted under the terms of the OCA. As such this request will be closed.
Thanks

Fix Bug#80833 by yoku0825 · Pull Request #102 · mysql/mysql-sys


Σ(゚д゚lll) confirm用のメッセージが表示されないまま「お前がconfirmしないからcloseするわー」ってなった!!!1


困った時の Lenkaちゃん 。
bugs.mysql.comにパッチを送り付けると、Lenkaちゃんから「受け取ったよ!」ってメールが来る(Lenkaちゃん宛てにbugs.mysql.comからメールが飛んでるっぽく、それを転送してくれるんだけど、どうもその時間差から察するに、自動転送ってわけではなさそう)ので、きっと彼女なら詳しいはず。

待つことしばし。


it looks like that for some reason I have not added (or it was somehow removed…) your GitHub name.
As a result the script did not know that you signed OCA.

( д ) ゚ ゚ ホワッ!?

そしてmysql-oca-botと同じアイコンの mysql-admin というアカウントによってreopenされるPull-Request。
https://github.com/mysql/mysql-sys/pull/102#issuecomment-215091765


その後は無事にbotによってbugs.mysql.comがアップデートされました。

Lenkaちゃんありがとう。



…ところでついさっき気付いたんだけど、俺、今まで一度も○racleさんにGitHubアカウント提出したことなかったや。。(今はOCAの段階で聞かれるのかしらん? 体験談求む)

取り敢えず困った時はLenkaちゃん。ありがとうございました(*-人-)