MySQLとPostgreSQLによるログレポートの作成

by

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でインストールしています。

pgbadgerのアウトプット
pgbadger

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

mysqldumpslow

by

スロー クエリ ログの内容は、long_query_time 秒より実行に時間がかかる
SQL ステートメントすべてが入ります。最初のテーブル ロックを取得するまでの時間は、
実行時間としてはカウントしていません。すべてのステートメントを実行し、
すべてのロックをリリースした後に、mysqld で、ステートメントをスロー クエリ ログ
として書き込むため、ログ順は実行順とは異なることがあります。最低限値は 1 で、
long_query_time のデフォルト値 (最大値) は 10です。

MySQL 5.1.6 以降、スロー クエリ ログを有効化するには、
mysqld を –log-slow-queries[=file_name]
オプションで起動します。必要に応じて、–log-output オプションを使用して、
ログの出力先を指定します。
MySQL 5.1.6 より前は、スロー クエリ ログの出力先はファイルです。
スロー クエリ ログ ファイルを有効化するには、–log-slow-queries[=file_name]
オプションを使用します。

スロー クエリ ログには、実行に時間がかかるクエリが入るため、最適化の対象になります。
しかし、時間がかかるスロー クエリ ログの検査は手間がかかります。
ここで、mysqldumpslowコマンドを使用してスロー クエリ ログを処理することで、
そのクエリをログに概括表示します。mysqldumpslow –help を使用して、
このコマンドに関するサポートを探してください。

MySQL 5.1 では、インデックスを使用しないクエリは、–log-queries-not-using-indexes
オプションで指定すると、スロー クエリ ログで記録するようになります。
MySQL 5.1 では、スロー クエリ ログに対して、–log-slow-admin-statements というサーバ
オプションで、OPTIMIZE TABLE、ANALYZE TABLE、ALTER TABLE など、時間がかかる管理ステートメントのロギング要求を有効化します。

クエリ キャッシュで扱うクエリは、スロー クエリ ログには付加しません。
テーブルのレコードがない、または 1 つだけであるときは、インデックスで管理する必要がないため、
これもスロー クエリ ログには入りません。

SlowログをCATコマンドで確認した場合

[root@colinux data]# cat mysql-slow.log
/usr/local/mysql/bin/mysqld, Version: 5.1.30-log (MySQL Community Server (GPL)).
 started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
[root@colinux data]#

mysqldumpslowでSlowログを確認した場合

[root@colinux data]# mysqldumpslow  mysql-slow.log

Reading mysql slow query log from mysql-slow.log
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts

[root@colinux data]#

MySQL Server 5.0 管理監視ガイド

4.11.5. スロー クエリ ログ

mysqldumpslow

[root@colinux data]# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
<code>
Parse and summarize the MySQL slow query log. Options are

  --verbose    verbose
  --debug      debug
  --help       write this text to standard output

  -v           verbose
  -d           debug
  -s ORDER     what to sort by (t, at, l, al, r, ar etc), 'at' is default
  -r           reverse the sort order (largest last instead of first)
  -t NUM       just show the top n queries
  -a           don't abstract all numbers to N and strings to 'S'
  -n NUM       abstract numbers with at least n digits within names
  -g PATTERN   grep: only consider stmts that include this string
  -h HOSTNAME  hostname of db server for *-slow.log filename (can be wildcard),
               default is '*', i.e. match all
  -i NAME      name of server instance (if using mysql.server startup script)
  -l           don't subtract lock time from total time
</code>
[root@colinux data]#

mysqldumpslowは、スロークエリーログ内における、条件値が異なるだけの
SQL文をまとめて、各SQL文をまとめて、各SQL文の平均実行時間の長い順番に
並び替えて表示してくれる。

mysql_slow

その他以下のように一定時間より長いQueryのみをフィルター抽出出来る。
mysql_slow_log_filter.pl

===========================================================
"tail -f mysql-slow.log | mysql_slow_log_filter -T 0.5 -R 1000"
===========================================================
Filtering Slow Query Log – Especially after the changes to log all
queries slow query log may be growing too rapidly to follow,
so we implemented slow query log filter (based on parse_mysql_slow_log by Nathanial Hendler)
which allows you to filter out only queries which took more than certain amount
of time or examined more than certain amount of rows. This is great as allows
multiple passes across same slow query log first to fix worse queries and then
come to find more optimization candidates.
So “tail -f mysql-slow.log | mysql_slow_log_filter -T 0.5 -R 1000” will look at queries
as they come and will print out queries taking more than 0.5 seconds to execute or
having more than 1000 rows examined.
===========================================================



[root@HOME001 data]# ./slolog.pl -T 0.05 <  home001-mysql-slow.log

 Starting...
# Query_time: 0.461031  Lock_time: 0.000137 Rows_sent: 0  Rows_examined: 39
SET timestamp=1359610099;
update test.TABLE001 set comment = 'test percona-toolkit-2.1.8';
# Time: 130131 14:28:25
# User@Host: root[root] @ localhost []
# Query_time: 0.433720  Lock_time: 0.000131 Rows_sent: 0  Rows_examined: 1
SET timestamp=1359610148;
delete from test.TABLE001 where id = 39;
# Time: 130131 14:29:12
# User@Host: root[root] @ localhost []
[root@HOME001 data]#
[/SQL]