lxyuma BLOG

開発関係のメモ

isucon4予選やってきた

isucon

isucon4予選やった。

言語は、せっかくの機会なので勉強して、Goで。

初めのscoreは1223点で、

最終的に、26631点まで伸ばして、2日目の17位で終わった。

つまり、予選通過ならず、敗退してしまった。

ここまでやった事でlog等から思い出せるだけを記録に残す。

事前準備

  • 予選問題をやった
  • ネットにころがってる、有り難い記事を読んでた(LINEの夏期講習完全版とか、関係者のまとめとか)
  • isuconを良い機会に、golangの勉強した
  • 参加メンバーの役割分担した。(皆がやる事分からないと混乱するので、大体何をするべきかエクセルにまとめた)
    • 俺:Go + nginx + mysql + KVS + infra
    • Aさん:Go + mysql + score算出programチェック周り
    • Bさん:front(cache周り) + infra
    • この担当のイメージで、更に細かいタスクを分けて分担していた
  • gitbucket準備した
  • 一日の流れを決めた
    • 午前中に最低限のinstallと設定と各種指標の調査計測を行って、
    • お昼にTODOを効果とリスク書いて整理して、
    • 午後にTODOを効果順につぶしていく。
    • | TODO内容 | 効果 | リスク | 担当 | みたいな感じ

予定していた構成

  • 過去の問題から、こんなイメージをしていた
  • front
    • varnichかnginxでcache
    • ※今時のサイトは画像とか絶対あるし、frontのcache周りが重要になるような気がしていた。
  • backend
    • nginx + Go(unix domain socket繋ぐ)
    • ※今迄のように生Go(with gorilla)の想定で、なんとなく心の奥底でmartiniかgin出るよ〜と言われてる気がしていたが、封じ込めていた。
  • DB
    • mysql + memcached
    • ※KVSはmemcachedだろうと思ってた。これも心の奥底ではそろそろRedis出るよーと言われてる気がしたが、封じ込めてた。

実際の構成

  • 結局真っ裸でtableも少ないweb appliだった。
    • KVS入ってなくて(これは独自で入れた方が良かったが、結局、私たちは入れなかった)
    • goはmartiniだった。(今後、参考にさせてもらいます。)
    • あと、front周りは静的fileが非常に少なかった。これが分かっていた時点で、早く、皆でbackendに注力するべきだったなー。
    • 初めからnginxだった。apacheをnginxにするだけでscore稼ぎみたいな事は出来なかった。

当日の朝

  • score算出プログラムを読もうとしたが、見当たらない。go binaryだけ?っぽく断念。
  • supervisordでGoに切り替えるのだが、どうやら、うまくいかない。
    • 何だろうと思ったら、元々立ち上がってたrubyunicornがずっと立ち上がりっぱなしだった。どうやら、停止に失敗していた
    • なんか、supervisordのrestartの動きが怪しい。
    • 原因はともあれ、もうruby要らないので、killして、Goを立ち上げ直した。
    • 予選終わった後に、Q&A見てみると同じくsupervisordがruby終わらせてくれてなくて困ってる人いた。皆一緒。
  • nginxの設定空っぽだったので、とりあえず最低限の設定した
    • worker_procesとかworker_connectionとかgzipとかepolとかsendfileとかそういうヤツ
  • /etc/my.cnfも基本的な設定を実施。slow queryとか仕込んで、innotopとpercona tool入れた。
    • でも、結局、mysqldumpslow/show process listしか、まともに使ってないな、そういえば。

domain socket繋ぎ

  • httpやtcp経由でnginx繋いだりmysql繋いだりしてると、3way hand shakeやフロー/輻輳制御する分コストかかるので、unix domain socketに変えていった
  • ただ、localhost内での話なので、scoreへの貢献は少なかったかもしれない
  • Goからnginx とのdomain socket
  //http.ListenAndServe(":8080", m)

  l,err := net.Listen("unix", "/tmp/go.sock")
  if err != nil {
    fmt.Printf("%s\n", err)
    return
  }
  sigc := make(chan os.Signal, 1)
  signal.Notify(sigc, os.Interrupt, os.Kill, syscall.SIGTERM)
  go func(c chan os.Signal){
    sig := <- c
    log.Printf("Caught signal %s: shutting down.", sig)
    l.Close()
    os.Exit(0)
  }(sigc)

  err = http.Serve(l, m)
  if err != nil {
    panic(err)
  } 
  • nginx側もsocketに対しての権限が必要で、Go側で権限を変えるコード書いてみたが動かなかったので、結局、supervisordからGoを実行するUserをnginxユーザーに変えた(権限でどこかのdir等ひっかかると思ったら、それで特に問題なかった)
  • goから繋ぐmysqltcpunix domain socketに変更

benchトラブル

  • この辺りでbenchmarkプログラムからエラーが出るようになった

その1

 type:fail  reason:init script failed  log:exit status 1  message:Do not run benchmark
  • 何これ?
  • benchmarkで使ってるinit.shでエラーになってて、中身を見ると、単に外部からtsvをimportしてるだけだった
  • 結局、一度に大量のデータ送られて困っているようで、以下/etc/my.cnfに書いたら解決した
max_allowed_packet=300M

その2

  • 次にこんな事言われた
02:47:40 type:fail  reason:Get http://localhost/: dial tcp: lookup localhost: too many open files  method:GET  uri:/
  • 確かこれは、いろんな所でfile descriptor上げると解決したと思う

その3

  • その次に更にこんな事言われた
01:31:07 type:fail  reason:Connection timeout  method:GET  uri:/
  • (もしかしたら、違うログだったかもしれないが)確か、これは、nginxがhost書き換えていたとかで、アプリ側で許可してるIPから外れてしまってエラーになっていたヤツだったと思う。
  • nginxの設定を見直して解決

  • ここら辺でお昼くらいになってた。気付けば。

お昼

  • 一旦、サーバーをimageにして皆にmaster AMIとして共有した
  • gitbucketも準備していたが、結局、AMIの共有で連携していた
    • Master AMI作成して皆に共有
    • 各自はmaster AMIを元につくった自分のinstanceで作業。うまくいけば、本番にも同じ適用
    • この適用の時は一部gitbucket使ってたんだけど、んーー。必要だったかな?
  • front任せてた人からgzipかけない方が良いといわれ外してもらった
    • 今回のケースではstatic file少なく、gzipかける前後のsize差がないのに、変換costかかるからscore下がってるっぽかった。

index

  • めっちゃ、遅かったが、ようやくベンチも動いてGoやnginxの基本構成も出来ていたので、ここでmysqldumpslowで遅いquery特定した
    • 明らかにindex不足だった
    • 弊社代表する優秀なエンジニア!にfrontやcache周り任せていたのだが、今回のシチュエーションだと殆ど活躍する機会が皆無で勿体ないので(というか申し訳ないので)、このmysql index周りをお願いした
    • 結局、このindexが一番効いて、一気に1万の台に上がった
    • なんというか、逆にあまり決めないで臨機応変な体制にしても良かったかもしれない。。。(ただ、そうすると、色々ぶつかりそうだったり、漏れがあったり...どうだろう。何がいいんだろう)

n+1問題

  • 所謂n + 1問題(ORMでよくあるLoopで毎回SQL発行するやつ)も見事にあったので、おっしゃ俺やるぜ!と思って頑張った
  • まあ、sqlは一個にまとめてprogramに適用したが、scoreに反映されず、あれ、と思ったらそもそも、このsqlを使っているのは、ルール上scoreに換算されない所だった!!!
    • 見事に1時間くらい無駄にしてしまった><うーーん。。
    • これ、もし罠的な意図無ければ、product codeに入れずに、score算出プログラム側でやってほしかったなーと思ったり
    • そもそも俺がルールよくみないのがいけないですよね。これ実際の現場でもよくありますよね。仕様よくみないとね。
    • 反省。

計測

  • 初め見たときはCPUもmemoryもがら空き状態だった。
    • nginxのconnection数やらGOのruntime.GOMAXPROCS(runtime.NumCPU())やらやってもCPU食ってくれない
    • 結局、IO待ちが多くて、上のindex追加対応とマージするとCPUそこそこ使ってくれるようになった
    • とはいえ、それでも確か8割位でLoadAverageも一桁で、まだまだ使い切れそう
  • process はnginxが複数たってくれなかった。(1台で玉に2,3台でてくる程度)
    • これも、index追加対応でIO待ち解消すると、ちゃんと複数あがってくれた。
    • worker_process autoの時の話だが。あれ、そもそも、ここ、皆固定値入れてるの?
  • あと、memoryが、超がら空きだったのが勿体なかった
    • swapも当然ほとんど発生してない。
    • 余裕有ればKVS入れて、Count処理とかcacheしても良かったなー。
    • KVSといえば、今回のtable構成では、loginのtrackingしてる所があり、単純にinsertしてselectしてるだけなので、これをKVS(redisでsort済みとかね)に突っ込むのやりたかった。ただ、queryが割と柔軟に書かれていたので、この対応いちいち書き換えて行く作業時間が、残り時間に入るか不安で没に。

夕方

  • /etc/my.cnf見直しをエンジニアAに依頼。ここは何をやったかあまり見てない
  • あと、locked usersというreportも気になって見てもらった
    • 今回のアプリはinsertとselectだけで、アプリ側でトランザクションも貼ってないので、どこからもdbのロックかかりそうもない。
    • 調べてもらうとresponseが3sec以上かかったuser?とかだった? ※ちょっと自分は確認してないが
    • なぜ、こんな事起こるか、その時は謎だった。
    • 予選後、反省会で、この話あがり、おそらく、nginx+GOの大きな蛇口に対してmysqlの蛇口が低すぎたんじゃないか、という説がでた。mysql周りで溢れた分が処理しきれていない可能性があるかもしれない。my.cnfもうちょっとしっかり見れば良かった

benchmarkのエラー

  • index追加して、nginx+Goの多重化を整理すると、またbenchmarkのエラーが出てきた
type:fail      reason:Get http://localhost/: dial tcp 127.0.0.1:80: cannot assign requested address    method:GET      uri:/
  • これ、多分、多くの出場者がひっかかっていたのでは?(井戸端でも誰か書いてた)
  • 調べると、goのnet/httpのkeepalive周りの問題っぽい。 ※参考1/2
  • nginxでkeepalive接続をoffにしたら、このエラーでなくなった。
  • こういうのも、現場でよくありますよね。

benchmarkの調整

  • 最後にベンチマークのworkaroundを幾つか指定して適性値を探した。
    • コア数前後が良さそうだが、この時点でまだCPU使い切ってなかったので、ばんばん並列度合い上げてみた
    • 結局、8くらいまであげれた(それ以上あげてもscoreにあまり貢献しなかった)
    • そして、それでも、まだCPU/LoadAvg余裕あった
    • 上にも書いたが、次はmysqlの蛇口を開くべきだったなー。my.cnfの設定に移れば良かった。
    • 反省会で出た内容だが、そもそもmysql冗長化してしまっても良かった気がした。
  • ここら辺で2万くらいのscoreになってた

最後

  • ぎりぎりになって、table設計の怪しそうな所を変えて試したが、score貢献なかった(varchar をintに、tinyint(4)を1にとか)
  • あと、mysqlの余計なlogとかoffにしたり。
  • マージしてマージして、と言っていたが、結局マージ反映全然出来てなくて最後少しバタバタした(何故か終了前にssh繋がらないとか、、、)
  • 17:50くらいに最終score送信して、それで終了

感想

  • 振り返ると、なんか、benchmark周りのエラーを除くのばっかやっていたような印象。
  • メモリーが全然がら空きでmemcache/redisとか突っ込めば良かったなーと
  • あと、初めに担当決め過ぎると、責任感の意識が働いて柔軟に動けず逆に良くなかったなーと
  • なんか、17:50くらいで終わったので、皆で反省会やったけど、なんか暗い雰囲気になってしまったのも良くなかった!
    • 反省会はお酒飲みながら明るくやらないとね!
    • その後、hikarieのおしゃれなお店で酒飲みながら反省会しました。

次回

  • 次回も参加したいっす。