本番は、11:00~17:00が競技の時間で、12:00と15:00に30分ずつ、メンターに相談する時間があるという形でした。また問題はYahoo! JapanさんのGitHub - yahoojapan/yisucon: Yahoo! JAPAN の社内 ISUCON である Y!SUCON です。を使わせていただきました。

時系列ごとに振り返っていきたいと思います。

はじめの1時間

@takoseにgit管理やツールの導入などをしてもらっている間に、自分は

mysqlのスキーマやテーブル容量の確認
挙動確認、ソースコードの解説

に取り組むと決めていたのですが、2 に関しては、明確に何をするかまで決めていなかったことに加え、まだ計測ツール(myprofiler, rack-lineprof)を入れられていなかったので、ただコードを眺め、問題の特定までにいたらずに、無駄に時間を過ごしてしまいました。

入れる予定だったスロークエリログを確認するための

GitHub - KLab/myprofiler: Sampling profiler for MySQL

がバージョンの指定が間違っていたため、MariaDBをサポートしておらず、動かないというトラブルにも見舞われました。またの導入に関しては、他のチームも同様に苦しんだようで、しっかりとドキュメントを読んだチームは正しくバージョン指定を行い、使えていたようです。

このタイミングでまず計測ツールの導入を優先し、あたりをつけてからソースコードを読み始めるべきでした。

後日談として、該当の箇所に関して、PRを作成し、ドキュメントを更新しました。

github.com

学び:

目標は全て行動できるレベルまで落とし込んでおくこと
計測して、あたりをつけてから、動き出す。
わからない時は、ドキュメントと向き合う。REAMDEが完璧ではない可能性を疑う。OSSはみんなで良くしていくもの。

12:00~15:00

昼のメンターとの相談で、「計測を行い、ボトルネックを特定してから、作業すること」を伝えられ、

スロークエリログ
rack-lineprof

を入れ、問題のありそうな箇所を特定したので、二人で別々にアプローチでその箇所に取り組みました。

以下のコードの

get_all_tweetsの部分を@takose
get_user_nameを@yakamez

が取り組んでいました。

              |  75      get '/' do
  0.5ms     3 |  76        @name = get_user_name session[:userId]
              |  77        if @name.nil?
              |  78          @flush = session[:flush]
             .......
              |  83        url = URI.parse "#{ISUTOMO_ENDPOINT}/#{@name}"
              |  84        req = Net::HTTP::Get.new url.path
  1.8ms     1 |  85        res = Net::HTTP.start(url.host, url.port) do |http|
  1.5ms     1 |  86          http.request req
              |  87        end
  0.2ms     2 |  88        friends = JSON.parse(res.body)['friends']
              |  89
              |  90        friends_name = {}
              |  91        @tweets = []
226.1ms    92 |  92        get_all_tweets(params[:until]).each do |row|
              |  93          # todo(kame): htmlifyの中身を、redisに載せたらよさそう。
 10.6ms    90 |  94          row['html'] = htmlify row['text']
  0.4ms    90 |  95          row['time'] = row['created_at'].strftime '%F %T'
 15.1ms    85 |  96          friends_name[row['user_id']] ||= get_user_name row['user_id']
              |  97          row['name'] = friends_name[row['user_id']]
  0.7ms   140 |  98          @tweets.push row if friends.include? row['name']
              |  99          break if @tweets.length == PERPAGE
              |  100        end
             .......
              |  104        else
              |  105
  2.6ms     1 |  106          erb :index, layout: :layout
              |  107        end
              |  108      end

今思えば、最終的には一つの変更で解決すべき問題だったので、近い箇所を変更する際は、ペアプロをした方が良いなと思いました。

またこのタイミングでお互いの問題意識が以下のようにずれていたにも関わらず、すり合わせを行なっていなかったのも良くなかったと感じています。

お互いの認識: - ツイートを全件取ってきているのがよくない - ループの中で、DBを叩いているのがよくない

学び:

問題意識は適宜共有(近い時は、特に。)
変更してからではなく、問題意識の段階で、ぶつけて、相互にレビューを行う。

15:00-17:00

二人で別々に作業するものの、いまいち進捗をうめず、この時点でも初期スコアからあまり変わらない状態でした。

そこでメンターから近い箇所に取り組むのであれば、一緒に作業をした方が良いと伝えられ、

二人で問題について話し合い、お互いの理解のレベルを合わせること(理解や前提知識がずれていると、議論が進みにくい。)
さらに、解決策を一緒に話し合い、完全にお互いのやることを明確にした上で動き出すこと

という方針で問題に取り組み、さらに各々の作業が終わったら、片方は手を止め、ペアプロしながら、本番に入れていくという形で進めました。

これが非常にうまくいき、最後にスコアを1500から7000前後まで伸ばすことができました 🎉🎉 黄色い線が自分のチームです。1500->2500->5000->7000と1時間強でスコアを伸ばすことができました。

特に、ペアプロをした効果は大きく、お互いに補完しあいながら、素早く変更を加えることができました。

学び:

理解をすり合わせることは大切
ペアプロすごい

結果発表後

結果発表の後も、最後のベンチを走らせた時に大量に出ていたエラーが気になったので、メンター陣に相談しながら、原因を探ると、nginxのtoo many open filesが原因でした。そこでその問題を修正すると(nginx.confに一行追記)、なんとスコアが7000前後->22000まで一気に上がりました。

nginxのエラーログが/var/log/nginx/error.ogにはかれている事を知らずに、自分の力では原因の特定をする事はできなかったので、エラーを正しく確認できる状態を作っておくこと(エラーが出る場所の知識、正しくローテートする事)が大切だと痛感しました。

学び:

計測やエラーは問題解決のための大きなヒントになるので、正しく見れるようにしておく

振り返り・学んだこと

最終的には、 @euglena @okuyama チームがCTOを抑え、優勝でした。おめでとうございます🎉

全体を通して

競技の期間は、1日だけでしたが、準備も含めて、技術的にも、タスクへの取り組み方的にも学びの多い良い機会になりました。

以下は特に自分が重要だと感じたことです。

限られた時間の中で、優先度をつけて、取り組む重要性。
"推測するな、計測せよ" by @tomoasleep
失敗は適切に対処すれば、学びになり、次に活かすことができる。

最後に

特に、準備をしてくださった@south37さん、メンターをしてくださった@tomoasleepさん, @munisystemさんありがとうございました。来年の開催も楽しみにしています！

2019-05-06

ActiveRecord各メソッドのクエリ実行タイミングについて

概要

ActiveRecordの各検索メソッドが実際にクエリを投げ、データベースにアクセスするタイミングについて調べてみた。

書こうと思ったきっかけ

ActiveRecordのどの検索メソッドがDBへのリクエストを発行し、どの検索メソッドがActiveRecord::Relationのオブジェクトを返すのか不明だったので、改めて調べてみた。

結論

まずはじめに結論から書くと、以下の二種類のメソッドに大別される。

ActiveRecord::FinderMethodsに実装されているメソッド(find, find_by, take, first, last, exists?) すぐにクエリを発行し、データベースにアクセスし、レコード(Modelのインスタンス or インスタンスの配列)を返す。
それ以外の検索メソッド(where, limit, など) ActiveRecord::Relationのオブジェクトを返し、実際にデータが必要になるタイミングまでデータベースにはアクセスしない。遅延評価(Lazy Evaluation)である。

ドキュメント: ActiveRecord::FinderMethods

ソースコード: rails/finder_methods.rb at master · rails/rails · GitHub

そもそもActiveRecord::Relationとは？

クエリを生成するための情報を保持し、メソッドチェーンでつなげることができるため、再利用性が高く、便利なものになっている。一方で、理解して使わないと、意図していないクエリを組み立ててしまい、パフォーマンスの悪化などを招くこともある。

内部実装としては、arelというライブラリをSQLの生成に用いている(元々は外部のライブラリとして開発され、取り込まれた。)

具体例: はまりがちなトラップ

limitとtakeの使い分け

上でも述べたようにtakeはActiveRecord::FinderMethodsのメソッドであり、データベースにアクセスを行い、レコードを取得する。そのためlimitと同じようなものだと思って使うと誤った挙動を招くことがある。

rails consoleで実行してみると、limitはデータベースにアクセスをせず、takeはデータベースにアクセスをしていることがわかる。 (※メソッドの後に;をつけることで、即時評価されてしまうことを防いでいる。)

> Book.limit(3);
> Book.take(3);
  Book Load (0.5ms)  SELECT  "books".* FROM "books" LIMIT $1  [["LIMIT", 3]]

例えば以下のようなケースを考えてみる。 2019年4月1日以降に作成されたレコードを更新日時順が新しい順に1000件取得し、さらにそのレコードを分析したいという要件があった時、以下のように書くことで再利用性を高めることができ、limitメソッドを使っているため、実際に評価されるまで、クエリは実行されない。

rel  = Book.where('created_at > ?', "2019-04-01").order(created_at: :desc).limit(1000);

しかし、以下のようにtakeを使ってしまうと、その段階で内部でto_aされてしまうため、クエリが実行されてしまうのと、ActiveRecord::Relationではなくなってしまうため、メソッドチェーンが利用できなくなってしまう。

rel  = Book.where('created_at > ?', "2019-04-01").order(created_at: :desc).take(1000);

もちろん要件によっては、limitではなく、takeを使ったほうが正しいケースもあるが、両者の違いを認識して、正しく使う必要がある。

参考にした記事: - ActiveRecord::QueryMethods#limitとActiveRecord::FinderMethods#take - Qiita

(補足)takeのソースコード

find_take_with_limitの中で、to_aが呼ばれており、このタイミングで評価され、データベースにアクセスしていることがわかる。

    def take(limit = nil)
      limit ? find_take_with_limit(limit) : find_take
    end
(中略)
      def find_take_with_limit(limit)
        if loaded?
          records.take(limit)
        else
          limit(limit).to_a
        end
      end

Ref: rails/finder_methods.rb at master · rails/rails · GitHub

まとめ

ActiveRecordは便利だが、挙動を勘違いして使うと無駄なアクセスが走り、パフォーマンスを低下させる恐れがある。具体例に関しては、他にも例があげられそうなので、業務などで詰まることがあったら更新していきたい。

ActiveRecord周りの話はパフォーマンスにも大きな影響を与えるので、引き続き調べていきたい。調べていく過程で面白かった記事も紹介しておく。

railsdm2018で「ActiveRecordデータ処理アンチパターン」を発表しました - Hack Your Design! ActiveRecordであるあるなアンチパターンをまとめた発表。
第43回 Rails 3を支える名脇役たちその1 - Arel -：Ruby Freaks Lounge｜gihyo.jp … 技術評論社
ActiveRecordを支える技術 - Arelとは何者なのか? (全5回) その1 - TIM Labs ActiveRecord::Relationのクエリ生成を司るArelに関してまとめた記事。
RailsのActiveRecord::FinderMethodsのSQLクエリ発行の有無について調べる - Qiita 今回の記事で取り上げたfinde_methodsのメソッドに関して、詳細にまとめてある記事。

ykamezの技術ブログ

日々学んだことをアウトプットしていきます。Ruby/Rails/グロース/分析/施策提案

大切なことは全て新卒ISUCONが教えてくれた

はじめに

新卒ISUCONまでに準備したこと

本番の流れ