【課題 5】pprof で見る、取りすぎているデータ

読了目安約3分

ログに出ない SQLite の処理を pprof で測り、必要な分だけ取るように書き換えます。

この章の目次

CPU が限界になったので、CPU の使われ方を測ります。アクセスログにもスロークエリログにも出ない処理は、pprof で見ます。

プロファイルを取る

main.go に 2 行足すと、プロファイルを取り出す口が開きます。

Go
import (
	"net/http"
	_ "net/http/pprof"

	isuports "github.com/isucon/isucon12-qualify/webapp/go"
)

func main() {
	// 計測用。最終盤には外す
	go func() {
		http.ListenAndServe("localhost:6060", nil)
	}()
	isuports.Run()
}

ベンチマーカーの走行中に 30 秒ぶんを採取します。

シェル

curl -o cpu.pprof "http://localhost:6060/debug/pprof/profile?seconds=30"

まず flat 順で、その関数自身が使った時間を見ます。

シェル

go tool pprof -top isuports cpu.pprof

テキスト

      flat  flat%        cum   cum%
     8.76s 40.74%     10.36s 48.19%  runtime.cgocall
     0.14s  0.65%      9.05s 42.09%  ...go-sqlite3.(*SQLiteRows).nextSyncLocked
     0.14s  0.65%      0.41s  1.91%  encoding/json.appendIndent

cgocall は Go から C のライブラリを呼ぶ処理です。 nextSyncLocked は SQLite から 1 行取り出す処理で、その中身が cgocall です。アプリが使う CPU の 4 割が、SQLite の行読み出しに消えています。

次に cum 順で、その関数とその中から呼ばれた処理の合計を見ます。

シェル

go tool pprof -top -cum isuports cpu.pprof

テキスト

      flat  flat%        cum   cum%
         0     0%     18.87s 87.77%  net/http.serverHandler.ServeHTTP
     0.02s 0.093%      9.91s 46.09%  ...go.competitionRankingHandler
     0.02s 0.093%      6.89s 32.05%  ...go.playerHandler

ランキングと参加者詳細の 2 つで、アプリの CPU の 8 割弱を使っています。

課題

-list を使うと、行ごとの内訳が出ます。

テキスト

ROUTINE ==== ...go.competitionRankingHandler
      20ms      9.91s (flat, cum) 46.09% of Total
         .      520ms   1324:	v, err := parseViewer(c)
         .      450ms   1338:	if err := authorizePlayer(ctx, tenantDB, v.playerID); err != nil {
         .         4s   1388:	if err := tenantDB.SelectContext(   // player_score
         .      3.06s   1399:	if err := tenantDB.SelectContext(   // player
         .      140ms   1432:	sort.Slice(ranks, func(i, j int) bool {
      10ms      760ms   1465:	return c.JSON(http.StatusOK, res)

該当する 2 つのクエリと、返しているレスポンスはこうです。

Go
// 1388 行目
"SELECT * FROM player_score WHERE tenant_id = ? AND competition_id = ? ORDER BY row_num DESC"

// 1399 行目
"SELECT * FROM player WHERE tenant_id = ?"

Go
pagedRanks := make([]CompetitionRank, 0, 100)
for i, rank := range ranks {
	if int64(i) < rankAfter {
		continue
	}
	pagedRanks = append(pagedRanks, CompetitionRank{
		Rank:              int64(i + 1),
		Score:             rank.Score,
		PlayerID:          rank.PlayerID,
		PlayerDisplayName: rank.PlayerDisplayName,
	})
	if len(pagedRanks) >= 100 {
		break
	}
}

この 2 つのクエリの何が無駄か、それぞれ答えてください。

解答例

使わない列まで取っている

SELECT * は 8 列すべてを取ります。使うのは player_id、score、row_num の 3 つだけです。

第 3 章で張ったインデックスには、この 3 列が入っています。列を絞ると、インデックスを読むだけで答えが出せます。

"SELECT player_id, score, row_num FROM player_score WHERE tenant_id = ? AND competition_id = ? ORDER BY row_num DESC"

使わない行まで取っている

参加者を全員引いていますが、名前を返すのは上位 100 件だけです。大きなテナントでは 5000 人以上を毎回読んでいました。

並べ替えて 100 件に切ったあとで、その 100 人ぶんだけ引きます。

Go
if len(pagedRanks) > 0 {
	ids := make([]string, 0, len(pagedRanks))
	for _, r := range pagedRanks {
		ids = append(ids, r.PlayerID)
	}
	query, args, err := sqlx.In("SELECT id, display_name FROM player WHERE id IN (?)", ids)
	if err != nil {
		return fmt.Errorf("error sqlx.In: %w", err)
	}
	pls := []PlayerRow{}
	if err := tenantDB.SelectContext(ctx, &pls, query, args...); err != nil {
		return fmt.Errorf("error Select player: %w", err)
	}
	displayNameByID := make(map[string]string, len(pls))
	for _, p := range pls {
		displayNameByID[p.ID] = p.DisplayName
	}
	for i := range pagedRanks {
		pagedRanks[i].PlayerDisplayName = displayNameByID[pagedRanks[i].PlayerID]
	}
}

第 4 章で書いた「参加者をまとめて引いて map にする」を、さらに書き換えたことになります。 N+1 を消すために全件取ると、今度は全件取ることが重くなります。

効果

	スコア
CSV 入稿をまとめた	35888
取る量を減らした	38522

プロファイルを取りながら走らせると、この環境では 1 % 前後スコアが下がりました。最後の 1 回はプロファイルを外して測ります。

覚えておくこと

取る列を減らすと、インデックスだけで答えが出る場合がある
返す件数が決まっているなら、その件数ぶんだけ取る
ログに出ない処理は pprof で見る