[FEATURE] Add option to return latency each feature adds to a query during feature logging

[adamjq]

Is your feature request related to a problem?

As a developer, I want to be able to debug the latency each feature adds to a query during feature logging.

This would help identify features which have an outsized impact on latency.

What solution would you like?

Note - the queries below are taken from a POC repo I created here.

Add a field similar to "time_in_nanos" to the feature logs in the SLTR query response when "profile": true, e.g.

"log_entry1": [
    {
      "name": "title_query",
      "value": 0.5442147,
      "time_in_nanos": 1020
    },

Request

GET http://localhost:9200/movies/_search
Content-Type: application/json

{
  "profile": true,  
  "query": {
      "bool": {
        "must": { 
            "match": {
                "title": "First"
            }
        },
        "filter" : [
            {
                "sltr" : {
                    "featureset" : "moviefeatureset",
                    "_name": "logged_featureset",
                    "active_features" : [ 
                        "title_query",
                        "description_query"
                    ],
                    "params": {
                        "query_text": "First"
                    }
                }
            }
        ]
      }
  },
  "ext": {
        "ltr_log": {
            "log_specs": {
                "name": "log_entry1",
                "named_query": "logged_featureset"
            }
        }
    }
}

Response:

{
  "took": 14,
  "timed_out": false,
  "_shards": {
    "total": 1,
    "successful": 1,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": {
      "value": 2,
      "relation": "eq"
    },
    "max_score": 0.5442147,
    "hits": [
      {
        "_index": "movies",
        "_id": "5lp2qY0BRnj6a9Pt_aCl",
        "_score": 0.5442147,
        "_source": {
          "title": "First Blood",
          "description": "First Blood is a 1982 American-Canadian action directed by Ted Kotcheff and co-written by and starring Sylvester Stallone as Vietnam War veteran John Rambo.",
          "year_released": 1982
        },
        "fields": {
          "_ltrlog": [
            {
              "log_entry1": [
                {
                  "name": "title_query",
                  "value": 0.5442147,
                  "time_in_nanos": 1020
                },
                {
                  "name": "description_query",
                  "value": 0.95960927,
                  "time_in_nanos": 8390
                }
              ]
            }
          ]
        },
        "matched_queries": [
          "logged_featureset"
        ]
      },
      {
        "_index": "movies",
        "_id": "6Fp3qY0BRnj6a9PtEaB7",
        "_score": 0.36928856,
        "_source": {
          "title": "Rambo: First Blood Part II",
          "description": "Rambo returns to the jungles of Vietnam on a mission to infiltrate an enemy base-camp and rescue the American POWs still held captive there.",
          "year_released": 1985
        },
        "fields": {
          "_ltrlog": [
            {
              "log_entry1": [
                {
                  "name": "title_query",
                  "value": 0.36928856,
                  "time_in_nanos": 3458
                },
                {
                  "name": "description_query"
                }
              ]
            }
          ]
        },
        "matched_queries": [
          "logged_featureset"
        ]
      }
    ]
  },
  "profile": {
    "shards": [
      {
        "id": "[a1wUq5DZToSLGmTEL04JXA][movies][0]",
        "inbound_network_time_in_millis": 0,
        "outbound_network_time_in_millis": 0,
        "searches": [
          {
            "query": [
              {
                "type": "BooleanQuery",
                "description": "+title:first #rankerquery:",
                "time_in_nanos": 346376,
                "breakdown": {
                  "set_min_competitive_score_count": 0,
                  "match_count": 0,
                  "shallow_advance_count": 0,
                  "set_min_competitive_score": 0,
                  "next_doc": 3000,
                  "match": 0,
                  "next_doc_count": 2,
                  "score_count": 2,
                  "compute_max_score_count": 0,
                  "compute_max_score": 0,
                  "advance": 5167,
                  "advance_count": 2,
                  "score": 4209,
                  "build_scorer_count": 5,
                  "create_weight": 195042,
                  "shallow_advance": 0,
                  "create_weight_count": 1,
                  "build_scorer": 138958
                },
                "children": [
                  {
                    "type": "TermQuery",
                    "description": "title:first",
                    "time_in_nanos": 231458,
                    "breakdown": {
                      "set_min_competitive_score_count": 0,
                      "match_count": 0,
                      "shallow_advance_count": 0,
                      "set_min_competitive_score": 0,
                      "next_doc": 0,
                      "match": 0,
                      "next_doc_count": 0,
                      "score_count": 2,
                      "compute_max_score_count": 0,
                      "compute_max_score": 0,
                      "advance": 3666,
                      "advance_count": 4,
                      "score": 2500,
                      "build_scorer_count": 7,
                      "create_weight": 178500,
                      "shallow_advance": 0,
                      "create_weight_count": 1,
                      "build_scorer": 46792
                    }
                  },
                  {
                    "type": "RankerQuery",
                    "description": "rankerquery:",
                    "time_in_nanos": 9624,
                    "breakdown": {
                      "set_min_competitive_score_count": 0,
                      "match_count": 0,
                      "shallow_advance_count": 0,
                      "set_min_competitive_score": 0,
                      "next_doc": 667,
                      "match": 0,
                      "next_doc_count": 2,
                      "score_count": 0,
                      "compute_max_score_count": 0,
                      "compute_max_score": 0,
                      "advance": 583,
                      "advance_count": 2,
                      "score": 0,
                      "build_scorer_count": 6,
                      "create_weight": 1625,
                      "shallow_advance": 0,
                      "create_weight_count": 1,
                      "build_scorer": 6749
                    }
                  }
                ]
              }
            ],
            "rewrite_time": 76125,
            "collector": [
              {
                "name": "SimpleTopScoreDocCollector",
                "reason": "search_top_hits",
                "time_in_nanos": 14374
              }
            ]
          }
        ],
        "aggregations": []
      }
    ]
  }
}

What alternatives have you considered?

This feature could also be implemented via an SLTR query parameter instead of through the profile API setting.

Do you have any additional context?

Please let me know if there are alternative ways to debug the latency each feature adds to a query during feature logging already using the plugin, as I couldn't find any references in the official documentation

[rishabhmaurya]

@noCharger Could you please take a look if this can be supported via LTR plugin, thanks.

[adamjq]

Thanks @noCharger. If you have any tips on how to profile latency for feature logging that would be great to hear too

[noCharger]

@adamjq By convention, I believe the profile API will include latency in the profile field rather than the hits field. If we want to record the logging, can we create a logging schema that includes both necessary and optional fields?

[JohannesDaniel]

@noCharger @adamjq

The value of this issue is not fully clear to me. The components of the sltr query that contribute to latency are the feature-related subqueries and the model execution (respectively prediction).

A regular query using sltr with "profile": true will include the latencies of the full re-ranking (RankerQuery), as well as the latencies of the subqueries. A query like

{
  "profile": "true", 
  "query": {
    "query_string": {
      "query": "title:rambo"
    }
  },
  "rescore": {
    "query": {
      "rescore_query": {
        "sltr": {
          "params": {
            "keywords": "rambo"
          },
          "model": "my_ranklib_model"
        }
      }
    }
  }
}

will return

{
  ...
  "profile": {
    "shards": [
      {
        "id": "[4uNofbnkSXKIqATg_DXrSw][movies][0]",
        "inbound_network_time_in_millis": 0,
        "outbound_network_time_in_millis": 0,
        "searches": [
          {
            "query": [
              {
                "type": "TermQuery",
                ...
              },
              {
                "type": "RankerQuery",
                "description": "rankerquery:",
                "time_in_nanos": 475327,
                "breakdown": {
                  "set_min_competitive_score_count": 0,
                  "match_count": 0,
                  "shallow_advance_count": 0,
                  "next_doc": 0,
                  "score_count": 3,
                  "compute_max_score_count": 0,
                  "advance": 10260,
                  "advance_count": 3,
                  "score": 88935,
                  "shallow_advance": 0,
                  "create_weight_count": 1,
                  "build_scorer": 121347,
                  "set_min_competitive_score": 0,
                  "match": 0,
                  "next_doc_count": 0,
                  "compute_max_score": 0,
                  "build_scorer_count": 2,
                  "create_weight": 254785
                },
                "children": [
                  {
                    "type": "TermQuery",
                    "description": "title:rambo",
                    "time_in_nanos": 330599,
                    "breakdown": {
                      "set_min_competitive_score_count": 0,
                      "match_count": 0,
                      "shallow_advance_count": 0,
                      "next_doc": 0,
                      "score_count": 3,
                      "compute_max_score_count": 0,
                      "advance": 3924,
                      "advance_count": 3,
                      "score": 4137,
                      "shallow_advance": 0,
                      "create_weight_count": 1,
                      "build_scorer": 99301,
                      "set_min_competitive_score": 0,
                      "match": 0,
                      "next_doc_count": 0,
                      "compute_max_score": 0,
                      "build_scorer_count": 2,
                      "create_weight": 223237
                    }
                  }
                ]
              }
            ],
            "rewrite_time": 48422,
            "collector": [
              {
                "name": "SimpleTopScoreDocCollector",
                "reason": "search_top_hits",
                "time_in_nanos": 55063
              }
            ]
          }
        ],
        "aggregations": []
      }
    ]
  }
}

The latency of the model should mostly depend on the model complexity (e.g. the number of trees) or size of the feature vector. So I think this rather needs to be considered as an attribute of the model rather than as an attribute of single features. The model latency then should be roughly the subtraction of RankerQuery latency minus the sum of latencies of the child queries. We could consider to measure the model latency to get more precise values and to simplify its evaluation, but I have not acknowledged so far whether or how it is possible to modify the profile output in a plugin.

[adamjq]

Thanks for the reply @JohannesDaniel. I was hoping to get better insights about the relative latency that each feature adds during feature logging, to understand if some features contribute more to latency than others, rather than the latency of the model during inference. I think we can mark this as not needed though if I can get that from the profile API