ほんじゃーねっと

おっさんがやせたがったり食べたがったりする日常エッセイ

PostgreSQLのプリペアド文とパラメータに分かれたスロークエリログを実行可能なSQLファイルに分割する

PostgreSQLのスロークエリログはパフォーマンス調査する際に必ずと言っていいほどよく利用するものですが、Java等のデータベースライブラリ経由で出力されるクエリはプリペアド文とパラメータに分かれて出力されるため、そのままコピペして実行して確認する、ということが手軽にできません。

パフォーマンス調査の時くらいしか必要になりませんし、パラメータをペタペタとプリペアド文に埋め込んでいけば実行できるのですが、いざやるとなるととても面倒なので自動化したいところです。

プリペアド文とパラメータを結合して実行可能なSQLファイルとして出力するプログラムを書けば実現できそうなので、Go言語の練習がてら作ってみましょう。

Go言語で作っておけば、実行ファイルをデータベースが動いているサーバに持っていってサクッと実行できるので、便利に使えそうです。

PostgreSQLでスロークエリログが出力されるように設定する

まず前提となるスロークエリログがどのように出力されるのかを確認しておきます。

上にも書きましたが、PostgreSQLでクエリのパフォーマンスを調査する時はスロークエリログを出力するように設定しておくと調査がしやすくなります。

たとえば下記のようにpostgresql.confに設定しておくことで、クエリの実行に3秒以上かかった場合にそのクエリと実行にかかった時間がログに出力されるようになります。

log_min_duration_statement = 3s

設定してからPostgreSQLを利用するアプリケーションをしばらく操作して、出力されたログを分析すればどのクエリで時間がかかっているのかが分かります。出力されたクエリをexplain analyze付きで実行すればクエリのどこで時間がかかっているのかも確認することができます。

プリペアド文を使用した場合に出力されるログ

プリペアド文を使用したクエリを実行すると、下記のようにプリペアド文とパラメータ値が分かれた状態で出力されます。「LOG:」が含まれるのがプリペアド文で、「DETAIL:」が含まれるのがパラメータ値の文です。

...
[2020-05-20 00:00:01.538 JST]  [99999]  [testuser]  [testdb]  LOG:  execute <unnamed>: SELECT *
    FROM test_table
    WHERE col1 = $1
    AND col2 = $2
[2020-05-20 00:00:01.538 JST]  [99999]  [testuser]  [testdb]  DETAIL:  parameters: $1 = 'abc', $2 = 100
...

時刻やユーザー名等の出力はロケール設定等によって変わります。

作成するツールの機能

作成するツールの機能は下記のような簡単なものとします。

  1. スロークエリログを先頭から1行ずつ読み込み、プリペアド文とパラメータ部分のセットが揃ったらSQL生成処理に移ります。
  2. SQL生成処理ではパラメータをインデックス($1,$2...)と値のマップに変換してプリペアド文のパラメータインデックスを値で置換します。
  3. 完成したSQLをファイルに出力します。

実際にデータベースに接続するわけではないので、ファイル入出力と置換処理が主な処理となります。

出力するSQLファイルのフォーマット

下記のようなSQLファイルを出力することとします。

-- duration: 5970.59
explain analyze

SELECT *
FROM test_table
WHERE col1 = 'abc'
AND col2 = 100

Go言語で実装する

完成版のソースはこちらで確認できます。

https://github.com/pirosuke/divide-postgres-slowquery

パターン設定ファイルを用意する

上にも書きましたがスロークエリログのフォーマットはロケール設定等によって変わるので、ログの行からデータを取得するためのパターンを設定ファイルを作成してそこに記載しておきます。設定ファイルはプログラムの実行時に読み込むことにします。

英語出力の場合はこんな感じの設定になります:

https://github.com/pirosuke/divide-postgres-slowquery/blob/master/config_en_utc_sample.json

{
    "pattern_start": "^< ([^\\]]*) >LOG:  duration: (.*) ms  execute <unnamed>: (.*)",
    "pattern_end": "(.*)DETAIL:  parameters: (.*)"
}

日本語出力の場合はこんな感じの設定になります:

https://github.com/pirosuke/divide-postgres-slowquery/blob/master/config_ja_sample.json

{
    "pattern_start": "^< ([^\\]]*) >LOG:  期間: (.*) ミリ秒  実行 <unnamed>: (.*)",
    "pattern_end": "(.*)詳細:  パラメータ: (.*)"
}

後方参照用の「()」が重要です。

pattern_startでは1つ目の()が実行日時、2つ目が実行にかかったミリ秒数、3つ目がクエリ部分を表します。 pattern_endでは1つ目の()が実行日時、2つ目がパラメータリスト部分を表します。

コマンドライン引数を受け取る

ここからはmain.goの実装内容です。

https://github.com/pirosuke/divide-postgres-slowquery/blob/master/cmd/divide_pg_slowquery/main.go

このツールは3つのコマンドライン引数を受け取ります。

  • -c: パターン設定ファイルパス
  • -f: スロークエリログファイルパス
  • -o: SQLファイル出力先ディレクトリパス

標準のflagライブラリを使用して受け取ります。

flag - The Go Programming Language

import (
    "flag"
)
inputFilePath := flag.String("f", "", "Input File Path")
outputDirBasePath := flag.String("o", ".", "Output Dir Path")
configFilePath := flag.String("c", "", "Config File Path")

flag.Parse()

設定ファイルの内容を構造体に読み込む

パターン設定ファイルの内容をすぐに使えるように構造体にセットしておきましょう。

構造体定義にjsonタグをつけておくことで簡単にセットすることができます。標準のjsonライブラリを使用します。

json - The Go Programming Language

import (
    "encoding/json"
    "io/ioutil"
)
// Config 構造体の定義
type Config struct {
    PatternStart string `json:"pattern_start"`
    PatternEnd   string `json:"pattern_end"`
}
// 設定ファイルの内容を読み込み
jsonContent, err := ioutil.ReadFile(*configFilePath)

...

// 読み込んだ設定ファイルの内容をconfigにセット
config := new(Config)
err := json.Unmarshal(jsonContent, config)

ログファイルの内容を1行ずつ読み込む

ログファイルはサイズが大きくなる可能性があるので、メモリを圧迫しないように1行ずつ読み込んで処理します。

まずはファイルをオープンしてFileオブジェクト(fp)を取得します。deferで処理終了後にファイルをクローズするように設定しておきます。

fp, err := os.Open(*inputFilePath)
if err != nil {
    fmt.Println("failed opening file.")
    return
}
defer fp.Close()

ファイルを1行ずつ読み込むには、標準のbufioライブラリを使用します。

bufio - The Go Programming Language

scanner := bufio.NewScanner(fp)
for scanner.Scan() {
    // ループ毎に行のテキストがlineにセットされる
    line := scanner.Text()

    // ここでlineを処理する
}

if err := scanner.Err(); err != nil {
    fmt.Println("failed reading file.")
    panic(err)
}

パターンマッチでプリペアド文とパラメータの内容を1つのオブジェクトにまとめる

スロークエリログの内容を1行ずつ取得できるようになったので、プリペアド文とパラメータのセットを作って、後で処理しやすい形にまとめることにします。

まずスロークエリをまとめるスロークエリオブジェクト用の構造体を宣言します。

type SlowQuery struct {
    SQL          string
    LoggedTime   string
    Duration     float64
    Params       string
    IsInProgress bool
}
  • SQL: プリペアド文
  • LoggedTime: クエリが実行された時刻
  • Duration: 実行にかかったミリ秒数
  • Params: パラメータ文
  • IsInProgress: スロークエリオブジェクトが作成途中かどうかの判定値

パターンにマッチしたデータを取り出せるようにパターンごとの正規表現オブジェクトを生成しておきます。

patternStart := regexp.MustCompile(config.PatternStart)
patternEnd := regexp.MustCompile(config.PatternEnd)

正規表現処理は標準のregexpライブラリを使用します。

regexp - The Go Programming Language

上で書いたログファイルを処理するループに下記のように処理を追加します。

   // スロークエリオブジェクト初期化
    stats := SlowQuery{
        Duration:     0,
        IsInProgress: false,
    }

    scanner := bufio.NewScanner(fp)
    for scanner.Scan() {
        line := scanner.Text()

        // ステータスが処理中でなければ
        if !stats.IsInProgress {

            // プリペアド文の開始パターンにマッチする場合は後方参照値を取得
            m := patternStart.FindStringSubmatch(line)

            // マッチしたら実行時刻と処理にかかった時間をオブジェクトにセットしてステータスを「処理中」に変更
            if m != nil {
                stats.LoggedTime = m[1]

                duration, _ := strconv.ParseFloat(m[2], 64)
                stats.Duration = duration

                stats.SQL = m[3] + "\n"
                stats.IsInProgress = true
            }
        // ステータスが処理中なら
        } else {
            // パラメータ文のパターンに一致する場合は後方参照値を取得
            m := patternEnd.FindStringSubmatch(line)

            // 一致したらパラメータ文をオブジェクトにセットして、実行時刻が設定されていたらクエリログ出力を実行する
            if m != nil {
                stats.Params = m[2]
                if stats.Duration > 0 {
                    // クエリログ出力関数(次のステップで作成します)
                    outputSlowQueryFile(outputDirPath, stats)
                }

                // 次のプリペアド文雅処理できるようにオブジェクトを初期化
                stats = SlowQuery{
                    Duration:     0,
                    IsInProgress: false,
                }
            } else {
                // ステータスが「処理中」でかつパラメータ文パターンにマッチしない場合はプリペアド文の途中なのでオブジェクトのSQLに追記する
                stats.SQL += line + "\n"
            }
        }
    }

プリペアド文にパラメータをセットしてSQLファイルに出力する

プリペアド文ごとに関数「outputSlowQueryFile」が呼ばれるようにできたので、SQLを生成して出力する処理を持つ関数「outputSlowQueryFile」作成します。

先にパラメータ文をパラメータのインデックス($1,$2...)と値のマップに変換する関数を作成しておきましょう。

パラメータ文は下記のようなにインデックスと値が「=」でつながったものがカンマで区切られた形式になっていますので、これを分解してmapにしたものを返します。

$1 = 'abc', $2 = 100 ...
func parseParams(paramString string) map[string]string {
    patternParam := regexp.MustCompile("(\\$[0-9]+) = ([^,]+)")
    paramList := strings.Split(paramString, ",")

    paramMap := map[string]string{}
    for _, param := range paramList {
        m := patternParam.FindStringSubmatch(param)
        if m != nil {
            paramMap[m[1]] = m[2]
        }
    }

    return paramMap
}

最後に関数「outputSlowQueryFile」を作成します。

func outputSlowQueryFile(outputDirPath string, state SlowQuery) {
    // 実行時刻をファイル名に使うため、timeオブジェクトに変換して「yyyymmddhhiiss」形式にフォーマット
    t, err := time.Parse("2006-01-02 15:04:05.000 MST", state.LoggedTime)
    if err != nil {
        t = time.Now()
    }

    ts := t.Format("20060102150405")
    outputFilePath := filepath.Join(outputDirPath, ts+".sql")
    fmt.Println("output file: ", outputFilePath)

    // パラメータ文をマップに変換
    paramMap := parseParams(state.Params)

    // SQL文作成開始
    // 参考用にコメントで実行にかかった時間を入れておく
    query := "-- duration: " + strconv.FormatFloat(state.Duration, 'f', 2, 64) + "\n"

    // explain analyzeをあらかじめ入れておく
    query = query + "explain analyze\n\n"

    query = query + state.SQL

    // query内のパラメータインデックスをパラメータ値に置換
    for paramKey, paramValue := range paramMap {
        re := regexp.MustCompile("([^\\$])(\\" + paramKey + ")([^0-9])")
        query = re.ReplaceAllString(query, "$1"+paramValue+"$3")
    }

    // 作成したSQLを出力
    err = ioutil.WriteFile(outputFilePath, []byte(query), 0644)
    if err != nil {
        fmt.Println(err)
    }
}

他のプログラミング言語と比較して独特なのが日時の扱いです。

   // 実行時刻をファイル名に使うため、timeオブジェクトに変換して「yyyymmddhhMMss」形式にフォーマット
    t, err := time.Parse("2006-01-02 15:04:05.000 MST", state.LoggedTime)
...
    ts := t.Format("20060102150405")

Go言語で日時のフォーマットを指定する時は「yyyy」のような文字ではなく、「2006」のように決められた値を指定します。

Go/golangでの日付処理まとめ(チートシート) - Qiita

下記のようなルールです。

  • yyyy -> 2006
  • mm -> 01
  • dd -> 02
  • hh -> 15
  • MM -> 04
  • ss -> 05

覚えられる気がしませんね。

おわりに

これでメイン部分の処理は完成です。ソースの完成版を見たい方は上に記載したリポジトリのリンクを参照してください。

実際このツールを使う機会がどれくらいあるかは分かりませんが、Go言語で「ファイルの行単位処理」「正規表現マッチと後方参照」「日付処理」を行う練習になりました。