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

Comments are closed.

Post Navigation