こんにちは。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