[RFC] Detecting search queries which have been cancelled but continues to run for long.

[sgup432]

Co-Author: @jainankitk

Problem Statement

As of now in OpenSearch, we have a best effort mechanism to cancel long running search queries via task cancel API POST _tasks/<task_id>/_cancel. We can refer this as soft cancellation as this mechanism works by setting a cancellable flag as true and then requires search thread to check on itself at regular intervals. As we have seen in the past, this mechanism doesn’t work all the time as there are some cases where search query continues to run in lucene tight loops and causes cluster instability.

While we eventually want to solve this problem by doing a "hard" cancellation, we first want to add a mechanism to detect such queries which were cancelled and still continues to run for a while. With the introduction of Search backpressure, there would be a lot of such cases and we need a mechanism to track them. This will also help us test the effectiveness of existing search cancellation, identify tight loops within OS/lucene and eventually build a case to hard cancel rogues queries.

Note: This problem deals with detecting cancelled queries at a shard level and not at coordinator level.

Solution

There are two parts to the solution.

1. First part comprises of detecting such long running cancelled queries.
2. Second part comprises of dumping such queries along with the stacktrace for later analysis.

We will only focus on the Part 1 for now.

Introduction of a new field in Task API to detect time elapsed for cancelled query

We will introduce a new variable as cancellationTime in CancellableTask. Every time a task is cancelled, we will capture this timestamp which will be later used to calculate time elapsed after this task was cancelled. We will also append this information in Tasks API by introducing a new field running_time_since_cancellation_nanos.

This will give us additional information to display such tasks especially for search.

"tasks" : {
    "oTUltX4IQMOUUVeiohTt8A:464" : {
    "node" : "oTUltX4IQMOUUVeiohTt8A",
    "id" : 464,
    "type" : "transport",
    "action" : "indices:data/read/search",
    "description" : "indices[test], types[test], search_type[QUERY_THEN_FETCH], source[{\"query\":...}]",
    "start_time_in_millis" : 1483478610008,
    "running_time_in_nanos" : 139913830000,
    "cancellable" : true,
    "cancelled" : true,
    "cancelled_at_millis": 1483479610008
    }
}

Separate monitoring thread to detect such queries

As part of this approach, we will have a monitor thread(out of generic threadpool) within opensearch running every Y seconds and extracting all such search tasks which have been running since X seconds after cancellation. Here Y << X.

In every such run, this monitoring thread will fetch all the current running search shard tasks using TaskResourceTrackingService::getResourceAwareTasks here. We will then filter out tasks which have been cancelled and have been running for more than X seconds using.

X ~ 10s - Reason to keep this value so that it is long enough to detect tight loops within OS/lucene and short enough to avoid missing long running queries after cancellation. Configurable.
Y ~ 5s - As X is 10s, keeping this 5 so that we don’t check too frequently and keeping enough buffer to incorporate execution time of detection. Configurable.

Below are the components that will be newly introduced:

SearchCancellationMonitoringService: This will run every Y seconds and fetch all current running searchShardTasks. And then filter tasks which have been cancelled and running since X seconds. Will store such tasks count in local variable.
SearchCancellationMonitoringStats: Maintains all stats related to search cancellation from above. Sample response for: _nodes/stats/search_cancellation

{
  "_nodes": {
    "total": 1,
    "successful": 1,
    "failed": 0
  },
  "cluster_name": "runTask",
  "nodes": {
    "T7aqO6zaQX-lt8XBWBYLsA": {
      "timestamp": 1667409521070,
      "name": "runTask-0",
      "transport_address": "127.0.0.1:9300",
      "host": "127.0.0.1",
      "ip": "127.0.0.1:9300",
      "roles": [],
      "attributes": {
        "testattr": "test",
        "shard_indexing_pressure_enabled": "true"
      },
      "search_cancellation": {
        "search_shard_task": {
          "post_cancellation_stats": {
             "current_query_count": 12,
             "total_query_count": 100
          }
        }
      }
    }
  }
}

Using above approach, we will have some insights on such queries. OS clients can also custom cron to call node/stats API to monitor such queries if required.

Future plan

We can eventually have a logic to dump such queries into log as well(Part 2). And a long term plan is to hard cancel such queries but requires more deep dive as there seems no easy way for now to do that.

Describe alternatives you've considered

• Only other way is to let OS clients build custom cron solution on top of Task API changes mentioned above and track such API's. But in case we want to extract/dump such rogue queries, it won't be possible using this.
• Using Search Backpressure Service to detect such queries. Search backpressure service runs after 1 second to identify potential tasks which are resource intensive and needs to be cancelled. We could have potentially used this to identify long running tasks. But it couples our logic with search backpressure. And we will have to use the same backpressure stats now which doesn't seem right.

Additional context
Add any other context or screenshots about the feature request here.

[sgup432]

@jainankitk @Bukhtawar @ketanv3 @nssuresh2007 @reta

[dblock]

How will this interact with slow log feature? https://opensearch.org/docs/1.2/opensearch/logs/#slow-logs

[sgup432]

How will this interact with slow log feature? https://opensearch.org/docs/1.2/opensearch/logs/#slow-logs

This is not meant to interact with slow log feature. As part of this proposal we only want to detect stats(count) around queries which were attempted for cancellation but still continues to run for a while. There is no way currently to do this. This will help us identify the effectiveness of search backpressure which internally tries to cancel queries. We might later plan to dump such queries along with stacktrace but not use slow log for this.

[dblock]

I guess I was asking a leading question. It feels to me that slow queries are the same thing as long running queries. In this proposal you're adding an API that returns information about long running queries, so can they also serve information about what is currently recorded as a slow query (and dumped in the logs)?

[sgup432]

I just changed the description to avoid confusion. Yes, slow logs are same as long running queries based on a defined threshold.
We are kind of capturing stats around long running queries only difference being that these were explicitly cancelled(manually or by search backpressure) and they still continue to run even after that(lets say 10secs).
Let me know if it makes sense.

[dblock]

@sgup432 I understand now.

I think I would prefer canceled_at_nanos to tell me when the task was cancelled (after how long the task was cancelled), rather than adding a field that is now - canceled_at_nanos. This would make the response stable over time and cacheable. Similarly, consider all kinds of post_cancellation_stats to be just stats that can return a stable response of, for example, what's still running. This makes the response stable before and after cancellation, which itself is just a boolean state.

[sgup432]

@dblock

Yeah adding cancelled_at_nanos does make sense. But I think we can also keep running_time_since_cancellation_nanos as it is easier to read similar to running_time_in_nanos. Let me know your thoughts.

Regarding post_cancellation_stats, do you mean to rename it to stats? If yes, then I wanted to explicitly call it such to be more clear to the user about what are we are showing. If not, can you elaborate with an example?

Also I would be correcting above stats to include current, total count. Total would help us to visualize it over time and compare with previous value.

"post_cancellation_stats": {
             "current_query_count": 12,
             "total_query_count": 100
          }

[dblock]

@dblock

Yeah adding cancelled_at_nanos does make sense. But I think we can also keep running_time_since_cancellation_nanos as it is easier to read similar to running_time_in_nanos. Let me know your thoughts.

This would be duplicate information (you can calculate running time from the timestamp), so that's another anti-pattern for an API. Return timestamps and let any UX consuming this data decide how to display it, including showing a duration. Speaking of displaying, getting this timestamp makes it possible to display a correct duration live without querying the API again.

Regarding post_cancellation_stats, do you mean to rename it to stats? If yes, then I wanted to explicitly call it such to be more clear to the user about what are we are showing. If not, can you elaborate with an example?

Yes, I mean renaming post_cancellation_stats to stats. You already have search_cancellation above. But more generally I don't think this API layout is generic enough.

How about a search stats API that includes cancelation stats? Something like this?

"search": {
   "search_shard_task": {
     "status": "cancelled",
     "created_at": ts,
     "cancelled_at": ts,
     "stats": {
         "pending_query_count": 12,
         "cancelled_query_count": 88,
          "total_query_count": 100
      }
   }
}

Also I would be correcting above stats to include current, total count. Total would help us to visualize it over time and compare with previous value.

"post_cancellation_stats": {
             "current_query_count": 12,
             "total_query_count": 100
          }

I am not sure I understand all kinds of query counts. What kids are there?

[sgup432]

@dblock

This would be duplicate information (you can calculate running time from the timestamp), so that's another anti-pattern for an API. Return timestamps and let any UX consuming this data decide how to display it, including showing a duration. Speaking of displaying, getting this timestamp makes it possible to display a correct duration live without querying the API again.

running_time_since_cancellation_nanos is indeed duplicate information which is calculated from cancelled start time but I still think it is important as usually this API is used by operator via command line, and to calculate running time, we will have to use some website/tool to calculate running time manually (current_time - start_time) which is a big disadvantage plus time consuming.

How about a search stats API that includes cancelation stats? Something like this?

We already have an existing search stats under indices stats something like below:

"indices": {
  "search": {
         "query_total" : 117284834,
          "query_time_in_millis" : 2309818328,
          "query_current" : 3,
          "fetch_total" : 47100569,
          "fetch_time_in_millis" : 76673528,
          "fetch_current" : 0
  }
}

So I don't think we should have duplicate search stats apart from this. And regarding updating this section with cancellation stats, that is also not possible as IndicesStats is maintained in memory by IndicesService. And I don't see anyway for our service(SearchCancellationMonitoringService) to update this search stats from outside.

Let me know if you have more suggestion. But as we are using a separate service to track such queries, we will need to create a new stats section specific to this use case.

I am not sure I understand all kinds of query counts. What kids are there?

"post_cancellation_stats": {
             "current_query_count": 12,
             "total_query_count": 100
          }

• current_query_count: Returns current running queries(on shard level) which got cancelled X seconds ago.
• total_query_count: Cumulative metric. Returns total such queries count since beginning. This will help us to get count for a particular period by calculating difference between current and previous value.

Name it explicitly post_cancellation_stats as we might have more stats under search_cancellation in future, so it distinguishes well.

[dblock]

running_time_since_cancellation_nanos is indeed duplicate information which is calculated from cancelled start time but I still think it is important as usually this API is used by operator via command line, and to calculate running time, we will have to use some website/tool to calculate running time manually (current_time - start_time) which is a big disadvantage plus time consuming.

I feel pretty strongly about returning a timestamp and not a duration for the reasons above, but I am happy to be convinced otherwise if other maintainers feel that it's not important - maybe @nknize or @andrross?

We already have an existing search stats under indices stats something like below:

"indices": {
  "search": {
         "query_total" : 117284834,
          "query_time_in_millis" : 2309818328,
          "query_current" : 3,
          "fetch_total" : 47100569,
          "fetch_time_in_millis" : 76673528,
          "fetch_current" : 0
  }
}

So I don't think we should have duplicate search stats apart from this. And regarding updating this section with cancellation stats, that is also not possible as IndicesStats is maintained in memory by IndicesService. And I don't see anyway for our service(SearchCancellationMonitoringService) to update this search stats from outside.

Okay, so that's an implementation problem not an API design. Implementation is obviously important, but shouldn't be driving our design decisions. In theory, at least.

What work do you expect SearchCancellationMonitoringService to be doing? If it collects stats about cancelation of queries, why wouldn't that be added to IndicesService? What's so special about search cancelation that requires it to be a standalone function and a separate section? I want to know all kinds of things about searches (how long they took, how often they get canceled, how many have been canceled, etc.).

As an example from above - we don't separate "fetch_total" into a "fetch_stats". So what's the reasoning to separate "post_cancellation_stats"?