GA

2025/03/17

slow_query_log / long_query_time / log_output でどれくらい違うかベンチマークその1

TL;DR

  • 特に何の結論もまだ出ていないベンチマーク
    • スローログをテーブルに吐かせるのって現実的かどうかを見たかっただけ
  • --threads=3 なのでもうちょっと並列性を上げないと本番向きではない
  • ジェネラルログファイル吐かせるのとスロークエリログ全部吐かせるのは同じくらい性能劣化するよなあと思ってた(どっちもmutexは1つしかないから)けどこれくらいだと差はよくわからない
  • CSVストレージエンジン遅い…ファイルサイズを大きくしていくともっと遅くなるかも?

久しぶりにベンチマーク取った。

ベンチマーク元: 8 CPUスレッド / 16GB Memory
ベンチマーク先: 2 CPUスレッド / 4GB Memory / 128MB buffer_pool / 10テーブルで100MB ibd (でも実際には42MBくらいしかバッファプールに載ってないので空きページはあるはず)

コマンド:

sysbench --mysql-host=bench --mysql-user=sbtest --mysql-password="sbtest" oltp_point_select --tables=10 --threads=3 --time=300 run --report-interval=1

メトリクスとサマリ:

slow_query_log long_query_time general_log log_output oltp_point_select_QPS memo
OFF 10 OFF FILE 11228.18 なにもログ出力ない状態
OFF 10 ON FILE 10629.95 ジェネラルログファイル
OFF 10 ON TABLE 9633.38 ジェネラルログテーブル
ON 10 OFF FILE 10714.53 スローログファイル有効だけど実質何も書かない
ON 0 OFF FILE 10900.19 来たクエリ全部スローログファイル
ON 0 OFF TABLE 10279.01 来たクエリ全部スローログテーブル

左の山から順に「何もログ出力ない」「ジェネラルログファイル」「ジェネラルログテーブル」「スローログ有効だけど実質何も書かない」「全部スローログファイル」「全部スローログテーブル」

  • performance_schema的にはcsv_readとcsv_writeが載ってるっぽい。だとするとサイズが大きくなるとオーバーヘッド載る?

  • iowaitは無視できる程度

2025/03/14

FLUSH TABLES WITH READ LOCK vs 実行中のクエリ

TL;DR

  • FLUSH TABLES WITH READ LOCK は「今まさに実行中のクエリ」と競合する
    • メタデータロックと違って「生きているトランザクション」ではなくて「今まさに実行中のクエリ」とだけ
    • WITH READ LOCK という名前ではあれど FLUSH TABLES なので SELECT とも競合する
  • FLUSH TABLES WITH READ LOCK は先に全体に GLOBAL read lock を置いてから1つずつテーブルを FLUSH する
  • FLUSH TABLES WITH READ LOCK をタイムアウトさせてもセッションを閉じない限り FLUSH待ちロック は解放されない

FLUSH TABLES WITH READ LOCK は実行中のクエリと競合する。
t1, t2, t3のテーブルがあって、t2にすごく時間がかかるクエリを実行している場合、

mysql80 44> SHOW TABLES;
+--------------+
| Tables_in_d1 |
+--------------+
| t1           |
| t2           |
| t3           |
+--------------+
3 rows in set (0.00 sec)

mysql80 44> SELECT SLEEP(100) FROM t2;

あとからやってきた FLUSH TABLES WITH READ LOCK は噛まれる。

mysql80 57> SHOW PROCESSLIST;
+----+-----------------+------------------+------+---------+--------+------------------------+---------------------------+
| Id | User            | Host             | db   | Command | Time   | State                  | Info                      |
+----+-----------------+------------------+------+---------+--------+------------------------+---------------------------+
| 44 | root            | localhost        | d1   | Query   |     12 | User sleep             | SELECT SLEEP(100) FROM t2 |
| 57 | root            | localhost        | d1   | Query   |      0 | init                   | SHOW PROCESSLIST          |
+----+-----------------+------------------+------+---------+--------+------------------------+---------------------------+

mysql80 57> FLUSH TABLES WITH READ LOCK;  --- 噛まれる

噛まれている FLUSH TABLES WITH READ LOCKSHOW PROCESSLIST で見るとこんな感じで、 Waiting for table flush で待つ。

mysql80 61> SHOW PROCESSLIST;
+----+-----------------+------------------+------+---------+--------+-------------------------+-----------------------------+
| Id | User            | Host             | db   | Command | Time   | State                   | Info                        |
+----+-----------------+------------------+------+---------+--------+-------------------------+-----------------------------+
|  5 | event_scheduler | localhost        | NULL | Daemon  | 178726 | Waiting on empty queue  | NULL                        |
| 44 | root            | localhost        | d1   | Query   |     72 | User sleep              | SELECT SLEEP(100) FROM t2   |
| 57 | root            | localhost        | d1   | Query   |     55 | Waiting for table flush | FLUSH TABLES WITH READ LOCK |
| 61 | root            | localhost        | d1   | Query   |      0 | init                    | SHOW PROCESSLIST            |
+----+-----------------+------------------+------+---------+--------+-------------------------+-----------------------------+

FLUSH TABLES WITH READ LOCK は最初(テーブルのFLUSHを始めるより前)に GLOBAL read lock( thd->global_read_lock.lock_global_read_lock(thd) を置く。これによって先にMySQL全体が書き込みをブロックされる。

この時点では、

table read write
t1 OK Blocked(waiting for global read lock)
t2 Blocked(waiting for table flush) Blocked(waiting for global read lock)
t3 OK Blocked(waiting for global read lock)

こうなる。

ところでこういう事態を防ぐために lock_wait_timeout があって FLUSH TABLES WITH READ LOCK がロック待ちになった時にタイムアウトさせられるんだけれど

mysql80 23> SET SESSION lock_wait_timeout = 1;
Query OK, 0 rows affected (0.01 sec)

mysql80 23> FLUSH TABLES WITH READ LOCK;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

何故かタイムアウトした後も FLUSH TABLES WITH READ LOCK の影響が収まらない。

mysql80 24> DELETE FROM t1;  -- 噛まれる

mysql80 25> SELECT * FROM t2;  -- 噛まれる

mysql80 26> SHOW PROCESSLIST;
+----+-----------------+-----------+------+---------+-------+------------------------------+---------------------------+
| Id | User            | Host      | db   | Command | Time  | State                        | Info                      |
+----+-----------------+-----------+------+---------+-------+------------------------------+---------------------------+
|  5 | event_scheduler | localhost | NULL | Daemon  | 22347 | Waiting on empty queue       | NULL                      |
| 13 | root            | localhost | d1   | Query   |    98 | User sleep                   | SELECT SLEEP(100) FROM t2 |
| 23 | root            | localhost | d1   | Sleep   |    75 |                              | NULL                      |        <---- これがFLUSH TABLES WITH READ LOCKがタイムアウトしたやつ
| 24 | root            | localhost | d1   | Query   |    15 | Waiting for global read lock | DELETE FROM t1            |
| 25 | root            | localhost | d1   | Query   |     6 | Waiting for table flush      | SELECT * FROM t2          |
| 26 | root            | localhost | NULL | Query   |     0 | init                         | SHOW PROCESSLIST          |
+----+-----------------+-----------+------+---------+-------+------------------------------+---------------------------+

思わぬ巻き込み事故に注意…というかこれバグっぽくない…?

【2025/03/20 21:14】

TL;DRには書いてあったけど、これに当たった場合は 「FLUSH TABLES WITH READ LOCKをブロックしたコネクション」をKILLする(クエリではなくてコネクションごとKILLする)

↑の例なら KILL 13 で復旧する。


【2025/03/14 18:59】

バグレポートしておいた

MySQL Bugs: #117707: FLUSH TABLES WITH READ LOCK timeout, but doesn't release the locks 
https://bugs.mysql.com/bug.php?id=117707

2025/03/10

MySQL 8.0ではINT系のデータ幅表記をdeprecatedにした…けれども

TL;DR


MySQL 8.0では INT, TINYINT, BIGINT, ..etc. で (xx) な桁数指定をしようとするとワーニングを吐く。
これはもともと整数系の桁数括弧書きは ZEROFILL 属性のためのパラメータで、DECIMALのように桁数を制限するものではなかったので、 ZEROFILL を使っていなければ単に無視すれば良い。

mysql80 18> CREATE TABLE t1 (tinyint_signed_1 TINYINT(1) SIGNED, tinyint_unsigned_1 TINYINT(1) UNSIGNED, tinyint_signed_2 TINYINT(2) SIGNED, tinyint_unsigned_2 TINYINT(2) UNSIGNED);
Query OK, 0 rows affected, 4 warnings (0.02 sec)

mysql80 18> SHOW WARNINGS;
+---------+------+------------------------------------------------------------------------------+
| Level   | Code | Message                                                                      |
+---------+------+------------------------------------------------------------------------------+
| Warning | 1681 | Integer display width is deprecated and will be removed in a future release. |
| Warning | 1681 | Integer display width is deprecated and will be removed in a future release. |
| Warning | 1681 | Integer display width is deprecated and will be removed in a future release. |
| Warning | 1681 | Integer display width is deprecated and will be removed in a future release. |
+---------+------+------------------------------------------------------------------------------+
4 rows in set (0.00 sec)

ところで TINYINT(1) といえば Connector/J がBoolean型にキャストすることで有名だが、桁数表記がサーバー側で無視されているとしたらJavaはこれをどう扱うんだろう…? と思った。

mysql80 18> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `tinyint_signed_1` tinyint(1) DEFAULT NULL,              ### <---- ここだけなんか違和感が
  `tinyint_unsigned_1` tinyint unsigned DEFAULT NULL,
  `tinyint_signed_2` tinyint DEFAULT NULL,
  `tinyint_unsigned_2` tinyint unsigned DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)

(つд⊂)ゴシゴシ

(;゚ Д゚) …!?

TINYINT(1) SIGNED の時だけ、データ型が tinyint(1) を返すようになっている。
どうやら意図したものらしい。

// Print TINYINT(1) since connectors use this to indicate BOOLEAN

ChatGPTにConnector/J側からの見え方を調べる方法を教えてもらった。

$ java -cp .:/usr/share/java/mysql-connector-java.jar MySQLColumnTypeViewer
Column Name | MySQL Type | Java Type
------------------------------------
tinyint_signed_1 | BIT        | Unknown
tinyint_unsigned_1 | TINYINT UNSIGNED | Byte
tinyint_signed_2 | TINYINT    | Byte
tinyint_unsigned_2 | TINYINT UNSIGNED | Byte

ああちゃんと特別扱いしてるっぽい…。

というか field_length 自体はまだ持ってるのね…。

2025/03/03

古いバージョンのxtrabackupをビルドしようとしたら -DDOWNLOAD_BOOST=1 だとダウンロードできなかった

TL;DR

  • boostを同梱していないMySQLやxtrabackupでboostのダウンロードっぽいところでcmakeが転けていたら cmake/boost.cmake を編集するとうまくいくことがある
    • boostorg.jfrog.io から archives.boost.io に変わってるっぽい

yoku0825/xtrabackup-monkey-patch を使って XtraBackup 8.0.35-31 をビルドしようと思ったら、boostをダウンロードしてるっぽいところで転けた。

$ git clone git@github.com:yoku0825/xtrabackup-monkey-patch
$ cd xtrabackup-monkey-patch
$ git checkout checkout 8.0.35-31

$ cd src
$ cmake -DCMAKE_INSTALL_PREFIX=~/xb-8.0.35-1 -DWITH_BOOST=./boost -DDOWNLOAD_BOOST=1 -DFORCE_INSOURCE_BUILD=1
..
-- Downloading boost_1_77_0.tar.bz2 to /home/yoku0825/git/xtrabackup-monkey-patch/src/boost
-- [download 100% complete]
-- [download 9% complete]
-- [download 22% complete]
-- [download 34% complete]
-- [download 46% complete]
-- [download 58% complete]
-- [download 70% complete]
-- [download 82% complete]
-- [download 94% complete]
-- [download 100% complete]
-- cd /home/yoku0825/git/xtrabackup-monkey-patch/src/boost; tar xfj /home/yoku0825/git/xtrabackup-monkey-patch/src/boost/boost_1_77_0.tar.bz2
CMake Error: Problem with archive_read_open_file(): Unrecognized archive format
CMake Error: Problem extracting tar: /home/yoku0825/git/xtrabackup-monkey-patch/src/boost/boost_1_77_0.tar.bz2
-- WITH_BOOST /home/yoku0825/git/xtrabackup-monkey-patch/src/boost.
-- Failed to extract files.
   Please try downloading and extracting yourself.
   The url is: https://boostorg.jfrog.io/artifactory/main/release/1.77.0/source/boost_1_77_0.tar.bz2
CMake Error at cmake/boost.cmake:256 (MESSAGE):
  Giving up.
Call Stack (most recent call first):
  CMakeLists.txt:1567 (INCLUDE)

-- Configuring incomplete, errors occurred!

DOWNLOAD_BOOSTのあたりで転けている様子…。

$ ll /home/yoku0825/git/xtrabackup-monkey-patch/src/boost/boost_1_77_0.tar.bz2
-rw-r--r--. 1 yoku0825 yoku0825 11534 Feb 20 07:21 /home/yoku0825/git/xtrabackup-monkey-patch/src/boost/boost_1_77_0.tar.bz2

$ file /home/yoku0825/git/xtrabackup-monkey-patch/src/boost/boost_1_77_0.tar.bz2
/home/yoku0825/git/xtrabackup-monkey-patch/src/boost/boost_1_77_0.tar.bz2: HTML document, ASCII text, with very long lines

$ w3m -no-mouse -T text/html /home/yoku0825/git/xtrabackup-monkey-patch/src/boost/boost_1_77_0.tar.bz2 | cat
bunzip2: (stdin) is not a bzip2 file.

ブラウザで https://boostorg.jfrog.io/artifactory/main/release/ を開いてみると我々が期待しないような感じになっているのでたぶんここのURLが古い…。

$ grep -r boostorg.jfrog.io cmake/
cmake/boost.cmake:  "https://boostorg.jfrog.io/artifactory/main/release/1.77.0/source/${BOOST_TARBALL}"

cmake/boost.cmake の中で指定している。

本家8.0.41のcmake/boost.cmakearchives.boost.io に向いているのでそれを検索してみる。
jfrogと archives.boost.io の話題で正に Where is https://archives.boost.io/ hosted? · Issue #845 · boostorg/boost なんていうのが出てきたし、 Boost公式のダウンロードページ から辿れるリンクも archives.boost.io に向いているので正しそう。

というわけでpushしました。

古いソースコードで同じようになるやつはこれで使えるようになるかも。