LoginSignup
0
2

More than 3 years have passed since last update.

MackerelAdvent Calendar 2020Day 22
@shiimaxx

MackerelでGoroutineのブロックを検知したい

Last updated at Posted at 2020-12-21

Mackerel Advent Calendar 2020 22日目のエントリです。

先日、とあるGo製のアプリケーションで、Goroutineの処理がブロックされて停止していることで、アプリケーション全体の動作が停止するということがありました。
このような問題を検知するための監視をMackerelで行う方法を考えてみたので、このエントリで紹介します。

Mackerelでは、mackerel-agentのプラグイン機構やカスタムメトリックなどの機能によって、監視対象のシステム/アプリケーションの特性にあわせた様々な監視を実装することができます。これらの機能を使って監視実装をしてみます。

アプリケーションの動作が停止したときの状態

まずはじめに、問題のアプリケーションの動作が停止していたときに、どのような事象が発生していたかを説明します。

以下は、アプリケーションに問題が発生していたタイミングにおけるGoroutineのスタックトレースの一部です。

goroutine 1 [chan receive, 1419 minutes]:
main.run(*app).Wait(0xc45114f3f0, 0x0, 0x0)
        /opt/app/app.go:22 +0x144
...
goroutine 12 [chan receive, 1419 minutes]:
main.handle.func1(0xc4201b56a0, 0xc44601d3f0)
        /opt/app/app.go:50 +0x41
...
goroutine 176 [IO wait, 1419 minutes]:
internal/poll.runtime_pollWait(0x7f1896c1ad60, 0x72, 0xc4206c88c0)
        /usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc4206b2318, 0x72, 0xffffffffffffff00, 0x94f100, 0xd76bd0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc4206b2318, 0xc4202fa000, 0x1000, 0x1000)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc4206b2300, 0xc4202fa000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:157 +0x17d
net.(*netFD).Read(0xc4206b2300, 0xc4202fa000, 0x1000, 0x1000, 0xc4200c0120, 0x28b621587cb3ad0b, 0xc4206c89d0)
        /usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc420670230, 0xc4202fa000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/net.go:176 +0x6a
bufio.(*Reader).Read(0xc420611500, 0xc42132ade8, 0x8, 0x8, 0xc420028070, 0x44ca18, 0x38caa669fac61c)
...

各Goroutineのスタックトレースは、goroutine <数字> […]という行で始まっています。
ここでは、goroutine 1, goroutine 12, goroutine 176をピックアップして載せました。各Goroutineは、ざっくり説明すると次のような状態です。

  • goroutine 1 [chan receive, 1419 minutes], goroutine 12 [IO wait, 1419 minutes]
    • goroutine 176の処理完了を待って処理がブロックされているGoroutine
    • アプリケーション内のchannelを受信する箇所でブロックされている
  • goroutine 176 [IO wait, 1419 minutes]
    • 外部サービスとのコネクションを確立したまま処理が停止したGoroutine

Mackerelで監視する

さて、アプリケーションに同様の問題が発生したことをMackerelで検知するために、監視の実装方法を考えていきます。

スタックトレースには次のような行がありました。

goroutine 176 [IO wait, 1419 minutes]

goroutine 176はIO waitの状態が1419分続いているということを表します。
これは、アラートとして検知できるようにしたい「アプリケーションが停止している状態」を表している出力なので、このようなスタックトレースの出力があることを何らかの方法でチェックできるようにするとよさそうです。

監視対象アプリケーションからスタックトレースを定期的に取得して（オーバーヘッドは無視できるものとします）、スタックトレースに含まれる[IO wait, 1419 minutes]の部分をカスタムメトリックとして投稿して、そのカスタムメトリックに対して監視ルールを設定することで、アラートとして検知できるようにしたいと思います。

以下が実装の流れです。​​

  • 監視対象のアプリケーションでnet/http/pprofをimportする
  • カスタムメトリックを取得するプログラムを作る
  • Mackerelで監視ルールを設定する

監視対象のアプリケーションでnet/http/pprofをimportする

まず、監視対象アプリケーションのGoroutineのスタックトレースをアプリケーション外から取得できるようにする必要があります。
そのために、Goの標準パッケージに含まれるnet/http/pprofを利用します。net/http/pprofをアプリケーションでimportすると、いくつかのデバッグ用のハンドラが追加されます。そのひとつにGoroutineのスタックトレースを取得するためのハンドラがあるので利用します。

監視対象のアプリケーションで、以下のようにnet/http/pprofをimportするだけでOKです。

import _ "net/http/pprof"

カスタムメトリックを取得するプログラムを作る

net/http/pprofをimportしたアプリケーションの、/debug/pprof/goroutine?debug=2にリクエストをすると、そのアプリケーションの全てのGoroutineのスタックトレースをレスポンスとして受け取ることができます。

カスタムメトリックを取得するプログラムでは、このエンドポイントを利用して監視対象アプリケーションのGoroutineのスタックトレースを取得し、そこから以下の部分をパースしてカスタムメトリックとして収集できるようにします。

goroutine 176 [IO wait, 1419 minutes]

ここで収集するカスタムメトリックは、Goroutineの状態とその状態の継続時間を組み合わせたものをキーにして、値はキーに該当するGoroutineの数とします。
具体的には、IO waitであるGoroutineは、以下のいずれかのキーに該当することになります。

  • IO_wait
  • IO_wait_1_minutes_over
  • IO_wait_10_minutes_over
  • IO_wait_100_minutes_over
  • IO_wait_1000_minutes_over

これに当てはめると、スタックトレースにgoroutine 176 [IO wait, 1419 minutes]という行が含まれていた場合、IO_wait_1000_minutes_overの値が1増える、という感じです。

サンプルとして作成したプログラムのソースコードです。


package main

import (
        "fmt"
        "io/ioutil"
        "net/http"
        "regexp"
        "strconv"
        "strings"
        "time"
)

var reg = regexp.MustCompile(`^goroutine [0-9]+ \[([a-zA-Z ]+)(, )?(([0-9]+) minutes)?.*\]`)

var prefix = "goroutine"

func main() {
        resp, err := http.Get("http://localhost:6060/debug/pprof/goroutine?debug=2")
        if err != nil {
                // エラー処理
        }
        defer resp.Body.Close()

        body, err := ioutil.ReadAll(resp.Body)
        if err != nil {
                // エラー処理
        }

        metric := make(map[string]int)
        for _, b := range strings.Split(string(body), "\n") {
                if strings.HasPrefix(b, "goroutine") {
                        m := reg.FindStringSubmatch(b)
                        state, duration := m[1], m[4]
                        state = strings.Replace(state, " ", "_", -1)
                        if duration == "" {
                                if _, ok := metric[state]; !ok {
                                        metric[state] = 1
                                } else {
                                        metric[state]++
                                }
                                continue
                        }

                        i, err := strconv.Atoi(duration)
                        if err != nil {
                                // エラー処理
                        }

                        if i >= 1000 {
                                s := fmt.Sprintf("%s_1000_minutes_over", state)
                                if _, ok := metric[s]; !ok {
                                        metric[s] = 1
                                } else {
                                        metric[s]++
                                }
                                continue
                        }

                        if i >= 100 {
                                s := fmt.Sprintf("%s_100_minutes_over", state)
                                if _, ok := metric[s]; !ok {
                                        metric[s] = 1
                                } else {
                                        metric[s]++
                                }
                                continue
                        }

                        if i >= 10 {
                                s := fmt.Sprintf("%s_10_minutes_over", state)
                                if _, ok := metric[s]; !ok {
                                        metric[s] = 1
                                } else {
                                        metric[s]++
                                }
                                continue
                        }

                        s := fmt.Sprintf("%s_1_minutes_over", state)
                        if _, ok := metric[s]; !ok {
                                metric[s] = 1
                        } else {
                                metric[s]++
                        }
                }
        }

        ts := time.Now().Unix()
        for k, v := range metric {
                fmt.Printf("%s.%s\t%d\t%d\n", prefix, k, v, ts)
        }
}

プログラムを実行すると、次のような出力が得られます。


$ /path/to/mackerel-plugin-goroutine
goroutine.syscall_1000_minutes_over     2       1608554105
goroutine.chan_receive_1_minutes_over   1       1608554105
goroutine.syscall       5       1608554105
goroutine.select_1000_minutes_over      4       1608554105
goroutine.select        172     1608554105
goroutine.syscall_10_minutes_over       1       1608554105
goroutine.chan_receive  1       1608554105
goroutine.IO_wait_10_minutes_over       1       1608554105
goroutine.IO_wait_1000_minutes_over     1       1608554105
goroutine.semacquire_1000_minutes_over  6       1608554105
goroutine.running       1       1608554105
goroutine.select_10_minutes_over        2       1608554105
goroutine.chan_receive_1000_minutes_over        11      1608554105
goroutine.select_1_minutes_over 1       1608554105

出力フォーマットは以下に沿っています。
https://mackerel.io/ja/docs/entry/advanced/custom-metrics

メトリックの投稿
設定ファイルで指定するコマンドは、標準出力の各行に以下のフォーマットの出力をすることが期待されます（\t はタブ文字です）:

{metric name}\t{metric value}\t{epoch seconds}

このプログラムの出力をカスタムメトリックとして投稿するために、mackerel-agent.confに設定を追加します。

[plugin.metrics.goroutine]
command = "/path/to/mackerel-plugin-goroutine"

ここまでやると、Mackereでカスタムメトリックのグラフが見られるようになります。

スクリーンショット 2020-12-21 21.44.03.png

Mackerelで監視ルールを設定する

あとは、ドキュメントを参考に監視ルール設定すればOKです。
​​https://mackerel.io/ja/docs/entry/howto/alerts

次のように設定をすれば、IO waitの状態が1000分以上継続しているGoroutineが存在している状態をアラートとして検知することができます。

スクリーンショット 2020-12-21 22.11.50.png

これで、以下で述べていたようなチェックをしてアラートとして検知することができます。

goroutine 176はIO waitの状態が1419分続いているということを表します。
これは、アラートとして検知できるようにしたい「アプリケーションが停止している状態」を表している出力なので、このようなスタックトレースの出力があることを何らかの方法でチェックできるようにするとよさそうです。

まとめ

監視を実現するためには、メトリックの取得、収集、チェック、アラーティング、と色々なコンポーネントが必要になるのですが、Mackerelでは「メトリックの取得」の部分だけ自前で用意すれば、あとのことはMackerelに任せて、オリジナルな監視を追加することができます。便利。

0
2
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
Sign upLogin
0
2