👓

TiDBで実行されるクエリをログに出力したい

2024/10/22に公開

Database

TiDB

tech

この記事について

この記事では、TiDBが実行するクエリをログに出力する方法を紹介します。

MySQLにはDBサーバーが実行したクエリをログに出力する機能があり、一般にgeneral logという名前で呼ばれています。

https://dev.mysql.com/doc/refman/8.0/en/query-log.html

MySQL互換を謳うTiDBにもこのgeneral log機能は用意されており、TiDB Self-Managed (いわゆるオンプレミス版)やplaygroundで利用可能です。

https://docs.pingcap.com/tidb/stable/system-variables#tidb_general_log

general logはデバッグ目的で利用することが多く、例えば、ORMなどが生成したクエリが実際にどのようなクエリとしてMySQLに届いているのかを確認するためなどに使われることがあります。

このように大変便利なgeneral logですが、TiDBでは以前から利用可能ではあったものの、v8.0以前はtidb.logに出力されて他のログと混ざってしまうため、やや使い勝手がよくありませんでしたが、v8.0からは指定したファイルに出力されるようになりました。一方、TiDB Cloudではまだgeneral logを有効にすることができないため、general logを使ったデバッグというものがやりづらいです。

この記事ではTiDB Self-ManagedやPlaygroundでgeneral logを有効にする方法、そしてgeneral logを有効にできない場合にクエリをログに出力する方法をご紹介します。なお、後者ではプロキシサーバーを独自に実装します。独自に実装するとはいえ、既存のMySQLライブラリを利用する簡易なものなので実装は難しくありません。ぜひ最後までご覧ください。

TiDBでgeneral logを設定する

TiDBでgeneral logを有効にすると、どのようにログに出力されるのかをみてみましょう。もしこれで十分というのであれば、ぜひこちらの機能をご利用ください。

設定方法

以下はtiup playgroundを利用した例で、v8.0以降のバージョンを想定しています。設定ファイルの内容などはTiDB Self-Managedでも同様に使うことができます。

https://docs.pingcap.com/tidb/stable/system-variables#tidb_general_log に従って、以下のように設定します。

log.levelをinfoまたはdebugとします。
log.general-log-fileまたはlog.file.filenameに出力したいログファイル名を指定します。

これらを設定ファイルとして記述すると、以下のようになります。ファイル名などは適宜設定ください。

[log]
# Log level: debug, info, warn, error, fatal.
level = "info"

# Stores general log into separated files.
# If it equals to empty, the general log will be written to the server log.
general-log-file = "tidb-general-log.log"

上記の内容をtidb.tomlとして保存し、以下のようにtiup playgroundを起動します。

tiup playground v8.1.1 --db 1 --db.config tidb.toml

playgroundクラスタが起動したら、TiDBにログインしてgeneral logの出力を有効にします。

tidb:4000 > SHOW VARIABLES LIKE 'tidb_general_log';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| tidb_general_log | OFF   |
+------------------+-------+
1 row in set (0.01 sec)

tidb:4000 > SET GLOBAL tidb_general_log='ON';
Query OK, 0 rows affected (0.00 sec)

tidb:4000 > SHOW VARIABLES LIKE 'tidb_general_log';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| tidb_general_log | ON    |
+------------------+-------+
1 row in set (0.01 sec)

いくつかクエリを実行して、その後、ログの出力を確認します。playgroundクラスタまたはTiDB Self-Managedの場合、ログの出力を確認する方法が２つあります。

管理画面で確認する
ログファイルに直接アクセスして確認する

管理画面で確認する

playgroundの場合、通常は http://127.0.0.1:2379/dashboard にアクセスすると管理画面が表示されます。この管理画面にログインして、左メニューの"Search Logs"（虫眼鏡が書かれたアイコン）をクリックします。その後、検索のキーワードに \[GENERAL_LOG\]（正規表現として扱われないように括弧をエスケープしています）と入力すると、以下のように実行したクエリがログに出力されていることが確認できます。

ログファイルに直接アクセスして確認する

ログファイルを直接参照したい場合、ログの出力先を確認する必要があります。管理画面のログ検索画面でfilenameをキーワードにして検索すると、以下のように出力先ディレクトリが/Users/shige/.tiup/data/URG0lYFであることが特定できます。もし管理画面にアクセスせずに確認したい場合は${HOME}/.tiup/data直下にある最新のディレクトリを参照するとよいでしょう。

${HOME}/.tiup/data以下のディレクトリ名には--tagで指定した値が使用されるようです。よって、わかりやすいディレクトリ名にしたい場合はplayground起動時に--tagオプションを指定するとよいでしょう。

# tagを指定してPlaygroundを起動するコマンドの例
tiup playground v8.1.1 --db 1 --db.config tidb.toml --tag general-log

general logはTiDBのコンポーネントごとに出力されるため、今回のようにTiDBノードが１つしかない場合、以下のように${HOME}/.tiup/data/${tag}/tidb-0ディレクトリの下に出力されます。

$ ls -l ~/.tiup/data/URG0lYF/tidb-0
total 336
drwxr-x--- 2 shige staff     64 10 15 17:33 oom_record
-rw------- 1 shige staff    884 10 15 17:36 tidb-general-log.log
-rw------- 1 shige staff    649 10 15 17:33 tidb-slow.log
-rw-r--r-- 1 shige staff 275045 10 15 17:36 tidb.log
-rw-r--r-- 1 shige staff     91 10 15 17:33 tidb.toml

出力内容は当然ですが管理画面上で見れるものと同じです。

[2024/10/15 17:02:37.241 +09:00] [INFO] [session.go:3920] [GENERAL_LOG] [conn=482344968] [session_alias=] [user=root@127.0.0.1] [schemaVersion=51] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="SHOW VARIABLES LIKE 'tidb_general_log'"]
[2024/10/15 17:05:33.626 +09:00] [INFO] [session.go:3920] [GENERAL_LOG] [conn=482344968] [session_alias=] [user=root@127.0.0.1] [schemaVersion=51] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="SELECT DATABASE()"]
[2024/10/15 17:05:33.627 +09:00] [INFO] [session.go:3920] [GENERAL_LOG] [conn=482344968] [session_alias=] [user=root@127.0.0.1] [schemaVersion=51] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="use `testl`"]
[2024/10/15 17:05:36.099 +09:00] [INFO] [session.go:3920] [GENERAL_LOG] [conn=482344968] [session_alias=] [user=root@127.0.0.1] [schemaVersion=51] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="SELECT DATABASE()"]
[2024/10/15 17:05:36.100 +09:00] [INFO] [session.go:3920] [GENERAL_LOG] [conn=482344968] [session_alias=] [user=root@127.0.0.1] [schemaVersion=51] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="use `test`"]

プロキシサーバーを使ってクエリをログに出力する

クエリのロギングをしたいクラスタがTiDB Cloudにあるなど、何らかの理由でgeneral logを利用することができない場合、クラスタの手前にプロキシサーバーを置いて、そのプロキシサーバーにクエリをログ出力させるという方法があります。ここでは、そのプロキシサーバーを簡易に実装して見たいと思います。

さて、早速始めましょう。ここではGoを用いて実装します。ライブラリにgo-mysqlを用いるので、あらかじめgo getしておきましょう。以下にコマンドの例を記載しますが、ご自身の環境に合わせて適宜変更してください。

$ go mod init example-proxy/m
go: creating new go.mod: module example-proxy/m

$ go mod vendor
go: warning: "all" matched no packages
go: no dependencies to vendor

$ go get "github.com/go-mysql-org/go-mysql"

$ touch main.go

$ \ls -l
total 8
-rw-r--r-- 1 shige wheel  95 10 17 11:07 go.mod
-rw-r--r-- 1 shige wheel 183 10 17 11:07 go.sum
-rw-r--r-- 1 shige wheel   0 10 17 11:08 main.go
drwxr-xr-x 3 shige wheel  96 10 17 11:07 vendor

準備が整ったら早速実装を始めましょう。とはいえ、ここではプロキシサーバーとは何ぞやということには触れず、サンプルコードをコピペするところから始めます。ReadmeにかかれているExampleのコードをmain.goにコピペしましょう。1つだけ修正箇所があります。サンプルコードではプロキシサーバーがポート4000番をリッスンしていますが、このあとに起動するplaygroundクラスタも4000番を使うため、プロキシサーバーのほうは4000番以外を使うようにしてください。

	// ポート4001番をリッスンするように修正
	l, err := net.Listen("tcp", "127.0.0.1:4001")

修正したら、以下のようにしてプロキシサーバーを立ち上げてみます。

$ go mod tidy

$ go mod vendor

$ go run main.go

次に、新しいウインドウでターミナルを起動し、tiup playgroundを立ち上げます。

$ tiup playground v8.1.1 --db 1 --tiflash 0 --without-monitor

もう1度新しいウインドウでターミナルを起動し、立ち上げたプロキシサーバーに接続します。ポート番号は先ほど修正した番号であることに注意してください。

mysql --comments --host 127.0.0.1 --port 4001 -u root
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 10001
Server version: 5.7.0

Copyright (c) 2000, 2024, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

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

mysql>

つながりました！単純なように見えますが、このように接続できたことはライブラリがクライアントから送信されてきたMySQLプロトコルを上手くハンドリングしていることを示しています。ですが、本来の接続先であるplaygroundとは接続されていません。なので、コマンドを実行すると、以下のようにエラーとなります。

mysql> show databases;
ERROR 1105 (HY000): not supported now
mysql>

not supported nowとでていますね。このエラーメッセージはプロキシサーバーで実装されているハンドラー（server.EmptyHandler）によるものです。

プロキシサーバーの実装

ここからすこしコードに足を踏み入れてみましょう。server.EmptyHandlerはinterfaceであるserver.Handlerを実装したものです。server.Handlerは以下のように定義されています。

なので、独自のハンドラーを定義して、これらの関数を実装すればよいわけですね。また、このプロキシサーバーは当然TiDBに接続して、コマンドをクライアントに代わって送信する必要がありますので、プロキシサーバーからDBサーバー、ここではTiDBクラスタへ接続する必要があります。

よって、今回のプロキシサーバーは1) server.Handlerの実装、2) DBサーバーへの接続、3) クライアントから送信されてきたコマンドのログ出力、以上3つを実現すれば良いわけです。簡単ですね！

ハンドラーの実装

早速ハンドラーの実装に入りましょう。先ほどお伝えしたように、server.Handlerを実装するだけなので、必要な部分をコピペします。その後、自分のハンドラーを定義して、そのハンドラーをserver.NewConnに渡します。コードは以下のようになるでしょう。

package main

import (
	"fmt"
	"log"
	"net"

	. "github.com/go-mysql-org/go-mysql/mysql"
	"github.com/go-mysql-org/go-mysql/server"
)

type handler struct{}

func (h handler) UseDB(dbName string) error {
	return nil
}
func (h handler) HandleQuery(query string) (*Result, error) {
	return nil, fmt.Errorf("not supported now")
}

func (h handler) HandleFieldList(table string, fieldWildcard string) ([]*Field, error) {
	return nil, fmt.Errorf("not supported now")
}
func (h handler) HandleStmtPrepare(query string) (int, int, interface{}, error) {
	return 0, 0, nil, fmt.Errorf("not supported now")
}
func (h handler) HandleStmtExecute(context interface{}, query string, args []interface{}) (*Result, error) {
	return nil, fmt.Errorf("not supported now")
}

func (h handler) HandleStmtClose(context interface{}) error {
	return nil
}

func (h handler) HandleOtherCommand(cmd byte, data []byte) error {
	return NewError(
		ER_UNKNOWN_ERROR,
		fmt.Sprintf("command %d is not supported now", cmd),
	)
}

func main() {
	l, err := net.Listen("tcp", "127.0.0.1:4001")
	if err != nil {
		log.Fatal(err)
	}

	for {
		c, err := l.Accept()
		if err != nil {
			log.Fatal(err)
		}

		conn, err := server.NewConn(c, "root", "", handler{})
		if err != nil {
			log.Fatal(err)
		}

		// as long as the client keeps sending commands, keep handling them
		for {
			if err := conn.HandleCommand(); err != nil {
				log.Fatal(err)
			}
		}
	}
}

これで独自のハンドラーが用意できました。また、l.Acceptからconn.HandleCommandをfor ループで囲うことで、継続的にクライアントからの接続を処理できるようにしています。この段階では、最初にコピペしたコードとほとんど変わりませんが、このあとのDBサーバーへの接続への実装を通じてさらに肉付けしていきます。

DBサーバーへの接続

DBサーバーへの接続を実装します。実装を単純にするために、以下のような方針で実装します。

必要な接続先の情報はすべて環境変数で渡す
接続オブジェクトの作成はコネクションごとに行う

go-mysqlはクライアント接続のためのライブラリも提供しているのでそれを使います。以下では主な変更部分であるimportとmain関数、新規に追加したrun関数を抜き出しています。

package main

import (
	...
	"github.com/go-mysql-org/go-mysql/client"
	...
)

...

func main() {
	targetAddress := os.Getenv("MYPROXY_TARGET")
	if targetAddress == "" {
		log.Printf("WARN: target address to be forwarded is missing. Set default address: %s", defaultTargetAddress)
		targetAddress = defaultTargetAddress
	}
	dbUser := os.Getenv("MYPROXY_DB_USER")
	if dbUser == "" {
		log.Printf("WARN: DB user is not set. Set default DB user: %s", defaultDBUser)
		dbUser = defaultDBUser
	}

	dbPassword := os.Getenv("MYPROXY_DB_PASSWORD")
	if dbPassword == "" {
		log.Print("WARN: DB password is not set. Set default DB password")
		dbPassword = defaultDBPassword
	}

	l, err := net.Listen("tcp", "127.0.0.1:4001")
	if err != nil {
		log.Fatal(err)
	}
	defer l.Close()

	for {
		c, err := l.Accept()
		if err != nil {
			log.Fatal(err)
		}

		go run(c, targetAddress, dbUser, dbPassword)
	}
}

func run(c net.Conn, targetAddress, dbUser, dbPassword string) {
	clientConn, err := client.Connect(targetAddress, dbUser, dbPassword, "test")
	if err != nil {
		log.Fatalf("Fatal: failed to establish the connection to the database server (%s, %s): %v", targetAddress, dbUser, err)
	}
	if err := clientConn.Ping(); err != nil {
		log.Fatalf("Fatal: failed to receive ping response from %s: %v", targetAddress, err)
	}
	defer clientConn.Close()

	h := handler{clientConn}
	serverConn, err := server.NewConn(c, "root", "", h)
	if err != nil {
		log.Fatal(err)
	}
	defer serverConn.Close()

	for {
		if err := serverConn.HandleCommand(); err != nil {
			log.Printf("WARN: failed to handle command: %v", err)
		}
	}
}

やや長いですが、やっていることはシンプルです。acceptした接続をrunに渡して、接続ごとに独立した処理となるようにgo routineで別スレッドに処理を分けています。また、serverConn.HandleCommand()から受け取ったエラーをlog.Fatalからlog.Printfに変更しています。これはクライアント接続で発生したエラーがプロキシサーバーを止めないようにするためです。

run関数では以下をしています。

プロキシサーバーとDBサーバー間での接続（client.Connect）
クライアントとプロキシサーバー間での接続（server.NewConn）
- DBサーバーとの接続オブジェクトをハンドラーに渡していることに注目してください
クライアントから送られてきたコマンドを処理する（serverConn.HandleCommand）

シンプルですね！特に申し上げることは無いかと思います。でも、これで今回実装したい事柄の９割は実装できました。では残りを実装しましょう！つぎも簡単ですよ！

コマンドのログ出力および転送を実装する

ようやく今回の目的であるコマンドのログ出力までたどり着きました。ところで、ログに出力したいコマンド、つまりクエリはどうやって参照することができるのでしょうか？ここで改めてコピペしたハンドラーの関数の１つであるHandleQueryを見てみましょう。

func (h handler) HandleQuery(query string) (*Result, error) {
	return nil, fmt.Errorf("not supported now")
}

引数にqueryがありますね！どうやらHandleQueryはクエリを受け取るようです。また、返り値のデータ型を見ると*Resultとあるので、HandleQueryはクエリを受け取るだけでなく、クエリを受け取り、実行して、その結果セットを返却するところまでを受け持つということがわかります。

では、どうやってハンドラーがクエリを実行することができるのでしょうか？やりたいことはクライアントから受け取ったクエリをDBサーバーに送信したいわけですね。ということは、DBサーバーとの接続オブジェクトを利用してクエリを実行することができそうです。実際にサンプルコードを見てみると、Executeを使うことでクエリが実行できそうなことがわかります。ここでは実装を簡単にするため、UseDB、HandleQueryの２つのみを実装します。余力がある読者はその他の関数も実装してみて下さい。

...
func (h handler) UseDB(dbName string) error {
	log.Printf("ID: %d, DB: %s", h.clientConn.GetConnectionID(), dbName)
	return h.clientConn.UseDB(dbName)
}
func (h handler) HandleQuery(query string) (*Result, error) {
	log.Printf("ID: %d, DB: %s, QUERY: %s", h.clientConn.GetConnectionID(), h.clientConn.GetDB(), query)
	return h.clientConn.Execute(query)
}
...

単純ですね！これも見たそのままであることがわかるかと思います。ログの出力には、接続を区別するためのID、接続先DB名、そしてクエリが含まれています。

最終的なコードは以下のgistでご確認ください。

おおよそ110行強で実装できました。実行してみると、以下のようにログが取得できていることがわかります。途中でIDが代わっているのは新しいクライアント接続が入ってきたためです。

$ go run main.go
2024/10/21 17:48:18 WARN: target address to be forwarded is missing. Set default address: 127.0.0.1:4000
2024/10/21 17:48:18 WARN: DB user is not set. Set default DB user: root
2024/10/21 17:48:18 WARN: DB password is not set. Set default DB password
2024/10/21 17:48:19 ID: 2514485272, USE DB: test
2024/10/21 17:48:19 ID: 2514485272, DB: test, QUERY: show databases
2024/10/21 17:48:19 ID: 2514485272, DB: test, QUERY: show tables
2024/10/21 17:48:19 ID: 2514485272, DB: test, QUERY: SELECT * FROM `t` LIMIT 0
2024/10/21 17:48:19 ID: 2514485272, DB: test, QUERY: select @@version_comment limit 1
2024/10/21 17:48:20 ID: 2514485272, DB: test, QUERY: select $$
2024/10/21 17:48:24 ID: 2514485272, DB: test, QUERY: show databases
2024/10/21 17:48:34 ID: 2514485272, DB: test, QUERY: SELECT DATABASE()
2024/10/21 17:48:34 ID: 2514485272, USE DB: test
2024/10/21 17:48:36 ID: 2514485272, DB: test, QUERY: show tables
2024/10/21 17:48:57 ID: 2514485272, DB: test, QUERY: create table t1 (id bigint primary key auto_increment)
2024/10/21 17:49:11 ID: 2514485272, DB: test, QUERY: insert into t1 values (1), (2), (3)
2024/10/21 17:49:20 ID: 2514485272, DB: test, QUERY: select * from t1
2024/10/21 17:49:43 ID: 2514485272, DB: test, QUERY: update t1 set id = id + 10
2024/10/21 17:49:50 ID: 2514485272, DB: test, QUERY: select * from t1
2024/10/21 17:49:57 ID: 2514485272, DB: test, QUERY: delete from t1
2024/10/21 17:49:59 ID: 2514485272, DB: test, QUERY: select * from t1
2024/10/21 17:50:02 ID: 2514485274, USE DB: test
2024/10/21 17:50:02 ID: 2514485274, DB: test, QUERY: show databases
2024/10/21 17:50:02 ID: 2514485274, DB: test, QUERY: show tables
2024/10/21 17:50:02 ID: 2514485274, DB: test, QUERY: SELECT * FROM `t` LIMIT 0
2024/10/21 17:50:02 ID: 2514485274, DB: test, QUERY: SELECT * FROM `t1` LIMIT 0
2024/10/21 17:50:02 ID: 2514485274, DB: test, QUERY: select @@version_comment limit 1
2024/10/21 17:50:02 ID: 2514485274, DB: test, QUERY: select $$

まとめ

いかがでしたか？この記事では以下をご紹介しました。

TiDBでgeneral logを出力する方法
プロキシサーバーを用いてログを出力する方法

内容の殆どがプロキシサーバーの実装になってしまいましたが、これは作者の趣味です。general logなどによるクエリのログ出力はデータベースを活用したアプリケーション開発には欠かせないと思いますので、ここで紹介した内容をぜひ日々の開発にお役立てください。

最後に（そして繰り返しに）なりますが、今回ご紹介したプロキシサーバーの実装は簡易なのもので実用には耐えません。例えばプリペアードステートメントに対応しておりませんし、複文（select 1; select version();のように１つのコールに複数のクエリが含まれること）には対応しておりません。また、プロキシサーバーとしても集中的な接続に耐えれるような実装にはなっていない点も注意が必要です。ご自身でプロキシサーバーを実装する際の参考としていただければと思います。

GitHubで編集を提案