新卒1年目の東です。
個人的にハッカソンやコンテストに出るのが好きで、去年はisucon6予選にも挑戦しました。 結果は惨敗だったのですが、isucon6予選はアプリケーションにボトルネックが仕掛けられており、非常に勉強になるものでした。
isucon6予選の言語比率をながめてみると、scalaは2組だけです。(自分もチームでruby使いましたが)
isuconにscalaで取り組む人への手助けになればと思い、scalaでisucon6予選を初期状態から少し改善するまでを記事にしてみます。
isucon6予選環境の構築 ~ scalaの初期スコア計測まで
vagrantで初期環境構築
これまでのisucon問題をvagrantで構築できるようまとめてくださっています。 本来はazureでVMインスタンスを用意し、ansibleを流して構築する必要があるのですが、今回はこちらを利用して進めていきます。
matsuu/vagrant-isucon
https://github.com/matsuu/vagrant-isucon
今回はisucon6-qualifier-standaloneを利用します。
計測用ツールの導入
isuconといえばスロークエリやアクセスログの解析、プロファイラを利用したりCPU・メモリ状況を観測してボトルネックを発見する、という部分に結構面白さがあります。 このツール群については既に色々な方が触れていると思うので、参考程度に自分が利用しているツールを挙げておきます。
pt-query-digest: スロークエリ解析
https://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html
alp: アクセスログ解析
https://github.com/tkuchiki/alp
その他、vmstat・sysstat・dstat・topなどを適宜
scala実装への切り替えとスコア計測
今回の初期実装はperlで動作しており、systemdで管理されています。 scala実装に切り替えた上で初期スコアを計測してみます。
$ systemctl disable isuda.perl.service isutar.perl.service $ systemctl enable isuda.scala.service isutar.scala.service
今回はisuda, isutarという2種類のサービスによって構成されているようです。
一旦vagrant reloadをかけた上で、ベンチマークをかけてみます。
$ ./isucon6q-bench -target http://127.0.0.1
2017/01/03 12:07:57 start pre-checking
2017/01/03 12:08:20 pre-check finished and start main benchmarking
2017/01/03 12:08:57 benchmarking finished
{"pass":true,"score":0,"success":121,"fail":57,"messages":["リクエストがタイムアウトしました (GET /)","リクエストがタイムアウトしました (GET /keyword/2089年)","リクエストがタイムアウトしました (GET /keyword/684年)","リクエストがタイムアウトしました (GET /keyword/イギリス政府)","リクエストがタイムアウトしました (GET /keyword/ウーズ)","リクエストがタイムアウトしました (GET /keyword/ジェイアールバス東北大湊営業所)","リクエストがタイムアウトしました (GET /keyword/ナンバーディスプレイ)","リクエストがタイムアウトしました (GET /keyword/フーリエ)","リクエストがタイムアウトしました (GET /keyword/印旛村)","リクエストがタイムアウトしました (GET /keyword/巨大基数)","リクエストがタイムアウトしました (GET /keyword/神戸国際会館)","リクエストがタイムアウトしました (POST /keyword)","リクエストがタイムアウトしました (POST /login)"]}
初期スコアは0のようです。めげずに改善していきましょう。
ボトルネックを改善し、スコア0から脱出
ボトルネックを特定する準備
ベンチマーク実行中のtopを眺めてみます。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2607 isucon 20 0 2990956 504256 19876 S 169.7 24.6 3:40.39 java 2606 isucon 20 0 2942064 274508 18500 S 52.2 13.4 0:40.19 java 1282 isucon 20 0 118136 10372 5752 S 2.3 0.5 0:02.61 isupam 2793 root 20 0 139580 87804 7184 S 1.0 4.3 0:01.60 isucon6q-bench 1348 mysql 20 0 1543880 230616 16944 S 0.7 11.3 0:05.30 mysqld
topの時点ではざっくりとしかわからないのですが、javaプロセスのCPU使用率が高いことからアプリケーションにボトルネックがあることが推測されます。
次にalpを用いてアクセス解析を行っていきます。
$ alp -f /var/log/access.log --aggregates "/keyword/*" -r +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+ | 18 | 1.421 | 15.005 | 187.433 | 10.413 | 1.421 | 15.000 | 15.005 | 6.163 | 0.000 | 44556.000 | 94325.000 | 5240.278 | GET | /keyword/* | | 21 | 2.895 | 15.005 | 265.020 | 12.620 | 2.895 | 15.000 | 15.005 | 3.679 | 0.000 | 80358.000 | 523460.000 | 24926.667 | GET | / | | 71 | 0.139 | 3.006 | 167.744 | 2.363 | 0.139 | 3.000 | 3.005 | 1.065 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login | | 11 | 0.473 | 3.002 | 18.487 | 1.681 | 0.473 | 0.769 | 3.002 | 1.124 | 0.000 | 5.000 | 10.000 | 0.909 | POST | /keyword/* | | 19 | 0.207 | 0.616 | 7.287 | 0.384 | 0.207 | 0.321 | 0.606 | 0.139 | 106015.000 | 106015.000 | 2014285.000 | 106015.000 | GET | /css/bootstrap.min.css | | 10 | 0.115 | 0.600 | 3.258 | 0.326 | 0.115 | 0.289 | 0.445 | 0.145 | 16849.000 | 16849.000 | 168490.000 | 16849.000 | GET | /css/bootstrap-responsive.min.css | | 10 | 0.151 | 0.583 | 3.504 | 0.350 | 0.151 | 0.311 | 0.546 | 0.132 | 86351.000 | 86351.000 | 863510.000 | 86351.000 | GET | /js/jquery.min.js | | 10 | 0.212 | 0.558 | 3.429 | 0.343 | 0.212 | 0.319 | 0.437 | 0.102 | 28631.000 | 28631.000 | 286310.000 | 28631.000 | GET | /js/bootstrap.min.js | | 10 | 0.109 | 0.548 | 3.361 | 0.336 | 0.109 | 0.285 | 0.547 | 0.141 | 1092.000 | 1092.000 | 10920.000 | 1092.000 | GET | /favicon.ico | | 10 | 0.195 | 0.536 | 3.350 | 0.335 | 0.195 | 0.296 | 0.465 | 0.109 | 93.000 | 93.000 | 930.000 | 93.000 | GET | /img/star.gif | | 1 | 0.330 | 0.330 | 0.330 | 0.330 | 0.330 | 0.330 | 0.330 | 0.000 | 79.000 | 79.000 | 79.000 | 79.000 | GET | /css/main.css | | 1 | 0.213 | 0.213 | 0.213 | 0.213 | 0.213 | 0.213 | 0.213 | 0.000 | 695.000 | 695.000 | 695.000 | 695.000 | GET | /js/star.js | | 1 | 0.131 | 0.131 | 0.131 | 0.131 | 0.131 | 0.131 | 0.131 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | GET | /logout | | 1 | 0.121 | 0.121 | 0.121 | 0.121 | 0.121 | 0.121 | 0.121 | 0.000 | 15.000 | 15.000 | 15.000 | 15.000 | GET | /initialize | +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+
どうやら/と/keyword/*に時間がかかっているようです。
ボトルネックを特定する
では、実際にコードをみていきます。 上記までの流れで、アプリケーションのエンドポイント2つにボトルネックがある予想を立てているので、コード内に散見するその他の部分については考えずに読んでみます。
get("/")(withUserName { maybeUserName => /** * ページング処理やDBからのデータ取得 */ render("index", "user" -> maybeUserName, "entries" -> entries.map(e => Map("entry" -> e.toHash)), "pages" -> pages.map(p => Map( "page" -> p, "active" -> (p == page) )), "prev" -> Option(page - 1).filter(_ > 0), "next" -> Option(page + 1).filter(_ < lastPage) ) } ) get("/keyword/:keyword")(withUserName { maybeUserName => val result = for { /** * DBからのデータ取得 */ } yield render("keyword", "user" -> maybeUserName, "entry" -> entry.toHash ) result.merge )
上記の処理について、気になるのは標準ライブラリの処理ではない.toHashの部分です。
implicit class EntryOps(private val entry: Model.Entry) extends AnyVal { def toHash: Map[String, Any] = toJSON(entry).extract[Map[String, Any]] ++ Map( "url" -> s"/keyword/${entry.keyword.uriEncoded}", "html" -> htmlify(entry.description), "stars" -> loadStars(entry.keyword).map(s => Map("star" -> s)) ) }
.uriEncoded, htmlify(), loadStars()が改善対象になりそうです。
これらについて改善の優先度をつけるには、プロファイラを用いて処理時間の測定を行う必要があるのですが、プロファイラの導入がうまくいかなかったので…今回は保留にします。
isucon6予選経験者の方ならご存知だと思いますが、今回はhtmlify()をどう改善するかというのが肝になっていました。今回はhtmlify()を改善してみます。
ボトルネックを改善する
htmlify()の内容は以下の通りです。
def htmlify(content: String): String = { val entries = DB.readOnly { implicit session => sql""" SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC """.map(asEntry).list.apply() } val regex = entries.map(e => Pattern.quote(e.keyword)).mkString("(", "|", ")").r val hashBuilder = Map.newBuilder[String, String] val escaped = regex.replaceAllIn(content, m => { val kw = m.group(1) val hash = s"isuda_${sha1Hex(kw)}" hashBuilder += kw -> hash hash }).htmlEscaped hashBuilder.result.foldLeft(escaped) { case (content, (kw, hash)) => val url = s"/keyword/${kw.uriEncoded}" val link = s"""<a href="$url">${kw.htmlEscaped}</a>""" content.replaceAllLiterally(hash, link) }.replaceAllLiterally("\n", "<br />\n") }
htmlify()の処理は、与えられた文字列の中にDBに登録済みのキーワードがあった場合に、そのキーワードのページへのリンクを生成・置換する内容になっています。
この処理の問題点を考えてみます。
1について、メモリ上に載せてしまうのが良さそうです。scalaにはシングルトンを保証するobjectが用意されているので、以下のようなEntryRegexオブジェクトを実装します。
object EntryRegex { import Model.WrappedSetConvert private var value: String = "" def initialize(): Unit = { val entries = DB.readOnly { implicit session => sql""" SELECT * FROM entry """.map(_.toEntry).list.apply() } value = entries.map(e => Pattern.quote(e.keyword)).mkString("(", "|", ")") } def regex: Regex = value.r }
キーワードの追加・削除・更新があった時にどうするか？という問題が出てきますが、既存のDBへ処理をそのままに、都度initialize()を実行することにします。
並列処理の時どうするのかとか考慮せずobjectにvarを使ってたり、実務でやったら首をはねられそうなコードになってますが…
isuconなので時間もないですし、問題が起きてから考えればいいです。
1,2の改善後のhtmlify()は以下の通りです。
def htmlify(content: String): String = { val regex = EntryRegex.regex val hashBuilder = Map.newBuilder[String, String] regex.replaceAllIn(content.htmlEscaped, m => { val kw = m.group(1) val url = s"/keyword/${kw.uriEncoded}" val link = s"""<a href="$url">${kw.htmlEscaped}</a>""" link }).replaceAllLiterally("\n", "<br />\n") }
だいぶすっきりした気がしますが、実際の処理は改善されたでしょうか？ 再度、計測してみます。
$ ./isucon6q-bench -target http://127.0.0.1
2017/01/03 16:28:45 start pre-checking
2017/01/03 16:28:52 pre-check finished and start main benchmarking
2017/01/03 16:29:45 benchmarking finished
{"pass":true,"score":3154,"success":1198,"fail":1,"messages":["荒川道路 に 中部地方の道路一覧 へのリンクがありません (GET /)"]}
エラーが発生しているようですが、無事スコア0から脱出できました。 本番のインスタンスはvagrant環境より性能が良いので、この内容でももっとスコア出るんじゃないかと思います。
感想
2015年, 2016年とisuconに挑戦してきましたが、ベンチマークを回すまでミスに気がつきにくいのが辛い部分でした。(意図しないnullの混入など)
特に本番はベンチマークを外部から実行する形式のため、長いベンチマーク実行待ちの後にエラーが吐き出されるとそれだけで気力が吸われます。 単体テストが用意されていないisuconに対して、コンパイル時にある程度ミスを発見しつつガシガシ書けるのは嬉しさがあります。
2017年のisuconはscalaで決勝進出者が出るといいなあ。
