golang

2016年09月20日

ISUCON6予選をトップ通過しました

はてなブックマークに登録

@methane です。「この技術部には問題がある!」というチーム名で @kizkoh (インフラ担当), @mecha_g3 (アプリ担当) とともに ISUCON 6 に参戦し、予選をトップスコアで通過しました。 恒例のふりかえり記事を書きます。

ふりかえり

残念ながらスコアは記録してないのですが、時系列順にやったことをまとめます。 アプリのコードは methane/isu6q-app で公開しているので、興味がある方はコードを確認してください。

strings.Replacer を使う

使用言語は最初から Go と決めていたのですが、Goの初期実装は遅すぎてタイムアウトで最初からスコア無しでした。 top でアプリのCPUが支配的なのはすぐ判りましたし、コードを読めばなにが遅いのかも一発で判りました。そんなに長くないので関数全体を張ります。

func htmlify(w http.ResponseWriter, r *http.Request, content string) string {
	if content == "" {
		return ""
	}
	rows, err := db.Query(`
		SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC
	`)
	panicIf(err)
	entries := make([]*Entry, 0, 500)
	for rows.Next() {
		e := Entry{}
		err := rows.Scan(&e.ID, &e.AuthorID, &e.Keyword, &e.Description, &e.UpdatedAt, &e.CreatedAt)
		panicIf(err)
		entries = append(entries, &e)
	}
	rows.Close()

	keywords := make([]string, 0, 500)
	for _, entry := range entries {
		keywords = append(keywords, regexp.QuoteMeta(entry.Keyword))
	}
	re := regexp.MustCompile("("+strings.Join(keywords, "|")+")")
	kw2sha := make(map[string]string)
	content = re.ReplaceAllStringFunc(content, func(kw string) string {
		kw2sha[kw] = "isuda_" + fmt.Sprintf("%x", sha1.Sum([]byte(kw)))
		return kw2sha[kw]
	})
	content = html.EscapeString(content)
	for kw, hash := range kw2sha {
		u, err := r.URL.Parse(baseUrl.String()+"/keyword/" + pathURIEscape(kw))
		panicIf(err)
		link := fmt.Sprintf("<a href=\"%s\">%s</a>", u, html.EscapeString(kw))
		content = strings.Replace(content, hash, link, -1)
	}
	return strings.Replace(content, "\n", "<br />\n", -1)
}

今回の問題ははてなキーワード+はてなスターのようなサービスで、この関数はキーワードの紹介記事に対して他のキーワードへのリンクを生成しつつHTMLエスケープするものです。キーワードは文字数順でソートしているので、最長一致でリンクになります。

キーワードからリンクへの変換が一発でされていないのは、先に変換するとHTMLエスケープで <a> タグまでエスケープされてしまうし、逆に先にHTMLエスケープをするとキーワードを見つけられなくなるからです。(一度これに気づかず一気に変換するようにしてハマりました)

正規表現のビルドと置換のどちらがどれくらいの割合で重いのかまではまだプロファイルを始めてなかったのでわかりませんが、初手からGoらしい最適化を始めてみます。

まずGoの正規表現は遅いので strings.Replacer を使ってキーワードからリンクへの変換をします。 Replacer を構築するのにも時間がかかるので、 htmlify() という関数で毎回構築するのではなく、起動時と、キーワードの追加削除時に再構築をするようにします。(実際にはすでに存在するキーワードの記事に対する修正のケースを見逃していて無駄に再構築していました。これに気づいていたらもっとスコア上がったはず…)

var (
	mKwControl sync.Mutex
	kwdList    KeywordArray

	mKwReplacer                  sync.RWMutex
	kwReplacer1st, kwReplacer2nd *strings.Replacer
)

func updateReplacer() {
	reps1 := make([]string, 0, len(kwdList)*2)
	reps2 := make([]string, 0, len(kwdList)*2)
	for i, k := range kwdList {
		if k.holder == "" {
			k.holder = fmt.Sprintf("isuda_%x", sha1.Sum([]byte(k.Key)))
			kwdList[i].holder = k.holder
		}

		reps1 = append(reps1, k.Key)
		reps1 = append(reps1, k.holder)

		reps2 = append(reps2, k.holder)
		reps2 = append(reps2, k.Link)
	}
	r1 := strings.NewReplacer(reps1...)
	r2 := strings.NewReplacer(reps2...)
	mKwReplacer.Lock()
	kwReplacer1st = r1
	kwReplacer2nd = r2
	mKwReplacer.Unlock()
}

func AddKeyword(key, link string) {
	k := Keyword{Key: key, Link: link}

	mKwControl.Lock()
	kwdList = append(kwdList, k)
	sort.Sort(kwdList)

	updateReplacer()
	mKwControl.Unlock()
}

func ReplaceKeyword(c string) string {
	mKwReplacer.RLock()
	r1 := kwReplacer1st
	r2 := kwReplacer2nd
	mKwReplacer.RUnlock()
	x := r1.Replace(c)
	x = html.EscapeString(x)
	return r2.Replace(x)
}

AddKeyword はキーワードをポストしたときに、 ReplaceKeywordhtmlify から呼ばれます。これで NewReplacer を呼び出す回数を大幅に削減することができました。

この変更を投入するタイミングで、 MySQL に接続するときに '127.0.0.1' からの接続が許可されていないというエラーがでるようになって(何もしてないのに壊れた追記: 秘伝のタレでskip-name-resolveが入ったのが原因の模様) Unix Domain Socket を使うようにしました。 @kizkoh による nginx や MySQL の設定 (静的ファイルを nginx で返す等) や、初期実装にあったバグを潰したりして、14:00すぎに12万点を出しました。

isutar を isuda にマージ

これは @mecha_g3 に任せた部分です。 isutar と isuda がお互いにJSON APIを使ってやり取りをしている部分があって、2つのアプリとMySQLが1台のマシンに乗っている以上完全に無駄なので全部1つにまとめました。スコアを記録してないのですが順当に性能アップしたはずです。

これを投入してベンチをかけるときにハマったのが、DBコネクションのデッドロックです。もともと2コアの1台のマシンなので、DBへの接続は4本も要らないだろうと思いつつ、念のために8本にしていました。ところが、次のようなコードが原因で8本あっても足りなくなってしまいました。

	rows, err := db.Query(fmt.Sprintf(
		"SELECT * FROM entry ORDER BY updated_at DESC LIMIT %d OFFSET %d",
		perPage, perPage*(page-1),
	))
	if err != nil && err != sql.ErrNoRows {
		panicIf(err)
	}
	entries := make([]*Entry, 0, 10)
	for rows.Next() {
		e := Entry{}
		err := rows.Scan(&e.ID, &e.AuthorID, &e.Keyword, &e.Description, &e.UpdatedAt, &e.CreatedAt)
		panicIf(err)
		e.Html = htmlify(w, r, e.Description)
		e.Stars = loadStars(e.Keyword)
		entries = append(entries, &e)
	}
	rows.Close()

このコードはトップページのハンドラーの一部です。 for rows.Next() ループが終了して rows.Close() が呼ばれるまでDBの接続を握るのですが、このループ中の loadStars(e.Keyword) の部分が中でさらにSQLを呼び出しています。 この状態で、 top ページに8個並列でアクセスが来てループの外側のクエリを実行すると、8本の接続を使い切った状態になり、どの goroutine も内側の loadStars() でDB接続を無限に待ってしまうことになります。

落ち着いて考えればすごく当たり前のことなのですが、最初は rows.Close() を呼んでない場所がどこかにあるんじゃないかと探し回ったり、この形のネストがまずいことに気づいたときも「でも1goroutineあたりのDB接続数が2倍になるだけだから、その程度の余裕は見込んで8本にしたんだけどなあ。」と考えてしまったりしてしまいました。

結果、この問題の対策もちゃんとネストを潰すのではなく、単にコネクションプールの数を倍の16に増やしただけです。ベンチマーカーがどんどん並列度上げてくるタイプだったらこれでも死んでました。

教訓として、 rows.Next() ループ内でネストしてクエリを実行するのは単に必要な接続数が倍になる以上の凶悪さを持っているので、 rows.Close() までの処理は単純にクエリ結果のフェッチだけにしましょう。

Replacer の構築を zero time cache 化

プロファイルを取ってみたところまだ Replacer の構築が重いので、個人的に zero time cache と呼んでいるイディオムを使って安全にキャッシュをしてみます。次のコードを見てください。

var (
	mKwControl sync.Mutex
	kwdList    KeywordArray

	mUpdateReplacer sync.Mutex
	repLastUpdated  time.Time
)

func AddKeyword(key, link string) {
	k := Keyword{Key: key, Link: link}
	mKwControl.Lock()
	kwdList = append(kwdList, k)
	mKwControl.Unlock()
	updateReplacer()
}

func updateReplacer() {
	now := time.Now()
	mUpdateReplacer.Lock()
	defer mUpdateReplacer.Unlock()

	if repLastUpdated.After(now) {
		return
	}
	repLastUpdated = time.Now()

	reps1 := make([]string, 0, len(kwdList)*2)
	reps2 := make([]string, 0, len(kwdList)*2)

	mKwControl.Lock()
	kws := kwdList[:]
	mKwControl.Unlock()

	sort.Sort(kws)
  // ... 以降 Replacer の構築処理
}

mUpdateReplacerrepLastUpdated が追加した変数で、 updateReplacer()repLastUpdated = time.Now() までがイディオムになっています。

例えば、キーワードA, B, C がほぼ同時に追加されたとします。

  1. まずAが最初にロックを取得して、 repLastUpdated = time.Now() を実行して Replacer の構築を始めます。
  2. 続いてキーワードBとCがともに mUpdateReplacer.Lock() で停止します。ロック直前に取得した now は (1) で更新した repLastUpdated よりも未来の時間になります。
  3. キーワードAの Replacer 更新が終了し、 mUpdateReplacer が開放されます。キーワードBを処理していた goroutine がそのロックを取得します。
  4. ロック取得前に取得した nowrepLastUpdated よりも新しいので、 if repLastUpdated.After(now) が真になりません。なので Replacer を再構築します。キーワードAを更新したときの kwdList にキーワードBは入っていなかった(厳密にはタイミング依存で入っていた可能性もある)ので、これは必要な処理です。
  5. さらにキーワードBの Replacer 更新が終わり、キーワードCが mUpdateReplacer のロックを取得します。今度は if repLastUpdated.After(now) が真になるので、 Replacer の再構築はスキップされます。 (4) で Replacer を再構築したときには確実にキーワードCも kwdList に入っていたので、スキップしても安全です。

この説明を一度読んだだけでは理解できないかもしれませんが、ぜひじっくりとコードと見比べて理解してみてください。 このイディオムはISUCONだけではなく、実際にGoで高性能なサーバーを書くときに大変便利です。

また、例えば MySQL が複数のトランザクションを一度の fsync でコミットするグループコミットなど、「同時に実行される重い処理をバッチ化する」というのは並列処理のデザインパターンと呼んでも良いくらい汎用的だと思うのですが、どなたかこのパターンの名前をご存知でしたら @methane 宛の Tweet などで教えてください。

仕上げ

まだ top ページのハンドラーが重かったので、再び zero time cache パターンを使ってさらにトップページの内容の取得を効率化します。

ただしこのときは効率より実装の手早さを優先して、 zero time cache パターンをトップページのハンドラ内に直接実装してしまいました。着実には性能向上しましたが、これもキーワードの更新側に処理を持っていけばもっと劇的な性能向上が見込めたはずです。

最後に、アプリの環境変数で GOGC=400 を設定し、プロファイルやモニタリングやnginxのアクセスログを切り、ベストスコアを出すまで enqueue を数回実行して終了しました。

考察

POST /keyword のアクセスがキーワードの追加だけではなく更新にも使われていることを見逃していて、一番重い Replacer の再構築を必要以上に実行してしまっていたのが悔やまれます。

また、上に書いたようにトップページの内容の更新も、 GET / ではなく POST /keyword で行えばもっと劇的なスコアアップができたでしょう。

さらに、非ログインユーザーのトップページを静的ファイルに書き出してしまって nginx に直接返させるのも、ISUCONで頻出の攻略法で事前に判っていたはずで、実装する時間もあったはずなのにやるタイミングを逸してしまいました。

これらを全部できていれば、ベンチマーカーの実装次第ですが、倍の50万点の可能性もあったかもしれません。

感想

今までは毎年予選は一人で戦って勝ち抜いてきたのですが、去年の予選のボリュームが本戦と同じくらいあってキツかったので、今年は予選からチームで戦うことにしました。

「直したはずのバグがこっちのブランチでは直ってなかった」「プロファイルが違う場所のバイナリ/ソースを参照してたかもしれなくてくてアテにならない」系のトラブルはあったものの、自分がアプリを書くときに心配事を忘れて集中できたり、逆に実装を任せてる間に自分は休憩したり落ち着いて見直しをしたりできて、精神的な負荷が大幅に減り、余裕を持って優雅に戦えたと思います。

一方で、Azureに慣れていなかったことや、14時過ぎに取った初めての0点以外のスコアがその時点の断トツトップで、そこからもほぼずっと2位のダブルスコアをキープしていたこともあって、保守的になりすぎて全力を出し切れたとは言い難いです。

本戦では全力を出せるように、もう少しチームワーク練習や環境構築の練習を重ねて行きます。

それでは、決勝進出者のみなさん、決勝でお会いしましょう。 運営・出題者のみなさんはお疲れ様でした。決勝も引き続きお願いいたします。

songofacandy at 16:25|この記事のURLComments(3)TrackBack(0)
2016年06月03日

pixiv private isucon 2016 攻略 (5/5)

はてなブックマークに登録

攻略記事一覧:

ボトルネック探し

前回は一番重かったトップページにページキャッシュを導入して劇的に高速化したものの、CPU以外がボトルネックになって大した高速化はできませんでした。 こういう場合は dstat が役に立つことが多いです。

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  2   0  98   0   0   0| 596k  271k|   0     0 |   0     0 | 606   755
  1   0 100   0   0   0|   0     0 | 192B 1190B|   0     0 | 119   177
  0   0 100   0   0   0|   0     0 |  66B  350B|   0     0 | 103   158
  1   0  98   1   0   0| 512k    0 | 537B  783B|   0     0 | 962  1035
 48   7  38   3   0   5|  16M  728k|4590k   60M|   0     0 |  24k   20k
 44   7  36   5   0   8|  11M  376k|6568k   71M|   0     0 |  34k   26k
 44  11  35   4   0   7|  18M  312k|6190k   71M|   0     0 |  33k   27k
 48   8  33   3   0   8|  14M  272k|7784k   71M|   0     0 |  31k   24k
 41   7  42   4   0   6|  17M  352k|8097k   72M|   0     0 |  31k   23k
 44   9  38   4   1   5|  14M  256k|8019k   71M|   0     0 |  33k   25k
 44  10  35   3   0   8|  10M  448k|7705k   71M|   0     0 |  32k   25k
 36   9  46   3   0   6|  14M  224k|7196k   71M|   0     0 |  32k   22k
 38  10  39   6   0   7|  16M   18M|7812k   71M|   0     0 |  31k   22k
 47   9  28  11   0   4|  20M   47M|6683k   72M|   0     0 |  29k   19k
 45   7  39   3   0   6|  10M  696k|6113k   71M|   0     0 |  33k   24k
 42   7  39   4   0   8|  12M  672k|3825k   71M|   0     0 |  33k   24k
 51   8  31   3   0   6|  13M  512k|6750k   71M|   0     0 |  31k   22k
 44   9  39   2   0   5|5496k  648k|8045k   71M|   0     0 |  32k   24k
 53   9  28   3   0   6|  20M  544k|5832k   71M|   0     0 |  29k   20k
 41   7  42   3   0   7|  14M  616k|7459k   71M|   0     0 |  35k   24k
 48   9  31   4   0   8|  17M  608k|5869k   71M|   0     0 |  30k   23k
 38  11  40   3   0   8|  14M  752k|8956k   71M|   0     0 |  32k   24k
 44  11  36   4   0   5|  13M  576k|7181k   71M|   0     0 |  33k   25k
 47   7  35   7   0   5|  14M   62M|5753k   65M|   0     0 |  30k   22k
...

net の send が 71M で張り付いてるのが目につきますね。アプリサーバーは c4.large なのでこんなもんでしょう。

ですが、 pixiv さんの Blog 記事 のスクリーンショットを見ると、多くのチームが 40k 点を超えていて、トップチームは180k点に到達しています。こっちは40k点の手前で帯域の壁にぶつかってるのに、変だぞ? (Twitter で pixiv の @catatsuy さんに、ポータルのスコアとコマンドラインによるベンチマーカーのスコアが同一であることを確認しました。)

さて、2つ目の記事で、次のように言っていましたね。

帯域は /image/ が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。

試しにクライアントのキャッシュ実装に影響を与えそうなヘッダーを追加してみましょう。 "nginx 静的ファイル キャッシュ" でググってそれっぽいのを探します

  upstream app {
    server 127.0.0.1:8080;
    keepalive 64;
  }

server {
  listen 80;

  client_max_body_size 10m;
  root /home/isucon/private_isu/webapp/public/;

  location / {
    try_files $uri @app;
  }
  location ~* \.(?:ico|css|js|gif|jpe?g|png)$ {
    try_files $uri @app;
    expires max;
    add_header Pragma public;
    add_header Cache-Control "public, must-revalidate, proxy-revalidate";
    etag off;
  }
  location @app {
    proxy_set_header Host $host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_pass http://app;
  }
}

計測してみます。

スコア:

{"pass":true,"score":182435,"success":174747,"fail":0,"messages":[]}

pixiv 社内 isucon のトップと同じくらいのスコアがでました。(これはプロファイルを取ったりいろいろしながらのスコアなので、仕上げしたらもう少し伸びるはずです)

top, dstat:

Tasks:  81 total,   3 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 80.7 us, 11.5 sy,  0.0 ni,  3.0 id,  0.5 wa,  0.0 hi,  4.2 si,  0.0 st
KiB Mem:   1022972 total,   954144 used,    68828 free,    25432 buffers
KiB Swap:        0 total,        0 used,        0 free.   557948 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1397 isucon    20   0  377096  97572   8880 S 100.5  9.5   0:27.35 app.dc4a3eaa
  731 mysql     20   0 1059292 183956  10552 S  65.9 18.0   2:26.08 mysqld
 1396 www-data  20   0   92088   5304   3144 R  18.6  0.5   0:04.99 nginx
 1069 isucon    20   0   33140  10476   2636 S   5.7  1.0   0:12.10 tmux
  308 memcache  20   0  334624   9744   2228 S   0.7  1.0   0:01.38 memcached
  110 root      20   0       0      0      0 S   0.3  0.0   0:00.08 jbd2/xvda2-8
 1034 root      20   0       0      0      0 S   0.3  0.0   0:02.89 kworker/1:0
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0 100   0   0   0|   0     0 |   0     0 |   0     0 |  45    76 
 21   5  71   2   0   1|  11M    0 |1987k   12M|   0     0 |8731  9184 
 73  15   5   2   0   5|  17M  904k|4574k   25M|   0     0 |  19k   20k
 78  13   3   1   0   6|  20M  272k|3815k   18M|   0     0 |  15k   17k
 80   9   6   2   0   4|  25M  272k|7221k   20M|   0     0 |  16k   17k
 81  11   4   1   0   4|  18M  272k|5953k   20M|   0     0 |  15k   16k
 81  10   4   0   0   5|  24M  256k|5363k   24M|   0     0 |  15k   17k
 76  13   6   2   0   4|  20M  272k|8293k   18M|   0     0 |  16k   17k
 82  11   2   1   0   5|  15M  552k|2665k   18M|   0     0 |  16k   16k
 80  14   3   1   0   4|  14M  408k|2870k   15M|   0     0 |  15k   16k
 79  12   5   1   0   4|  16M  360k|5475k   19M|   0     0 |  17k   18k
 79  11   5   2   0   3|  16M   65M|5456k   21M|   0     0 |  15k   16k
 77  12   6   1   0   4|  19M  760k|6763k   23M|   0     0 |  19k   20k
 79  12   4   2   0   4|  23M  592k|6824k   19M|   0     0 |  16k   17k
 79  12   5   2   0   3|  11M  632k|5994k   20M|   0     0 |  16k   18k
 82  11   3   1   0   4|  11M  680k|3447k   16M|   0     0 |  15k   17k
 83  11   2   0   0   4|  13M  792k|5076k   18M|   0     0 |  16k   18k
...

CPUを使い切るようになったのが判ります。

access.log 集計:

Request by count
117444 GET /image/*
7987 GET /
6394 GET /js/jquery-2.2.0.js
6394 GET /css/style.css
6394 GET /js/jquery.timeago.ja.js
6394 GET /favicon.ico
6394 GET /js/jquery.timeago.js
6394 GET /js/main.js
4028 POST /login
1459 GET /login
1176 GET /posts/*
959 POST /register
958 GET /admin/banned
873 GET /@user
731 GET /logout
609 POST /
330 GET /posts?max_created_at=
268 POST /comment
1 GET /initialize

Request by total time
98.996 0.299987878788 GET /posts?max_created_at=
84.66 0.0105997245524 GET /
84.077 0.0963081328751 GET /@user
52.172 0.0129523336643 POST /login
39.666 0.0337295918367 GET /posts/*
33.621 0.0552068965517 POST /
19.801 0.0738843283582 POST /comment
17.144 0.0117505140507 GET /login
...

Request by out bytes
894159053 7613 GET /image/*
185613643 23239 GET /
16456443 18850 GET /@user
11202870 33948 GET /posts?max_created_at=
4098331 3484 GET /posts/*
...

image の転送量が大幅に減ったことが確認できます。また、集計せずに access.log を見ると、狙い通り 304 を返せていることが判ります。

(余談) 壁の超え方

2つ目の記事で 304 Not Modified を返せることを予想していたのは、エスパーでもなんでもありません。一昨年 (2014年) の決勝であったんです。その時はこの壁を超えられず悔しい思いをしました。

その時、壁を超えたチームが2チームありました。準優勝チームは静的ファイルを返すための nginx の設定のテンプレ(いわゆる「秘伝のタレ」)を使ったらいきなりスコアが上がったけど何が起こったのか設定した本人にも分からなかった、そして優勝チームは順優勝チームのスコアを見て「必ず壁を超える方法があるはずだ」と試行錯誤した結果壁を超えたと記憶しています。(興味がある方は当時の blog 記事を探してみてください)

「秘伝のタレ」が偶然ハマる、という壁の超え方は準備の賜物です。 個人的にはチューニングするときはパラメーターを1つ1ついじって効果確認したいところですが、それだと時間がもったいないし、ベンチマーカーの挙動についての予想が当てられないと壁が超えられないので、やはり「秘伝のタレ」は強力な武器になります。

一方、ベンチマーカーの動作を予想し試行錯誤するやり方は、問題作成側の心理を読む ISUCON 力、可能性のある試行錯誤をするための引き出し(今回でいえば HTTP ヘッダーとキャッシュに関する知識)、精神力などが求められます。 過去に決勝で優勝したチームはどれもこの能力が特に優れていたチームだと思います。難しいですが優勝を目指して勉強と鍛錬をしましょう。

雑巾絞り

CPUネックになったことですし、CPUプロファイルを見てみましょう。

(pprof) top30 -cum
7.63s of 29.87s total (25.54%)
Dropped 601 nodes (cum <= 0.15s)
Showing top 30 nodes out of 296 (cum >= 4.36s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     28.68s 96.02%  runtime.goexit
         0     0%     0%     24.58s 82.29%  net/http.(*conn).serve
         0     0%     0%     23.35s 78.17%  net/http.(*ServeMux).ServeHTTP
         0     0%     0%     23.35s 78.17%  net/http.serverHandler.ServeHTTP
         0     0%     0%     23.32s 78.07%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%     0%     23.30s 78.00%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%     0%     23.30s 78.00%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0%     0%     23.30s 78.00%  net/http.HandlerFunc.ServeHTTP
         0     0%     0%     23.25s 77.84%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0%     0%     22.71s 76.03%  github.com/zenazn/goji/web.(*mStack).newStack.func1
     0.01s 0.033% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web.(*router).route
         0     0% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
         0     0% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web/middleware.Recoverer.func1
     0.01s 0.033% 0.067%     18.11s 60.63%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0% 0.067%     12.85s 43.02%  main.getPosts
         0     0% 0.067%     12.46s 41.71%  github.com/jmoiron/sqlx.(*DB).Select
         0     0% 0.067%     12.46s 41.71%  github.com/jmoiron/sqlx.Select
     0.07s  0.23%   0.3%     11.69s 39.14%  github.com/jmoiron/sqlx.scanAll
     1.72s  5.76%  6.06%      9.78s 32.74%  runtime.mallocgc
     0.16s  0.54%  6.60%      8.62s 28.86%  runtime.systemstack
     5.02s 16.81% 23.40%      7.29s 24.41%  runtime.scanobject
     0.15s   0.5% 23.90%      5.91s 19.79%  runtime.newobject
         0     0% 23.90%      5.33s 17.84%  runtime.gcAssistAlloc
         0     0% 23.90%      5.33s 17.84%  runtime.gcAssistAlloc.func1
     0.04s  0.13% 24.04%      5.33s 17.84%  runtime.gcDrainN
     0.04s  0.13% 24.17%      5.22s 17.48%  database/sql.(*Rows).Next
     0.03s   0.1% 24.27%      5.04s 16.87%  github.com/go-sql-driver/mysql.(*textRows).Next
     0.34s  1.14% 25.41%      5.01s 16.77%  github.com/go-sql-driver/mysql.(*textRows).readRow
         0     0% 25.41%      4.55s 15.23%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.04s  0.13% 25.54%      4.36s 14.60%  main.makePosts


(pprof) list getPosts
Total: 29.87s
ROUTINE ======================== main.getPosts in /home/isucon/private_isu/webapp/golang/app.go
         0     12.85s (flat, cum) 43.02% of Total
         .          .    593:           fmt.Println(terr)
         .          .    594:           return
         .          .    595:   }
         .          .    596:
         .          .    597:   results := []Post{}
         .     11.19s    598:   rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT
))
         .          .    599:   if rerr != nil {
         .          .    600:           fmt.Println(rerr)
         .          .    601:           return
         .          .    602:   }
         .          .    603:
         .      1.03s    604:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    605:   if merr != nil {
         .          .    606:           fmt.Println(merr)
         .          .    607:           return
         .          .    608:   }
         .          .    609:
         .          .    610:   if len(posts) == 0 {
         .          .    611:           w.WriteHeader(http.StatusNotFound)
         .          .    612:           return
         .          .    613:   }
         .          .    614:
         .          .    615:   fmap := template.FuncMap{
         .          .    616:           "imageURL": imageURL,
         .          .    617:   }
         .          .    618:
         .          .    619:   template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
         .       10ms    620:           getTemplPath("posts.html"),
         .          .    621:           getTemplPath("post.html"),
         .      620ms    622:   )).Execute(w, posts)
         .          .    623:}
         .          .    624:
         .          .    625:func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    626:   pid, err := strconv.Atoi(c.URLParams["id"])
         .          .    627:   if err != nil {

(pprof) list makePosts
Total: 29.87s
ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
      40ms      4.36s (flat, cum) 14.60% of Total
         .          .    188:}
         .          .    189:
         .          .    190:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
         .          .    191:   var posts []Post
         .          .    192:
         .       20ms    193:   for _, p := range results {
         .      720ms    194:           err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
         .          .    195:           if err != nil {
         .          .    196:                   return nil, err
         .          .    197:           }
         .          .    198:
         .          .    199:           query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
         .          .    200:           if !allComments {
         .          .    201:                   query += " LIMIT 3"
         .          .    202:           }
         .          .    203:           var comments []Comment
         .      920ms    204:           cerr := db.Select(&comments, query, p.ID)
         .          .    205:           if cerr != nil {
         .          .    206:                   return nil, cerr
         .          .    207:           }
         .          .    208:
         .          .    209:           for i := 0; i < len(comments); i++ {
      20ms      1.89s    210:                   uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
         .          .    211:                   if uerr != nil {
         .          .    212:                           return nil, uerr
         .          .    213:                   }
         .          .    214:           }
         .          .    215:
         .          .    216:           // reverse
         .          .    217:           for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
         .          .    218:                   comments[i], comments[j] = comments[j], comments[i]
         .          .    219:           }
         .          .    220:
         .          .    221:           p.Comments = comments
         .          .    222:
      20ms      780ms    223:           perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
         .          .    224:           if perr != nil {
         .          .    225:                   return nil, perr
         .          .    226:           }
         .          .    227:
         .          .    228:           p.CSRFToken = CSRFToken
         .          .    229:
         .          .    230:           if p.User.DelFlg == 0 {
         .       30ms    231:                   posts = append(posts, p)
         .          .    232:           }
         .          .    233:           if len(posts) >= postsPerPage {
         .          .    234:                   break
         .          .    235:           }
         .          .    236:   }

getPosts が重いのは、前に getIndex が重いのを直した時と同じく、 LIMIT すれば良さそうですね。

makePosts もクエリを投げすぎているので、 Post の取得とその User の取得は INNER JOIN で一気にする、コメント一覧はメモリ上にキャッシュしてしまうことにします。 あとテンプレートのコンパイルも事前にするようにしていきます。 Go アプリ側で出力しているログも tmux や ssh の CPU を食ってるのでそろそろ止めてしまいましょう。 (nginx のログを止めるのは一番最後です)

diff --git a/app.go b/app.go
index f246ad6..eca8413 100644
--- a/app.go
+++ b/app.go
@@ -187,54 +184,78 @@ func getFlash(w http.ResponseWriter, r *http.Request, key string) string {
 	}
 }
 
-func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
-	var posts []Post
+var (
+	commentM     sync.Mutex
+	commentStore map[int][]Comment = make(map[int][]Comment)
+)
 
-	for _, p := range results {
-		err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
+func getCommentsLocked(postID int) []Comment {
+	if cs, ok := commentStore[postID]; ok {
+		return cs
+	}
+
+	var cs []Comment
+	query := ("SELECT comments.id, comments.comment, comments.created_at, users.id, users.account_name " +
+		" FROM `comments` INNER JOIN users ON comments.user_id = users.id " +
+		" WHERE `post_id` = ? ORDER BY comments.`created_at`")
+
+	rows, err := db.Query(query, postID)
+	if err != nil {
+		log.Println(err)
+		return cs
+	}
+	for rows.Next() {
+		var c Comment
+		err := rows.Scan(&c.ID, &c.Comment, &c.CreatedAt, &c.User.ID, &c.User.AccountName)
 		if err != nil {
-			return nil, err
+			log.Println(err)
+			continue
 		}
+		cs = append(cs, c)
+	}
+	rows.Close()
 
-		query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
-		if !allComments {
-			query += " LIMIT 3"
-		}
-		var comments []Comment
-		cerr := db.Select(&comments, query, p.ID)
-		if cerr != nil {
-			return nil, cerr
-		}
+	commentStore[postID] = cs
+	return cs
+}
 
-		for i := 0; i < len(comments); i++ {
-			uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
-			if uerr != nil {
-				return nil, uerr
-			}
-		}
+func getComments(postID int) []Comment {
+	commentM.Lock()
+	defer commentM.Unlock()
+	return getCommentsLocked(postID)
+}
 
-		// reverse
-		for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
-			comments[i], comments[j] = comments[j], comments[i]
-		}
+func appendComent(c Comment) {
+	commentM.Lock()
+	cs := getCommentsLocked(c.PostID)
+	commentStore[c.PostID] = append(cs, c)
+	commentM.Unlock()
+}
+
+func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
+	var posts []Post
 
+	for _, p := range results {
+		comments := getComments(p.ID)
+		if !allComments && len(comments) > 3 {
+			comments = comments[len(comments)-3:]
+		}
 		p.Comments = comments
+		p.CSRFToken = CSRFToken
 
 		perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
 		if perr != nil {
 			return nil, perr
 		}
 
-		p.CSRFToken = CSRFToken
-
-		if p.User.DelFlg == 0 {
-			posts = append(posts, p)
+		if p.User.DelFlg != 0 {
+			continue
 		}
+		posts = append(posts, p)
 		if len(posts) >= postsPerPage {
 			break
 		}
 	}
-
 	return posts, nil
 }
 
@@ -411,8 +432,9 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
 }
 
 var (
-	indexTemplate *template.Template
-	postsTemplate *template.Template
+	indexTemplate       *template.Template
+	postsTemplate       *template.Template
+	accountNameTempalte *template.Template
 
 	indexPostsM         sync.Mutex
 	indexPostsT         time.Time
@@ -434,6 +456,13 @@ func init() {
 		getTemplPath("posts.html"),
 		getTemplPath("post.html"),
 	))
+
+	accountNameTempalte = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+		getTemplPath("layout.html"),
+		getTemplPath("user.html"),
+		getTemplPath("posts.html"),
+		getTemplPath("post.html"),
+	))
 }
 
 func renderIndexPosts() {
@@ -506,7 +535,6 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 	}
 
 	results := []Post{}
-
 	rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = ? ORDER BY `created_at` DESC", user.ID)
 	if rerr != nil {
 		fmt.Println(rerr)
@@ -527,12 +555,10 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 	}
 
 	postIDs := []int{}
-	perr := db.Select(&postIDs, "SELECT `id` FROM `posts` WHERE `user_id` = ?", user.ID)
-	if perr != nil {
-		fmt.Println(perr)
-		return
+	for _, r := range results {
+		postIDs = append(postIDs, r.ID)
 	}
-	postCount := len(postIDs)
+	postCount := len(results)
 
 	commentedCount := 0
 	if postCount > 0 {
@@ -557,16 +583,7 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 
 	me := getSessionUser(r)
 
-	fmap := template.FuncMap{
-		"imageURL": imageURL,
-	}
-
-	template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
-		getTemplPath("layout.html"),
-		getTemplPath("user.html"),
-		getTemplPath("posts.html"),
-		getTemplPath("post.html"),
-	)).Execute(w, struct {
+	accountNameTempalte.Execute(w, struct {
 		Posts          []Post
 		User           User
 		PostCount      int
@@ -595,7 +612,7 @@ func getPosts(w http.ResponseWriter, r *http.Request) {
 	}
 
 	results := []Post{}
-	rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT))
+	rerr := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 AND posts.`created_at` <= ? ORDER BY `created_at` DESC LIMIT 20", t.Format(ISO8601_FORMAT))
 	if rerr != nil {
 		fmt.Println(rerr)
 		return
@@ -806,9 +823,24 @@ func postComment(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
-	db.Exec(query, postID, me.ID, r.FormValue("comment"))
-
+	now := time.Now()
+	commentStr := r.FormValue("comment")
+	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`, `created_at`) VALUES (?,?,?,?)"
+	res, err := db.Exec(query, postID, me.ID, commentStr, now)
+	if err != nil {
+		log.Println(err)
+		return
+	}
+	lid, _ := res.LastInsertId()
+	c := Comment{
+		ID:        int(lid),
+		PostID:    postID,
+		UserID:    me.ID,
+		Comment:   commentStr,
+		CreatedAt: now,
+		User:      me,
+	}
+	appendComent(c)
 	renderIndexPosts()
 	http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
 }
@@ -921,6 +953,7 @@ func main() {
 
 	go http.ListenAndServe(":3000", nil)
 
+	goji.DefaultMux = web.New()
 	goji.Get("/initialize", getInitialize)
 	goji.Get("/login", getLogin)
 	goji.Post("/login", postLogin)

計測

スコア:

{"pass":true,"score":271542,"success":256436,"fail":0,"messages":[]}

pixiv 社内 isucon の優勝チームのスコアを超えることができたと思います。

top:

ks:  82 total,   4 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 57.1 us, 13.8 sy,  0.0 ni, 16.5 id,  5.1 wa,  0.0 hi,  7.3 si,  0.2 st
KiB Mem:   1022972 total,   926504 used,    96468 free,    27152 buffers
KiB Swap:        0 total,        0 used,        0 free.   432620 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                 1494 isucon    20   0  544796 191292   8940 S  81.5 18.7   0:29.06 app.7f063c1
  731 mysql     20   0 1125024 182444  10552 S  44.9 17.8   3:04.05 mysqld
 1524 www-data  20   0   92056   5276   3140 R  27.6  0.5   0:09.65 nginx
  308 memcache  20   0  336672  11756   2228 S   1.7  1.1   0:02.25 memcached
   31 root      20   0       0      0      0 S   0.7  0.0   0:00.40 kswapd0
   89 root       0 -20       0      0      0 S   0.3  0.0   0:00.73 kworker/0:1H
    1 root      20   0   28636   4736   3100 S   0.0  0.5   0:01.31 systemd

ちょっと idle が出てきたかな。

dstat:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0 100   0   0   0|   0     0 |   0     0 |   0     0 |  82   283 
 11   3  82   2   0   2|  12M    0 |1684k   15M|   0     0 |7607  5952 
 55  13  17   9   0   7|  49M  864k|  11M   44M|   0     0 |  27k   20k
 58  15  14   8   0   6|  48M  416k|  13M   43M|   0     0 |  28k   20k
 48  14  21  12   0   5|  43M   63M|  12M   40M|   0     0 |  25k   19k
 55  17  14   7   0   7|  48M  528k|  14M   42M|   0     0 |  25k   18k
 55  12  19   8   0   6|  45M  488k|  12M   42M|   0     0 |  27k   20k
 52  17  16   6   0   8|  35M  592k|  14M   38M|   0     0 |  27k   19k
 50  12  19  14   0   6|  34M   59M|  11M   38M|   0     0 |  25k   17k
 56  12  18   6   0   7|  42M  720k|  11M   45M|   0     0 |  28k   20k
 51  15  18   9   0   8|  45M  704k|  14M   39M|   0     0 |  26k   19k
 52  17  17   7   0   7|  39M 3936k|  14M   45M|   0     0 |  27k   19k
 47  17  18  13   0   5|  41M   56M|  12M   39M|   0     0 |  24k   17k
 53  13  19   9   0   6|  45M  848k|  13M   41M|   0     0 |  27k   20k
 57  15  16   6   0   6|  38M  776k|  13M   42M|   0     0 |  27k   19k
 53  14  20   9   0   4|  28M   58M|  11M   29M|   0     0 |  24k   16k
 53  13  19   6   0   8|  44M  672k|  13M   38M|   0     0 |  26k   18k
 57  13  16   9   0   6|  46M  872k|  10M   38M|   0     0 |  25k   18k
 53  12  22   7   0   6|  44M  776k|  12M   41M|   0     0 |  28k   20k
 54  16  16   8   0   6|  33M   57M|9049k   33M|   0     0 |  24k   18k
 51  16  21   5   0   7|  32M  888k|  12M   38M|   0     0 |  27k   19k
 54  13  19   7   0   7|  49M 2264k|  11M   46M|   0     0 |  26k   18k
 54  14  19   6   0   7|  36M  680k|  12M   42M|   0     0 |  28k   19k
 48  16  19  10   0   7|  33M   52M|  14M   31M|   0     0 |  23k   16k
 55  15  15   7   0   7|  42M  720k|  12M   34M|   0     0 |  26k   20k
 59  14  17   5   0   6|  33M  744k|  12M   35M|   0     0 |  25k   18k
 47  15  25   7   0   6|  34M  736k|9604k   43M|   0     0 |  28k   19k
 47  11  27   8   0   6|  31M   51M|  12M   39M|   0     0 |  25k   17k
 54  18  17   5   0   7|  34M  816k|  12M   33M|   0     0 |  27k   20k
 55  16  16   6   0   6|  35M  888k|  14M   34M|   0     0 |  27k   19k
 57  13  18   6   0   6|  34M  720k|  11M   37M|   0     0 |  27k   19k
 52  12  18  12   0   6|  36M   53M|  11M   34M|   0     0 |  23k   17k
 62  12  15   4   0   7|  26M  720k|9309k   29M|   0     0 |  25k   19k
 46  20  19   5   0   9|  30M  560k|  16M   35M|   0     0 |  28k   20k
 59  12  20   5   0   5|  23M  544k|  10M   36M|   0     0 |  25k   17k
 53  13  21   8   0   5|  25M   47M|  11M   31M|   0     0 |  23k   16k
 54  14  18   6   0   9|  38M  584k|  14M   35M|   0     0 |  27k   21k
...

帯域は半分強使っていますね。大きい js があるので、 `nginx の gzip_static モジュールを使うなどでもう少し帯域を開けられると思います。

pprof:

(pprof) top30 -cum
6.95s of 22.25s total (31.24%)
Dropped 621 nodes (cum <= 0.11s)
Showing top 30 nodes out of 321 (cum >= 2.44s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     20.30s 91.24%  runtime.goexit
     0.02s  0.09%  0.09%     17.03s 76.54%  net/http.(*conn).serve
         0     0%  0.09%     14.60s 65.62%  net/http.(*ServeMux).ServeHTTP
         0     0%  0.09%     14.60s 65.62%  net/http.serverHandler.ServeHTTP
         0     0%  0.09%     14.58s 65.53%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*router).route
         0     0%  0.09%     14.57s 65.48%  net/http.HandlerFunc.ServeHTTP
         0     0%  0.09%     10.03s 45.08%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
     0.01s 0.045%  0.13%      6.12s 27.51%  html/template.(*Template).Execute
         0     0%  0.13%      5.58s 25.08%  text/template.(*Template).Execute
     0.12s  0.54%  0.67%      5.57s 25.03%  text/template.(*state).walk
     0.01s 0.045%  0.72%      5.20s 23.37%  text/template.(*state).walkTemplate
     0.04s  0.18%   0.9%      4.68s 21.03%  text/template.(*state).walkRange
     0.01s 0.045%  0.94%      4.65s 20.90%  text/template.(*state).walkRange.func1
     0.97s  4.36%  5.30%      4.60s 20.67%  runtime.mallocgc
         0     0%  5.30%      4.46s 20.04%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.23s  1.03%  6.34%      4.38s 19.69%  runtime.systemstack
     0.04s  0.18%  6.52%      4.07s 18.29%  text/template.(*state).evalPipeline
     0.08s  0.36%  6.88%      4.03s 18.11%  text/template.(*state).evalCommand
     2.54s 11.42% 18.29%      3.71s 16.67%  runtime.scanobject
     0.10s  0.45% 18.74%      3.09s 13.89%  text/template.(*state).evalCall
     0.03s  0.13% 18.88%      3.07s 13.80%  text/template.(*state).evalFunction
         0     0% 18.88%      2.99s 13.44%  main.getAccountName
     2.48s 11.15% 30.02%      2.70s 12.13%  syscall.Syscall
         0     0% 30.02%      2.62s 11.78%  main.getPosts
     0.01s 0.045% 30.07%      2.56s 11.51%  reflect.Value.Call
     0.26s  1.17% 31.24%      2.52s 11.33%  reflect.Value.call
         0     0% 31.24%      2.44s 10.97%  github.com/jmoiron/sqlx.(*DB).Get

テンプレートの実行とが重いのと、あとGCが重いですね。

テンプレートが重いのは、ページキャッシュだとトップページ以外はどれくらいキャッシュヒット率が見込めるかわかりません。 valyala/quicktemplate などの、リフレクションを多用しない高速なテンプレートエンジンに乗り換えるほうが早いかもしれません。

GCの方は、クエリ実行回数をさらに削っていけば、一時オブジェクトがを削減するのが有効そう。どこでアロケートが多発しているのかを確認したい場合は pprof -alloc_objects を使ってみてください。

まとめ

スコア: 4745 (初期状態) -> 39743 (前回) -> 182435 (Not Modified) -> 271542 (最終版)

壁を超えた効果で、いままで伸び悩んでいたスコアが一気にジャンプしました。

攻略記はここまでにしますが、できればさらにチューニングを続けてみてください。練習で実際に手を動かしていないことは、本番ではほぼ確実にできません。 私の場合は、次のようなチューニングで500k点を超えましたが、これでもまだ帯域を使い切っていないし nginx よりも app と MySQL が使用するCPUの方が大きいのでさらに上を狙えるはずです。

  • gzip_static を使う (スコアは上がりませんでしたが、帯域に余裕を作りました)
  • テンプレートが重い posts の部分で valyala/quicktemplate を使ってみる
  • ユーザーをオンメモリキャッシュし、強引なJOINをやめる
  • セッションストアを memcached からオンメモリに切り替える
  • nginx と app の間を unix domain socket に切り替える
  • nginx が重くなってきていたので worker_processes を 2 にする
  • 更新系のリクエストであえて time.Sleep() で待たせて、スコアへの影響が大きいシナリオの処理にリソースを向ける
  • アクセスログを切る (最初は静的ファイルだけ、最後は全部のアクセスログを消す)

ここまでのコミットログは methane/pixiv-private-isucon-2016 に置いてあります。 ですが、できるだけ自力で 500k 点超えを目指してみてください。

最後に、ISUCON の練習にとても良い題材を提供して頂いた pixiv さんに感謝します。


@methane

songofacandy at 18:53|この記事のURLComments(0)TrackBack(0)
2016年06月02日

pixiv private isucon 2016 攻略 (4/5)

はてなブックマークに登録

攻略記事一覧:

ここから、いよいよ ISUCON らしくなってきますよ。

現状確認

access.log の集計はこんな感じです。

Request by count
12317 GET /image/*
2797 GET /
1983 POST /login
1218 GET /posts/*
1029 GET /js/jquery-2.2.0.js
1029 GET /favicon.ico
1029 GET /js/jquery.timeago.js
1028 GET /css/style.css
1028 GET /js/jquery.timeago.ja.js
1028 GET /js/main.js
930 GET /@user
655 POST /register
654 GET /admin/banned
579 POST /comment
579 POST /
112 GET /login
83 GET /posts?max_created_at=
56 GET /logout
1 GET /initialize

Request by total time
72.877 0.0260554165177 GET /
34.018 0.0365784946237 GET /@user
18.444 0.22221686747 GET /posts?max_created_at=
15.705 0.0271243523316 POST /
12.566 0.0103169129721 GET /posts/*
8.439 0.000685150604855 GET /image/*
5.644 0.00284619263742 POST /login
1.825 0.00278625954198 POST /register
1.661 0.00286873920553 POST /comment
1.648 0.00251987767584 GET /admin/banned
0.475 0.00424107142857 GET /login
0.45 0.00803571428571 GET /logout
0.026 0.026 GET /initialize

top はこんな感じ

Tasks:  73 total,   1 running,  72 sleeping,   0 stopped,   0 zombie
%Cpu(s): 55.4 us, 10.8 sy,  0.0 ni, 23.5 id,  3.1 wa,  0.0 hi,  6.7 si,  0.5 st
KiB Mem:   1022972 total,   617428 used,   405544 free,    18260 buffers
KiB Swap:        0 total,        0 used,        0 free.   314552 cached Mem
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1122 isucon    20   0  403944  68064   8328 S  76.3  6.7   0:16.87 app.f9aa6c7
  731 mysql     20   0  993756 159744  10756 S  62.6 15.6   0:15.46 mysqld
 1033 www-data  20   0   92024   5136   3056 S   7.0  0.5   0:01.63 nginx
 1069 isucon    20   0   28796   6136   2636 S   2.7  0.6   0:00.80 tmux
  308 memcache  20   0  330528   6060   2228 S   0.7  0.6   0:00.14 memcached

そろそろリクエスト数が増えてきたのと、まだ少し idle が残っているので、念の為ベンチマーク直後の netstat を確認しておきます。

$ netstat -tn
...
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63462         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64494         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63477         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63563         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63877         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64234         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63565         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64008         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63594         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64065         TIME_WAIT  

$ netstat -tn | grep -c TIME_WAIT
1981

まだ詰まるほどじゃないけど一応 /etc/nginx/sites-enabled/isucon.conf で upstream の keepalive を 64 に増やしておきます。

ページキャッシュ

プロファイルを見てみます。

(pprof) top30 -cum
5.66s of 23.80s total (23.78%)
Dropped 584 nodes (cum <= 0.12s)
Showing top 30 nodes out of 326 (cum >= 3.55s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     22.30s 93.70%  runtime.goexit
         0     0%     0%     19.44s 81.68%  net/http.(*conn).serve
     0.01s 0.042% 0.042%     18.79s 78.95%  net/http.serverHandler.ServeHTTP
         0     0% 0.042%     18.78s 78.91%  net/http.(*ServeMux).ServeHTTP
         0     0% 0.042%     18.76s 78.82%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0% 0.042%     18.72s 78.66%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0% 0.042%     18.72s 78.66%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0% 0.042%     18.72s 78.66%  net/http.HandlerFunc.ServeHTTP
     0.01s 0.042% 0.084%     18.69s 78.53%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0% 0.084%     18.27s 76.76%  github.com/zenazn/goji/web/middleware.Recoverer.func1
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web.(*router).route
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
     0.01s 0.042%  0.13%     14.43s 60.63%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%  0.13%     12.63s 53.07%  main.getIndex
     0.07s  0.29%  0.42%      9.88s 41.51%  main.makePosts
     0.01s 0.042%  0.46%      6.89s 28.95%  github.com/jmoiron/sqlx.(*DB).Get
     0.01s 0.042%   0.5%      6.88s 28.91%  github.com/jmoiron/sqlx.Get
     0.03s  0.13%  0.63%      6.80s 28.57%  database/sql.(*DB).Query
     0.02s 0.084%  0.71%      6.77s 28.45%  database/sql.(*DB).query
     0.03s  0.13%  0.84%      6.43s 27.02%  database/sql.(*DB).queryConn
     0.06s  0.25%  1.09%      6.02s 25.29%  github.com/go-sql-driver/mysql.(*mysqlConn).Query
     0.02s 0.084%  1.18%      4.65s 19.54%  github.com/jmoiron/sqlx.(*DB).QueryRowx
     4.06s 17.06% 18.24%      4.38s 18.40%  syscall.Syscall
     1.17s  4.92% 23.15%      4.08s 17.14%  runtime.mallocgc
         0     0% 23.15%      3.83s 16.09%  github.com/jmoiron/sqlx.(*DB).Select
     0.01s 0.042% 23.19%      3.83s 16.09%  github.com/jmoiron/sqlx.Select
         0     0% 23.19%      3.72s 15.63%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.12s   0.5% 23.70%      3.58s 15.04%  runtime.systemstack
     0.02s 0.084% 23.78%      3.55s 14.92%  syscall.Write

(pprof) list getIndex
Total: 23.80s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
         0     12.63s (flat, cum) 53.07% of Total
         .          .    413:
         .          .    414:   http.Redirect(w, r, "/", http.StatusFound)
         .          .    415:}
         .          .    416:
         .          .    417:func getIndex(w http.ResponseWriter, r *http.Request) {
         .      330ms    418:   me := getSessionUser(r)
         .          .    419:
         .          .    420:   results := []Post{}
         .          .    421:
         .      600ms    422:   err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
         .          .    423:   if err != nil {
         .          .    424:           fmt.Println(err)
         .          .    425:           return
         .          .    426:   }
         .          .    427:
         .      8.43s    428:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    429:   if merr != nil {
         .          .    430:           fmt.Println(merr)
         .          .    431:           return
         .          .    432:   }
         .          .    433:
         .          .    434:   fmap := template.FuncMap{
         .          .    435:           "imageURL": imageURL,
         .          .    436:   }
         .          .    437:
         .       40ms    438:   template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
         .       10ms    439:           getTemplPath("layout.html"),
         .       10ms    440:           getTemplPath("index.html"),
         .          .    441:           getTemplPath("posts.html"),
         .          .    442:           getTemplPath("post.html"),
         .      1.20s    443:   )).Execute(w, struct {
         .          .    444:           Posts     []Post
         .          .    445:           Me        User
         .          .    446:           CSRFToken string
         .          .    447:           Flash     string
         .      2.01s    448:   }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
         .          .    449:}
         .          .    450:
         .          .    451:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    452:   user := User{}
         .          .    453:   uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])

テンプレートに渡すための []Post を用意する makePosts 関数が一番重いものの、最初に Post 一覧を取得する select が 600ms, テンプレートのコンパイルと実行を足して 3.2sec ありますね。 テンプレートのコンパイルは起動時に一度やればいい処理なので 1.2sec は無駄です。 また、トップページに表示される内容はユーザーにかかわらず一定なので、レンダリング結果をまるごとページキャッシュできれば、 makePosts の 8.4sec とテンプレートのレンダリングの 2sec の合わせて 10sec をほぼ消し去ることができます。

ページキャッシュが実現できそうかテンプレートの中身を確認してみると、ユーザーごとに異なる内容は、 (1) ヘッダー部分, (2) 全フォームにある csrf token, でした。レンダリングが重いのはポスト一覧の部分でしょうから、ヘッダーはページキャッシュの対象外にして、ポスト一覧部分だけをキャッシュすれば (1) は問題ありません。問題は (2) ですが、レンダリング時に固定のキーワードを入れてレンダリングしておき、ユーザーに返すときに本当の csrf token に文字列置換することにします。

ページキャッシュを作るタイミングですが、 getIndex() が呼ばれた時にするよりも、トップページに何か変更があったとき (画像が投稿された、コメントされた、ユーザーが削除されたなど) にレンダリングするほうが効率的です。 さらに、性能が上がってくるとトップページに変更があるリクエストが並列で来る可能性があるので、レンダリングを Mutex で排他したうえで、 Mutex を待ってる goroutine が同時に複数存在した場合はそのうちの1つだけがレンダリングする方式を採用しました。 この方式は GoCon 2016 Spring で zero time cache パターンとして紹介したもので、全ての POST リクエストがレンダリングを待ってからレスポンスを返すので、キャッシュによる更新が反映されるまでの遅延が存在しません。

diff --git a/app.go b/app.go
index b5a8fac..f246ad6 100644
--- a/app.go
+++ b/app.go
@@ -1,6 +1,7 @@
 package main
 
 import (
+	"bytes"
 	crand "crypto/rand"
 	"crypto/sha512"
 	"encoding/hex"
@@ -109,6 +110,8 @@ func dbInitialize() {
 	for _, sql := range sqls {
 		db.Exec(sql)
 	}
+
+	renderIndexPosts()
 }
 
 func tryLogin(accountName, password string) *User {
@@ -414,38 +410,85 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
 	http.Redirect(w, r, "/", http.StatusFound)
 }
 
-func getIndex(w http.ResponseWriter, r *http.Request) {
-	me := getSessionUser(r)
+var (
+	indexTemplate *template.Template
+	postsTemplate *template.Template
 
-	results := []Post{}
+	indexPostsM         sync.Mutex
+	indexPostsT         time.Time
+	indexPostsRenderedM sync.RWMutex
+	indexPostsRendered  []byte
+)
+
+func init() {
+	fmap := template.FuncMap{
+		"imageURL": imageURL,
+	}
 
+	indexTemplate = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+		getTemplPath("layout.html"),
+		getTemplPath("index.html"),
+	))
+
+	postsTemplate = template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
+		getTemplPath("posts.html"),
+		getTemplPath("post.html"),
+	))
+}
+
+func renderIndexPosts() {
+	now := time.Now()
+	indexPostsM.Lock()
+	defer indexPostsM.Unlock()
+	if indexPostsT.After(now) {
+		return
+	}
+	now = time.Now()
+
+	results := []Post{}
 	err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
 	if err != nil {
-		fmt.Println(err)
+		log.Println(err)
 		return
 	}
 
-	posts, merr := makePosts(results, getCSRFToken(r), false)
+	posts, merr := makePosts(results, "[[[CSRFTOKEN]]]", false)
 	if merr != nil {
-		fmt.Println(merr)
+		log.Println(merr)
 		return
 	}
 
-	fmap := template.FuncMap{
-		"imageURL": imageURL,
+	var b bytes.Buffer
+	if err := postsTemplate.Execute(&b, posts); err != nil {
+		log.Println(err)
+		return
 	}
 
-	template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
-		getTemplPath("layout.html"),
-		getTemplPath("index.html"),
-		getTemplPath("posts.html"),
-		getTemplPath("post.html"),
-	)).Execute(w, struct {
-		Posts     []Post
-		Me        User
-		CSRFToken string
-		Flash     string
-	}{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
+	indexPostsT = now
+	indexPostsRenderedM.Lock()
+	indexPostsRendered = b.Bytes()
+	indexPostsRenderedM.Unlock()
+}
+
+func getIndexPosts(csrf string) template.HTML {
+	indexPostsRenderedM.RLock()
+	t := bytes.Replace(indexPostsRendered, []byte("[[[CSRFTOKEN]]]"), []byte(csrf), -1)
+	indexPostsRenderedM.RUnlock()
+	return template.HTML(string(t))
+}
+
+func getIndex(w http.ResponseWriter, r *http.Request) {
+	me := getSessionUser(r)
+	csrf := getCSRFToken(r)
+	posts := getIndexPosts(csrf)
+
+	indexTemplate.Execute(w,
+		map[string]interface{}{
+			"Me":        me,
+			"CSRFToken": csrf,
+			"Flash":     getFlash(w, r, "notice"),
+			"Posts":     posts},
+	)
 }
 
 func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -708,8 +751,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
 	}
 	tf.Close()
 	copyImage(int(pid), tf.Name(), mime)
+
+	renderIndexPosts()
 	http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
-	return
 }
 
 func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -765,6 +809,7 @@ func postComment(w http.ResponseWriter, r *http.Request) {
 	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
 	db.Exec(query, postID, me.ID, r.FormValue("comment"))
 
+	renderIndexPosts()
 	http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
 }
 
@@ -821,6 +866,7 @@ func postAdminBanned(w http.ResponseWriter, r *http.Request) {
 		db.Exec(query, 1, id)
 	}
 
+	renderIndexPosts()
 	http.Redirect(w, r, "/admin/banned", http.StatusFound)
 }
 
@@ -864,6 +910,15 @@ func main() {
 	db.SetMaxIdleConns(8)
 	defer db.Close()
 
+	for {
+		if db.Ping() == nil {
+			break
+		}
+		log.Println("waiting db...")
+	}
+
+	renderIndexPosts()
+
 	go http.ListenAndServe(":3000", nil)
 
 	goji.Get("/initialize", getInitialize)
diff --git a/templates/index.html b/templates/index.html
index 22ff9c2..8c2b639 100644
--- a/templates/index.html
+++ b/templates/index.html
@@ -19,7 +19,7 @@
   </form>
 </div>
 
-{{ template "posts.html" .Posts }}
+{{ .Posts }}
 
 <div id="isu-post-more">
   <button id="isu-post-more-btn">もっと見る</button>

計測

スコア:

{"pass":true,"score":39743,"success":32254,"fail":0,"messages":[]}

top:

Tasks:  77 total,   1 running,  76 sleeping,   0 stopped,   0 zombie
%Cpu(s): 44.7 us,  8.3 sy,  0.0 ni, 35.3 id,  5.1 wa,  0.0 hi,  6.0 si,  0.5 st
KiB Mem:   1022972 total,   961900 used,    61072 free,    23704 buffers
KiB Swap:        0 total,        0 used,        0 free.   604328 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1337 isucon    20   0  207476  68192   8880 S  63.6  6.7   0:13.73 app.dc4a3eaa
  731 mysql     20   0 1059292 181996  10552 S  45.6 17.8   1:49.68 mysqld
 1033 www-data  20   0   92008   5092   3056 S   8.0  0.5   0:11.70 nginx
 1069 isucon    20   0   32140   9332   2636 S   4.0  0.9   0:07.71 tmux
    3 root      20   0       0      0      0 S   0.3  0.0   0:15.56 ksoftirqd/0
   13 root      20   0       0      0      0 S   0.3  0.0   0:29.07 ksoftirqd/1
   43 root      20   0       0      0      0 S   0.3  0.0   0:00.15 kworker/u30:1
  308 memcache  20   0  332576   7896   2228 S   0.3  0.8   0:00.89 memcached
  968 isucon    20   0   80656   3496   2656 S   0.3  0.3   0:00.28 sshd

CPU がだいぶ遊んできましたね。どこか別のところにあるボトルネックを見つけないといけません。

myprofiler:

  34 SELECT * FROM `users` WHERE `id` = N
  30 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
  23 SELECT * FROM `posts` WHERE `id` = N
  19 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
  11 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
  10 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   8 SELECT `id` FROM `posts` WHERE `user_id` = N
   2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S)
   1 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC
   1 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)

user を PK で取得する部分が重いみたいです。

access.log:

Request by count
12394 GET /image/*
4149 GET /
2791 POST /login
1395 GET /posts/*
1207 POST /register
1207 GET /admin/banned
1049 GET /@user
1021 GET /js/jquery-2.2.0.js
1021 GET /css/style.css
1021 GET /js/jquery.timeago.ja.js
1021 GET /favicon.ico
1021 GET /js/jquery.timeago.js
1021 GET /js/main.js
704 POST /comment
698 POST /
120 GET /login
77 GET /posts?max_created_at=
61 GET /logout
1 GET /initialize

Request by total time
30.646 0.0292144899905 GET /@user
24.051 0.0344570200573 POST /
14.411 0.187155844156 GET /posts?max_created_at=
12.099 0.00867311827957 GET /posts/*
11.879 0.0168735795455 POST /comment
9.296 0.00224053988913 GET /
6.612 0.00236904335364 POST /login
3.355 0.00277961888981 POST /register
2.882 0.00023253187026 GET /image/*
2.21 0.00183098591549 GET /admin/banned
0.448 0.00373333333333 GET /login
0.443 0.00726229508197 GET /logout
0.038 0.038 GET /initialize

Request by out bytes
3847419944 310426 GET /image/*
264074503 258643 GET /js/jquery-2.2.0.js
99628388 24012 GET /
...

GET / が 2.2msec まで速くなりました。まだ速く出来る余地はあるけど、先に GET /@user などの高速化が先でしょうね。

まとめ

スコア: 4745 (初期状態) -> 32771 (前回) -> 39743 (トップページのページキャッシュ)

ボトルネックがCPU以外に移っているので、スコアが期待したほど伸びませんでした。次回はそのボトルネックを調査・解決します。

ページキャッシュに利用した zero time cache パターンは Go だから簡単に実現できるものなので、 prefork 型のアプリサーバーを使う他の言語ではちょっと難しいです。 (node.js なら、2コアマシンならシングルプロセスで頑張れるかも知れません)

他の言語では、普通に getIndex でページキャッシュしてベンチが完走するようにキャッシュの生存期間を調整するとか、バックグラウンドで動くデーモンが定期的にページキャッシュを生成するようにしてベンチが通るようにその生成間隔を調整するといったやり方がISUCONでは一般的だと思います。

しかし、今回の pixiv private isucon ではルールに POST が返ってからその内容が別の GET リクエストに反映されるまでの猶予が明記されていないので、調整のために複数回ベンチを走らせる必要があるかもしれません。 (Go 推し)


@methane

songofacandy at 17:51|この記事のURLComments(0)TrackBack(0)
2016年06月01日

pixiv private isucon 2016 攻略 (3/5)

はてなブックマークに登録

攻略記事一覧:

現状確認

access.log をもう一度見直しましょう。

Request by total time
74.113 0.0307140489018 GET /
70.007 0.00532696697611 GET /image/*
43.428 0.0575205298013 GET /@user
24.058 0.283035294118 GET /posts?max_created_at=
23.976 0.0522352941176 POST /
12.767 0.012987792472 GET /posts/*
6.642 0.00390476190476 POST /login
...

CPU を一番使っているのはトップページですが、レスポンスタイムに占める時間で言えば /image/* がほとんど並びました。 そろそろ /image/* をリバースプロキシするのは止めないといけません。

Go を使う場合は nginx を使うのをやめるのも候補になるのですが、静的ファイル配信は nginx に任せたほうがてっとり早いので、 nginx を外さない方針で行きましょう。

nginx の設定

僕も ISUCON 前以外は nginx の設定に詳しくないので、とりあえずこんな感じで設定しました。

  root /home/isucon/private_isu/webapp/public/;

  location / {
    try_files $uri @app;
  }
  location @app {
    proxy_set_header Host $host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_pass http://app;
  }

public ディレクトリは css とか js も入ってるので、その中に mkdir image しておき、 try_files ディレクティブでファイルが有ればそれを返す、なければリバースプロキシの設定を書いた @app location を使う設定にしています。

アプリ側は、 /image/* にアクセスがあったときに画像を返すついでにファイルに書き出すのと、画像がアップロードされたときにファイルに書いてDBには書かないように修正します。DBに書かないのは Disk IO 負荷低減のためです。

--- a/app.go
+++ b/app.go
@@ -78,6 +78,29 @@ func init() {
        store = gsm.NewMemcacheStore(memcacheClient, "isucogram_", []byte("sendagaya"))
 }

+func writeImage(id int, mime string, data []byte) {
+       var ext string
+       switch mime {
+       case "image/jpeg":
+               ext = ".jpg"
+       case "image/png":
+               ext = ".png"
+       case "image/gif":
+               ext = ".gif"
+       default:
+               fmt.Println("Failed to write file: ", id, mime)
+               return
+       }
+
+       fn := fmt.Sprintf("../public/image/%d%s", id, ext)
+       f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
+       if err != nil {
+               panic(err)
+       }
+       f.Write(data)
+       f.Close()
+}
+
 func dbInitialize() {
        sqls := []string{
                "DELETE FROM users WHERE id > 1000",
@@ -652,7 +675,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                query,
                me.ID,
                mime,
-               filedata,
+               []byte(""),
                r.FormValue("body"),
        )
        if eerr != nil {
@@ -665,7 +688,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                fmt.Println(lerr.Error())
                return
        }
-
+       writeImage(int(pid), mime, filedata)
        http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
        return
 }
@@ -695,6 +718,7 @@ func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
                if err != nil {
                        fmt.Println(err.Error())
                }
+               writeImage(pid, post.Mime, post.Imgdata)
                return
        }

メモリが足りない!!

ここで問題にぶつかりました。メモリが足りなくてベンチが完走しません。 静的ファイル配信を nginx に任せることでメモリ使用量が減らせると思っていたのに!

多分、性能が向上したためにメモリアロケートのペースが早くなって問題が顕在化したのでしょう。プロファイラーで、ベンチマーク中 (メモリ使用量が増えてきたけどメモリ不足で落ちるよりは前) のメモリ使用量を調査してみます。

$ go tool pprof -inuse_space app.e27b8a http://localhost:3000/debug/pprof/heap
Fetching profile from http://localhost:3000/debug/pprof/heap
Saved profile in /home/isucon/pprof/pprof.app.e27b8a.localhost:3000.inuse_objects.inuse_space.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top40 -cum
319.72MB of 338.26MB total (94.52%)
Dropped 338 nodes (cum <= 1.69MB)
Showing top 40 nodes out of 52 (cum >= 8.34MB)
      flat  flat%   sum%        cum   cum%
         0     0%     0%   337.76MB 99.85%  runtime.goexit
         0     0%     0%   336.72MB 99.54%  net/http.(*conn).serve
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web.(*router).route
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.Recoverer.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0%     0%   322.22MB 95.26%  net/http.HandlerFunc.ServeHTTP
         0     0%     0%   321.72MB 95.11%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%     0%   321.72MB 95.11%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%     0%   321.72MB 95.11%  net/http.(*ServeMux).ServeHTTP
         0     0%     0%   321.72MB 95.11%  net/http.serverHandler.ServeHTTP
         0     0%     0%   309.80MB 91.59%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%     0%   301.29MB 89.07%  net/http.(*Request).FormValue
         0     0%     0%   301.29MB 89.07%  net/http.(*Request).ParseMultipartForm
         0     0%     0%   299.29MB 88.48%  main.postIndex
    0.50MB  0.15%  0.15%   298.79MB 88.33%  mime/multipart.(*Reader).ReadForm
         0     0%  0.15%   298.29MB 88.18%  bytes.(*Buffer).ReadFrom
  298.29MB 88.18% 88.33%   298.29MB 88.18%  bytes.makeSlice
         0     0% 88.33%   298.29MB 88.18%  io.Copy
         0     0% 88.33%   298.29MB 88.18%  io.CopyN
         0     0% 88.33%   298.29MB 88.18%  io.copyBuffer
         0     0% 88.33%       15MB  4.44%  net/http.(*conn).readRequest
       1MB   0.3% 88.63%       15MB  4.44%  net/http.readRequest
         0     0% 88.63%    12.42MB  3.67%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
   10.50MB  3.11% 91.73%       11MB  3.25%  net/textproto.(*Reader).ReadMIMEHeader
         0     0% 91.73%    10.50MB  3.10%  github.com/bradleypeabody/gorilla-sessions-memcache.(*MemcacheStore).Get
         0     0% 91.73%    10.50MB  3.10%  main.getSession
         0     0% 91.73%     9.42MB  2.78%  database/sql.(*Rows).Next
    9.42MB  2.78% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*buffer).fill
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*buffer).readNext
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*mysqlConn).readPacket
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*textRows).Next
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*textRows).readRow
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.(*DB).Get
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.(*Row).Scan
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.(*Row).scanAny
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.Get
         0     0% 94.52%     8.34MB  2.47%  main.getImage
(pprof) list ReadForm
Total: 338.26MB
ROUTINE ======================== mime/multipart.(*Reader).ReadForm in /home/isucon/.local/go/src/mime/multipart/formdata.go
  512.02kB   298.79MB (flat, cum) 88.33% of Total
         .          .     19:// ReadForm parses an entire multipart message whose parts have
         .          .     20:// a Content-Disposition of "form-data".
         .          .     21:// It stores up to maxMemory bytes of the file parts in memory
         .          .     22:// and the remainder on disk in temporary files.
         .          .     23:func (r *Reader) ReadForm(maxMemory int64) (f *Form, err error) {
  512.02kB   512.02kB     24:   form := &Form{make(map[string][]string), make(map[string][]*FileHeader)}
         .          .     25:   defer func() {
         .          .     26:           if err != nil {
         .          .     27:                   form.RemoveAll()
         .          .     28:           }
         .          .     29:   }()
         .          .     30:
         .          .     31:   maxValueBytes := int64(10 << 20) // 10 MB is a lot of text.
         .          .     32:   for {
         .          .     33:           p, err := r.NextPart()
         .          .     34:           if err == io.EOF {
         .          .     35:                   break
         .          .     36:           }
         .          .     37:           if err != nil {
         .          .     38:                   return nil, err
         .          .     39:           }
         .          .     40:
         .          .     41:           name := p.FormName()
         .          .     42:           if name == "" {
         .          .     43:                   continue
         .          .     44:           }
         .          .     45:           filename := p.FileName()
         .          .     46:
         .          .     47:           var b bytes.Buffer
         .          .     48:
         .          .     49:           if filename == "" {
         .          .     50:                   // value, store as string in memory
         .          .     51:                   n, err := io.CopyN(&b, p, maxValueBytes)
         .          .     52:                   if err != nil && err != io.EOF {
         .          .     53:                           return nil, err
         .          .     54:                   }
         .          .     55:                   maxValueBytes -= n
         .          .     56:                   if maxValueBytes == 0 {
         .          .     57:                           return nil, errors.New("multipart: message too large")
         .          .     58:                   }
         .          .     59:                   form.Value[name] = append(form.Value[name], b.String())
         .          .     60:                   continue
         .          .     61:           }
         .          .     62:
         .          .     63:           // file, store in memory or on disk
         .          .     64:           fh := &FileHeader{
         .          .     65:                   Filename: filename,
         .          .     66:                   Header:   p.Header,
         .          .     67:           }
         .   298.29MB     68:           n, err := io.CopyN(&b, p, maxMemory+1)
         .          .     69:           if err != nil && err != io.EOF {
         .          .     70:                   return nil, err
         .          .     71:           }
         .          .     72:           if n > maxMemory {
         .          .     73:                   // too big, write to disk and flush buffer
(pprof) list postIndex
Total: 338.26MB
ROUTINE ======================== main.postIndex in /home/isucon/private_isu/webapp/golang/app.go
         0   299.29MB (flat, cum) 88.48% of Total
         .          .    612:           Me   User
         .          .    613:   }{p, me})
         .          .    614:}
         .          .    615:
         .          .    616:func postIndex(w http.ResponseWriter, r *http.Request) {
         .   512.17kB    617:   me := getSessionUser(r)
         .          .    618:   if !isLogin(me) {
         .          .    619:           http.Redirect(w, r, "/login", http.StatusFound)
         .          .    620:           return
         .          .    621:   }
         .          .    622:
         .   298.79MB    623:   if r.FormValue("csrf_token") != getCSRFToken(r) {
         .          .    624:           w.WriteHeader(StatusUnprocessableEntity)
         .          .    625:           return
         .          .    626:   }

メモリーを使ってる箇所はわかりましたが、どう見てもリークではないです。

ファイルアップロードの効率化

ググったり、multipart の ReadForm 周辺のソースコードを読んで、原因を調べ、対策を考えます。

原因:

  • postIndex で最初に Request.FormValue を呼んだときにフォームを解析する処理が実行されていて、そこでアップロードされたファイルを読み込んでいる。
  • アップロードされたファイルは、ある程度 (デフォルト32MB) までは bytes.Buffer に読み込まれ、それを超える場合はテンポラリファイルに書き出される。
  • bytes.Buffer は小さいサイズからどんどんリアロケートして拡大していくので、短時間に大量のアロケートが発生する。アプリの性能が上がるのに連動してファイルのアップロードの頻度が増え、アロケートのペースが速すぎてGCが追いつかなくなったようだ。

対策:

  • multipart を解析するときに明示的に ParseMultipartForm を呼び出し、32MBよりももっと早めにテンポラリファイルを使うようにする。
  • 並列にファイルアップロードの解析が走らないように Mutex で保護する。
--- a/app.go
+++ b/app.go
@@ -17,6 +17,7 @@ import (
        "regexp"
        "strconv"
        "strings"
+       "sync"
        "time"

        "github.com/bradfitz/gomemcache/memcache"
@@ -613,6 +614,8 @@ func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
        }{p, me})
 }

+var uploadM sync.Mutex
+
 func postIndex(w http.ResponseWriter, r *http.Request) {
        me := getSessionUser(r)
        if !isLogin(me) {
@@ -620,6 +623,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                return
        }

+       uploadM.Lock()
+       defer uploadM.Unlock()
+       r.ParseMultipartForm(1 << 10)
        if r.FormValue("csrf_token") != getCSRFToken(r) {
                w.WriteHeader(StatusUnprocessableEntity)
                return

これでもまだ足りませんでした。なので、一旦メモリに置いてからファイルに書き出すのを止め、一時ファイルにコピーして、それを image/ ディレクトリ配下にリネームするように改修しました。

--- a/app.go
+++ b/app.go
@@ -80,26 +80,21 @@ func init() {
 }

 func writeImage(id int, mime string, data []byte) {
-       var ext string
-       switch mime {
-       case "image/jpeg":
-               ext = ".jpg"
-       case "image/png":
-               ext = ".png"
-       case "image/gif":
-               ext = ".gif"
-       default:
-               fmt.Println("Failed to write file: ", id, mime)
-               return
+       fn := imagePath(id, mime)
+       err := ioutil.WriteFile(fn, data, 0666)
+       if err != nil {
+               log.Println("failed to write file; path=%q, err=%v", fn, err)
        }
+}

-       fn := fmt.Sprintf("../public/image/%d%s", id, ext)
-       f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
-       if err != nil {
-               panic(err)
+func copyImage(id int, src, mime string) {
+       dst := imagePath(id, mime)
+       if err := os.Chmod(src, 0666); err != nil {
+               log.Println("failed to chmod: path=%v, %v", src, err)
+       }
+       if err := os.Rename(src, dst); err != nil {
+               log.Println("failed to rename; src=%q, dst=%q; %v", src, dst, err)
        }
-       f.Write(data)
-       f.Close()
 }

 func dbInitialize() {
@@ -260,6 +255,19 @@ func imageURL(p Post) string {
        return "/image/" + strconv.Itoa(p.ID) + ext
 }

+func imagePath(id int, mime string) string {
+       var ext string
+       switch mime {
+       case "image/jpeg":
+               ext = ".jpg"
+       case "image/png":
+               ext = ".png"
+       case "image/gif":
+               ext = ".gif"
+       }
+       return fmt.Sprintf("../public/image/%d%s", id, ext)
+}
+
 func isLogin(u User) bool {
        return u.ID != 0
 }
@@ -662,16 +670,20 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                }
        }

-       filedata, rerr := ioutil.ReadAll(file)
-       if rerr != nil {
-               fmt.Println(rerr.Error())
+       tf, err := ioutil.TempFile("../upload", "img-")
+       if err != nil {
+               log.Panicf("failed to create image: %v", err)
        }
-
-       if len(filedata) > UploadLimit {
+       written, err := io.CopyN(tf, file, UploadLimit+1)
+       if err != nil && err != io.EOF {
+               log.Panicf("failed to write to temporary file: %v", err)
+       }
+       if written > UploadLimit {
+               os.Remove(tf.Name())
+               tf.Close()
                session := getSession(r)
                session.Values["notice"] = "ファイルサイズが大きすぎます"
                session.Save(r, w)
-
                http.Redirect(w, r, "/", http.StatusFound)
                return
        }
@@ -694,7 +706,8 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                fmt.Println(lerr.Error())
                return
        }
-       writeImage(int(pid), mime, filedata)
+       tf.Close()
+       copyImage(int(pid), tf.Name(), mime)
        http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
        return
 }

これでメモリ不足は落ち着き、とりあえず静的ファイルと投稿画像を nginx から返す設定でベンチが完走しました。

{"pass":true,"score":32771,"success":27352,"fail":0,"messages":[]}

本当は、 http.Request の Form 解析によって作られる一時ファイルからアプリケーションの一時ファイルへのコピーが無駄なので、 Request の Form 系のAPIを使わず直接 Body を解析するともっと効率が良くなります。(難しそうに聞こえるかもしれませんが、ほぼ Request.ParseMultipartFormのコピペで行けるはずです)

ただし、この時点でメモリ不足は収まったので、これ以上はディスク書き込みがネックになってどうしようもなくなるまで置いておいて、本来やりたかったチューニングにもどりましょう。

まとめ

スコア: 4745 (初期状態) -> 30076 (前回) -> 32771 (nginxで画像配信)

思っていたより性能向上が少ないです。これは次回に持ち越しです。

今回はファイルアップロードによるメモリ不足に悩まされましたが、(2010年代も後半になって)1GBメモリのマシンで、すごい大量にアップロードされる画像を裁くのは ISUCON だとありがちです。ちゃんと効率のいいファイルアップロードのやり方を調べておきましょう。

また、自分が使う予定の言語でメモリ不足を調査する方法も調べておきましょう。(例えば Python なら標準ライブラリの tracemalloc が使えると思います。)


@methane

songofacandy at 15:52|この記事のURLComments(0)TrackBack(0)
2016年05月31日

pixiv private isucon 2016 攻略 (2/5)

はてなブックマークに登録

攻略記事一覧:

アプリを読む

ソースコードを読みながらだいたいの構成を把握していきます。

  • フレームワークは goji を使っている。 goji のサイトを見ると同じ名前で新しいフレームワークを作り直したみたいだけど、これは古い方を使ってるみたいです。
  • セッションは Gorilla のライブラリに memcached store を組み合わせている
  • テンプレートをレンダリングのたびにコンパイルしてるのが重そう。
  • コメントのユーザーをいちいちユーザーテーブルから引っ張ってるのも JOIN かキャッシュが効きそう。
  • 画像データを MySQL に突っ込んでるのは、ファイルに出す必要がありそう。(ファイルなら数十KBずつ読んでは返せるけれど、DBだと簡単な方法だと一度に全体をメモリに読んでしまうので、並列にアクセスが来たときにメモリが足りなくなります。)

読んでいると改善したいポイントがたくさん出てくるものの、いきなりあちこち改造しだすとバグったときに困ります。はじめは基礎的な設定とボトルネックに絞ったチューニングです。

最初にDBのコネクションプール設定できてないので設定しておきましょう。2コアなんでそんなにたくさんコネクションあっても仕方ないハズ。とりあえずちょい多めの8にしておきます。

+    db.SetMaxOpenConns(8)
+    db.SetMaxIdleConns(8)
     defer db.Close()

アクセスログを読む

事前に用意しておいたアクセスログ集計ツール(自作してもいいですし、過去のいろいろな方のISUCONの記事を探してみれば良いツールが紹介されているはずです)を、アクセスログやアプリのURLルーティングの設定を参考にカスタマイズしましょう。

僕の場合は自作スクリプトで、次のような集計をしました。

Request by count
8028 GET /image/*
644 GET /
551 GET /js/jquery-2.2.0.js
551 GET /css/style.css
551 GET /js/jquery.timeago.ja.js
551 GET /favicon.ico
551 GET /js/jquery.timeago.js
551 GET /js/main.js
450 POST /login
299 GET /posts/*
235 GET /@user
130 POST /
98 GET /login
90 POST /comment
79 POST /register
78 GET /admin/banned
56 GET /posts?max_created_at=
50 GET /logout
1 GET /initialize

Request by total time (total avg [sec])
198.379 0.308041925466 GET /
168.858 0.021033632287 GET /image/*
47.605 0.202574468085 GET /@user
34.491 0.0766466666667 POST /login
30.444 0.543642857143 GET /posts?max_created_at=
15.095 0.0504849498328 GET /posts/*
7.068 0.0894683544304 POST /register
6.7 0.0515384615385 POST /
6.51 0.0118148820327 GET /favicon.ico
6.483 0.0117658802178 GET /js/jquery-2.2.0.js
5.784 0.010497277677 GET /js/jquery.timeago.js
5.213 0.0094609800363 GET /js/jquery.timeago.ja.js
5.095 0.00924682395644 GET /css/style.css
4.997 0.00906896551724 GET /js/main.js
2.478 0.0275333333333 POST /comment
2.257 0.0230306122449 GET /login
1.314 0.0168461538462 GET /admin/banned
1.131 0.02262 GET /logout
0.061 0.061 GET /initialize

Request by out bytes (total avg)
2485959550 309661 GET /image/*
142499069 258619 GET /js/jquery-2.2.0.js
12206011 18953 GET /
4287247 18243 GET /@user
4105501 7451 GET /js/jquery.timeago.js
1912146 34145 GET /posts?max_created_at=
1108574 3707 GET /posts/*
980229 1779 GET /css/style.css
487635 885 GET /js/main.js
357048 648 GET /js/jquery.timeago.ja.js
195356 434 POST /login
177772 1814 GET /login
149872 272 GET /favicon.ico
34286 434 POST /register
23530 181 POST /
22200 444 GET /logout
16833 187 POST /comment
13104 168 GET /admin/banned
161 161 GET /initialize

これで考えるのは、主に次の2点です。

  • トップページと /image/ に掛かる時間が一番重い。特にトップページを最初にチューニングするのが良さそう。
  • 帯域は /image/ が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。

pprof

とりあえず app の CPU が重いので、CPUプロファイルから始めましょう。 pprof の基本的な使い方は、以前に Blog を書いたのでそれを参照してください。

diff --git a/app.go b/app.go
index 861ff03..eb52f47 100644
--- a/app.go
+++ b/app.go
@@ -9,6 +9,7 @@ import (
        "io/ioutil"
        "log"
        "net/http"
+       _ "net/http/pprof"
        "net/url"
        "os"
        "os/exec"
@@ -826,6 +827,8 @@ func main() {
+
+        db.SetMaxOpenConns(8)
+        db.SetMaxIdleConns(8)
        defer db.Close()

+       go http.ListenAndServe(":3000", nil)
+
        goji.Get("/initialize", getInitialize)
        goji.Get("/login", getLogin)
        goji.Post("/login", postLogin)
$ go tool pprof app http://localhost:3000/debug/pprof/profile
Fetching profile from http://localhost:3000/debug/pprof/profile
Please wait... (30s)
Saved profile in /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top 10
14440ms of 29650ms total (48.70%)
Dropped 546 nodes (cum <= 148.25ms)
Showing top 10 nodes out of 214 (cum >= 7370ms)
      flat  flat%   sum%        cum   cum%
    2270ms  7.66%  7.66%     8650ms 29.17%  runtime.mallocgc
    2220ms  7.49% 15.14%     2220ms  7.49%  runtime.memclr
    2150ms  7.25% 22.39%     2840ms  9.58%  runtime.scanobject
    1930ms  6.51% 28.90%     2060ms  6.95%  syscall.Syscall
    1280ms  4.32% 33.22%     1280ms  4.32%  runtime.heapBitsSetType
    1240ms  4.18% 37.40%     1270ms  4.28%  runtime.(*mspan).sweep.func1
    1000ms  3.37% 40.78%     1000ms  3.37%  runtime.memmove
     930ms  3.14% 43.91%     5070ms 17.10%  database/sql.convertAssign
     750ms  2.53% 46.44%     2240ms  7.55%  time.parse
     670ms  2.26% 48.70%     7370ms 24.86%  github.com/go-sql-driver/mysql.(*textRows).readRow

メモリ管理が重いですね。あと MySQL から受け取った結果をパースしてる部分が重い。

メモリ管理が重い場合、メモリのアロケートしてる部分を見つけて潰していく方法もありますが、もっと高いレイヤーでのアプリのチューニングの方が先です。この場合 -cum オプションを使ってトップダウンにプロファイルを見ます。

(pprof) top -cum 40
10.25s of 29.65s total (34.57%)
Dropped 546 nodes (cum <= 0.15s)
Showing top 40 nodes out of 214 (cum >= 2.22s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     28.99s 97.77%  runtime.goexit
         0     0%     0%     25.69s 86.64%  net/http.(*conn).serve
         0     0%     0%     25.40s 85.67%  net/http.(*ServeMux).ServeHTTP
...
         0     0%     0%     25.08s 84.59%  github.com/zenazn/goji/web/middleware.Recoverer.func1
         0     0%     0%     22.42s 75.62%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%     0%     20.61s 69.51%  main.getIndex
         0     0%     0%     20.26s 68.33%  github.com/jmoiron/sqlx.(*DB).Select
         0     0%     0%     20.26s 68.33%  github.com/jmoiron/sqlx.Select
...

上位にいるリクエストハンドラーは getIndex だけです。ここに集中しましょう。

ソースコードの行単位のプロファイルを見るにはデバッグ情報が必要なので、 pprof 起動時にアプリのバイナリを指定しておく必要があります。 バイナリを指定し忘れて URL だけでプロファイルを取ってしまった場合も、起動したときの "Saved profile in ..." に表示されているパスにプロファイル結果が保存されているので、再度プロファイリングしなくても go tool pprof app <プロファイル結果のパス> で大丈夫です。

isucon:~/private_isu/webapp/golang$ go tool pprof app  /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) list main.getIndex
Total: 29.65s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
         0     20.61s (flat, cum) 69.51% of Total
         .          .    388:
         .          .    389:   http.Redirect(w, r, "/", http.StatusFound)
         .          .    390:}
         .          .    391:
         .          .    392:func getIndex(w http.ResponseWriter, r *http.Request) {
         .      120ms    393:   me := getSessionUser(r)
         .          .    394:
         .          .    395:   results := []Post{}
         .          .    396:
         .     18.39s    397:   err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
         .          .    398:   if err != nil {
         .          .    399:           fmt.Println(err)
         .          .    400:           return
         .          .    401:   }
         .          .    402:
         .      1.34s    403:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    404:   if merr != nil {
         .          .    405:           fmt.Println(merr)
         .          .    406:           return
         .          .    407:   }
         .          .    408:
         .          .    409:   fmap := template.FuncMap{
         .          .    410:           "imageURL": imageURL,
         .          .    411:   }
         .          .    412:
         .          .    413:   template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
         .          .    414:           getTemplPath("layout.html"),
         .          .    415:           getTemplPath("index.html"),
         .          .    416:           getTemplPath("posts.html"),
         .          .    417:           getTemplPath("post.html"),
         .       70ms    418:   )).Execute(w, struct {
         .          .    419:           Posts     []Post
         .          .    420:           Me        User
         .          .    421:           CSRFToken string
         .          .    422:           Flash     string
         .      690ms    423:   }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
         .          .    424:}
         .          .    425:
         .          .    426:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    427:   user := User{}
         .          .    428:   uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])

前回の記事の最後で myprofiler で見つけた、 posts からの LIMIT なしクエリが重い問題ですね。MySQL 側だけでなく、その大量の結果を全件取得してパースしてる app 側でも一番重くなっているようです。

このクエリの結果を利用している makePosts() の中を見てみると、ループの終端にこんな if 文があります。

        if len(posts) >= postsPerPage {
            break
        }

この手前に continue 文もないので、このまま postsPerPage で LIMIT しましょう。 (注: これが確認不足で後でハマります)

diff --git a/app.go b/app.go
index eb52f47..3dd9804 100644
--- a/app.go
+++ b/app.go
@@ -394,7 +394,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {

        results := []Post{}

-       err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
+       err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
        if err != nil {
                fmt.Println(err)
                return

さて、計測です。本当は計測とプロファイルは別にした方がいいですが、時間が勿体無いのでプロファイルしながら計測です。

スコア:

{"pass":true,"score":12848,"success":22272,"fail":1201,"messages":["1ページに表示される画像の数が足りません (GET /)","リダイレクト先URLが正しくありません: expected '^/$', got '/login' (GET /login)"]}

あらら。エラーがでてきました。アプリのログを見ると、

fork/exec /bin/bash: cannot allocate memory

メモリが足りなくて fork に失敗してました。

top:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
11931 isucon    20   0  406248 183372   9052 S  74.8 17.9   0:19.55 app
  720 mysql     20   0 1226416 215076  10404 S  65.5 21.0   3:24.11 mysqld

CPU 使用率は app と mysql がだいたい一緒ですね。足しても200にだいぶ届かないので、CPU以外の部分がネックにりはじめていそうです。

myprofiler:

  17 SELECT * FROM `posts` WHERE `id` = N
  12 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   4 SELECT * FROM `users` WHERE `id` = N
   3 SELECT * FROM `users` WHERE `id` = ?

posts から id 指定で1レコード取得が重くなりました。 N+1 かな?

外部プロセス呼び出しをやめる

fork に失敗するのは、多分(スワップがないせいで?)オーバーコミットがオフになっていて、fork した瞬間に app と同じだけのメモリを持ってるもう1プロセスを作れないからだと思います。

CPU使用率が2コアなのに200%に全然届かないのも fork のせい (Go のランタイムの都合上 fork するためには全 goroutine を一旦止めないといけなくて待ち時間が発生する) かもしれないので、メモリ使用量削減のために画像ファイルをDBから切り出すよりも外部プロセス呼び出しをやめる方を優先しましょう。

外部プロセスを読んでるところを見ると、 openssl dgst -sha512 コマンドで sha512 ダイジェストを計算しているようです。 Go で sha512 を計算する方法を調べて、同じ出力をするプログラムを書いてみます。

$ cat t.go < app.go
package main

import (
        "crypto/sha512"
        "fmt"
        "io/ioutil"
        "os"
)

func main() {
        data, _ := ioutil.ReadAll(os.Stdin)
        fmt.Printf("%x\n", sha512.Sum512(data))
}
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ go run t.go < t.go
b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ openssl dgst -sha512 < t.go
(stdin)= b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17

これを参考に app.go を書き換えます。

@@ -125,14 +125,7 @@ func escapeshellarg(arg string) string {
 }

 func digest(src string) string {
-       // opensslのバージョンによっては (stdin)= というのがつくので取る
-       out, err := exec.Command("/bin/bash", "-c", `printf "%s" `+escapeshellarg(src)+` | openssl dgst -sha512 | sed 's/^.*= //'`).Output()
-       if err != nil {
-               fmt.Println(err)
-               return ""
-       }
-
-       return strings.TrimSuffix(string(out), "\n")
+       return fmt.Sprintf("%x", sha512.Sum512([]byte(src)))
 }

さて、プロファイル&計測です。アプリのログには fork エラーが消えました。

スコア:

{"pass":true,"score":26755,"success":24050,"fail":119,"messages":["1ページに表示される画像の数が足りません (GET /)"]}

うーん、まだエラー出てますね。これは LIMIT 足したのがマズいかな?

top:

Tasks:  84 total,   1 running,  83 sleeping,   0 stopped,   0 zombie
%Cpu(s): 54.2 us, 20.7 sy,  0.0 ni, 15.0 id,  1.4 wa,  0.0 hi,  8.3 si,  0.4 st
KiB Mem:   1022972 total,   958404 used,    64568 free,    18292 buffers
KiB Swap:        0 total,        0 used,        0 free.   425600 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1357488 210336   4476 S  78.6 20.6   5:19.05 mysqld
  763 isucon    20   0  619612 198632   9120 S  70.2 19.4   0:13.54 app
 2904 www-data  20   0   92028   4088   1928 S  11.3  0.4   0:29.40 nginx
 2572 isucon    20   0   34344  11148   2160 S   7.3  1.1   0:28.48 tmux

idle が 15% まで下がってます。狙い通り。 あと、 tmux が 7% まで来ました。 Goji のログがリッチすぎるので、最後には切らないといけませんね。

myprofiler:

##  2016-05-25 20:18:44.06 +0900
  13 SELECT * FROM `posts` WHERE `id` = N
   9 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   6 SELECT * FROM `users` WHERE `id` = ?
   6 SELECT `id` FROM `posts` WHERE `user_id` = N
   4 SELECT * FROM `users` WHERE `id` = N
   4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?
   2 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
   2 SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC LIMIT N
   2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC

バグ修正

makePosts() を見直してみると、投稿したユーザーが論理削除されていたら配列への追加をしないようなコードになっていました。 (Go だと early return (continue) イディオムを使うことが多いのでこの部分を見逃していました)

        if p.User.DelFlg == 0 {
            posts = append(posts, p)
        }

SELECT の段階で強引に JOIN してこの論理削除のフィルタリングを実行してしまいます。

@@ -394,7 +387,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {
 
        results := []Post{}
 
-       err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
+       err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
        if err != nil {
                fmt.Println(err)
                return

スコア:

{"pass":true,"score":27399,"success":23615,"fail":0,"messages":[]}

今度はちゃんと通りました。

top:

Tasks:  83 total,   4 running,  79 sleeping,   0 stopped,   0 zombie
%Cpu(s): 53.9 us, 23.6 sy,  0.0 ni,  9.8 id,  4.2 wa,  0.0 hi,  8.2 si,  0.2 st
KiB Mem:   1022972 total,   948340 used,    74632 free,    12604 buffers
KiB Swap:        0 total,        0 used,        0 free.   486056 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1359224 209144   4576 S  85.9 20.4   6:06.96 mysqld
  910 isucon    20   0  487224 139892   8884 S  67.9 13.7   0:09.58 app
 2904 www-data  20   0   91852   2828    844 R  10.7  0.3   0:35.40 nginx
 2572 isucon    20   0   34472  10100    928 S   6.7  1.0   0:33.64 tmux

ちょっと mysql が重いですね。

myprofiler:

  15 SELECT * FROM `posts` WHERE `id` = N
   7 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   6 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   5 SELECT * FROM `users` WHERE `id` = ?
   5 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)
   5 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
   5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
   4 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (?,?,?,?)
   4 INSERT INTO `users` (`account_name`, `passhash`) VALUES (?,?)
   3 SELECT * FROM `users` WHERE `id` = N

JOIN を足したけど、それでもまだ post を id で引くのが重いみたいです。

pprof top40 -cum:

...
         0     0%  0.38%     13.88s 76.18%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
     0.01s 0.055%  0.44%      8.85s 48.57%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%  0.44%      6.11s 33.53%  main.getIndex
     0.02s  0.11%  0.55%      4.92s 27.00%  github.com/jmoiron/sqlx.(*DB).Get
     0.01s 0.055%   0.6%      4.90s 26.89%  github.com/jmoiron/sqlx.Get
         0     0%   0.6%      4.78s 26.23%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.02s  0.11%  0.71%      4.65s 25.52%  main.makePosts
     3.82s 20.97% 21.68%      4.06s 22.28%  syscall.Syscall
...

pprof list makePosts:

ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
      20ms      4.65s (flat, cum) 25.52% of Total
         .          .    173:}
         .          .    174:
         .          .    175:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
         .          .    176:   var posts []Post
         .          .    177:
      10ms       10ms    178:   for _, p := range results {
         .      1.05s    179:           err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
         .          .    180:           if err != nil {
         .          .    181:                   return nil, err
         .          .    182:           }
         .          .    183:
         .          .    184:           query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
         .          .    185:           if !allComments {
         .       20ms    186:                   query += " LIMIT 3"
         .          .    187:           }
         .          .    188:           var comments []Comment
         .      1.38s    189:           cerr := db.Select(&comments, query, p.ID)
         .          .    190:           if cerr != nil {
         .          .    191:                   return nil, cerr
         .          .    192:           }
         .          .    193:
         .          .    194:           for i := 0; i < len(comments); i++ {
         .      770ms    195:                   uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
         .          .    196:                   if uerr != nil {
         .          .    197:                           return nil, uerr
         .          .    198:                   }
         .          .    199:           }
         .          .    200:
         .          .    201:           // reverse
         .          .    202:           for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
         .          .    203:                   comments[i], comments[j] = comments[j], comments[i]
         .          .    204:           }
         .          .    205:
      10ms       10ms    206:           p.Comments = comments
         .          .    207:
         .      1.35s    208:           perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
         .          .    209:           if perr != nil {
         .          .    210:                   return nil, perr
         .          .    211:           }
         .          .    212:
         .          .    213:           p.CSRFToken = CSRFToken
         .          .    214:
         .          .    215:           if p.User.DelFlg == 0 {
         .       60ms    216:                   posts = append(posts, p)
         .          .    217:           }
         .          .    218:           if len(posts) >= postsPerPage {
         .          .    219:                   break
         .          .    220:           }
         .          .    221:   }

時間のかかってるクエリがコメント取得を除いて1レコード取得するだけのクエリなので、簡単なクエリを大量に投げてるのが問題で重いのでしょう。

プレースホルダがあるクエリは、デフォルトでは prepared statement を使い捨てにしている (prepare, execute, close の3コマンド) ので、明示的に prepared statement を再利用するコードを書くか、 prepared statement を使わないようにするのがいいです。 最高性能を目指すなら再利用の方がいいですが、改修が簡単なのは prepared statement を使わない方です。 dsn に interpolateParams=true を足すだけ! (僕が実装した機能です。 参考)

diff:

@@ -805,7 +805,7 @@ func main() {
        }

        dsn := fmt.Sprintf(
-               "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local",
+               "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local&interpolateParams=true",
                user,
                password,
                host,

スコア:

{"pass":true,"score":30076,"success":25687,"fail":0,"messages":[]}

30k 点に到達。

top:

Tasks:  83 total,   5 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 63.1 us, 17.4 sy,  0.0 ni,  8.5 id,  3.4 wa,  0.0 hi,  7.4 si,  0.2 st
KiB Mem:   1022972 total,   960140 used,    62832 free,    13192 buffers
KiB Swap:        0 total,        0 used,        0 free.   472760 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1359224 209132   4128 S  79.7 20.4   6:56.71 mysqld
 1010 isucon    20   0  514368 157192   8888 S  66.8 15.4   0:08.93 app
 2904 www-data  20   0   91876   2824    844 R  11.3  0.3   0:41.86 nginx
 1015 isucon    20   0   21176  18648   3444 R   8.3  1.8   0:01.31 myprofiler
 2572 isucon    20   0   34920  10472    916 S   7.3  1.0   0:38.28 tmux

myprofiler:

  18 SELECT * FROM `posts` WHERE `id` = N
  11 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (N,S,_binaryS,S)
   9 SELECT * FROM `users` WHERE `id` = N
   7 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   6 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
   5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
   2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S)
   1 SELECT * FROM `users` WHERE `account_name` = S AND `del_flg` = N
   1 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (N,N,S)

pprof:

(pprof) top40 -cum
4.23s of 18.58s total (22.77%)
Dropped 583 nodes (cum <= 0.09s)
Showing top 40 nodes out of 317 (cum >= 2.07s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     17.10s 92.03%  runtime.goexit
...
         0     0%  0.22%      8.84s 47.58%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%  0.22%      5.66s 30.46%  main.getIndex
         0     0%  0.22%      4.90s 26.37%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
         0     0%  0.22%      4.04s 21.74%  github.com/jmoiron/sqlx.(*DB).Get
     0.04s  0.22%  0.43%      4.04s 21.74%  github.com/jmoiron/sqlx.Get
         0     0%  0.43%      3.73s 20.08%  html/template.(*Template).Execute
     0.03s  0.16%  0.59%      3.50s 18.84%  main.makePosts
         0     0%  0.59%      3.32s 17.87%  github.com/jmoiron/sqlx.(*DB).Select
         0     0%  0.59%      3.32s 17.87%  github.com/jmoiron/sqlx.Select
     0.93s  5.01%  5.60%      3.23s 17.38%  runtime.mallocgc
         0     0%  5.60%      3.12s 16.79%  text/template.(*Template).Execute
     0.08s  0.43%  6.03%      3.12s 16.79%  text/template.(*state).walk
     0.01s 0.054%  6.08%      3.07s 16.52%  text/template.(*state).walkTemplate
         0     0%  6.08%      3.02s 16.25%  text/template.(*state).walkRange
         0     0%  6.08%      3.02s 16.25%  text/template.(*state).walkRange.func1
     0.13s   0.7%  6.78%      2.96s 15.93%  runtime.systemstack

そろそろテンプレートの重さが上位に見え始めましたが、まだDBの方が重い。

まとめ

スコア: 4745 (初期状態) -> 14208 (前回) -> 30076 (今回)

さて、そろそろプロファイルで重いところを潰すチューニングは、乾いた雑巾絞りに近づいてきました。 次回はもっとドラスティックなチューニングに移っていきたいと思います。

今回は pprof や myprofiler を使ったチューニングの紹介の意図があったのでちょっとやりすぎてしまいました。 実際にはもっと早めに大改造を必要とするようなチューニングを考えて実行しないと、後半に時間が足りなくてジリ貧になってしまうので気をつけましょう。


@methane

songofacandy at 11:10|この記事のURLComments(0)TrackBack(0)
2016年05月30日

pixiv private isucon 2016 攻略 (1/5)

はてなブックマークに登録

攻略記事一覧:

pixiv さんが社内で開催したプライベート ISUCON の AMI を公開してくれたので、手順を残しながら攻略していきます。

この記事の対象読者は途中で何をすればいいかわからなくなってしまう ISUCON 初心者です。 Go を利用して攻略していきますが、他の言語で参加する場合でも考え方などは参考になると思います。

最低限の初期設定

ssh の公開鍵を入れたり、エディターや git などのツール類をインストール・設定します。

このあたりは事前に自分用のチートシートやスクリプトを作って、手早くできるようにしておきましょう。

マシン調査

スペック

とりあえず CPU とメモリくらいはちゃんと把握しておきましょう。

$ grep processor /proc/cpuinfo
processor       : 0
processor       : 1

$ free -m
             total       used       free     shared    buffers     cached
Mem:           998        906         92         12         25        335
-/+ buffers/cache:        545        453
Swap:            0          0          0

CPUは2コアですね。メモリはトータル1GBでスワップなし。要注意です。

ps aux

何が動いているか確認します。 メールサーバーとか、AppArmor のような、競技に明らかに不要そうなデーモンは、ベンチマークスコアを安定させるためとメモリの節約のために落としておいたほうが良いです。

今回は特に何もする必要はありませんでした。

アプリの仕様把握

初期状態に復元する手順を確認してから、実際にアプリをブラウザからさわってみましょう。

初期状態への復元は、 tar でアーカイブしてローカルに持ってきておいたり、 mysqldump を取ったりしておくと良いです。 ただし今回の場合はAMIからやり直せるので、 /initialize というパスで初期化されると言うことだけアプリのコードで確認し、バックアップは手抜きしました。 ISUCON 本番では初期状態を復元するのに必要なデータをオペミスで失うと即死する恐れがあるので注意しましょう。

ブラウザのデバッグ機能でどういう通信をしているのか見たり、アプリのコードのURLルーティング部分を中心に軽く目を通したり、 mysqldump --no-data isuconp で取得したスキーマを参考に、ざっくりと全体像を把握していきます。

nginx の基礎設定

アクセスログを事前に用意しておいたフォーマットに変更して、 upstream への keepalive を付ける。 コア数少ないので worker_processes を 1 にして、 keepalive の効率を上げる。

静的ファイルを nginx から返す設定は、アプリの動作を把握してからでも遅くない。 Go 以外を使う人は、完全に静的なファイルが分かった段階ですぐに、Go を使う人はある程度チューニングが進んで nginx を外すかどうかを判断するタイミングで nginx から返すようにしよう。

/etc/nginx/nginx.conf:

    worker_processes 1;
    ...
        ##
        # Logging Settings
        ##
        log_format  isucon '$time_local $msec\t$status\treqtime:$request_time\t'
                           'in:$request_length\tout:$bytes_sent\trequest:$request\t'
                           'acceptencoding:$http_accept_encoding\treferer:$http_referer\t'
                           'ua:$http_user_agent';
        access_log /var/log/nginx/access.log isucon;

/etc/nginx/sites-enabled/isucon.conf:

  upstream app {
    server 127.0.0.1:8080;
    keepalive 32;
  }

  server {
    listen 80;
  
    client_max_body_size 10m;
    root /home/isucon/private_isu/webapp/public/;
  
    location / {
      proxy_set_header Host $host;
      proxy_set_header X-Real-IP $remote_addr;
      proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
      proxy_pass http://app;
    }
  }

あと、今回は Go を使うので ruby と php のサービスも止めてしまいます。 Go のサービスは開発中はコマンドラインで起動したいのでここでは設定しません。

$ sudo systemctl stop isu-ruby
$ sudo systemctl disable isu-ruby
$ sudo systemctl stop php7.0-fpm
$ sudo systemctl disable php7.0-fpm

MySQL の基礎設定

/etc/mysql/my.cnf を見てみます。ほぼディストリのデフォルトで使っているようなので、メモリ使用量削減とIO待ち削減のために次の設定だけ追加しておきます。

innodb_flush_method = O_DIRECT
innodb_flush_log_at_trx_commit = 2

重いクエリを手早く見つけるためのツールを用意する。僕の場合は myprofiler を使う。

$ wget https://github.com/KLab/myprofiler/releases/download/0.1/myprofiler.linux_amd64.tar.gz
$ tar xf myprofiler.linux_amd64.tar.gz
$ sudo mv myprofiler /usr/local/bin/

myprofiler の使い方は、 myprofiler -user=root です。クエリが減ってきたら myprofiler -user=root -interval=0.2 くらいにサンプリング間隔を短くすると良いでしょう。それ以外のオプションは myprofiler -h で確認してください。

ベンチマークの実行とざっくり状況把握

スコア:

{"pass":true,"score":4745,"success":4408,"fail":0,"messages":[]}

top:

Tasks:  81 total,   1 running,  80 sleeping,   0 stopped,   0 zombie
%Cpu(s): 94.1 us,  4.2 sy,  0.0 ni,  0.3 id,  0.0 wa,  0.0 hi,  1.3 si,  0.0 st
KiB Mem:   1022972 total,   701036 used,   321936 free,    21396 buffers
KiB Swap:        0 total,        0 used,        0 free.   346564 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1087768 140276  10724 S 142.8 13.7   0:52.09 mysqld
 2908 isucon    20   0  582876 124364   8800 S  46.6 12.2   0:12.98 app
 2904 www-data  20   0   91680   4800   2988 S   1.7  0.5   0:00.61 nginx

MySQL が app の3倍CPU食ってるのがわかります。

myprofiler:

 198 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
 124 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
  11 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC
   9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC
   5 SELECT * FROM `posts` WHERE `id` = N
   4 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)
   2 SELECT * FROM `users` WHERE `id` = ?
   2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   1 SELECT * FROM users WHERE account_name = S AND del_flg = N
   1 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N

comments の SELECT と COUNT が遅い事がわかる。その次に posts の select。

一番最初のチューニング: インデックス

上位3件のクエリについて、インデックスが有るか確認して、なければ張っておく。

mysql> show create table comments\G
*************************** 1. row ***************************
       Table: comments
Create Table: CREATE TABLE `comments` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `post_id` int(11) NOT NULL,
  `user_id` int(11) NOT NULL,
  `comment` text NOT NULL,
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100049 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

mysql> show create table posts\G
*************************** 1. row ***************************
       Table: posts
Create Table: CREATE TABLE `posts` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `user_id` int(11) NOT NULL,
  `mime` varchar(64) NOT NULL,
  `imgdata` mediumblob NOT NULL,
  `body` text NOT NULL,
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=10056 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

comments.post_idposts.created_at にインデックスがない。重いクエリ上位3つがこれ。

mysql> create index post_id on comments (post_id);
Query OK, 0 rows affected (0.19 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> create index created_at on posts (created_at);
Query OK, 0 rows affected (0.03 sec)
Records: 0  Duplicates: 0  Warnings: 0

とりあえずこれでもう一度計測しておきます。

top:

top - 18:13:32 up  2:13,  1 user,  load average: 2.01, 0.84, 0.52
Tasks:  79 total,   1 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 74.0 us, 19.3 sy,  0.0 ni,  3.2 id,  0.2 wa,  0.0 hi,  3.4 si,  0.0 st
KiB Mem:   1022972 total,   944288 used,    78684 free,    23344 buffers
KiB Swap:        0 total,        0 used,        0 free.   462656 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 2908 isucon    20   0  640148 174444   8800 S 109.7 17.1   0:44.93 app
  720 mysql     20   0 1093212 212252  10740 S  58.5 20.7   1:56.57 mysqld

app が mysql の 2倍になり、クエリがネックじゃなくなったのがわかります。

スコア:

{"pass":true,"score":14208,"success":13157,"fail":0,"messages":[]}

myprofiler:

  36 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC
  15 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N
   5 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   4 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC

上位2件を見ると

  • posts からの SELECT に LIMIT が無い
  • comments.user_id にインデックスがない

LIMIT がないのはアプリ側で修正が必要なのと、ボトルネックがアプリに移ってるので、アプリ改修に移る。

comments.user_id はついでにインデックス張っておく。(1番重いクエリじゃないのでベンチは省略)

mysql> create index user_id on comments (user_id);
Query OK, 0 rows affected (0.14 sec)
Records: 0  Duplicates: 0  Warnings: 0

まとめ

スコア: 4745 (初期状態) -> 14208 (インデックスチューニング)

systemd のコマンドとか nginx の設定とか MySQL の設定ファイルを見るとかインデックス張るとかいろいろ慣れて、ここまではスムーズにできるようになりましょう。

感覚値ですが、一人でやってる場合はここまでを2時間以内には終わらせられるようにしましょう。1時間を切れればスゴイです。


@methane

songofacandy at 11:09|この記事のURLComments(0)TrackBack(0)
2015年05月01日

Go ではエラーを文字列比較する?という話について

はてなブックマークに登録

Go で関数の戻り値のエラーを判別するときに、エラーメッセージの文字列をチェックするコードが存在します。 ()

これは、 Go が言語設計としてエラー処理が貧弱だったり、標準ライブラリがエラー処理を軽視しているからでしょうか? 言語設計や標準ライブラリのAPIの設計をみて行きましょう。

TL;DR

  • 言語設計としては、Java的例外機構と同等以上の(文字列比較によらない)エラー検査が可能
  • ただし Go のエラーに関する哲学により、公開されていないエラーが多い
  • 実際にエラーを文字列比較されている実例についての解説

Go のエラー検査方法

Java の例外機構では、例外をキャッチするために専用の構文が用意されており、型によりマッチングすることができます。 これはクラスのツリー構造を利用してサブクラスをまとめて分岐することもできます。 一方で、同じクラスでも値によりエラー処理が異なる場合には、 try をネストしないといけないケースが有ります。

作為的な例ですが、例外が Errno クラスで、なおかつその errno が EINTR の場合はリトライし、それ以外のケースでは終了するコードはこうなります。

    try {
        while (true) {
            try {
                // ...
            } catch (Errno e) {
                if (e.getErrno() == Errno.EINTR) {
                    continue;
                }
                throw e;
            }
        }
    } catch (Exception e) {
        System.err.println(e.getMessage());
        System.exit(1);
    }

Go の場合、一般的にエラーは error というインターフェイスによって返されます。 Go にはエラー検査専用の構文はありませんが、インターフェイス一般に使える conversion 構文が Java の catch と同等以上の機能を持っているので、問題になりません。conversion には次の2種類の書き方があり、場面によって使い分けます。

    // シンプルな conversion.主に if 文と組み合わせて使う。型以外の条件式を if 文に書ける。
    if nerr, ok := err.(net.Error); ok && nerr.Temporary() {
        continue
    }

    // Type switch. 複数の型の振り分けを見やすく書ける
    switch e := err.(type) {
    case net.Error:
        if e.Temporary() {
            continue
        }
    // ...
    }

実際には複数のエラー型を扱うケースはあまりないのと、 io.EOF の様に型ではなく定数と比較するエラーがあるので、シンプルな conversion と if 文の組み合わせがよく使われます。

conversion は具体型だけでなく別の interface への変換も可能なので、 interface を抽象型として使うことで、 Java の例外階層と同じように複数の型のエラーをまとめて扱うことができます。例えば、 syscall.Errnonet.Error インターフェイスを実装しているので、先ほどのコードは次のようにより一般的に書くことができます。

    defer r.Close()
    for {
        data, err := r.Read()
        // 最後のデータを読み込みつつEOFが返る事があるので、エラーチェックよりdataチェックが先
        if len(data) > 0 {
            received <- data
        }
        if err == io.EOF {
            break
        }
        if err != nil {
            if nerr, ok := err.(net.Error); ok && nerr.Temporary() {
                continue
            }
            log.Error(err)
            break
        }
    }

Go のエラーに関する哲学

Go の作者の一人である Dave Cheney 氏のBlog に、Goのエラーに対する重要な哲学が紹介されています。

In the majority of cases, error values returned from functions should be opaque to the caller. That is to say, a test that error is nil indicates if the call succeeded or failed, and that’s all there is to it.

A small number of cases, generally revolving around interactions with the world outside your process, like network activity, require that the caller investigate the nature of the error to decide if it is reasonable to retry the operation.

訳:

ほとんどのケースにおいて、関数が返した error 値は呼び出し元にとって不透明であるべきです。 error が nil かどうかチェックすることで呼び出しが成功したかどうかを知ることができ、そしてそれ以上のことはできません。

少ないケースにおいて、主にネットワークなどプロセス外の世界とやりとりする場合に、呼び出し側がエラーの種別を調べて、操作をリトライするべきかどうかを決める必要があります。

この "error ... should be opaque to the caller" の部分は、後で紹介する issue でも Go の philosophy だと言及されています。 この Blog 記事は改めて翻訳したいと思いますが、要約すると次のような方針になっているようです。

  • 可能な限り個別の具体的なエラー型やエラー定数はパッケージ外に公開しない
  • エラー処理が必要な場合は、代わりに Timeout() boolTemporary() bool といった目的に応じたメソッドを定義する

この設計思想のために、特定のエラーを判別するためにエラーメッセージを文字列マッチするしか方法がないケースがあります。

Go で文字列でエラーを判別している実例

一番よく文字列比較されてしまっているエラーが、たぶん net.errClosing です。これは次のように非公開で定義されているエラー定数です。

	errClosing                = errors.New("use of closed network connection")

このエラーは、 Close された ListenerConnAccept(), Read(), Write(), Close() などのメソッドを呼び出した時に返されます。

このエラーは net パッケージ自身も戻り値として返す場合とテスト中でしか使われておらず、 if err == errClosing のような使い方はされていません。 このエラーを受け取った呼び出し側はができる回復処理は無いので、 "should be opaque" なのだと思います。

一方で、 Go はネットワークのブロッキングIOをランタイムで隠蔽してノンブロッキングIOのAPIを提供している言語なので、 Listener.Accept()Conn.Read() は呼び出し側をブロックします。これらのメソッドを利用するときは独立した goroutine を使います。そして Accept()Read() している goroutine を止める手段は、その ListenerConnClose() することです。一般的な設計のネットワークプログラムで、正常系として、 errClosing が返るのです。

errClosing のような回復不能なエラーが発生した時、一般的な後処理は、Connであればそのセッションを捨てる、Listener であればプログラム自体を止めることですが、その際にエラーをログに書くべきです。しかし、 errClosing のような正常系で発生するエラーをエラーログに書いていたら、より重要なエラーログが埋もれてしまいます。 Close() したあとの Accept()Read() のエラーを無視することもできますが、 Close() するのは別の goroutine なので面倒ですし、 errClosing 以外のエラーまで無視してしまう可能性がある気持ち悪さも残ります。

この errClosing を公開してほしいという Issue golang/go#4373 があり、エラーログに書きたくないというユースケースが投稿された結果、 Won't fix ラベルが解除されました。まだ修正されると決まったわけではありませんが、設計者の想定(回復できないエラーを個別に見せる必要がない)と実際のユースケース(このエラーはログに書きたくない)のミスマッチの一番の例だと思います。

go#4373 と関連する Issue として、golang/go#9405 もあります。 こちらは、 http クライアントをタイムアウト付きで利用した際に (Timeout() bool を実装していない) errClosing がそのまま返されてしまうという問題で、開発中の Go 1.5 では修正済みの問題なのですが、現在リリースされている Go 1.4 までではタイムアウトしたかどうかを判定するために errClosing の文字列比較が必要になってしまっています。

このように、決して多くは無いものの、設計者の想定していないユースケースやバグによりエラーを文字列比較で判定しているケースが残念ながら存在します。 ただし、あくまでもこれらは例外であって、 Go のエラー処理が弱いからエラーを文字列比較しないといけないといったようなことはなく、 Go の哲学は現実的にうまく機能していると思います。


@methane

songofacandy at 14:45|この記事のURLComments(0)TrackBack(0)
2015年02月18日

Goでアロケーションに気をつけたコードを書く方法

はてなブックマークに登録

GoはPythonのようなLLと比べると実行速度は速いのですが、GCは特別速いわけではないので、相対的にGCがパフォーマンスに与える影響は大きくなります。

また、Java に比べると、一時オブジェクトなどのために頻繁にヒープアロケーションを行うとGCの停止時間が長くなりがちですが、一方でヒープアロケーションを避けたプログラミングがしやすい言語でもあります。

MySQL ドライバのような低レイヤーのライブラリを作る場合、アプリケーション側の性能要件を勝手に決めることができないので、現実的な範囲でアロケーションを減らす努力をするべきです。

ということで、前回の記事 で紹介したプレースホルダ置換を実装するにあたって経験した、アロケーションに気を使ったプログラミングについて、チューニングする手順やコード上のテクニックを紹介したいと思います。

1. まずは正しく動くものを作る

go-sql-driver/mysql のメンテナに受け入れられるかどうか分からない機能だったので、最初はなるべく簡単に実装して、この機能を取り込むかどうか、APIや設計はこれでいいかという話から始めます。

2. ベンチマークプログラムを書く

チューニングを始める前に、効果確認用のベンチマークプログラムを書きます。 テストと同じく _test.go という名前で終わるファイルに、 BenchmarkXxxx(b *testing.B) という関数を定義します。その中で b.ReportAllocs() を呼んでおくとアロケート回数を計測することができます。

今回作成したベンチマークプログラムは次のようなものです。 database/sql がユーザーが渡した値を正規化してくれるので、ドライバ側に渡される値は int64, float64, bool, time.Time, []byte, string の6つの型だけになります。そこで6つの方の値を1つずつ用意して、プレースホルダ置換を実行しています。

func BenchmarkInterpolation(b *testing.B) {
	mc := &mysqlConn{
		cfg: &config{
			interpolateParams: true,
			loc:               time.UTC,
		},
		maxPacketAllowed: maxPacketSize,
		maxWriteSize:     maxPacketSize - 1,
	}

	args := []driver.Value{
		int64(42424242),
		float64(math.Pi),
		false,
		time.Unix(1423411542, 807015000),
		[]byte("bytes containing special chars ' \" \a \x00"),
		"string containing special chars ' \" \a \x00",
	}
	q := "SELECT ?, ?, ?, ?, ?, ?"

	b.ReportAllocs()
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		_, err := mc.interpolateParams(q, args)
		if err != nil {
			b.Fatal(err)
		}
	}
}

実行するには次のようなコマンドを実行します。

$ go test -bench=BenchmarkInterpolation
PASS
BenchmarkInterpolation	  300000	      3887 ns/op	    1144 B/op	      15 allocs/op
ok  	github.com/go-sql-driver/mysql	2.386s

3. アロケーションが起こっている場所を調べる

GODEBUG=allocfreetrace=1 という環境変数を設定すると、アロケートが起こった場所のスタックトレースを見ることができます。 (ドキュメント)

そこで、ベンチマークプログラムのループの中身だけを実行する小さなプログラムを用意したいのですが、今回用意しているのは小文字から始まる名前の内部処理なので、 main パッケージから直接呼び出すことはできません。 mysql パッケージにコミットに含めないソースファイルを追加してそこから呼び出せば良いのですが、今回はベンチマークプログラムを直接利用することにしました。

GODEBUG を設定したまま go test を実行するとノイズが多すぎるので、先に go test -c を使って mysql.test という実行ファイルを作り、それを実行します。その際、オプションは go test に渡すオプションに test. という prefix をつけることになります。

$ go test -c
$ GODEBUG=allocfreetrace=1 ./mysql.test -test.run=none -test.bench=BenchmarkInter -test.benchtime=10ms 2>trace.log
PASS
BenchmarkInterpolation      5000          4095 ns/op        1144 B/op         15 allocs/op

この例では、 -test.run にどのテストにもマッチしない適当な名前 none を指定してベンチマーク以外のテストが実行されることを防ぎ、 -test.bench で目的以外のベンチマーク関数の実行を抑止し、 -test.benchtime=10ms でデフォルト1秒のベンチマーク時間を短くしています。標準エラー出力にアロケートのスタックトレースが出力されているので、それを trace.log に出力しています。

目的の関数である interpolateParams を探し、それより手前を削除します。すると次のようなスタックトレースが得られます。

tracealloc(0xc2080100e0, 0x70, string)
goroutine 5 [running]:
runtime.mallocgc(0x70, 0x22e4e0, 0x0, 0x2)
	/usr/local/Cellar/go/1.4.1/libexec/src/runtime/malloc.go:327 +0x32a fp=0xc20802ea60 sp=0xc20802e9b0
runtime.newarray(0x22e4e0, 0x7, 0x15c5e)
	/usr/local/Cellar/go/1.4.1/libexec/src/runtime/malloc.go:365 +0xc1 fp=0xc20802ea98 sp=0xc20802ea60
runtime.makeslice(0x2229c0, 0x7, 0x7, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.4.1/libexec/src/runtime/slice.go:32 +0x15c fp=0xc20802eae0 sp=0xc20802ea98
strings.genSplit(0x30c190, 0x17, 0x2e1f10, 0x1, 0x0, 0x7, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.4.1/libexec/src/strings/strings.go:287 +0x14d fp=0xc20802eb60 sp=0xc20802eae0
strings.Split(0x30c190, 0x17, 0x2e1f10, 0x1, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.4.1/libexec/src/strings/strings.go:325 +0x76 fp=0xc20802ebb0 sp=0xc20802eb60
github.com/go-sql-driver/mysql.(*mysqlConn).interpolateParams(0xc20802eed0, 0x30c190, 0x17, 0xc20802ee70, 0x6, 0x6, 0x0, 0x0, 0x0, 0x0)
	/Users/inada-n/go1.4/src/github.com/go-sql-driver/mysql/connection.go:180 +0x86 fp=0xc20802ed38 sp=0xc20802ebb0
github.com/go-sql-driver/mysql.BenchmarkInterpolation(0xc20806a400)
	/Users/inada-n/go1.4/src/github.com/go-sql-driver/mysql/benchmark_test.go:240 +0x437 fp=0xc20802ef58 sp=0xc20802ed38
testing.(*B).runN(0xc20806a400, 0x1)
	/usr/local/Cellar/go/1.4.1/libexec/src/testing/benchmark.go:124 +0x95 fp=0xc20802ef68 sp=0xc20802ef58
testing.(*B).launch(0xc20806a400)
	/usr/local/Cellar/go/1.4.1/libexec/src/testing/benchmark.go:199 +0x78 fp=0xc20802efd8 sp=0xc20802ef68
runtime.goexit()
	/usr/local/Cellar/go/1.4.1/libexec/src/runtime/asm_amd64.s:2232 +0x1 fp=0xc20802efe0 sp=0xc20802efd8
created by testing.(*B).run
	/usr/local/Cellar/go/1.4.1/libexec/src/testing/benchmark.go:179 +0x3e

...(続く)

このスタックトレースで interpolateParams() から strings.Split() を呼び出している部分でアロケートが発生していることが分かります。 ソースコードのファイル名と行数も書かれているので、簡単に該当部分を特定できます。

func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (string, error) {
	chunks := strings.Split(query, "?")
	if len(chunks) != len(args)+1 {
		return "", driver.ErrSkip
	}

余談ですが、スタックトレースのような「たくさんの英数字」を見た時に、反射的に無視してエラーメッセージだけをコピペして質問する人をよく見かけます。確かに読むのに気力がいるかもしれませんが、スタックトレースはその言語やアプリケーションを深く知る重要な手がかりなので、デバッグ時やチューニングするときなどはしっかりと向きあいましょう。

4. チューニング

これで準備は万端です。あとは1つ1つ改善しながらで効果を確認していくだけです。とりあえず初期状態のベンチマーク結果を残しておきましょう。

$ go test -bench=BenchmarkInterpolation | tee old.txt
PASS
BenchmarkInterpolation	  500000	      3942 ns/op	    1144 B/op	      15 allocs/op
ok  	github.com/go-sql-driver/mysql	3.219s

4.1. 文字列連結から []byte への append へ

最初の実装は、クエリ文字列を ? で分割して、 parts []string に分割された各クエリ文字列と、パラメータを文字列化したものを交互に格納し ("SELECT SLEEP(0)", 42 なら []string{"SELECT SLEEP(", "42", ")"})、最後に strings.Join(parts, "") で結合するという、LLで書くようなコードでした。

Go の文字列は immutable なので、小さい文字列をたくさんつくるこの方式ではアロケートが増えるのを避けられません。そこで、最初に []byte のバッファを確保してそこに追記していくようにしました。

バッファの容量は先にクエリ文字列と各パラメータから概算して確保することで、リアロケーションを避けます。整数や実数は strconv.AppendInt() という、 []byte に追記しつつ文字列化する関数が標準ライブラリに用意されているのでそれを使います。これで次のようなコードになりました。

	buf := make([]byte, 0, estimated)
	argPos := 0

	// Go 1.5 will optimize range([]byte(string)) to skip allocation.
	for _, c := range []byte(query) {
		if c != '?' {
			buf = append(buf, c)
			continue
		}

		arg := args[argPos]
		argPos++

		if arg == nil {
			buf = append(buf, []byte("NULL")...)
			continue
		}

		switch v := arg.(type) {
		case int64:
			buf = strconv.AppendInt(buf, v, 10)

4.2. benchcmp

これで一旦効果を確認します。その際、 benchcmp というツールを使って比較し、それをコミットログに含めると Go のコミッタみたいでクールです。

$ go get -u golang.org/x/tools/cmd/benchcmp
$ go test -bench=BenchmarkInterpolation > new.txt
$ benchcmp old.txt new.txt
benchmark                  old ns/op     new ns/op     delta
BenchmarkInterpolation     3942          2573          -34.73%

benchmark                  old allocs     new allocs     delta
BenchmarkInterpolation     15             6              -60.00%

benchmark                  old bytes     new bytes     delta
BenchmarkInterpolation     1144          560           -51.05%

アロケート回数が 15 から 6 に減っているのが分かります。実行速度もメモリ消費も大幅に削減できていますね。

4.3. Time.Format() を避ける

int64 と float64 は strconv.AppendInt()strconv.AppendFloat() でそれぞれ []byte に追記することが出来ましたが、残念ながら time.Time にはそのようなメソッドがありません。 そこで、ベッタベタなコードで文字列表現を作ります。

before:

		case time.Time:
			if v.IsZero() {
				buf = append(buf, []byte("'0000-00-00'")...)
			} else {
				fmt := "'2006-01-02 15:04:05.999999'"
				if v.Nanosecond() == 0 {
					fmt = "'2006-01-02 15:04:05'"
				}
				s := v.In(mc.cfg.loc).Format(fmt)
				buf = append(buf, []byte(s)...)
			}

after:

		case time.Time:
			if v.IsZero() {
				buf = append(buf, "'0000-00-00'"...)
			} else {
				v := v.In(mc.cfg.loc)
				v = v.Add(time.Nanosecond * 500) // To round under microsecond
				year := v.Year()
				year100 := year / 100
				year1 := year % 100
				month := v.Month()
				day := v.Day()
				hour := v.Hour()
				minute := v.Minute()
				second := v.Second()
				micro := v.Nanosecond() / 1000

				buf = append(buf, []byte{
					'\'',
					digits10[year100], digits01[year100],
					digits10[year1], digits01[year1],
					'-',
					digits10[month], digits01[month],
					'-',
					digits10[day], digits01[day],
					' ',
					digits10[hour], digits01[hour],
					':',
					digits10[minute], digits01[minute],
					':',
					digits10[second], digits01[second],
				}...)

				if micro != 0 {
					micro10000 := micro / 10000
					micro100 := micro / 100 % 100
					micro1 := micro % 100
					buf = append(buf, []byte{
						'.',
						digits10[micro10000], digits01[micro10000],
						digits10[micro100], digits01[micro100],
						digits10[micro1], digits01[micro1],
					}...)
				}
				buf = append(buf, '\'')
			}

after は最終版のコードで、チューニング以外にマイクロ秒部分が0なら省略するなどの改善も入っています。 digits10, digits01 は除算を減らすために 0~99 の10の位と1の位の文字を並べたものです。これは今回用意したものではなくて既に mysql ドライバの他の箇所で利用されていた最適化を適用しました。

これでアロケートを2つ減らせました。

    benchmark                  old allocs     new allocs     delta
    BenchmarkInterpolation     6              4              -33.33%

4.4. 文字列に対して range を使わない

Go でループを使うときは良く range 構文を使うのですが、 string 型の s に対して for i, c := range s { とすると、バイト単位ではなく unicode の code point 単位でループしてしまいます。

for i, c := range([]byte(s)) { のように []byte にキャストしてループしていたのですが、ここで string から []byte への変換でアロケートとコピーが実行されてしまいます。 (Go 1.5 では最適化されます)

そこで、これを C 言語風の for 文に書き直します。

@@ -210,8 +210,8 @@ func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (strin
        buf := make([]byte, 0, estimated)
        argPos := 0

-       // Go 1.5 will optimize range([]byte(string)) to skip allocation.
-       for _, c := range []byte(query) {
+       for i := 0; i < len(query); i++ {
+               c := query[i]
                if c != '?' {

これでもう1つアロケートを減らすことができました。

    benchmark                  old allocs     new allocs     delta
    BenchmarkInterpolation     4              3              -25.00%

4.5. []byte に string を直接 append する

Go の append には、 []T 型のスライス ts に T 型の要素 t を1つ追加する ts = append(ts, t) と、別の []T 型のスライス ts2 を結合する ts = append(ts, ts2...) の2つの使い方があります。

ただし []byte に string を追記する場合については、 string が []byte 型であるかのように直接 append を利用することができます。 buff = append(buff, s...)

アロケートを避けるために 1 バイトずつ append していた部分を改良したり、文字列リテラルをキャストしながら append していた部分(最適化されて余計なアロケートとコピーは発生しない)を簡潔にする事ができました。

@@ -210,17 +210,19 @@ func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (strin
        argPos := 0

        for i := 0; i < len(query); i++ {
-               c := query[i]
-               if c != '?' {
-                       buf = append(buf, c)
-                       continue
+               q := strings.IndexByte(query[i:], '?')
+               if q == -1 {
+                       buf = append(buf, query[i:]...)
+                       break
                }
+               buf = append(buf, query[i:i+q]...)
+               i += q

                arg := args[argPos]
                argPos++

                if arg == nil {
-                       buf = append(buf, []byte("NULL")...)
+                       buf = append(buf, "NULL"...)
                        continue
                }

今回はこれでアロケートを避けられる部分は無かったですが、 []byte に append していくコードを書くときに覚えておきたい Tips でした。

4.6. []bytes 用の関数と string 用の関数を別に用意する

[]byte 型の引数と string 型の引数は両方同じようにクォート、エスケープします。 しかし、残念ながら Go は []byte と string の間の変換でアロケート&コピーが発生してしまいます。

最適化で除去されるのは buf = append(buf, []byte("NULL")...) のようなシンプルなケースだけで、 string を引数に取る関数に []bytestring(bs) でキャストして渡す場合やその逆のケースでは現在の Go では最適化されません。

そこで、全く同じエスケープ処理を行う関数を、 []byte を引数に取るバージョンと string を引数に取るバージョンの2つ用意します。 せめてループ内の switch だけでも共通化できないかと思いましたが、インライン展開を行うしきい値となる大きさを超えてしまうようで性能が落ちてしまったので、殆どコピペな2つの関数を用意することになりました。

これは実行するべきか迷ったのですが、クエリ文字列に比べて、パラメータに渡される文字列/バイト列は BLOB や TEXT 型の大きなデータである可能性があるので、速度・アロケート共に妥協しないことにしました。

コピペコードはもちろんメンテナンス性に悪影響を及ぼすので、これは最後の手段です。将来の Go のバージョンで何らかの回避手段が用意されることを期待します。

これで、アロケート回数が2つにまで減りました。

    benchmark                  old ns/op     new ns/op     delta
    BenchmarkInterpolation     2463          2118          -14.01%

    benchmark                  old allocs     new allocs     delta
    BenchmarkInterpolation     3              2              -33.33%

    benchmark                  old bytes     new bytes     delta
    BenchmarkInterpolation     496           448           -9.68%

4.7. 送受信バッファの再利用

最後に残った2つのアロケートは、最初にバッファを用意する部分と、最後に MySQL にコマンドを投げる関数に渡す文字列を作るためにバッファを string にキャストする2箇所です。

MySQL にコマンドを送信するときに利用している送信用のバッファに、パケットヘッダの部分を空けて直接クエリを生成することで最後の2つのアロケートも消すことができます。

しかし、既存のコマンドを送る部分の設計を汚してしまうのと、テストがしにくくなるので、直接パケットを作って送るのは自重しておいて、送信用のバッファをinterpolateに使えだけにしました。送信するパケットはクエリに4バイトのヘッダを付けたものなので、サイズ的にも再利用するのにぴったりです。

    benchmark                  old ns/op     new ns/op     delta
    BenchmarkInterpolation     1900          1403          -26.16%

    benchmark                  old allocs     new allocs     delta
    BenchmarkInterpolation     2              1              -50.00%

    benchmark                  old bytes     new bytes     delta
    BenchmarkInterpolation     448           160           -64.29%

まとめ

アロケート箇所を特定する方法や、主に文字列処理をチューニングする際に覚えておきたいコーディング上の Tips を紹介しました。


@methane

songofacandy at 16:07|この記事のURLComments(0)TrackBack(0)
2015年02月16日

go-sql-driver/mysql でプレースホルダ置換をサポートしました

はてなブックマークに登録

前回の記事で少し触れましたが、 go-sql-driver/mysql にドライバ側でのプレースホルダ置換を実装するプルリクエストを出していました。

それがマージされたので、背景のおさらいと利用方法を紹介しておきます。

背景

Go の database/sql の概要については前回の記事で解説しました。

そこで説明したとおり、 DB.Prepare() を使わずに直接 DB.Exec()DB.Query() を使った場合、 ドライバ側でのプレースホルダ置換に対応していないドライバでは prepare, exec, close で3回のラウンドトリップが発生することになり、パフォーマンスが悪くなります。

基本的には DB.Prepare() を使えばいいのですが、前回の記事で修正したスケーラビリティの問題は Go 1.5 になるまで直りませんし、 IN 句があるSQL文などで事前に Prepare するのが難しいケースも有ります。

また、O/Rマッパーやクエリビルダーを使う場合、そのライブラリが Prepared Statement のキャッシュに対応していないと、 アプリケーションプログラマが制御できない部分で DB.Prepare() を使わないで DB.Query() が使われるケースが出てきます。

ちょうど prepared statement をクエリの都度発行するデメリットが 幾つかの 場所で 話題になったこともあり、 go-sql-driver/mysql にオプションを付与する RFC (Request For Comment) だったプルリクエストがマージに向けて動き始めました。(マージされるまでに行ったチューニングについてはまた次回紹介しようと思います。)

go-sql-driver/mysql のプレースホルダ置換について

go-sql-drvier/mysqlgo get -u github.com/go-sql-driver/mysql で取得します。 まだこの機能はマージされたばかりなので、すでに利用されている方は再度このコマンドを実行して更新してください。

sql.Open() の第二引数に渡す dsl で interpolateParams=true というオプションをURLのクエリパラメタの形で渡すことにより、プレースホルダ置換が有効になります。 ただし、文字列をエスケープする際にバイト単位で処理しているので、 collation オプションで cp932big5 など危険なエンコーディングを指定した場合はエラーにしています。

(ちなみに、 go-sql-driver/mysql でコネクションのエンコーディングを指定する charset オプションは非推奨なので、 collation オプションを利用してください) collationは指定しない場合デフォルトで utf8_general_ci ですが、次の例では utf8mb4_bin に指定しています。

package main

import (
	"database/sql"
	"log"

	_ "github.com/go-sql-driver/mysql"
)

func main() {
	// localhost の 3306 番ポートで動いている MySQL に、ユーザー名=root, パスワード=password, データベース=test で接続する。
	// interpolateParams=true オプションを利用する。
	db, err := sql.Open("mysql", "root:password@tcp(localhost:3306)/test?interpolateParams=true&collation=utf8mb4_bin")
        // プレースホルダ置換を行わない場合はこちら
	//db, err := sql.Open("mysql", "root:password@tcp(localhost:3306)/test?collation=utf8mb4_bin")
	if err != nil {
		log.Fatal(err)
	}
	if _, err := db.Exec("SELECT SLEEP(?)", 42); err != nil {
		log.Fatal(err)
	}
}

このプログラムを実行してる時、別のセッションから SHOW FULL PROCESSLIST を実行すると、オプションの効果が確認できます。 interpolateParams=true を付けない場合は、次のように CommandExecute になり、 Info ではプレースホルダがそのまま表示されます。(とてもタイミングが良ければ、 Execute コマンドじゃなくて Prepare コマンドが見えるかもしれません)

mysql> show full processlist;
+------+------+-----------------+------+---------+------+------------+-----------------------+
| Id   | User | Host            | db   | Command | Time | State      | Info                  |
+------+------+-----------------+------+---------+------+------------+-----------------------+
| 7508 | root | localhost       | NULL | Query   |    0 | init       | show full processlist |
| 7511 | root | localhost:55283 | test | Execute |    2 | User sleep | SELECT SLEEP(?)       |
+------+------+-----------------+------+---------+------+------------+-----------------------+
2 rows in set (0.00 sec)

interpolateParams=true を付けた場合は、次のように CommandQuery になり、 Info でプレースホルダの部分に値が挿入されていることを確認できます。

mysql> show full processlist;
+----+------+-----------------+------+---------+------+------------+-----------------------+
| Id | User | Host            | db   | Command | Time | State      | Info                  |
+----+------+-----------------+------+---------+------+------------+-----------------------+
|  2 | root | localhost       | NULL | Query   |    0 | init       | show full processlist |
|  3 | root | localhost:49283 | test | Query   |    1 | User sleep | SELECT SLEEP(42)      |
+----+------+-----------------+------+---------+------+------------+-----------------------+
2 rows in set (0.00 sec)

文字列のエスケープでは、 sql_modeNO_BACKSLASH_ESCAPES を設定した場合にも対応しています。 次の結果は db.Exec("SELECT ?, SLEEP(?)", "Hel'lo\nWorld", 42) した時のものです。

mysql> SELECT @@GLOBAL.sql_mode;
+-----------------------------------------------------------------+
| @@GLOBAL.sql_mode                                               |
+-----------------------------------------------------------------+
| NO_BACKSLASH_ESCAPES,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION |
+-----------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> show full processlist;
+------+------+-----------------+------+---------+------+------------+-----------------------------------+
| Id   | User | Host            | db   | Command | Time | State      | Info                              |
+------+------+-----------------+------+---------+------+------------+-----------------------------------+
| 7515 | root | localhost       | NULL | Query   |    0 | init       | show full processlist             |
| 7517 | root | localhost:55400 | test | Query   |    2 | User sleep | SELECT 'Hel''lo
World', SLEEP(42) |
+------+------+-----------------+------+---------+------+------------+-----------------------------------+
2 rows in set (0.00 sec)

@methane

songofacandy at 12:58|この記事のURLComments(0)TrackBack(0)
2015年01月26日

Goのdatabase/sql.Stmtのスケーラビリティを改善しました

はてなブックマークに登録

先日、 Goに初めて私のパッチが取り込まれ 、コントリビュータに仲間入りしました。

このパッチは、 database/sql.Stmt をヘビーに使った時に性能がだいたい16コア以上のコア数にスケールしないという問題を解決するものです。 こういった問題をどうやって調査するのかと、Goにパッチが取り込まれるまでの手順を紹介します。

背景

私は TechEmpower の FrameworkBenchmarks という、いろんな言語/フレームワークで同一のアプリを作ってベンチマークするというプロジェクトで、主にPython関連のメンテナをしています。 Goにも興味があるので、Ginというフレームワークを追加したりコードレビューに参加したりしています。

2014-05-01 に行われた前回のベンチマーク Round 9 では、 PEAK Hosting が実行環境に加わりました。この環境は、デュアル Xeon E5-2660 v2 のマシンを 10Gbit Ethernet で接続するというハイスペックなものです。

この環境で、少し不思議な結果が出ていました。他の環境ではJavaやnginxベースの環境に続いて上位につけていた大量のGoのフレームワークが軒並み順位を落とし、Scala, node.js, php の軽量フレームワークにまで負けてしまっていたのです。

2014-11-02 に この問題を改善するプルリクエスト が登場しました。このプルリクエストは、 *sql.DB を複数作りラウンドロビンで利用することでロック競合を改善するというものでした。 私は当初この修正方法に反対でした。このプロジェクトは単にハイスコアを狙うためだけのものではなく、各フレームワークの 現実的な コードのサンプルと、その現実的なコードがどれくらいの性能を出すのかの参考値を多くの人に提供するためのものです。 *sql.DB を複数作るのは設計意図と異なり、あまり現実的なものには感じられませんでした。

database/sql の設計について

少し寄り道して、 database/sql の基本設計について説明します。 Go でデータベースを使うプログラムを書いた経験のある方はこのセクションは読み飛ばしてください。

database/sql は、 PHP でいう PDO のように、各種データベースへ接続するドライバの上に被さり、統一したインタフェースを提供します。例えば MySQL であれば go-sql-drivers/mysql が一番有名なドライバになります。ユーザーは基本的にはドライバを直接利用することはしません。

database/sql の中心になるのが sql.DB です。これはコネクションプールになっていて、以下のような使い方をします。

  1. DB.Exec()DB.Query() で直接クエリを投げる
  2. DB.Prepare() でプリペアドステートメントを表す Stmt オブジェクトを作り、 Stmt.Exec()Stmt.Query() を使う
  3. DB.Begin() でトランザクションを表す Tx オブジェクトを作り、 Tx.Exec()Tx.Query() を使う

トランザクションを使う場合は Tx オブジェクトが DB からチェックアウトしたコネクションを保持しますが、それ以外の場合は DB がプールしているコネクションのいずれかでクエリが実行され、ユーザーはコネクションを選ぶことができません。 (一部のカバーできていないユースケースに対応するため、 Go 1.5 ではトランザクションなしでコネクションをチェックアウトして使う API が追加される見込みです。)

1番の方法を使う場合、 DB.Query() はドライバがプレースホルダの置換に対応していない場合は内部で DB.Prepare(), Stmt.Exec(), Stmt.Close() を行います。1回のクエリで3回のラウンドトリップが発生するので性能的には不利になります。 go-sql-drivers/mysql もプレースホルダ置換に対応していない (対応するためのプルリクエスト を投げていて議論中です) ので、 2番の方法が一番性能が出ることになります。

2番の方法を利用する場合、 Stmt が各ドライバで prepare した結果と DB 内のコネクションとの対応を管理してくれるので、ユーザーはどの接続で Prepare をしたのかを気にする必要はありません。今回の問題はこの部分がネックになってきます。

このような設計になっているために、 DB 自体を複数持つのはイレギュラーな使い方で、1つのデータベースあたり1つの DB だけで性能がスケールするようにするのが理想です。

調査

まず、現象が発生している PEAK Hosting に近い環境を用意する必要があります。 AWS で c3.8xlarge のマシンを2台、拡張ネットワーキングを有効にして、同一の placement group に配置することで、32コアのマシンを10Gbitの安定したネットワークで接続した環境を用意することができます。 Amazon Linux AMI を使えば、デフォルトで拡張ネットワーキングが有効になっているので楽です。 スポットインスタンスを利用すれば、2台の c3.8xlarge はだいたい $0.7/h で借りることができます。

次に、ベンチマークをかけて問題が再現することを確認しつつ、 top コマンドでCPUの利用状況を確認します。 Mutex を使ったロックは、ロックをすぐに取得できた場合は低コストですが、競合した場合はそこそこCPUサイクルを消費します。 問題になっている Mutex が長時間ロックされている場合は、動作できるスレッドが減るのでCPU使用率が低くなり、短時間だけど非常に頻繁にロックされる場合はロックの競合の発生頻度が激しくなり、性能がコア数にスケールしてない割にはCPU使用率は高くなる傾向にあります。今回はどちらかというと後者だということが確認できました。

最後に、 net/http/pprof を利用して、原因を特定します。 net/http/pprof はCPUプロファイルをはじめ幾つかの診断機能がありますが、ロック競合で一番役に立つのは full stack dump です。実際のスタックダンプが こちら になります。

まず、多くの goroutine が止まっている Mutex.Lock() を見つけます。今回の場合は次のようなスタックトレースで止まっている場合が多いのがわかります。 ソースコードでは この部分 になります。

goroutine 81 [semacquire]:
sync.(*Mutex).Lock(0xc2080c42d0)
	/home/ec2-user/local/go/src/sync/mutex.go:66 +0xd3
database/sql.(*Stmt).connStmt(0xc2080c4280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/ec2-user/local/go/src/database/sql/sql.go:1357 +0xa6
database/sql.(*Stmt).Query(0xc2080c4280, 0xc2089a1be8, 0x1, 0x1, 0x0, 0x0, 0x0)
	/home/ec2-user/local/go/src/database/sql/sql.go:1438 +0x120

だいぶ原因に近づいてきましたが、まだこの部分が犯人だと断言することはできません。ロック競合は、ロックを取得する頻度とロックを持っている時間の掛け算が問題になるのに対して、スタックダンプでは頻度が多い部分が多く表示されるからです。 そこで、これと同じスタックダンプを除外した中から、この Stmt.mu のロックを持っているものを探します。すると次のスタックダンプが見つかります。

goroutine 158 [semacquire]:
sync.(*Mutex).Lock(0xc208096de0)
	/home/ec2-user/local/go/src/sync/mutex.go:66 +0xd3
database/sql.(*DB).connIfFree(0xc208096dc0, 0xc2083080c0, 0x0, 0x0, 0x0)
	/home/ec2-user/local/go/src/database/sql/sql.go:695 +0x67
database/sql.(*Stmt).connStmt(0xc2080c4280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/ec2-user/local/go/src/database/sql/sql.go:1378 +0x316

Stmt.mu をロックしているのは先ほどと同じ位置なのですが、その中で今度は DB.mu のロックを待っていることがわかります。 Stmt.connStmt()DB.connIfFree() のコードを読むと、 connStmt()Stmt.css (prepare 済みのコネクションと stmt のペアを管理しているリスト) に対してループしつつ、 connIfFree() を呼び出し、 connIfFree() が毎回 DB.mu をロックしているために、 DB.mu が高い頻度でロックされているのがわかります。しかし、この場所は Stmt.mu をロックしている1つの goroutine しか同時にこないので、他の場所の DB.mu のロックと競合しているようです。今度はスタックダンプのなかから、 DB.mu のロックを持ってるものを探します。すると、 DB.addDep() のロック競合に行き当たります。

# DB.mu を持っている DB.addDep
goroutine 18 [runnable]:
database/sql.(*DB).addDep(0xc208096dc0, 0x7f0932f0e4d8, 0xc2080c4280, 0x73d340, 0xc2082ec540)
	/home/ec2-user/local/go/src/database/sql/sql.go:362
database/sql.(*Stmt).Query(0xc2080c4280, 0xc2087cbbe8, 0x1, 0x1, 0x0, 0x0, 0x0)
	/home/ec2-user/local/go/src/database/sql/sql.go:1455 +0x49a

# DB.mu を待っている DB.addDep. これと同じスタックダンプが多数.
goroutine 64 [semacquire]:
sync.(*Mutex).Lock(0xc208096de0)
	/home/ec2-user/local/go/src/sync/mutex.go:66 +0xd3
database/sql.(*DB).addDep(0xc208096dc0, 0x7f0932f0e4d8, 0xc2080c4280, 0x73d340, 0xc2085f0540)
	/home/ec2-user/local/go/src/database/sql/sql.go:364 +0x38
database/sql.(*Stmt).Query(0xc2080c4280, 0xc20899fbe8, 0x1, 0x1, 0x0, 0x0, 0x0)
	/home/ec2-user/local/go/src/database/sql/sql.go:1455 +0x49a

これで問題の全体像が把握できました。

  • Stmt.connStmt() が(比較的)長時間 Stmt.mu をロックしているので、 Stmt があまりたくさん並列に動けない。
  • Stmt.connStmt() は繰り返し DB.connIfFree() を呼び出し、そこで DB.mu のロックが競合しているため遅くなる。
  • DB.mu のロック競合相手は DB.addDep()

解決策1: DB.mu を分離する

DB.addDep() を読んでみると、参照カウント方式でリソースを管理していて、最後にリソースの解放を行っているようです。 参照カウントと解放処理を管理するための map を守るために DB.mu をロックして排他していますが、これは独立した Mutex に分離できます。

DB.connIfFree()DB.mu がロック競合を起こさなければ十分に速くなる可能性があり、それなら振る舞いを一切変更せずに問題を解決することができます。

しかし、実際にロックを分離してみたところ、2割程度しか性能が改善せず、 DB 自体を複数持ってラウンドロビンするのに比べるとまだ性能がかなり悪いです。 DB.mu のロック競合を解決しても、 Stmt.connStmt()Stmt.mu をロックしている内側がまだ遅いので Stmt.mu のロック競合が解決されてないようです。

Mutex の分離はパッチを投げつつ、 Stmt.connStmt() の高速化に乗り出します。

解決策2: Stmt.connStmt() / DB.connIfFree() の高速化

Stmt.connStmt()Stmt.css に対してループで DB.connIfFree() を呼び出しているのですが、このループは prepare 済みの接続が空いていたらそれを利用するという目的と、 prepare 済みの接続が close されていたら Stmt.css から除去するという2つの目的があります。 しかし、接続が close されているかどうか、利用されているかどうかは、 DB.mu をロックしてさえいれば、 DB のメンバを参照しなくても高速に判定できます。

そこで、 Stmt.connStmt() の中の、 Stmt.css に対するループの外側で直接 DB.mu をロックしてしまい、なおかつ接続のチェックもループ内で直接行い DB.connIfFree() の呼び出しを減らす修正を行ったところ、今度は複数 DB のラウンドロビンと同じ程度の速度がでるようになりました。

こちらを本命としてまたパッチを投げます。 参考

Go にパッチを送り取り込まれるまで

とりあえず Go の Contribution Guideline を読みましょう。 以下かいつまんで説明します。

最初に Github Issue で修正の大まかな方針について合意をとっておきます。

修正を始める前に、 Google の CLA に署名しておきましょう。 参考

Goのリポジトリは最近 Mercurial から Git に移行しましたが、Githubに移行したわけではありません。 Github は Issue Tracker と、リポジトリのクローンに利用されています。オリジナルのリポジトリの場所は https://go.googlesource.com/go なので、 github から clone しているなら git upstream set-url などで origin の向き先を変える必要があります。

Go のコードレビューは Gerrit で行われています。ここにアクセスしてログインし、コマンドラインツールからパッチを投げるのに必要なパスワードを発行しておきます。

次に、 git-codereview というツールをインストールします。

go get -u golang.org/x/review/git-codereview

このツールは、パッチを1コミットのブランチという形で管理し、そのパッチを gerrit に送信するものです。 git に慣れた人向けに説明すると次のようになります。

  • git codereview change fix-abcgit checkout -b fix-abc 相当
  • git codereview change は、最初のコミットであれば git commit 相当、2回目以降は git commit --amend 相当. (commit と同じ -a が利用可能).
  • git codereview syncgit fetch origin && git rebase origin/master 相当
  • git codereview mail -diffgit diff HEAD..master 相当
  • git codereview mail で Gerrit にパッチを送る

パッチを投げるとレビューが始まります。 (Go の開発はとても活発で、元旦にパッチを投げたらその日のうちにコメントがついてびっくりしました)

  1. 大まかな設計
  2. コードの書き方、コミットログの書き方
  3. テストの書き方
  4. コメントの書き方

という感じで、レビューの注意点が移っていき、複数の Googler から繰り返しレビューを受けます。

レビューを通った感想

レビューの初期で、 prepare 済みの接続を優先して使うという処理自体を消すなど大幅にシンプルな設計になりました。 これは Github Issue の時点で提案されていた方針で、ちゃんとコメントを読んでおけばお互いに無駄な時間を省けたはずです。

テストについては、既存のベンチマークを簡単に修正していたのですが、平行性のベンチマークは RunParallel を使うように指摘されて、そのままたたき台として使えるようなサンプルをコメントしてもらいました。既存のファイルの上下がレガシーなら自分の修正部分もレガシーな書き方が許されるわけではないようです。

最後の方は、コメントを対象行の右に書くときは主語を省略していいけど、長くなって対象行の上に移動するならちゃんと主語から書き始めるとか、英語の構文、言い回しなど全然コードと関係ない指摘と修正の繰り返しでした。最終的に取り込まれるまでにパッチを送った回数は13回になりました。

ぶっちゃけて言えば、調査結果を詳細に Issue で報告するだけで止めておいて、実際の修正は Googler に任せてしまった方が、私だけでなくレビューする側も楽だったでしょう。それでも、複数の Googler から丁寧なコードレビューを受けるというのは貴重な経験でした。「あとはやっとくから」と言わず、最後までレビューに付き合ってもらって感謝しています。


@methane
songofacandy at 18:46|この記事のURLComments(0)TrackBack(0)
2014年09月03日

チャットで学ぶ Go ネットワークプログラミング

はてなブックマークに登録

簡単なチャットプログラムは、ネットワークプログラミング用のフレームワークでは定番のサンプルプログラムです。
echo サーバーが Hello World とするなら、チャットは FizzBuzz といったところでしょう。

とりあえず動くだけのチャットならだれでもすぐに作れるようになりますが、まじめにチャットを作ることで、 ネットワークプログラミングで考えないといけない点やエラー処理の重要な基礎を学ぶことができます。

ということで、 Go でシンプルなチャットを実装してみました。 (ソースコード)

以降、何を考えてどういう設計を採用したのかを解説していきます。

考慮すべきポイント

  • 特定のクライアントへの送信に長時間待たされた場合に、他のクライアントへの送信が遅れないようにする。
  • クライアントを切断するのは、 (1)ルーム側から kick する場合, (2)受信エラー, (3)送信エラー
    の3種類を考える必要がある。
  • 送信待ちのメッセージを無制限にバッファリングすると、メッセージを送信するだけで受信しないような
    クライアントがいるとメモリを使いきってしまうので、容易に DoS 攻撃が可能になってしまう。
    この場合メモリを使いきって OOM Killer が動くなどの被害を受ける。

Read のエラー処理

受信エラーだけでなく、送信エラーやサーバーからの kick などでも Read() している goroutine を止める必要があります。

Go の Read() は同期的な API になっているので、 select などを使って他の channel と並列に待つことはできません。 Read() 待ちの goroutine を止めるには、 Read() をエラーで停止させる必要があります。 net.Conn はスレッドセーフに作られているので、他の goroutine から conn.Close() を呼び出すことで Read() を止められます。

この場合、 Read() は io.EOF だけでなく、 closed connection から Read しようとしたという エラーも正常系で発生することになります。このエラーは io.EOF のように公開された変数が用意されて いるわけではありません。
ネットワークエラーだけをログに残したいと思うかもしれませんが、もともと Go の conn.Read() は 返すエラーの一覧を公開していないので、割りきって全て(あるいは EOF を除く全て)のエラーをログに残すようにしましょう。

他の goroutine から conn.Close() が呼ばれているかどうかを正確に判断する方法がないので、 client.Stop() を呼び出しておきます。この関数の処理は後述します。

func (c *Client) receiver() {
    defer c.Stop() // receiver が止まるときはかならず全体を止める.
    // 1行を512byteに制限する.
    reader := bufio.NewReaderSize(c.conn, 512)
    for {
        // Read() する goroutine を中断するのは難しい。
        // 外側で conn.Close() して、エラーで死ぬのが楽.
        // エラーは io.EOF であるとは限らない。
        msg, err := reader.ReadString(byte('\n'))
        if msg != "" {
            //log.Printf("receiver: Received %#v", msg)
            c.recv <- msg
        }
        if err != nil {
            log.Println("receiver: ", err)
            return
        }
    }
}

クライアントの切断処理

メッセージの送信中に他の goroutine から conn.Close() を呼び出すと 中途半端なメッセージを送る可能性があるので、 conn.Close() は送信 goroutine から行います。
そのために、 channel を利用して送信 goroutine に停止通知を行います。

今回のサンプルだと停止しないといけないのは送信 goroutine だけ (送信 goroutine が conn.Close() を呼ぶことで受信 goroutine も止まる)ですが、停止しないといけない goroutine が増えた場合にその分だけ channel を作らなければなりません。
また、クライアントの停止は複数の条件で、複数の goroutine から呼ばれる可能性があります。
停止通知に使うチャンネルへの送信がブロックするといけないので、次のようなコードになるでしょう。

type Client struct {
    // ...
    stopA chan bool,
    stopB chan bool,
    // ...
}

func newClient() *Client {
    c := &Client{
        //...
        // 1回はブロックせずに送信できるように、 buffered channel を使う.
        stopA: make(chan bool, 1),
        stopB: make(chan bool, 1),
        // ...
    }
    // ...
    return c
}

func (c *Client) Stop() {
    select {
    case c.stopA <- true:
    default:  // 既に停止メッセージを送信していてもブロックしない
    }
    select {
    case c.stopB <- true:
    default:
    }
    //...
}

これをもう少し楽にするために、 channel の close をメッセージ代わりに使います。
close() は同じチャンネルに対して複数回呼び出すと2回め以降は panic を起こすので、 recover を使って無視します。

func (c *Client) Stop() {
    // ちなみに defer recover() ではダメ
    defer func() {
        if r := recover(); r != nil {
            log.Println(r)
        }
    }()
    close(c.stop)
}

func (c *Client) sender() {
    defer func() {
        if err := c.conn.Close(); err != nil {
            log.Println(err)
        }
        log.Printf("%v is closed", c)
        clientWait.Done()  // graceful shutdown用. 後述
        c.closed <- c  // room のクライアント管理用. 後述
    }()
    for {
        select {
        case <-c.stop:
            //log.Println("sender: Received stop")
            return
        case msg := <-c.send:
            //log.Printf("sender: %#v", msg)
            _, err := c.conn.Write([]byte(msg))
            // net.Error.Temporary() をハンドルする必要は多分ない.
            // 書き込みできたバイト数が len(msg) より小さい場合は必ず err != nil なので、
            // Write() の第一戻り値は無視してエラーハンドリングだけを行う
            if err != nil {
                log.Println(err)
                return
            }
        }
    }
}

送信遅延の管理

受信側で1メッセージのサイズは制限しているので、送信待ちメッセージ数だけ制限すれば、 メモリを無制限に使うことは防げます。
送信 goroutine へメッセージを送る channel を buffered にすることで、 room goroutine からの送信を待たせないという効果も一緒に得られます。

バッファがいっぱいになった時に単にメッセージを drop すると、クライアントは何も知らずに 受信したメッセージが歯抜けになってしまうので、その場合はクライアントを切断します。

ただし、バッファがいっぱいになる条件はネットワークの送信が遅れた場合だけではありません。
CPUコアが1つしか無いのにたくさんのクライアントを扱う場合などに、メッセージの流量が多いと、 単に全てのクライアントの送信 goroutine に十分に実行権が行き渡ってないだけの可能性があります。

なので、バッファがいっぱいになった時に無制限に待つのは避けますが、固定時間は待つことにします。 goroutine の実行優先順位を制御できないので、あまりにクライアントが多いと待ち時間内に 待っているクライアントの送信 goroutine に実行権が与えられない可能性は残りますが、 それでも高負荷時の動作はかなり安定するはずです。

// Send msg to the client.
func (c *Client) Send(msg string) error {
    // 特定のクライアントが遅いときに、全体を遅くしたくないので、 select を使って
    // すぐに送信できない場合は諦める。
    // ただし、 room goroutine が sender goroutine より速く回ってるためにチャンネルの
    // バッファがいっぱいになってるだけの可能性もあるので、一定時間は待つ.
    // バッファに空きがあるときに時に time.After を生成するのは無駄なので、 select を2段にする.
    select {
    case c.send <- msg:
        return nil
    default:
        select {
        case c.send <- msg:
            return nil
        case <-time.After(time.Millisecond * 10):
            return errors.New("Can't send to client")
        }
    }
}

room のクライアント管理

ここまででクライアントの送受信部分はできてきましたが、クライアントが閉じた時に room 側が持ってる
クライアント一覧からも確実にそのクライアントを削除しないと、 channel が GC されずメモリリーク
してしまいます。

送信 goroutine で確実に conn.Close() を呼び出すようにしたので、そこで一緒に room に
メッセージを送るようにします。

room が持つ client 一覧は、 slice ではなく map にすることで、同時接続数が増えた時も
クライアント削除にかかる時間を一定にできます。

slice からの要素の削除は地味に罠があるので
(slice を縮めても背後の配列に参照が残ってるとGCされないのでリークするので縮める前に末尾へゼロ値を代入する必要がある)、
その点も delete() するだけで済む map の方が楽です。

func newRoom() *Room {
    r := &Room{
        Join:    make(chan *Client),
        Closed:  make(chan *Client),
        Recv:    make(chan string),
        Purge:   make(chan bool),
        Stop:    make(chan chan bool),
        clients: make(map[*Client]bool),
    }
    go r.run()
    return r
}

func (r *Room) run() {
    defer log.Println("Room closed.")
    for {
        select {
        case c := <-r.Join:
            log.Printf("Room: %v is joined", c)
            if err := r.sendLog(c); err != nil {
                log.Println(err)
                c.Stop()
            } else {
                r.clients[c] = true
            }
        case c := <-r.Closed: // c は停止済み.
            log.Printf("Room: %v has been closed", c)
            // delete は指定されたキーが無かったら何もしない
            delete(r.clients, c)
    /// ...
}

graceful shutdown

このチャットでは実装してませんが、例えばサーバー終了時に接続中のクライアントに終了メッセージを送信してから 接続を終了するといった仕様にしたくなる可能性もあります。 graceful shutdown の実装も練習してみましょう。

このチャットでは room を閉じてから、全クライアントの切断を待って、プロセスを終了するのが良さそうです。/> SIGINT (Ctrl-C で送られる) と SIGTERM (オプションなしの kill コマンドで送られる) で graceful shutdown しましょう。

go は main() 関数が終了すると、他にいくら goroutine が動いていてもプログラムが終了します。
なので、 main() 関数の最後で、シグナルを待って、 room に停止メッセージを送り、全クライアントの 切断を待つという処理を書きます。

クライアントの終了を待つのは sync.WaitGroup を利用するのが楽です。
クライアント生成時に wg.Add(1) を行い、送信 goroutine の conn.Close() 直後に wg.Done() を行い、 main 関数の最後では wg.Wait() を呼びます。

// main() の最後
    sigc := make(chan os.Signal, 1)
    signal.Notify(sigc, syscall.SIGUSR1, syscall.SIGTERM, os.Interrupt)
    for sig := range sigc {
        switch sig {
        case syscall.SIGUSR1:
            room.Purge <- true
        case syscall.SIGTERM, os.Interrupt:
            room.Stop <- true
            // 全ての client の sender を待つ
            clientWait.Wait()
            // おわり
            return
        }
    }
func (c *Client) sender() {
    defer func() {
        if err := c.conn.Close(); err != nil {
            log.Println(err)
        }
        log.Printf("%v is closed", c)
        clientWait.Done()
        c.closed <- c
    }()
//...

まとめ

チャットはシンプルに見えますが、送受信がバラバラに発生するので、リクエスト - レスポンス型のプログラムよりも 書くのが難しいです。
その分、チャットを正しく書けるようになれば、それ以外のサーバーの設計をするときに大いに参考になるはずです。

このプログラムは私なりに考えて設計したものですが、他の良いやり方を知っている・思いついた方は ぜひ教えてください。


@methane

songofacandy at 20:27|この記事のURLComments(0)TrackBack(0)
2013年03月14日

WebSocket アプリの負荷分散

はてなブックマークに登録

最近 SPDY と WebSocket がアツいですね。 再来週の SPDY & WS 勉強会 も、定員100名に対して 参加者が 247 名とかなりアツいことになっています。

その予習というわけでもないですが、最近 WebSocket を実サービスへの 導入方法を考えながら遊んでいたので、 WebSocket の負荷分散方法について 考えていることを書いておこうと思います。

ステートフルな WebSocket アプリケーション

HTTP サービスは基本的にステートレスな実装になっており、リクエストが来るたびに DBサーバーや memcached などのバックエンドから情報を取得して返していました。

この構成では Web アプリ自体は完全にステートレス化することができているので、 負荷分散機はラウンドロビン等のアプリケーションを無視した負荷分散をすることができました。

しかし、 WebSocket が登場してリアルタイム Web が普及し、それがリッチ化してくると、 ステートレス型では効率が悪くなる事があります。

たとえば複数のチャットルームを持つチャットアプリを作る場合、チャットの内容を Redis に格納し、 Redis の pubsub 機能を使って他の Web サーバーに更新を通知することができますが、 Redis は subscribe している Web サーバー全てに通知を送り、チャットログを取得するリクエストを さばかなければなりません.

MMO ゲームのようにアプリサーバーのメモリ上にチャットログを格納し、同じチャットルームにいる ユーザーが全員同じアプリサーバーに接続するようにすればどうでしょうか? アプリサーバーはバックエンドから通知を受け取ったりメッセージを取得しなくても全員に メッセージを配信できます。これならバックエンドとの通信はログを保存する1回で済みます。

正攻法でこの構成を組む場合、アプリをステートレスなフロントWebアプリとステートフルな バックエンドアプリの2段構成にすることができます。 でも、この程度ならリバースプロキシで直接リクエストの振り分けをやってしまったほうが 楽だし低コストですよね。

redis を使った動的な負荷分散

そこで、 redis に URL のパスごとに分散先を格納しておき、それを使って動的に リバースプロキシする構成を考えてみました。

効率や応答速度のことを考えたら、リバースプロキシは WebSocket のデコード&エンコードをする よりも、HTTP サーバーが Upgrade ヘッダを見つけると TCP プロキシとして動作するほうがいいはずです。

Go

最初に目をつけたのは Go です。nginx よりはコードを読み書きしやすいからです。 (node.js でも良いのですが個人的には JavaScript よりも Go の方が好きです)

Go の標準ライブラリ "net/http" にはそのものズバリな revserseproxy があります。 ただしこれは WebSocket に対応していないので、ちょっと改造して Upgrade ヘッダを見つけると TCP プロキシになる機能を追加しました。 (methane/rproxy)

あとは redigo という Redis クライアント(名前がカッコイイ!) と組み合わせればお手軽に賢いリバースプロキシの完成です。

nginx + lua

そういえば nginx も最近 WebSocket に対応したって話題になってたなーと思って調べてみると、 これも Upgrade ヘッダを見て TCP プロキシとしてふるまうようです。 さらに調べてみたら Redis + Lua を使って動的な負荷分散するサンプルもいくつかみつかりました。

ただし、 nginx のサブリクエストは基本的に HTTP 用であまり memcached や redis に格納した 生の文字列を扱うのに向いていないので、 lua-resty-redis という pure Lua のライブラリを使って書きなおしてみました。

これもちゃんと nginx の非同期機能を使ってくれるので Redis に問い合わせしている間 ブロックしたりはしませんし、コネクションプールも可能です。

せっかく作ったので Go 版を紹介したものの, nginx が使えるならもう nginx でいいですね。 でも、毎回 Redis に問い合わせるのではなく expire 付きの LRU キャッシュをインメモリでやるとか、 Socket.IO のセッションを解析して自分で Redis に格納するとか複雑なことをするなら Go の強みが生きてくるかもしれません。

サンプル

お待たせしました。サンプルはこちらになります。

KLab/websocket-reverseproxy-demo

このサンプルでは、 Tornado を使ったオンメモリで動くチャットアプリを2つのポートで立ち上げ、 Redis にチャットルームごとのバックエンドを格納した上で、 nginx と go によるリバースプロクシの動作を確認しています。

Go も nginx も開発版を使っているので少しハードルが高いかもしれませんが、 SPDY & WS 勉強会の 参加者はぜひ予習として試してみてください。


@methane
klab_gijutsu2 at 18:33|この記事のURLComments(2)TrackBack(0)
2012年03月29日

因縁の Google 独自言語対決! Go 1 vs PyPy

はてなブックマークに登録

エイプリルフールネタが思いつかないけど4/1は休日なんで問題ありません。 methane です。

とうとう ゴー のバージョン 1 がリリースされましたね。おめでとうございます。 まだRC2が出てからあまり時間が経ってない気がするのですが、パイソンにグーグル独自言語の称号を奪われそうになって慌てたのかもしれません。

前回のechoサーバー対決 から半年すこし経ったのですが、この間にどれくらい高速化したのか、早速ベンチマークをアップデートしました。

echoserver on github
Google Docs Spreadsheet

前回のスコアと比較してみると、 Go の r59 では

Throughput: 52087.16 [#/sec]
Throughput: 52070.02 [#/sec]
Throughput: 52068.27 [#/sec]
だったのが、 Go 1 では
Throughput: 55872.09 [#/sec]
Throughput: 55857.82 [#/sec]
Throughput: 55949.57 [#/sec]
と、順位に変動があるほどではありませんが、着実に速くなってます。一方、 PyPy 1.6では
Throughput: 79193.30 [#/sec]
Throughput: 81063.83 [#/sec]
Throughput: 81442.70 [#/sec]
だったのが、 PyPy 1.8 だと、、、
Throughput: 84852.55 [#/sec]
Throughput: 106760.88 [#/sec]
Throughput: 107032.43 [#/sec]

なんと、シングルスレッドのC++(epoll版)に迫る性能を叩き出すようになってます。

今回は Go と PyPy だけの更新ですが、夏までには軽量スレッド最速環境である Haskell の新しい Haskell Platform というディストリビューションが出ると思うので、それを待って全体的に更新したいと思います。


@methane
klab_gijutsu2 at 12:45|この記事のURLComments(0)TrackBack(0)
2010年06月18日

Twisted vs Tornado vs Go で非同期Webサーバー対決

はてなブックマークに登録

昨日の takada-at の記事で「サーバー側では単純に100ms待ってからレスポンスを返すだけのページを用意しておき、」とあったのですが、今日はそのサーバー側の話をします。

もともとこのサーバーを作った動機は、takada-at が作成中の負荷試験システムがちゃんと並列に負荷をかけられるかどうかを検証するためでした。 すぐにレスポンスを返してしまうと、負荷試験スクリプトがきちんと並列に負荷をかけられなくても PV/sec が出てしまいます。 そこで、 epoll を使って高速に並列接続を扱えるTwistedフレームワークを使って、100msの遅延をしつつ数千PV/secに耐えるWebサーバーを作ってみました。 さらに、同じく epoll を使っている Tornado や Go にも興味があったので、こちらでも同じものを作成し、パフォーマンスを比較してみました。

コード

まずは、コードを見てみましょう。

Twisted Python:

from twisted.internet import epollreactor
epollreactor.install()

from twisted.web import server, resource
from twisted.internet import reactor

class Lazy(resource.Resource):
    isLeaf = True
    def __init__(self, delay=0.1):
        self._delay = delay

    def render_GET(self, request):
        def after():
            request.write('Hello, World!')
            request.finish()
        reactor.callLater(self._delay, after)
        return server.NOT_DONE_YET

if __name__ == '__main__':
    import sys
    delay = 0.1
    try:
        delay = float(sys.argv[1]) / 1000
    except Exception:
        pass
    site = server.Site(Lazy(delay))
    reactor.listenTCP(8000, site)
    reactor.run()

次は、Tornadoです。

from tornado import httpserver, ioloop, web

from time import time

DELAY = 0.1

class MainHandler(web.RequestHandler):
    @web.asynchronous
    def get(self):
        def _hello():
            self.write("Hello, World!")
            self.finish()
        ioloop.IOLoop.instance().add_timeout(time() + DELAY, _hello)

application = web.Application([
    (r"/", MainHandler),
])

if __name__ == "__main__":
    import sys
    try:
        DELAY = float(sys.argv[1]) / 1000
    except Exception:
        pass
    http_server = httpserver.HTTPServer(application)
    http_server.listen(8001)
    ioloop.IOLoop.instance().start()

最後に、Goです。

package main

import (
    "flag"
    "http"
    "io"
    "log"
    "time"
    )

var addr = flag.String("addr", ":9000", "http service address")
var delay = flag.Int64("delay", 100, "response delay[ms]")

func main() {
    flag.Int64Var(delay, "d", 100, "response delay[ms]")
    flag.Parse()
    http.Handle("/", http.HandlerFunc(hello))
    err := http.ListenAndServe(*addr, nil)
    if err != nil {
        log.Exit("ListenAndServe:", err)
    }
}

func hello(c *http.Conn, req *http.Request) {
    time.Sleep(int64(1000000) * int64(*delay))
    io.WriteString(c, "Hello, World!\n")
}

TwistedやTornadoは、ループに後で呼び出す関数を登録していていて明らかにイベントドリブンフレームワークという感じがします。 それに対してGoは Sleep() を使っていて、一見普通のスレッドべースの並列処理に見えます。 しかし、Goはネイティブスレッドではなくgoroutineという軽量なユーザーランドスレッドを利用しており、そのスケジューラは(Linuxの場合)epollを利用しています。通常のスレッドを使うよりも効率的に動作するはずです。

ベンチマーク

それでは、この3つにそれぞれ負荷をかけてみましょう。といっても、100msの遅延だと負荷をかけるのが大変なので、10msの遅延で実行し、ab -c100 -n10000で実験してみます。

Twisted:
Requests per second:    2620.31 [#/sec] (mean)
Time per request:       38.163 [ms] (mean)
Time per request:       0.382 [ms] (mean, across all concurrent requests)

Percentage of the requests served within a certain time (ms)
  50%     31
  66%     32
  75%     33
  80%     37
  90%     38
  95%     38
  98%     40
  99%     44
 100%   3082 (longest request)


Tornado:
Requests per second:    5299.04 [#/sec] (mean)
Time per request:       18.871 [ms] (mean)
Time per request:       0.189 [ms] (mean, across all concurrent requests)

Percentage of the requests served within a certain time (ms)
  50%     19
  66%     19
  75%     19
  80%     19
  90%     19
  95%     19
  98%     21
  99%     22
 100%     33 (longest request)


Go:
Requests per second:    4712.63 [#/sec] (mean)
Time per request:       21.220 [ms] (mean)
Time per request:       0.212 [ms] (mean, across all concurrent requests)

Percentage of the requests served within a certain time (ms)
  50%     19
  66%     20
  75%     20
  80%     21
  90%     32
  95%     40
  98%     42
  99%     42
 100%     48 (longest request)

TornadoやGoに比べると、Twistedが残念な結果になっています。 これは、Twistedが比較的汎用的で高機能なフレームワークということもありますが、遅延実行する関数をリストに格納していて、実行する関数があるかどうかをリストを全部チェックしているのが大きそうです。(Tornadoはソート済みリストを利用していてます)

Goも、コンパイラ型なのにTornadoに負けてるのが残念ですが、epollから直接イベントドリブンしているTornadoに比べると goroutine という抽象化レイヤを1枚はさんでいるので仕方ないかもしれません。

さらに高速化

まずはTornadoのJITによる高速化に挑戦してみます。PyPy-1.2が一番よさそうですが、セットアップが面倒なのでお手軽なpsycoを使ってみました。もとのソースコードに、次の2行を追加します。

import psyco
psyco.full()

結果はこうなりました。

Requests per second:    7503.16 [#/sec] (mean)
Time per request:       13.328 [ms] (mean)
Time per request:       0.133 [ms] (mean, across all concurrent requests)

Percentage of the requests served within a certain time (ms)
  50%     13
  66%     13
  75%     14
  80%     14
  90%     14
  95%     14
  98%     15
  99%     15
 100%     23 (longest request)

5299req/sec => 7503req/sec で、20%以上高速化できました。topで見ている限り、メモリ使用量(RES)も1MB以下です。Tornado+psycoは非常に優秀ですね。

次に、Goでマルチスレッド化を試してみます。goroutineは複数のネイティブスレッドを利用して並列に動作することができます。しかし、現時点ではまだスケジューラがよくないらしく、デフォルトではマルチスレッドを使わないようになっています。環境変数 GOMAXPROCS に並列数を指定して実験してみました。

GOMAXPROCS=6 の場合:
Requests per second:    5760.33 [#/sec] (mean)
Time per request:       17.360 [ms] (mean)
Time per request:       0.174 [ms] (mean, across all concurrent requests)

Percentage of the requests served within a certain time (ms)
  50%     16
  66%     17
  75%     17
  80%     18
  90%     28
  95%     33
  98%     37
  99%     40
 100%     53 (longest request)

実験マシンはCore2 Duoで2コアしか載っていない(Hyper Threadingもなし)なのですが、2を指定してもあまり性能が上がらず、そこから1つずつ数字を上げていったところ6までは少しずつ性能が向上していきました。しかも、topを見ている限りCPU使用率は最大の200%には全く届かず120%以下しか利用できていません。 CPUを原因は判りませんが、今回のようなイベントループをヘビーに使う用途にはスケジューラが最適化されておらず、もっとサーバー側でCPUを利用する計算を行う処理をしないとマルチコアを使いきれないのかもしれません。

Goは今回のケースではTornadoに負けてしまいましたが、IO多重化をイベントドリブンよりシンプルに記述でき、コンパイル型言語なので複雑な計算をPythonより圧倒的に高速に計算できそうなので、非常に期待しています。


@methane
klab_gijutsu2 at 18:37|この記事のURLComments(0)TrackBack(0)
Blog内検索
Archives
このブログについて
DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在5ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。
最新コメント