Septeni Engineer's Blog

セプテーニエンジニアが綴る技術ブログ

isucon6予選をscala実装で挑戦

新卒1年目の東です。

個人的にハッカソンやコンテストに出るのが好きで、去年はisucon6予選にも挑戦しました。 結果は惨敗だったのですが、isucon6予選はアプリケーションにボトルネックが仕掛けられており、非常に勉強になるものでした。

isucon6予選の言語比率をながめてみると、scala2組だけです。(自分もチームで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. 処理の都度、DBのentryテーブルから全取得して正規表現を生成している
  2. 正規表現にマッチするキーワードの抽出とリンクへの置き換えを別々の反復で行っている

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()を実行することにします。 並列処理の時どうするのかとか考慮せずobjectvarを使ってたり、実務でやったら首をはねられそうなコードになってますが… 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で決勝進出者が出るといいなあ。