goのプログラムを観察するのにgopsが便利だった

• gopsというツールがありまして
• https://github.com/google/gops
• memstatsやtreeというサブコマンドを使用するとgoで動作しているプログラムから簡単に取得出来たりするので大変便利です
• profileも楽に取れるしありがたい

gops tree

 gops tree
...
├── 956
│   └── 7217 (gops) {go1.12}
└── 544
    └── 593 (com.docker.supervisor) {go1.10.6}
        └── 596 (com.docker.driver.amd64-linux) {go1.10.6}

この辺の設定を追加すると良い感じにとれる

package main

import (
    "log"
    "time"

    "github.com/google/gops/agent"
)

func main() {
    if err := agent.Listen(agent.Options{}); err != nil {
        log.Fatal(err)
    }
    time.Sleep(time.Hour)
}

goのsqlにあるfreeConnにどこで追加してるか気になったので調べた

• putConnDBLockedというメソッド中でやっていた
• ここでdb.freeConにappendしている

   } else if err == nil && !db.closed {
        if db.maxIdleConnsLocked() > len(db.freeConn) {
            db.freeConn = append(db.freeConn, dc)
            db.startCleanerLocked()
            return true
        }

参照

• https://golang.org/pkg/database/sql/

goのsql/databaseの接続でやり方間違えると資源枯渇したりして大変らしいので負荷をかけてみた

• http://go-database-sql.org/surprises.html
• こちらのページに書かれている

Opening and closing databases can cause exhaustion of resources.

が気になったのでwrkで負荷をかけてみた。

条件

• dockerでmysqlを立ち上げる
• SelectとUpdateが単純に走るだけのhandlerを設置したgoのserverを立ち上げる

1. 最初にdbオブジェクトを初期化して持ち回す方法
2. リクエストのたびにdbオブジェクトをOpenする方法

上記2つを検証した

結論

wrk -c 2 -t 1 -d 30 http://localhost:8080/ping

• 上記の負荷に1のケースは耐えられたが、2のケースはtoo many connectionsを多発して耐えられなかった

追記のメモ

go run -gcflags '-m' main.go

• コンパイルオプションでheap調査が出来るんだけど
• 上の1のケースでもleaking closure reference dbとか物騒な単語が出てくる
• 本当にリークするのか、その可能性があるから警告してるのか
• 後者だと信じたいのでruntimeのコードを見た

2025 >...>...// Treat a captured closure variable as equivalent to the
2026 >...>...// original variable.
2027 >...>...if src.IsClosureVar() {
2028 >...>...>...if leaks && Debug['m'] != 0 {
2029 >...>...>...>...Warnl(src.Pos, "leaking closure reference %S", src)
2030 >...>...>...>...step.describe(src)
2031 >...>...>...}
2032 >...>...>...e.escwalk(level, dst, src.Name.Defn, e.stepWalk(dst, src.Name.Defn, "closure-var", step))
2033 >...>...}

• なんとなくだけど、IsClosureVarがコードにあった場合に出してる警告ぽいので
• 後者だと信じて寝ます

Goのmemstatsの項目をみてみる

• https://golang.org/pkg/runtime/#MemStats
• MemStatsから取得出来る各項目を一覧してみた
• 細かいコメント等は本家を参照すること

項目名	説明
Alloc	割り当てられたヒープオブジェクトのバイト数
TotalAlloc	ヒープオブジェクトに割り当てられた累積バイト数
Sys	OSから取得したメモリの総バイト数
Lookups	ランタイムによって実行されたポインタの参照数
Mallocs	割り当てられたヒープオブジェクトの累積数
Frees	解放されたヒープオブジェクトの累積数
HeapAlloc	割り当てられたヒープオブジェクトのバイト数
HeapSys	OSから取得したヒープメモリのバイト数
HeapIdle	HeapIdleは、アイドル（未使用）スパンのバイト数
HeapInuse	使用中のスパンのバイト数
HeapReleased	OSに返される物理メモリのバイト数
HeapObjects	割り当てられたヒープオブジェクトの数
StackInuse	スタックスパン内のバイト数
StackSys	OSから取得したスタックメモリのバイト数
MSpanInuse	割り当てられたmspan構造体のバイト数
MSpanSys	mspan構造体用にOSから取得されたメモリのバイト数
MCacheInuse	割り当てられたmcache構造体のバイト数
MCacheSys	mcache構造体用にOSから取得されたメモリのバイト数
BuckHashSys	プロファイリングバケットハッシュテーブル内のメモリのバイト数
GCSys	ガベージコレクションメタデータ内のメモリのバイト数
OtherSys	雑多なオフヒープランタイム割り当てにおけるメモリのバイト数
NextGC	次のGCサイクルの目標ヒープサイズ
LastGC	最後のガベージコレクションが終了した時刻
PauseTotalNs	プログラムが開始されてからのGC停止の累積ナノ秒数
PauseNs	最近のGCの世界一時停止時間を示す循環バッファ
PauseEnd	最近のGCの一時停止の終了時刻を示す循環バッファ
NumGC	完了したGCサイクルの数
NumForcedGC	アプリケーションがGC関数を呼び出すことによって強制されたGCサイクル数
GCCPUFraction	プログラムが起動してからこのプログラムで使用可能なCPU時間の割合

appengineでmemstatsしたかった

• appengineのバージョンが古いとデータが取れなかったりするので
• こちらのコードから必要そうな処理をお借りしました
• https://github.com/google/gops

package hello

import (
    "encoding/json"
    "fmt"
    "net/http"
    "runtime"
    "time"

    "google.golang.org/appengine"
)

func formatBytes(val uint64) string {
    return fmt.Sprintf("%d", val)
}

func main() {
    http.HandleFunc("/", handle)
    http.HandleFunc("/memstats", handleMemStats)
    appengine.Main()
}

func handle(w http.ResponseWriter, r *http.Request) {
    fmt.Fprintln(w, "Hello, world!")
}

type responseMemStats struct {
    Alloc        string `json:"alloc"`
    TotalAlloc   string `json:"total-alloc"`
    Sys          string `json:"sys"`
    Lookups      string `json:"lookups"`
    Mallocs      string `json:"mallocs"`
    Frees        string `json:"frees"`
    HeapAlloc    string `json:"heap-alloc"`
    HeapSys      string `json:"heap-sys"`
    HeapIdle     string `json:"heap-idle"`
    HeapInuse    string `json:"heap-in-use"`
    HeapReleased string `json:"heap-released"`
    HeapObjects  string `json:"heap-objects"`
    StackInuse   string `josn:"stack-in-use"`
    StackSys     string `json:"stack-sys"`
    MSpanInuse   string `json:"stack-mspan-inuse"`
    MSpanSys     string `json:"stack-mspan-sys"`
    MCacheInuse  string `json:"stack-mcache-inuse"`
    MCacheSys    string `json:"stack-mcache-sys"`
    OtherSys     string `json:"other-sys"`
    GCSys        string `json:"gc-sys"`
    NextGC       string `json:"next-gc"`
    LastGC       string `json:"last-gc"`
    PauseTotalNs string `json:"gc-pause-total"`
    Pause        string `json:"gc-pause"`
    NumGC        string `json:"num-gc"`
    EnableGC     string `json:"enable-gc"`
    DebugGC      string `json:"debug-gc"`
}

func handleMemStats(w http.ResponseWriter, r *http.Request) {
    var s runtime.MemStats
    runtime.ReadMemStats(&s)
    lastGC := "-"
    if s.LastGC != 0 {
        lastGC = fmt.Sprint(time.Unix(0, int64(s.LastGC)))
    }
    responseMemStats := &responseMemStats{
        Alloc:        formatBytes(s.Alloc),
        TotalAlloc:   formatBytes(s.TotalAlloc),
        Sys:          formatBytes(s.Sys),
        Lookups:      fmt.Sprintf("%v", s.Lookups),
        Mallocs:      fmt.Sprintf("%v", s.Mallocs),
        Frees:        fmt.Sprintf("%v", s.Frees),
        HeapAlloc:    formatBytes(s.HeapAlloc),
        HeapSys:      formatBytes(s.HeapSys),
        HeapIdle:     formatBytes(s.HeapIdle),
        HeapInuse:    formatBytes(s.HeapInuse),
        HeapReleased: formatBytes(s.HeapReleased),
        HeapObjects:  fmt.Sprintf("%v", s.HeapObjects),
        StackInuse:   formatBytes(s.StackInuse),
        StackSys:     formatBytes(s.StackSys),
        MSpanInuse:   formatBytes(s.MSpanInuse),
        MSpanSys:     formatBytes(s.MSpanSys),
        MCacheInuse:  formatBytes(s.MCacheInuse),
        MCacheSys:    formatBytes(s.MCacheSys),
        OtherSys:     formatBytes(s.OtherSys),
        GCSys:        formatBytes(s.GCSys),
        NextGC:       formatBytes(s.NextGC),
        LastGC:       lastGC,
        PauseTotalNs: fmt.Sprintf("%v", time.Duration(s.PauseTotalNs)),
        Pause:        fmt.Sprintf("%v", s.PauseNs[(s.NumGC+255)%256]),
        NumGC:        fmt.Sprintf("%v", s.NumGC),
        EnableGC:     fmt.Sprintf("%v", s.EnableGC),
        DebugGC:      fmt.Sprintf("%v", s.DebugGC),
    }
    json, err := json.Marshal(responseMemStats)

    if err != nil {
        fmt.Fprint(w, err.Error())
        return
    }
    fmt.Fprint(w, string(json))
}

こんな感じでserverを立てて

package main

import (
    "encoding/json"
    "fmt"
    "io/ioutil"
    "log"
    "net/http"
    "reflect"
    "strings"
)

type responseMemStats struct {
    Alloc        string `json:"alloc"`
    TotalAlloc   string `json:"total-alloc"`
    Sys          string `json:"sys"`
    Lookups      string `json:"lookups"`
    Mallocs      string `json:"mallocs"`
    Frees        string `json:"frees"`
    HeapAlloc    string `json:"heap-alloc"`
    HeapSys      string `json:"heap-sys"`
    HeapIdle     string `json:"heap-idle"`
    HeapInuse    string `json:"heap-in-use"`
    HeapReleased string `json:"heap-released"`
    HeapObjects  string `json:"heap-objects"`
    StackInuse   string `josn:"stack-in-use"`
    StackSys     string `json:"stack-sys"`
    MSpanInuse   string `json:"stack-mspan-inuse"`
    MSpanSys     string `json:"stack-mspan-sys"`
    MCacheInuse  string `json:"stack-mcache-inuse"`
    MCacheSys    string `json:"stack-mcache-sys"`
    OtherSys     string `json:"other-sys"`
    GCSys        string `json:"gc-sys"`
    NextGC       string `json:"next-gc"`
    LastGC       string `json:"last-gc"`
    PauseTotalNs string `json:"gc-pause-total"`
    Pause        string `json:"gc-pause"`
    NumGC        string `json:"num-gc"`
    EnableGC     string `json:"enable-gc"`
    DebugGC      string `json:"debug-gc"`
}

func main() {
    targetFields := map[string]bool{
        "Alloc":      true,
        "TotalAlloc": true,
        "LastGC":     true,
    }

    res, err := http.Get("http://localhost:8080/memstats")
    if err != nil {
        log.Fatal(err)
    }
    body, err := ioutil.ReadAll(res.Body)
    res.Body.Close()
    if err != nil {
        log.Fatal(err)
    }

    data := &responseMemStats{}
    if err = json.Unmarshal(body, data); err != nil {
        log.Fatal(err)
    }

    v := reflect.Indirect(reflect.ValueOf(data))
    t := v.Type()
    rows := []string{}
    for i := 0; i < t.NumField(); i++ {
        if !targetFields[t.Field(i).Name] {
            continue
        }
        f := v.Field(i)
        row := fmt.Sprintf("%s:%s", t.Field(i).Name, f.String())
        rows = append(rows, row)
    }

    fmt.Println(strings.Join(rows, ","))
}

適当に出力できます

GoのメモリにおけるHeapの確認 (2)

• appendでsliceのサイズをいじった場合にどうなるかをみた
• heapへのescapeはあくまで関数間でデータの受け渡しを参照で行った場合に起きるようだ

sliceへappendしてポインタを返した場合

package main

func makeHeap() *[]int {
    v := []int{}
    for i := 0; i < 1000; i++ {
        v = append(v, i)
    }
    return &v
}

func main() {
    _ = makeHeap()
}

これは、heapに乗る

go run -gcflags '-m -l' main.go
# command-line-arguments
./main.go:8:9: &v escapes to heap
./main.go:4:2: moved to heap: v
./main.go:4:12: []int literal escapes to heap

インライン展開をした場合もheapに乗る

go run -gcflags '-m' main.go
# command-line-arguments
./main.go:11:6: can inline main
./main.go:8:9: &v escapes to heap
./main.go:4:2: moved to heap: v
./main.go:4:12: []int literal escapes to heap

単純にsliceへappendした場合

package main

func makeHeap() {
    v := []int{}
    for i := 0; i < 1000; i++ {
        v = append(v, i)
    }
}

func main() {
    makeHeap()
}

関数内部で完結している場合はheapに乗らない

go run -gcflags '-m -l' main.go
# command-line-arguments
./main.go:4:12: makeHeap []int literal does not escape

インライン展開をしても当然一緒

go run -gcflags '-m' main.go
# command-line-arguments
./main.go:10:6: can inline main
./main.go:4:12: makeHeap []int literal does not escape

GoのメモリにおけるHeapの確認 (1)

コード

• 単純にポインタを返すからheapかと言われると
• インライン展開で最適化されてそうじゃなくなるケースがあるようだ

package main

func makeHeap() *[]int {
    v := []int{}
    return &v
}

func main() {
    for i := 0; i < 1000; i++ {
        _ = makeHeap()
    }
}

インライン展開無しでheapを確認する

• -lを使用するとインライン展開を無しに出来る
• vはheapへ行く

go run -gcflags '-m -l' main.go
# command-line-arguments
./main.go:5:9: &v escapes to heap
./main.go:4:2: moved to heap: v
./main.go:4:12: []int literal escapes to heap

この状態でtraceすると、heapにデータがのっていることがわかる

インライン展開つきでheapを確認する

• -lを取り除くとインライン展開される

go run -gcflags '-m' main.go
# command-line-arguments
./main.go:3:6: can inline makeHeap
./main.go:10:15: inlining call to makeHeap
./main.go:5:9: &v escapes to heap
./main.go:4:2: moved to heap: v
./main.go:4:12: []int literal escapes to heap
./main.go:10:15: main []int literal does not escape
./main.go:10:15: main &v does not escape

この状態でtraceをするとheapが使われていないことが分かる

コンパイルオプションについて

• https://github.com/golang/go/wiki/CompilerOptimizations
• https://qiita.com/ryskiwt/items/574a07c6235735afa5d7
• https://golang.org/cmd/compile/#hdr-Command_Line
• こちらのURLに詳しい

参照

• http://najeira.blogspot.com/2013/10/go.html
• https://hnakamur.github.io/blog/2018/01/30/go-heap-allocations/
• https://qiita.com/KoyaFukushi/items/fc532d7dae29381e8186
• https://ja.wikipedia.org/wiki/%E3%82%A8%E3%82%B9%E3%82%B1%E3%83%BC%E3%83%97%E8%A7%A3%E6%9E%90