sysbenchで実際に実行しているクエリを眺めたい

はじめに

以前、MariaDBに対してのベンチマークをsysbenchで実施してみました。

MariaDB(mysql)をsysbenchでベンチマークする

でも、実際にどんなクエリを使っているんでしょうか。

環境

target	version
OS	CentOS 6.9
MariaDB	10.2.10
sysbench	1.0.9

全てのクエリをログに出す

slow__queryの時間を0にすればいいのですが、general_quer_logを有効にしてみましょう。

General Query Log

公式ドキュメント通り、my.cnfに以下を追加します。

my.cnf

[mysqld]
general-log
general-log-file=queries.log
log-output=file

serviceを再起動すると、general query logが有効になります。

ログインして、データベース一覧を見てみた結果です。

操作

# mysql -uroot
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 9
Server version: 10.2.10-MariaDB-log MariaDB Server

Copyright (c) 2000, 2017, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| mysql              |
| performance_schema |
| sbtest             |
| test               |
+--------------------+
5 rows in set (0.00 sec)

クエリログ

/var/lib/mysql/queries.log

/usr/sbin/mysqld, Version: 10.2.10-MariaDB-log (MariaDB Server). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
171128 16:14:55     8 Connect   root@localhost as anonymous on 
                    8 Quit 
171128 16:15:24     9 Connect   root@localhost as anonymous on 
                    9 Query     select @@version_comment limit 1
171128 16:15:34     9 Query     show databases

ベンチマーク

使っているlua scriptはこれ。

/usr/share/sysbench/oltp_read_write.lua

githubではこちら。

oltp_commonを見ないとなんとも言えませんね。

実行scriptは冒頭で紹介した記事をご覧ください。

事前準備(CREATE TABLE)

1000000レコードのtableを事前に作成してるんですがinsert文が死ぬほど出でビビりました。これだけで186MB。

# ll -h /var/lib/mysql/queries.log
-rw-rw----. 1 mysql mysql 186M 11月 28 16:20 2017 /var/lib/mysql/queries.log

実行しているクエリはこんな感じ。冒頭だけですが。ランダムに生成したらしい文字列を大量にINSERTしています。

                   11 Query     CREATE TABLE sbtest1(
  id INTEGER NOT NULL AUTO_INCREMENT,
  k INTEGER DEFAULT '0' NOT NULL,
  c CHAR(120) DEFAULT '' NOT NULL,
  pad CHAR(60) DEFAULT '' NOT NULL,
  PRIMARY KEY (id)
) /*! ENGINE = innodb */
                   11 Query     INSERT INTO sbtest1(k, c, pad) VALUES(499284, '83868641912-28773972837-60736120486-75162659906-27563526494-20381887404-41576422241-93426793964-56405065102-33518432330', '67847967377-48000963322-62604785301-91415491898-96926520291'),

実行

60秒間、readとwriteを実施してみました。

実行結果

# ./sysbench.sh run
sysbench 1.0.9 (using system LuaJIT 2.0.4)

Running the test with following options:
Number of threads: 1
Initializing random number generator from current time


Initializing worker threads...

Threads started!

SQL statistics:
    queries performed:
        read:                            233002
        write:                           66572
        other:                           33286
        total:                           332860
    transactions:                        16643  (277.37 per sec.)
    queries:                             332860 (5547.44 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          60.0009s
    total number of events:              16643

Latency (ms):
         min:                                  2.94
         avg:                                  3.60
         max:                                367.76
         95th percentile:                      3.82
         sum:                              59959.92

Threads fairness:
    events (avg/stddev):           16643.0000/0.00
    execution time (avg/stddev):   59.9599/0.00

60秒間に16643 transaction実行できました。

クエリログ

                   12 Query     BEGIN
                   12 Query     SELECT c FROM sbtest1 WHERE id=501672
                   12 Query     SELECT c FROM sbtest1 WHERE id=497507
                   12 Query     SELECT c FROM sbtest1 WHERE id=502317
                   12 Query     SELECT c FROM sbtest1 WHERE id=619375
                   12 Query     SELECT c FROM sbtest1 WHERE id=498242
                   12 Query     SELECT c FROM sbtest1 WHERE id=504622
                   12 Query     SELECT c FROM sbtest1 WHERE id=503902
                   12 Query     SELECT c FROM sbtest1 WHERE id=504343
                   12 Query     SELECT c FROM sbtest1 WHERE id=498982
                   12 Query     SELECT c FROM sbtest1 WHERE id=647054
                   12 Query     SELECT c FROM sbtest1 WHERE id BETWEEN 499669 AND 499768
                   12 Query     SELECT SUM(k) FROM sbtest1 WHERE id BETWEEN 471655 AND 471754
                   12 Query     SELECT c FROM sbtest1 WHERE id BETWEEN 497559 AND 497658 ORDER BY c
                   12 Query     SELECT DISTINCT c FROM sbtest1 WHERE id BETWEEN 500376 AND 500475 ORDER BY c
                   12 Query     UPDATE sbtest1 SET k=k+1 WHERE id=630815
                   12 Query     UPDATE sbtest1 SET c='02880234208-10973640075-17668219584-46559619296-73328477817-23498294048-05436719100-83231271866-50754095991-28768938853' WHERE id=500340
                   12 Query     DELETE FROM sbtest1 WHERE id=498369
                   12 Query     DELETE FROM sbtest1 WHERE id=498369
                   12 Query     INSERT INTO sbtest1 (id, k, c, pad) VALUES (498369, 500157, '44640943269-61112078666-61150008978-19901826863-58303268247-94163699767-94879471345-52517202750-51527356439-08757128412', '22876116924-84196778171-42596827938-26341949807-35047522887')
                   12 Query     COMMIT

ランダムなidのSELECTから、計算、UPDATE、DELETE、INSERTがそれぞれ行われ、一定単位でCOMMITが行われています。このBEGIN～COMMITの集まりが何度も繰り返されているようです。

lua scriptを見比べる

上記クエリログ結果を踏まえて、もう一度lua scriptを眺めてみましょう。

上記で述べた1単位は、最後にcommitがあることから、eventのfunctionでしょう。(L44)

1. skip_trxというoptionがなければbegin
2. select文実行。今回は10回実施。
3. range_selectsというoptionがあれば、次4つ実施 3.1 BETWEENで適当な範囲をselect 3.2 BETWEENで適当な範囲をsum計算 3.3 ORDER byを使って並べ替え 3.4 適当な範囲のものをDISTINCTで重複排除
4. indexを更新するUPDATE
5. indexを更新しないUPDATE
6. DELETE2つとINSERT1つ実施
7. skip_trxというoptionがなければcommit

trxはtransacionの略でしょうか？これをskipする場合はbeginとcommitが行われません。
range_selectsはその名の通り一定範囲のselectを実施して何か処理するという処理群ですね。

importしているoltp_common.luaを見ると、より詳細な実行内容が記載されています。

これらをよく読めば、自分のオリジナルのテスト計画を作ることができそうですね。

おわりに

何事も実行されている内容が分からないままでは不安な気持ちになりますよね。確認できてよかったです。

• general query logを出力し、sysbenchで実行している実際のクエリを確認しました
• general query logの内容と読み込んでいるlua scriptを見比べました

おしまい。