Search error rate 100

maximiliano_carrasco · July 25, 2023, 11:32pm

I am trying to run a simple track with search operation but I keep getting 100 error rate,

This is my track

{% import "rally.helpers" as rally with context %}
{
  "version": 2,
  "description": "Tracker-generated track for gustavo",
  "indices": [
    {
      "name": "gustavo-joined",
      "body": "gustavo-joined.json"
    }
  ],
  "corpora": [
    {
      "name": "gustavo-joined",
      "documents": [
        {
          "target-index": "gustavo-joined",
          "source-file": "gustavo-joined-documents.json.bz2",
          "document-count": 3,
          "compressed-bytes": 1211,
          "uncompressed-bytes": 3434
        }
      ]
    }
  ],
   "schedule": [
    {
      "operation": {
        "name": "search",
        "operation-type": "search",
        "body": {
          "query": {
            "match_all": {}
          }
        }
      }
    }
  ]
}

and this is the logs

2023-07-25 23:30:51,940 ActorAddr-(T|:51558)/PID:10526 esrally.client.factory INFO Creating ES client connected to [{'host': '127.0.0.1', 'port': 39200}] with options [{'timeout': 60, 'retry_on_timeout': True}]
2023-07-25 23:30:51,943 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO Checking if REST API is available.
2023-07-25 23:30:52,39 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO REST API is available.
2023-07-25 23:30:52,40 ActorAddr-(T|:51558)/PID:10526 esrally.actor INFO Starting prepare track process on hosts [['localhost']]
2023-07-25 23:30:52,44 ActorAddr-(T|:51563)/PID:10528 esrally.actor INFO Track Preparator started
2023-07-25 23:30:52,48 ActorAddr-(T|:51563)/PID:10528 esrally.track.loader INFO Reading track specification file [/Users/maximiliano/tracks/gustavo/track.json].
2023-07-25 23:30:52,53 ActorAddr-(T|:51563)/PID:10528 esrally.track.loader INFO Final rendered track for '/Users/maximiliano/tracks/gustavo/track.json' has been written to '/var/folders/lr/y_6t5gsn4f36n48p8kdphd2h0000gn/T/tmpjo9jlnqv.json'.
2023-07-25 23:30:52,56 ActorAddr-(T|:51563)/PID:10528 esrally.track.loader INFO Loading template [definition for index gustavo-joined in gustavo-joined.json].
2023-07-25 23:30:52,59 ActorAddr-(T|:51563)/PID:10528 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,62 ActorAddr-(T|:51563)/PID:10528 esrally.actor INFO Preparing track [gustavo]
2023-07-25 23:30:52,62 ActorAddr-(T|:51563)/PID:10528 esrally.actor INFO Reloading track [gustavo] to ensure plugins are up-to-date.
2023-07-25 23:30:52,99 ActorAddr-(T|:51566)/PID:10529 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,63 ActorAddr-(T|:51563)/PID:10528 esrally.track.loader INFO Reading track specification file [/Users/maximiliano/tracks/gustavo/track.json].
2023-07-25 23:30:52,100 ActorAddr-(T|:51568)/PID:10530 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,103 ActorAddr-(T|:51570)/PID:10531 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,66 ActorAddr-(T|:51563)/PID:10528 esrally.track.loader INFO Final rendered track for '/Users/maximiliano/tracks/gustavo/track.json' has been written to '/var/folders/lr/y_6t5gsn4f36n48p8kdphd2h0000gn/T/tmpy2m8swnl.json'.
2023-07-25 23:30:52,105 ActorAddr-(T|:51572)/PID:10532 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,106 ActorAddr-(T|:51574)/PID:10533 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,107 ActorAddr-(T|:51576)/PID:10534 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,109 ActorAddr-(T|:51578)/PID:10535 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,68 ActorAddr-(T|:51563)/PID:10528 esrally.track.loader INFO Loading template [definition for index gustavo-joined in gustavo-joined.json].
2023-07-25 23:30:52,112 ActorAddr-(T|:51580)/PID:10536 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,70 ActorAddr-(T|:51563)/PID:10528 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:52,70 ActorAddr-(T|:51563)/PID:10528 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,120 ActorAddr-(T|:51566)/PID:10529 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,120 ActorAddr-(T|:51568)/PID:10530 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,122 ActorAddr-(T|:51570)/PID:10531 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,126 ActorAddr-(T|:51572)/PID:10532 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,126 ActorAddr-(T|:51574)/PID:10533 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,127 ActorAddr-(T|:51576)/PID:10534 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,130 ActorAddr-(T|:51578)/PID:10535 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:30:57,131 ActorAddr-(T|:51580)/PID:10536 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,147 ActorAddr-(T|:51566)/PID:10529 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,148 ActorAddr-(T|:51568)/PID:10530 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,150 ActorAddr-(T|:51570)/PID:10531 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,154 ActorAddr-(T|:51576)/PID:10534 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,157 ActorAddr-(T|:51578)/PID:10535 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,162 ActorAddr-(T|:51574)/PID:10533 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,163 ActorAddr-(T|:51580)/PID:10536 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,163 ActorAddr-(T|:51572)/PID:10532 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,843 ActorAddr-(T|:51516)/PID:10445 esrally.actor INFO Telling driver to start benchmark.
2023-07-25 23:31:02,846 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO Benchmark is about to start.
2023-07-25 23:31:02,846 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO Attaching cluster-level telemetry devices.
2023-07-25 23:31:02,925 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry INFO JvmStatsSummary on benchmark start
2023-07-25 23:31:02,933 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [merges,total_time_in_millis]. Returning default value [None]
2023-07-25 23:31:02,934 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [merges,total_throttled_time_in_millis]. Returning default value [None]
2023-07-25 23:31:02,934 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [indexing,index_time_in_millis]. Returning default value [None]
2023-07-25 23:31:02,934 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [indexing,throttle_time_in_millis]. Returning default value [None]
2023-07-25 23:31:02,934 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [refresh,total_time_in_millis]. Returning default value [None]
2023-07-25 23:31:02,934 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [flush,total_time_in_millis]. Returning default value [None]
2023-07-25 23:31:02,934 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry INFO Gathering Ingest Pipeline stats at benchmark start
2023-07-25 23:31:02,936 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO Cluster-level telemetry devices are now attached.
2023-07-25 23:31:02,936 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO Benchmark consists of [1] steps executed by [1] clients.
2023-07-25 23:31:02,943 ActorAddr-(T|:51597)/PID:10548 esrally.actor INFO Worker[0] is about to start.
2023-07-25 23:31:02,947 ActorAddr-(T|:51597)/PID:10548 esrally.utils.modules INFO Loading component [gustavo] from [/Users/maximiliano/tracks/gustavo]
2023-07-25 23:31:02,947 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO All workers completed their tasks until join point [0/1].
2023-07-25 23:31:02,948 ActorAddr-(T|:51516)/PID:10445 esrally.racecontrol INFO Bulk adding request metrics to metrics store.
2023-07-25 23:31:03,953 ActorAddr-(T|:51597)/PID:10548 esrally.client.factory INFO Creating ES client connected to [{'host': '127.0.0.1', 'port': 39200}] with options [{'timeout': 60}]
2023-07-25 23:31:03,956 ActorAddr-(T|:51540)/PID:10467 esrally.mechanic.mechanic INFO Resetting relative time of system metrics store.
2023-07-25 23:31:03,959 ActorAddr-(T|:51597)/PID:10548 esrally.driver.driver INFO Worker[0] executing tasks: ['search']
2023-07-25 23:31:04,4 ActorAddr-(T|:51597)/PID:10548 esrally.driver.driver INFO Worker[0] finished executing tasks ['search'] in 0.044619 seconds
2023-07-25 23:31:08,955 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO All workers completed their tasks until join point [1/1].
2023-07-25 23:31:09,255 ActorAddr-(T|:51558)/PID:10526 esrally.metrics INFO Successfully added 4 metrics documents for race timestamp=[20230725T232954Z], track=[gustavo], challenge=[default], car=[['defaults']] in [0.298790] seconds.
2023-07-25 23:31:09,261 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry INFO Gathering index stats for all primaries on benchmark stop.
2023-07-25 23:31:09,265 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [segments,count]. Returning default value [None]
2023-07-25 23:31:09,266 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [segments,memory_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,266 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [merges,total_time_in_millis]. Returning default value [None]
2023-07-25 23:31:09,266 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [merges,total_throttled_time_in_millis]. Returning default value [None]
2023-07-25 23:31:09,266 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [indexing,index_time_in_millis]. Returning default value [None]
2023-07-25 23:31:10,868 ActorAddr-(T|:51516)/PID:10445 esrally.racecontrol INFO Benchmark is complete.
2023-07-25 23:31:09,267 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [indexing,throttle_time_in_millis]. Returning default value [None]
2023-07-25 23:31:09,267 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [refresh,total_time_in_millis]. Returning default value [None]
2023-07-25 23:31:09,267 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [flush,total_time_in_millis]. Returning default value [None]
2023-07-25 23:31:09,267 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [merges,total]. Returning default value [None]
2023-07-25 23:31:09,267 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [refresh,total]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [flush,total]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [segments,doc_values_memory_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [segments,stored_fields_memory_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [segments,terms_memory_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [segments,norms_memory_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [segments,points_memory_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [_all,total,store,size_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,268 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry WARNING Could not determine value at path [_all,total,translog,size_in_bytes]. Returning default value [None]
2023-07-25 23:31:09,964 ActorAddr-(T|:51558)/PID:10526 esrally.telemetry INFO Gathering Ingest Pipeline stats at benchmark end
2023-07-25 23:31:09,971 ActorAddr-(T|:51558)/PID:10526 esrally.driver.driver INFO All steps completed.
2023-07-25 23:31:09,971 ActorAddr-(T|:51558)/PID:10526 esrally.metrics INFO Closing metrics store.
2023-07-25 23:31:10,691 ActorAddr-(T|:51558)/PID:10526 esrally.metrics INFO Successfully added 90 metrics documents for race timestamp=[20230725T232954Z], track=[gustavo], challenge=[default], car=[['defaults']] in [0.718959] seconds.
2023-07-25 23:31:26,36 ActorAddr-(T|:51558)/PID:10526 esrally.actor INFO Main driver received ActorExitRequest and will terminate all load generators.
2023-07-25 23:31:10,869 ActorAddr-(T|:51516)/PID:10445 esrally.racecontrol INFO Bulk adding request metrics to metrics store.
2023-07-25 23:31:24,247 ActorAddr-(T|:51516)/PID:10445 esrally.metrics INFO Creating ES results store
2023-07-25 23:31:26,39 ActorAddr-(T|:51540)/PID:10467 esrally.mechanic.mechanic INFO Stopping nodes [rally-node-0].
2023-07-25 23:31:24,249 ActorAddr-(T|:51516)/PID:10445 esrally.client.factory INFO Creating ES client connected to [{'host': 'my-deployment-a0647e.es.us-central1.gcp.cloud.es.io', 'port': '9243'}] with options [{'use_ssl': True, 'verify_certs': True, 'timeout': 120, 'basic_auth_user': 'gustavo', 'basic_auth_password': '*****'}]
2023-07-25 23:31:25,886 ActorAddr-(T|:51516)/PID:10445 esrally.reporter INFO e[1m
------------------------------------------------------
    _______             __   _____
   / ____(_)___  ____ _/ /  / ___/_________  ________
  / /_  / / __ \/ __ `/ /   \__ \/ ___/ __ \/ ___/ _ \
 / __/ / / / / / /_/ / /   ___/ / /__/ /_/ / /  /  __/
/_/   /_/_/ /_/\__,_/_/   /____/\___/\____/_/   \___/
------------------------------------------------------
            e[0m
2023-07-25 23:31:25,894 ActorAddr-(T|:51516)/PID:10445 esrally.reporter INFO |                        Metric |   Task |    Value |   Unit |
|------------------------------:|-------:|---------:|-------:|
|       Total Young Gen GC time |        |   0      |      s |
|      Total Young Gen GC count |        |   0      |        |
|         Total Old Gen GC time |        |   0      |      s |
|        Total Old Gen GC count |        |   0      |        |
|   Total Ingest Pipeline count |        |   0      |        |
|    Total Ingest Pipeline time |        |   0      |      s |
|  Total Ingest Pipeline failed |        |   0      |        |
|      100th percentile latency | search |  41.7864 |     ms |
| 100th percentile service time | search |  41.7864 |     ms |
|                    error rate | search | 100      |      % |

2023-07-25 23:31:25,895 ActorAddr-(T|:51516)/PID:10445 esrally.metrics INFO Closing metrics store.
2023-07-25 23:31:26,35 ActorAddr-(T|:51516)/PID:10445 esrally.actor INFO Asking mechanic to stop the engine.

I dont understand what I am doing wrong

Bradley_Deam · July 26, 2023, 12:41am

The search could be erroring out for many reasons, the cluster may not healthy etc. The easiest way to unearth the error is to add --on-error=abort to your esrally race invocation, e.g.:

esrally race --track=[...] --on-error=abort

For example, given this operation:

    {
      "name": "test",
      "operation": {
        "operation-type": "search",
        "body": {
          "query": {
            "this_isnt_a_valid_query": {}
          }
        }
      }
    },

Running without --on-error=abort gives me logs that look like this:

2023-07-26 00:35:40,41 ActorAddr-(T|:51842)/PID:876 esrally.driver.driver INFO Worker[0] executing tasks: ['test']
2023-07-26 00:35:40,69 ActorAddr-(T|:51842)/PID:876 esrally.driver.driver INFO Worker[0] finished executing tasks ['test'] in 0.026799 seconds
2023-07-26 00:35:45,35 ActorAddr-(T|:51806)/PID:845 esrally.driver.driver INFO All workers completed their tasks until join point [1/1].

and a summary that looks like:

|                                   Total Ingest Pipeline failed |        |   0         |        |
|                                       100th percentile latency |   test |  25.4275    |     ms |
|                                  100th percentile service time |   test |  25.4275    |     ms |
|                                                     error rate |   test | 100         |      % |

[WARNING] Error rate is 100.0 for operation 'test'. Please check the logs.
[WARNING] No throughput metrics available for [test]. Likely cause: Error rate is 100.0%. Please check the logs.

--------------------------------
[INFO] SUCCESS (took 22 seconds)
--------------------------------

If I add --on-error=abort, I get a summary like:

Running test                                                                   [  0% done]
[ERROR] Cannot race. Error in load generator [0]
        Cannot run task [test]: Request returned an error. Error type: api, Description: <_io.BytesIO object at 0x1075d4270> ({"error":{"root_cause":[{"type":"parsing_exception","reason":"unknown query [this_isnt_a_valid_query]","line":1,"col":37}],"type":"parsing_exception","reason":"unknown query [this_isnt_a_valid_query]","line":1,"col":37,"caused_by":{"type":"named_object_not_found_exception","reason":"[1:37] unknown field [this_isnt_a_valid_query]"}},"status":400})

Getting further help:
*********************
* Check the log files in /home/b-deam/.rally/logs for errors.
* Read the documentation at https://esrally.readthedocs.io/en/latest/.
* Ask a question on the forum at https://discuss.elastic.co/tags/c/elastic-stack/elasticsearch/rally.
* Raise an issue at https://github.com/elastic/rally/issues and include the log files in /home/b-deam/.rally/logs.

If you don't want to cancel benchmark execution on any error, but still want to work out where your error is coming from then you'll want to adjust the logging threshold to capture the search request response.

You'll find the logger configuration in ~/.rally/logging.json, but depending on which version of Rally you're using will depend on the logger you want to modify.

For versions < 2.7.1 you'll want to change the elasticsearch logger from WARNING to something like INFO or even DEBUG:

    "elasticsearch": {
      "handlers": [
        "rally_log_handler"
      ],
      "level": "WARNING",
      "propagate": false
    },

For versions > 2.7.1 you'll want to adjust the elastic_transport logger:

    "elastic_transport": {
      "handlers": [
        "rally_log_handler"
      ],
      "level": "WARNING",
      "propagate": false
    }

For example, adjusting the logger to INFO from WARNING at least gives me this in the logs:

2023-07-26 00:41:11,246 ActorAddr-(T|:51998)/PID:1948 esrally.driver.driver INFO Worker[0] executing tasks: ['test']
2023-07-26 00:41:11,276 -not-actor-/PID:1948 elastic_transport.transport INFO GET https://localhost:9200/logs-221998/_search [status:400 duration:0.028s]
2023-07-26 00:41:11,276 ActorAddr-(T|:51998)/PID:1948 esrally.driver.driver INFO Worker[0] finished executing tasks ['test'] in 0.029163 seconds

system · August 23, 2023, 12:42am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.