LoginSignup
0
0

時間かかっているSQLのあぶり出し

Posted at

【管理画面】にてある画面を開こうとするとステータスバーがグルグル回り固まっているような事象に陥ることがある。
コレの原因を調査する一貫として設定する。

以下は初期の値を確認したモノ

[root@1036oci_opedbslave etc]# mysql -h'100.0.1.36' -e'show variables like "slow_query%";'
+---------------------+-------------------------+
| Variable_name       | Value                   |
+---------------------+-------------------------+
| slow_query_log      | OFF                     |
| slow_query_log_file | /var/lib/mysql/slow.log |
+---------------------+-------------------------+
[root@1036oci_opedbslave etc]# mysql -h'100.0.1.36' -e'show variables like "long_query%";'
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
[root@1036oci_opedbslave etc]#

シェル画面1
受け取るためのファイルを作成(rootで実行する)

[opc@1036oci_opedbslave ~]$ sudo su #作業A-1.suになる
[root@1035oci_opedbmaster opc]# ls -l /var/lib/mysql/slow.log #作業A-2.受けファイルが無いことを確認
ls: cannot access '/var/lib/mysql/slow.log': No such file or directory	ls: cannot access '/var/lib/mysql/slow.log': No such file or directory
[root@1035oci_opedbmaster opc]# echo -n > /var/lib/mysql/slow.log #作業A-3.受けファイルを作成
[root@1035oci_opedbmaster opc]# chown mysql.mysql /var/lib/mysql/slow.log #作業A-4.受けファイルの所有者変更
[root@1035oci_opedbmaster opc]# chmod 644 /var/lib/mysql/slow.log #作業A-5.受けファイルのパ-ミッション変更
[root@1035oci_opedbmaster opc]# ls -l /var/lib/mysql/slow.log #作業A-1.受けファイルがmysqlので644になっている事を確認
-rw-r--r-- 1 mysql mysql 1 Dec 1 04:28 /var/lib/mysql/slow.log	-rw-r--r-- 1 mysql mysql 1 Dec 1 13:29 /var/lib/mysql/slow.log
[root@1035oci_opedbmaster opc]#
👆しなくても作られるがパーミッションが厳しくなる👇

[root@1120resdbmaster opc]# ll /var/lib/mysql/slow.log
-rw-rw----. 1 mysql mysql 470 Dec  4 01:25 /var/lib/mysql/slow.log
[root@1120resdbmaster opc]#
mysqlの設定を実行する(平ユーザーにて。「set global」での変数セットはマスター→レプリカへの反映がされないので、各レプリカにてセットが必要です。)

[opc@1035oci_opedbmaster ~]$ mysql -e'show variables like "long_query%";' #作業-1a.確認する
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |👈この時点では1秒
+-----------------+----------+
[opc@1035oci_opedbmaster ~]$ mysql -e'show variables like "slow_query_log%";' #作業-2a.確認する
+---------------------+-------------------------+
| Variable_name       | Value                   |
+---------------------+-------------------------+
| slow_query_log      | OFF                     |👈この時点ではOFF
| slow_query_log_file | /var/lib/mysql/slow.log |
+---------------------+-------------------------+
[opc@1035oci_opedbmaster ~]$ mysql -e'set global long_query_time=120;' #作業-1.時間を秒数でセットする
[opc@1035oci_opedbmaster ~]$ mysql -e'set global slow_query_log=1;' #作業-2.捕まえる設定をONにする
[opc@1035oci_opedbmaster ~]$ mysql -e'show variables like "long_query%";' #作業-1a.確認する
+-----------------+------------+
| Variable_name   | Value      |
+-----------------+------------+
| long_query_time | 120.000000 |👈この時点で120秒
+-----------------+------------+
[opc@1035oci_opedbmaster ~]$ mysql -e'show variables like "slow_query_log%";' #作業-2a.確認する
+---------------------+-------------------------+
| Variable_name       | Value                   |
+---------------------+-------------------------+
| slow_query_log      | ON                      |👈この時点でON
| slow_query_log_file | /var/lib/mysql/slow.log |
+---------------------+-------------------------+
[opc@1035oci_opedbmaster ~]$ tail -f /var/lib/mysql/slow.log #作業-3.動くか確認する。

/usr/sbin/mariadbd, Version: 100.5.10-MariaDB-log (MariaDB Server). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                Id Command  Argument
# Time: 231201  4:41:59
# User@Host: [opc] @  [100.0.0.100]👈100番からopcでアクセス
# Thread_id: 26422937  Schema:   QC_hit: No
# Query_time: 126.000182  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0👈秒数が126秒であることを確認
# Rows_affected: 0  Bytes_sent: 277
SET timestamp=1701405719;
SELECT NOW(),SYSDATE(), SLEEP(126) SLEPT,NOW(),SYSDATE();👈別ホストから投げたSQLがキャッチ出来てる

シェル画面2(シェル画面1とは別のホストから)

[opc@0100satellite ~]$ mysql -h'100.0.1.36' -e'SELECT NOW(),SYSDATE(), SLEEP(126) SLEPT,NOW(),SYSDATE();' #作業ー4.意図的に時間のかかるクエリを実行
+---------------------+---------------------+-------+---------------------+---------------------+
| NOW()               | SYSDATE()           | SLEPT | NOW()               | SYSDATE()           |
+---------------------+---------------------+-------+---------------------+---------------------+
| 2023-12-01 13:42:49 | 2023-12-01 13:42:49 |     0 | 2023-12-01 13:42:49 | 2023-12-01 13:44:55 |
+---------------------+---------------------+-------+---------------------+---------------------+
[opc@0100satellite ~]$

ファイルフォーマットの説明

slow.log
# Time: 231205  4:27:05👈記録された日時=SQLが終了した日時(SQLを開始した日時ではない。標準時刻になっているので変換が必要。)4:27:05(標準時間)→13:27:05(日本時間)
# User@Host: [whoam1] @  [100.0.0.101]👈ログイン名とfromホスト
# Thread_id: 27150103  Schema:   QC_hit: No👈Schemaには使用したデータベースが書かれている。
# Query_time: 126.000194  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0👈126秒かかった=SQLが開始されたのは13:24:59と逆算できる。
# Rows_affected: 0  Bytes_sent: 277
SET timestamp=1701750425;
SELECT NOW(),SYSDATE(), SLEEP(126) SLEPT,NOW(),SYSDATE();👈126秒かかったSQLはコチラ

参考にしたURL
スロークエリの確認方法:MySQL編
https://ptune.jp/tech/how-to-check-mysql-slow-query/ 👈コマンドの場合を参照
通常のクエリーログ、遅いクエリーログの保存設定
https://www.wakuwakubank.com/posts/700-mysql-query-log/
MySQLのチューニング slow logの設定方法
https://webkaru.net/mysql/mysql-tuning-slow-log/
MySQL slow_query_log はmy.cnfの[mysqld]の欄に書くのよ
https://it-afi.com/mysql/mysql-slow_query_log-%e3%81%afmy-cnf%e3%81%aemysqld%e3%81%ae%e6%ac%84%e3%81%ab%e6%9b%b8%e3%81%8f%e3%81%ae%e3%82%88/
MySQL で my.cnf のシンタックスチェックを行う方法
https://gotohayato.com/content/83/

動作確認用
上部のメニューアイコン「レス投稿エラー機能(URLは/post_error_list/)」
一回開こうとすると数分OPEサーバーのWEBが操作不能になる。

[opc@0205oci_opeweb ~]$ mysql -h'100.0.1.70' #👈bbsのメインサーバーに接続
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 2586254760
Server version: 100.5.10-MariaDB-log MariaDB Server

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

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

MariaDB [(none)]> select sql_calc_found_rows * from myproject.post_error_log order by id desc limit 2; #👈時間のかかっているSQLを投げる
(省略します)
2 rows in set (1 min 28.799 sec) #🔍88秒かかっている。

MariaDB [(none)]> Bye
[opc@0205oci_opeweb ~]$

あいうえお

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
0
0