こんにちは。ZOZOテクノロジーズZOZOTOWN部 検索チーム 兼 ECプラットフォーム部 検索基盤チームの有村です。 ZOZOTOWNでは 先日公開した記事 の通り、すべての検索をElasticsearchへ置き換えました。置き換え直後は順調に見えたのですが、実際に数%ずつリリースしていく中で一部時間帯、一部リクエストでレスポンス速度の低下がみられました。 本記事ではその解決のために行ったパフォーマンス調査、チューニング方法についてご紹介します。なお、一般的に行われるであろうElasticsearch本体のパラメータチューニングの話ではなく、クエリやmapping、setting面の話がメインとなります。 改善前後の速度について 詳細な内容の前に、本改善によるレスポンス速度の最終的な改善結果を示します。 今回の計測では、一定パターンのリクエストを10秒間繰り返し、95%tileのレスポンス速度をp95、99%tileのレスポンス速度をp99と表しています。 p95 (sec) p99 (sec) 改善前 0.553 0.667 改善後 0.147 0.205 95%tileで 約276% の改善、99%tileで 約225% の改善となりました。 調査方法 環境 今回の検証は以下の環境で行いました。 ツール バージョン Elasticsearch 7.5.1 Kibana 7.5.1 Gatling 3.3.1 Search Profilerの使用 RDBMSのチューニングでは実行計画を見て適切なインデックス設計・クエリチューニングを行うように、今回はKibanaの Search Profiler を用いて検証を行いました。 Search ProfilerはElasticsearchの Profile API を可視化したものであり、具体的には以下の情報が取得可能です。 項目 詳細 create_weight 検索の最中にWeightを保持するオブジェクトの生成にかかる時間 build_scorer スコアラー(≠ドキュメントのスコア)オブジェクトの生成にかかる時間 next_doc マッチした次のドキュメントIDを返すのにかかった時間 advance next_docの内部でも呼ばれている、低レベルなイテレータの実行にかかった時間 match phrase queryのような、2フェーズ目の厳密なマッチの際にかかった時間 score スコアラーを用いて実際に特定のドキュメントをスコアリングした際にかかった時間 *_count 特定のメソッドの呼び出し回数 下記はKibanaをインストールした際にデフォルトで選択可能なSample eCommerce ordersデータセットを用いてプロファイリングしたサンプルです。 -- 検索リクエスト GET /kibana_sample_data_ecommerce/_search { " query ": { " bool ": { " filter ": [ { " term ": { " currency ": " EUR " } } , { " range ": { " products.base_price ": { " gte ": 50.00 } } } ] } } , " size ": 0 , " profile ": true } -- レスポンス { " took " : 29 , " timed_out " : false , " _shards " : { " total " : 1 , " successful " : 1 , " skipped " : 0 , " failed " : 0 } , " hits " : { " total " : { " value " : 2097 , " relation " : " eq " } , " max_score " : null , " hits " : [ ] } , " profile " : { " shards " : [ { " id " : " [8Xdz-7ZTSzyo4IAHkWSTsA][kibana_sample_data_ecommerce][0] ", " searches " : [ { " query " : [ { " type " : " BooleanQuery ", " description " : " #currency:EUR #products.base_price:[50.0 TO Infinity] ", " time_in_nanos " : 21453981 , " breakdown " : { " set_min_competitive_score_count " : 0 , " match_count " : 0 , " shallow_advance_count " : 0 , " set_min_competitive_score " : 0 , " next_doc " : 3014562 , " match " : 0 , " next_doc_count " : 2097 , " score_count " : 0 , " compute_max_score_count " : 0 , " compute_max_score " : 0 , " advance " : 848900 , " advance_count " : 7 , " score " : 0 , " build_scorer_count " : 14 , " create_weight " : 45100 , " shallow_advance " : 0 , " create_weight_count " : 1 , " build_scorer " : 17543300 } , " children " : [ { " type " : " TermQuery ", " description " : " currency:EUR ", " time_in_nanos " : 20980103 , " breakdown " : { " set_min_competitive_score_count " : 0 , " match_count " : 0 , " shallow_advance_count " : 0 , " set_min_competitive_score " : 0 , " next_doc " : 277970 , " match " : 0 , " next_doc_count " : 591 , " score_count " : 0 , " compute_max_score_count " : 0 , " compute_max_score " : 0 , " advance " : 7522992 , " advance_count " : 1828 , " score " : 0 , " build_scorer_count " : 21 , " create_weight " : 7400 , " shallow_advance " : 0 , " create_weight_count " : 1 , " build_scorer " : 13169300 } } , { " type " : " IndexOrDocValuesQuery ", " description " : " products.base_price:[50.0 TO Infinity] ", " time_in_nanos " : 4954816 , " breakdown " : { " set_min_competitive_score_count " : 0 , " match_count " : 0 , " shallow_advance_count " : 0 , " set_min_competitive_score " : 0 , " next_doc " : 683762 , " match " : 0 , " next_doc_count " : 1506 , " score_count " : 0 , " compute_max_score_count " : 0 , " compute_max_score " : 0 , " advance " : 217728 , " advance_count " : 598 , " score " : 0 , " build_scorer_count " : 21 , " create_weight " : 5800 , " shallow_advance " : 0 , " create_weight_count " : 1 , " build_scorer " : 4045400 } } ] } ] , " rewrite_time " : 6600 , " collector " : [ { " name " : " EarlyTerminatingCollector ", " reason " : " search_count ", " time_in_nanos " : 2358000 } ] } ] , " aggregations " : [ ] } ] } } これをKibanaのDev Tools内にあるSearch Profilerから可視化すると以下のような表示となります。 右側にあるView detailsをクリックすると、上に記載した詳細な項目が表示され、内部でどのような処理にどれだけ時間がかかるか可視化されます。 また、analyzerを適用したフィールドに対する検索をプロファイリングした場合、内部でどのように展開され、どれだけ時間がかかるか可視化されます。 -- マッピング PUT /kuromoji_sample { " mappings ": { " properties ": { " category ": { " type ": " keyword ", " fields ": { " kuromoji ": { " type ": " text ", " analyzer ": " kuromoji " } } } } } , " settings ": { " index ": { " analysis ": { " analyzer ": { " kuromoji ": { " type ": " custom ", " tokenizer ": " kuromoji_tokenizer " } } } } } } -- データ登録 POST /kuromoji_sample/_bulk { " index ": {} } { " category ": " 靴 " } { " index ": {} } { " category ": " かばん " } { " index ": {} } { " category ": " Tシャツ " } -- 検索 GET /kuromoji_sample/_search { " query ": { " match ": { " category.kuromoji " : " 通勤かばん " } } } 効果のあった変更点 Rangeクエリの丸め込み ZOZOTOWNでは発売日での絞り込みやタイムセールの制御など、検索の要所要所でdate型データに対する絞り込みを行っています。その際、Elasticsearchへのリクエストには現在時刻のタイムスタンプを用いていました。 { " query ": { " bool ": { " filter ": { " range ": { " order_date ": { " gte ": " 2020-08-20T09:01:12+00:00 " } } } } } } しかし、 Elasticsearch公式のドキュメント にもある通り、時刻によるフィルタリングはfilter cacheに載らないため、毎回絞り込みが行われ低速になる傾向がありました。 Tune for search speed を参照すると、丸め込まれた時刻指定のfilterクエリはfilter cache対象になる、との記載がありサイトとしての必要要件を確認する事になりました。その結果、発売日の絞り込みやその他イベントに関して1分単位の精度が確保できていればよく、必ずしも秒単位で考える必要がないと判明しました。 そこでリクエストを以下のような末尾に ||/m を付与し、明示的に丸め込んでいることがわかる形式に変更しました。 { " query ": { " bool ": { " filter ": { " range ": { " order_date ": { " gte ": " 2020-08-20T09:01:12+00:00||/m " } } } } } } p95 (sec) p99 (sec) 改善前 0.553 0.667 改善後 0.202 0.516 95%tileで 約174% の改善に対し、99%tileでは 約29% の改善に留まりました。 search_analyzerの使用 上記のRangeクエリの改善によって95%tileのレスポンス速度は改善しましたが、99%tileの改善度合いが思わしくなかったため、追加の改善案を模索しました。 この時点までは全体の最適化を行っていましたが、リクエスト単位に注目して深堀りしたところ、特定のリクエストが毎回遅くなっていることが判明しました。 その特定のリクエストは日本語によるキーワードが含まれるような検索リクエストで、かつZOZOTOWN独自で定義しているシノニム(類義語)が含まれるものでした。 そこで、前述のSearch Profilerを用いて内部でどの部分に時間を要しているのか確認したところ、シノニムによって展開されたキーワード分検索リクエストが走っている様子でした。 インデックスのマッピングは、以下の設定となっていました。 { " mappings ": { " properties ": { " category ": { " type ": " keyword ", " fields ": { " synonym ": { " type ": " text ", " analyzer ": " synonym_analyzer " } } } } } , " settings ": { " index ": { " analysis ": { " filter ": { " synonym_graph ": { " type ": " synonym_graph ", " synonyms ": [ " かばん, カバン, バッグ, 鞄 " ] } } , " analyzer ": { " synonym_analyzer ": { " type ": " custom ", " tokenizer ": " kuromoji_tokenizer ", " filter ": [ " synonym_graph " ] } , } } } } } デフォルトの設定では、検索時に使用されるアナライザと、インデキシング時に使用されるアナライザは同一のものが設定されます。そのため、上記の設定ではインデキシング時・検索時共にkuromojiとシノニムが適用されることになります。 一方、追加の設定として search_analyzer を設定することにより、インデキシング時と検索時で異なるアナライザを指定することも可能です。 { " mappings ": { " properties ": { " category ": { " type ": " keyword ", " fields ": { " synonym ": { " type ": " text ", " analyzer ": " synonym_analyzer ", " search_analyzer ": " kuromoji " } } } } } , " settings ": { " index ": { " analysis ": { " filter ": { " synonym_graph ": { " type ": " synonym_graph ", " synonyms ": [ " かばん, カバン, バッグ, 鞄 " ] } } , " analyzer ": { " synonym_analyzer ": { " type ": " custom ", " tokenizer ": " kuromoji_tokenizer ", " filter ": [ " synonym_graph " ] } , " kuromoji ": { " type ": " custom ", " tokenizer ": " kuromoji_tokenizer " } } } } } } このようにsearch_analyzerではシノニムの展開を行わない設定が可能ですが、この設定には以下のようなメリット・デメリットがあります。 メリット インデキシング時のみにシノニム展開するため、検索時の負荷が低減される デメリット 再インデックスしない限り、既存のドキュメントに対して類義語の更新が反映されない 詳しくはElastic社公式の 記事 で議論されていましたので、そちらをご覧ください。記事内ではデメリットとメリットを比較した結果、検索時にアナライザを適用する方向で収束していました。 しかし、弊社におけるユースケースでは以下のポイントから、インデキシング時に適用することとなりました。 インデキシングリクエスト数より検索リクエスト数が圧倒的に多いため、検索時のパフォーマンスを重視したい 日次で新規インデックスに対して全件インデキシングを行い、エイリアスを用いて検索先の管理を行っているため、類義語の更新に対して再インデックスを考える必要がない ドキュメントに対するマッチスコアを用いた評価を行っていない 実際に上記の設定を適用したうえで計測されたパフォーマンスは以下の通りとなります。 p95 (sec) p99 (sec) 改善前(オリジナル) 0.553 0.667 改善前(Range丸め込み) 0.202 0.516 改善後(Range丸め込み + search_analyzer) 0.147 0.205 Range丸め込み改修後と比較すると、95%tileで 約37% の改善、99%tileで 約152% の改善となりました。 Search Profilerで確認しても、検索時にシノニムが展開されていないことが確認できます。 効果のなかった変更点 max_result_window Elasticsearchのindexのsettingsに max_result_window という設定項目があり、これによって取得できる件数の制限が発生しています。 具体的には、検索時に指定する from と size の合計がmax_result_window以下でなくてはならず、超えた場合は query_phase_execution_exception が発生します。 弊社では初期設定時に max_result_window の値を内部のドキュメント数以上に設定し、制限なく検索が可能な状態にしていました。 { " mappings ": { ... } , " settings ": { " index ": { " max_result_window ": 100000 } , ... } } 一方で、 公式ドキュメント に記載がある通り、深いページングを行う際は (from + size) * number_of_shard 分のドキュメントを取得するためコストがかかります。 このオプション値の変更によって内部のパフォーマンスがどれ程変わるかは全く未知数でしたが、悪影響を与えていないかを確認するため検証を行うことにしました。 以下がその検証結果です。 p95 (sec) p99 (sec) max_result_window = 10,000,000 0.599 0.763 max_result_window = 10,000 0.580 0.653 95%tileでは約17%、99%tileで約3%の改善とあまり効果はありませんでした。 改善度合いに対して、一定数以上の検索に対する制限をかけてしまうデメリットが大きいと考え、今回採用は見送ることとなりました。 番外編 BulkのExceptionによるパフォーマンス影響 こちらは完全にデータの前処理が原因のミスでしたが、自分への戒めも兼ねて書き残します。 上記で解決した全体的なレスポンス速度低下の問題とは別に、1日の中で数十分ほど局所的にレスポンス速度の低下がみられました。 その際、具体的には以下のような症状が見られました。 レスポンス速度の低下(タイミングによっては、通常の数倍かかることも) /_nodes/stats から観測できるOld GCの増加 該当の時間にはドキュメントの一部を更新する処理が走っており、 _id 指定でbulk updateを行っていたのですが、多くのリクエストで更新対象がインデックス内に存在していませんでした。 Bulkで返ってくるレスポンスの実態は BulkResponse 、 BulkItemResponse ですが、この BulkItemResponse の挙動の差に原因がありました。通常アップデートに成功すると、この BulkItemResponse には DocWriteResponse 型のオブジェクトが格納されますが、失敗時には Failure 型のオブジェクトが格納されます。このオブジェクトにはメンバー変数として、例外の状態を示すオブジェクトが存在しており、 DocWriteResponse よりオブジェクトのサイズが大きいと考えられます。 またもう1つの要因として、Bulkの1リクエスト当たりのサイズを全バッチ共通の値でかなり大きめに設定していたことも関係していました。1フィールドだけを更新するシンプルなリクエストの場合、1リクエストで1万件以上の更新がかかっている状況でした。レスポンスは List<BulkItemResponse> として保持されているため、最大1万件以上分の BulkItemResponse が更新中メモリ上に居座ります。そのため、上記画像のような特定時間帯に集中したGCが発生し、局所的にリクエストが遅くなる状況となっていました。 検証 実際に今回のケースで発生していた DocumentMissingException と、成功時に生成される UpdateResponse を用いて、オブジェクトのサイズ比較を行いました。 また、1万件分を実際のレスポンスである BulkResponse に格納した際、差がどれほど出るかの検証も合わせて行いました。 public void test() throws IOException { int nbBulkItems = 10000 ; List<BulkItemResponse> succeedItems = new ArrayList<>(); List<BulkItemResponse> failureItems = new ArrayList<>(); UpdateResponse updateResponse = null ; Failure failure = null ; for ( int i = 0 ; i < nbBulkItems; i++) { updateResponse = new UpdateResponse( new ShardId( "index" , "index_uuid" , 0 ), "type" , "id" , - 2 , 0 , 0 , UPDATED); failure = new Failure( "index" , "type" , "id" , new DocumentMissingException( new ShardId( "index" , "index_uuid" , 0 ), "1" , "1" ), RestStatus.fromCode( 404 )); succeedItems.add( new BulkItemResponse(i, DocWriteRequest.OpType.UPDATE, updateResponse)); failureItems.add( new BulkItemResponse(i, DocWriteRequest.OpType.UPDATE, failure)); } BulkResponse succeedResponse = new BulkResponse(succeedItems.toArray( new BulkItemResponse[succeedItems.size()]), 0 , 0 ); BulkResponse failureResponse = new BulkResponse(failureItems.toArray( new BulkItemResponse[failureItems.size()]), 0 , 0 ); System.out.println( "SucceedResponse => " + RamUsageEstimator.sizeOf( new BulkItemResponse( 1 , DocWriteRequest.OpType.UPDATE, updateResponse))); System.out.println( "FailureResponse => " + RamUsageEstimator.sizeOf( new BulkItemResponse( 1 , DocWriteRequest.OpType.UPDATE, failure))); System.out.println( "SucceedResponse(10000) => " + RamUsageEstimator.sizeOf(succeedResponse)); System.out.println( "FailureResponse(10000) => " + RamUsageEstimator.sizeOf(failureResponse)); } 結果 ucceedResponse => 696 FailureResponse => 1392 SucceedResponse(10000) => 1960560 FailureResponse(10000) => 6840768 上記のような簡易的な検証でも、 BulkItemResponse 単体で2倍、1万件の BulkResponse では約3.5倍となっていることがわかりました。 解決策 解決策として以下の2つを試したところ、GC・レスポンス速度共に大幅な改善が見られました。 Bulkリクエストのサイズ縮小 DocumentMissingExceptionの回避(更新対象の再考) まとめ 本記事では、ZOZOTOWNの検索改善におけるクエリ、mapping、settingのパフォーマンス調査、チューニング方法について紹介しました。個人的にはSearch Profilerが特に気に入っており、SQLの実行プランと同じ感覚で実際に発行されるリクエストレベルの確認できるためとても勉強になります。 最後に、ZOZOテクノロジーズでは検索をさらに改善する検索エンジニアを募集しています。ご興味のある方は、以下のリンクからぜひご応募ください! tech.zozo.com 謝辞 本記事に含まれる検証の一部については、検索分野の技術顧問である 大谷氏(@johtani) による協力のもと行われました。また、テックブログの執筆に際してもレビュー・アドバイスを頂くなど、多大なるご協力を頂きましたことをこの場を借りて御礼申し上げます。