MySQLとPostgreSQLにおけるログの確認方法
TPCCなどをダウンロードして参照のみ、更新と参照、参照と更新の比率変更等して様々な負荷をかけてベンチマークする方が良いと思うが、カジュアルにベンチマークしたいケースもあると思います。毎回、同じ方法でベンチマークする事で、ある程度サーバーの構成変更時のパフォーマンスの変化を把握できるのでMySQLやPostgreSQLにバンドルされているベンチマークツールも便利なベンチマークオプションとして使える。取得したログを簡単に確認したり、実際に運用中のシステムのログも定期的に確認出来れば尚便利。そんなニーズに対して、カジュアルにメモしておきました。
PostgreSQL
postgres@ubuntu:~$ pgbench -i scaffold NOTICE: table "pgbench_history" does not exist, skipping NOTICE: table "pgbench_tellers" does not exist, skipping NOTICE: table "pgbench_accounts" does not exist, skipping NOTICE: table "pgbench_branches" does not exist, skipping creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.28 s, remaining 0.00 s) vacuum... set primary keys... done. postgres@ubuntu:~$ psql scaffold -c "\d" List of relations Schema | Name | Type | Owner --------+------------------+-------+---------- public | pgbench_accounts | table | postgres public | pgbench_branches | table | postgres public | pgbench_history | table | postgres public | pgbench_tellers | table | postgres (4 rows) postgres@ubuntu:~$ postgres@ubuntu:~$ pgbench -c 30 -t 1000 scaffold starting vacuum...end. transaction type: scaling factor: 1 query mode: simple number of clients: 30 number of threads: 1 number of transactions per client: 1000 number of transactions actually processed: 30000/30000 latency average = 41.333 ms tps = 725.808779 (including connections establishing) tps = 726.545616 (excluding connections establishing) postgres@ubuntu:~$ root@ubuntu:/var/log/postgresql# pgbadger postgresql-10-main.log [========================>] Parsed 96663 bytes of 96663 (100.00%), queries: 0, events: 301 LOG: Ok, generating html report... root@ubuntu:/var/log/postgresql# ls -l total 1392 -rw-r--r-- 1 root root 1324353 May 24 10:34 out.html -rw-r----- 1 postgres adm 96663 May 24 10:23 postgresql-10-main.log
pgbadger
*メモ:それぞれのパッケージは、aptもしくはyumでインストールしています。
MySQL
負荷をかけてログを記録
[root@GA02 admin]# /usr/local/mysql/bin/mysqlslap --no-defaults --create-schema=SQLSLAP --auto-generate-sql --auto-generate-sql-add-autoincrement --engine=InnoDB --number-int-cols=3 --number-char-cols=5 --concurrency=30 --auto-generate-sql-write-number=1000 --auto-generate-sql-execute-number=1000 --auto-generate-sql-load-type=mixed -u root -p Enter password: Benchmark Running for engine InnoDB Average number of seconds to run all queries: 19.724 seconds Minimum number of seconds to run all queries: 19.724 seconds Maximum number of seconds to run all queries: 19.724 seconds Number of clients running queries: 30 Average number of queries per client: 1000 [root@GA02 admin]#
mysqldumpslow (MySQL Default)でログ解析
[root@GA02 data]# mysqldumpslow -s c /usr/local/mysql/data/mysql-slow.log Reading mysql slow query log from /usr/local/mysql/data/mysql-slow.log Count: 17349 Time=0.03s (463s) Lock=0.00s (5s) Rows=0.0 (0), root[root]@localhost INSERT INTO t1 VALUES (NULL,N,N,N,'S','S','S','S','S') Count: 13375 Time=0.00s (2s) Lock=0.00s (1s) Rows=1.0 (13375), root[root]@localhost SELECT intcol1,intcol2,intcol3,charcol1,charcol2,charcol3,charcol4,charcol5 FROM t1 WHERE id = 'S' Count: 31 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (30), root[root]@localhost # Count: 31 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), 0users@0hosts administrator command: Quit
Percona Tool Kitでログ解析
[root@GA02 admin]# wget https://repo.percona.com/yum/percona-release-latest.noarch.rpm --2020-05-24 13:51:20-- https://repo.percona.com/yum/percona-release-latest.noarch.rpm repo.percona.com (repo.percona.com) をDNSに問いあわせています... 167.71.118.3, 157.245.119.64, 167.99.233.229 repo.percona.com (repo.percona.com)|167.71.118.3|:443 に接続しています... 接続しました。 HTTP による接続要求を送信しました、応答を待っています... 200 OK 長さ: 17684 (17K) [application/x-redhat-package-manager] `percona-release-latest.noarch.rpm' に保存中 100%[==============================================================================================================================================================================================>] 17,684 --.-K/s 時間 0s 2020-05-24 13:51:21 (51.5 GB/s) - `percona-release-latest.noarch.rpm' へ保存完了 [17684/17684] [root@GA02 admin]# yum install percona-release-latest.noarch.rpm 読み込んだプラグイン:fastestmirror, priorities percona-release-latest.noarch.rpm を調べています: percona-release-1.0-18.noarch 次のリポジトリーへの更新として percona-release-latest.noarch.rpm を設定します: percona-release-0.1-4.noarch 依存性の解決をしています --> トランザクションの確認を実行しています。 ---> パッケージ percona-release.noarch 0:0.1-4 を 更新 ---> パッケージ percona-release.noarch 0:1.0-18 を アップデート --> 依存性解決を終了しました。 依存性を解決しました ======================================================================================================================================================================================================================================== Package アーキテクチャー バージョン リポジトリー 容量 ======================================================================================================================================================================================================================================== 更新します: percona-release noarch 1.0-18 /percona-release-latest.noarch 22 k トランザクションの要約 ======================================================================================================================================================================================================================================== 更新 1 パッケージ 合計容量: 22 k Is this ok [y/d/N]: y Downloading packages: Running transaction check Running transaction test Transaction test succeeded Running transaction 更新します : percona-release-1.0-18.noarch 1/2 * Enabling the Percona Original repository <*> All done! The percona-release package now contains a percona-release script that can enable additional repositories for our newer products. For example, to enable the Percona Server 8.0 repository use: percona-release setup ps80 Note: To avoid conflicts with older product versions, the percona-release setup command may disable our original repository for some products. For more information, please visit: https://www.percona.com/doc/percona-repo-config/percona-release.html 整理中 : percona-release-0.1-4.noarch 2/2 検証中 : percona-release-1.0-18.noarch 1/2 検証中 : percona-release-0.1-4.noarch 2/2 更新: percona-release.noarch 0:1.0-18 完了しました! [root@GA02 admin]# [root@GA02 admin]# yum install percona-toolkit 読み込んだプラグイン:fastestmirror, priorities percona-release-noarch | 2.9 kB 00:00:00 percona-release-x86_64 | 2.9 kB 00:00:00 Loading mirror speeds from cached hostfile * base: mirrors.cat.net * epel: ftp.jaist.ac.jp * extras: mirrors.cat.net * updates: mirrors.cat.net 依存性の解決をしています --> トランザクションの確認を実行しています。 ---> パッケージ percona-toolkit.x86_64 0:3.2.0-1.el7 を インストール --> 依存性解決を終了しました。 依存性を解決しました ======================================================================================================================================================================================================================================== Package アーキテクチャー バージョン リポジトリー 容量 ======================================================================================================================================================================================================================================== インストール中: percona-toolkit x86_64 3.2.0-1.el7 percona-release-x86_64 12 M トランザクションの要約 ======================================================================================================================================================================================================================================== インストール 1 パッケージ 総ダウンロード容量: 12 M インストール容量: 12 M Is this ok [y/d/N]: y Downloading packages: 警告: /var/cache/yum/x86_64/7/percona-release-x86_64/packages/percona-toolkit-3.2.0-1.el7.x86_64.rpm: ヘッダー V4 RSA/SHA256 Signature、鍵 ID 8507efa5: NOKEY========================================-] 184 kB/s | 12 MB 00:00:00 ETA percona-toolkit-3.2.0-1.el7.x86_64.rpm の公開鍵がインストールされていません percona-toolkit-3.2.0-1.el7.x86_64.rpm | 12 MB 00:00:50 file:///etc/pki/rpm-gpg/PERCONA-PACKAGING-KEY から鍵を取得中です。 Importing GPG key 0x8507EFA5: Userid : "Percona MySQL Development Team (Packaging key) <mysql-dev@percona.com>" Fingerprint: 4d1b b29d 63d9 8e42 2b21 13b1 9334 a25f 8507 efa5 Package : percona-release-1.0-18.noarch (@/percona-release-latest.noarch) From : /etc/pki/rpm-gpg/PERCONA-PACKAGING-KEY 上記の処理を行います。よろしいでしょうか? [y/N]y Running transaction check Running transaction test Transaction test succeeded Running transaction インストール中 : percona-toolkit-3.2.0-1.el7.x86_64 1/1 検証中 : percona-toolkit-3.2.0-1.el7.x86_64 1/1 インストール: percona-toolkit.x86_64 0:3.2.0-1.el7 完了しました! [root@GA02 admin]#
pt-query-digestのアウトプット
[root@GA02 data]# pt-query-digest /usr/local/mysql/data/mysql-slow.log --no-version-check # 20.9s user time, 50ms system time, 31.58M rss, 232.37M vsz # Current date: Sun May 24 14:19:42 2020 # Hostname: GA02 # Files: /usr/local/mysql/data/mysql-slow.log # Overall: 30.76k total, 9 unique, 242.22 QPS, 3.73x concurrency _________ # Time range: 2020-05-24T05:07:09 to 2020-05-24T05:09:16 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 474s 1us 221ms 15ms 34ms 15ms 20ms # Lock time 7s 0 179ms 230us 332us 4ms 103us # Rows sent 14.04k 0 999 0.47 0.99 5.52 0 # Rows examine 14.04k 0 999 0.47 0.99 5.52 0 # Query size 12.96M 17 707 441.72 685.39 291.70 685.39 # Profile # Rank Query ID Response time Calls R/Call V/M I # ==== =============================== ============== ===== ====== ===== = # 1 0x76F7DD6D2A72EB7BCAEC22E79B... 468.9853 99.0% 17349 0.0270 0.00 INSERT t? # MISC 0xMISC 4.5256 1.0% 13413 0.0003 0.0 <8 ITEMS> # Query 1: 667.27 QPS, 18.04x concurrency, ID 0x76F7DD6D2A72EB7BCAEC22E79B0EFD3B at byte 988485 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: 2020-05-24T05:08:50 to 2020-05-24T05:09:16 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 56 17349 # Exec time 99 469s 1ms 221ms 27ms 38ms 11ms 26ms # Lock time 75 5s 0 179ms 309us 384us 5ms 108us # Rows sent 0 0 0 0 0 0 0 0 # Rows examine 0 0 0 0 0 0 0 0 # Query size 90 11.67M 704 707 705.36 685.39 0 685.39 # String: # Databases SQLSLAP # Hosts localhost # Users root # Query_time distribution # 1us # 10us # 100us # 1ms ### # 10ms ################################################################ # 100ms # # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `SQLSLAP` LIKE 't1'\G # SHOW CREATE TABLE `SQLSLAP`.`t1`\G INSERT INTO t1 VALUES (NULL,633998215,1598162325,1839677468,'l4dgQpQ2FFmHegccMlq0FmNIrmjthL1IPWzrCHuRYgk2KDWaqKb57qNyczrAKlSl7JcJcMe8uN26SYhItGF0yXybWhdqQxRQHvltIGuCfwJzTs9M0OEyv4PHl274sQ','W9M7ugNokudvtyn2CnJQmEMBO76N3yqZzCZtkwaSrBGc93XDjqfLwtOK0WkwKaLJeu5MrfiaiyAjuZwdNRyKKMYClG85iMHKGMaztHPR7SA11yWPPKddj9pKQqH8CQ','LKgvKZ4d0C52570cOHw1uXAkjSQ1TeJqy0lAPqoQ2lKzsLR8WG9PnC1NYRG1xbrvbdy1ReJLNfC8sgGFwIgbMhyu0EwxinsHGiAbKLoct1klhs0d2Y4O53J5972run','13L3eiPRAISuv1eoWhKaxQTGNfFIMA5F5QJj0k2A2WwxNRlt8yS5GpEfSTxjXuycD9CDtEGnd4d0XEufCEdS3j0O4p7ckx4x7G2sNAg0FH0mXmIc0nwwWoKaeJ2E87','3FFx0e8YWNpN1C9JgA6T6SHI3vdx1lw4tC2liAH5PySQ2dejfcCd5Lv0HOxA2uFnyHYYJhdcf52ZbYGE9KkEifErw31qx8dnH1KSax4DvzmWXvcY7KmhssOowIWlQz')\G [root@GA02 data]#
MySQLのエラーログ含めてGUIで確認するのであればこんなツールもあります。
Percona Monitoring and Management
MySQL Enterprise Monitor