スロークエリログの取得でハマった話

こんにちは！
たけひとです。

最近、「達人が教えるwebパフォーマンスチューニング」を読み始めたのですが3章の「MySQLのボトルネックを発見する準備」で少しはまってしまったのでその原因と解決方法を記録しておこうと思います。

何があった？

コンテナを起動し、abコマンドを使ってベンチマークを取った後、mysql-slow.logというファイル名でスロークエリログが取得できるはずなのですがディレクトリが空のままでした。

何でそうなった？

mysqlコンテナのログを見てみるとmysqld: File '/var/log/mysql/mysql-slow.log' not found (OS errno 13 - Permission denied)というエラーが出力されていました。

$ docker logs webapp-mysql-1 
[Entrypoint] MySQL Docker Image 8.0.29-1.2.8-server
[Entrypoint] Starting MySQL 8.0.29-1.2.8-server
2022-09-03T18:58:32.114915Z 0 [Warning] [MY-010918] [Server] 'default_authentication_plugin' is deprecated and will be removed in a future release. Please use authentication_policy instead.
2022-09-03T18:58:32.114927Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.29) starting as process 1
2022-09-03T18:58:32.120170Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-09-03T18:58:32.250234Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-09-03T18:58:32.449959Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2022-09-03T18:58:32.449985Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2022-09-03T18:58:32.472982Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2022-09-03T18:58:32.473075Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.29'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server - GPL.
2022-09-03T19:07:24.687039Z 0 [System] [MY-013172] [Server] Received SHUTDOWN from user <via user signal>. Shutting down mysqld (Version: 8.0.29).
2022-09-03T19:07:25.835878Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.29)  MySQL Community Server - GPL.
[Entrypoint] MySQL Docker Image 8.0.29-1.2.8-server
[Entrypoint] Starting MySQL 8.0.29-1.2.8-server
2022-09-04T02:28:35.519602Z 0 [Warning] [MY-010918] [Server] 'default_authentication_plugin' is deprecated and will be removed in a future release. Please use authentication_policy instead.
2022-09-04T02:28:35.519613Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.29) starting as process 1
2022-09-04T02:28:35.523854Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-09-04T02:28:35.675816Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
mysqld: File '/var/log/mysql/mysql-slow.log' not found (OS errno 13 - Permission denied)
2022-09-04T02:28:35.778473Z 0 [ERROR] [MY-011263] [Server] Could not use /var/log/mysql/mysql-slow.log for logging (error 13 - Permission denied). Turning logging off for the server process. To turn it on again: fix the cause, then either restart the query logging by using "SET GLOBAL SLOW_QUERY_LOG=ON" or restart the MySQL server.
2022-09-04T02:28:35.866304Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2022-09-04T02:28:35.866329Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2022-09-04T02:28:35.883550Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2022-09-04T02:28:35.883580Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.29'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server - GPL.

permission deniedと出ているので用意したディレクトリのパーミッションの設定の変更等を試したのですが特に変化はありませんでした。

こちらのブログが参考になりました。スロークエリログファイルはmysqlが起動時に勝手に作ってくれるわけではなかったようですね。

どうやって解決した？

mysqlはコンテナ上で動かしているのでホスト側でmysql-slow.logを作成しただけではパーミッションエラーは変わりません。最終的に以下のコマンドで解決しました。

$ touch logs/mysql/mysql-slow.log
$ sudo chmod 0666 logs/mysql/mysql-slow.log

まとめ

微妙にこの記事の内容とずれるのですがsqlのパフォーマンスチューニングというものをしたことがなかったので3章の内容はかなり新鮮で面白かったです。

自分もISUCON出てみたいな。