there are many defunct process while esrally race success.

Rally version (get with esrally --version):

esrally 2.10.0

Invoked command:

esrally race \
    --track-path=track.json \
    --pipeline=benchmark-only \
    --user-tag="init:init" \
    --target-hosts=xxxx:9200 \
    --client-options="basic_auth_user:'xxx',basic_auth_password:'xxx'" \
    --telemetry=disk-usage \
    --report-format=csv \
    --report-file=result.csv \
    --kill-running-processes

Configuration file (located in ~/.rally/rally.ini)):

[meta]
config.version = 17

[system]
env.name = local

[node]
root.dir = /home/cong/.rally/benchmarks
src.root.dir = /home/cong/.rally/benchmarks/src

[source]
remote.repo.url = https://github.com/elastic/elasticsearch.git
elasticsearch.src.subdir = elasticsearch

[benchmarks]
local.dataset.cache = /home/cong/.rally/benchmarks/data

[reporting]
datastore.type = in-memory
datastore.host =
datastore.port =
datastore.secure = False
datastore.user =
datastore.password =

[tracks]
default.url = https://github.com/elastic/rally-tracks

[teams]
default.url = https://github.com/elastic/rally-teams

[defaults]
preserve_benchmark_candidate = false

[distributions]
release.cache = true

JVM version:

OS version:

Linux es-benchmark-b897746db-qxcfp 5.4.0-125-generic #141-Ubuntu SMP Wed Aug 10 13:42:03 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:

Steps to reproduce:

esrally race xxxxx

Provide logs (if relevant):

Describe the feature:

Why are there so many defunct processes and how do I close them?

Hello!

Defunct typically means that there is a child process of the process in question that has not exited. Rally should also try and clean up existing processes if they are still around. What does the log file in .rally/logs/rally.log say at the end of the test? Can you also provide the full command you ran (starting esrally race ? )

Thanks

well, I wanted to run a esrally benchmark to show you, and I just encountered this case. The benchmark seemed to be completed, but after waiting for more than an hour, there was no output report. The process did not exit either.

esrally race command

esrally race \
--track-path=track_search.json \
--pipeline=benchmark-only \
--track-params=track_search_param.json \
--user-tag="xx:xxx" \
--target-hosts=xxx:9200 \
--client-options="basic_auth_user:'xxx',basic_auth_password:'xxx'" \
--report-format=csv \
--report-file=result.csv \
--kill-running-processes

track_search.json

{% import "rally.helpers" as rally with context %}
{
"version": 2,
"description": "Tracker-generated track for doc_rep-analysis-store",
"schedule": [
{
  "operation": "search_by_file_id",
  "clients": {{clients | default(1)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(1000)}},
  "target-throughput": {{target_throughput | default(1000)}}
}
],
"operations": [
{
  "name": "search_all_data",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "size" : 10000,
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "search_by_file_id",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "size" : 10000,
    "query": {
      "term": {
        "file_id": "6644a21f52c051b9a93b6b51"
      }
    }
  }
}
]
}

track param

{
"index": "xxxx",
"clients": 10,
"iterations": 10,
"target_throughput": 5000
}

~/.rally/logs/rally.log

2024-06-03 15:38:34,512 -not-actor-/PID:1072 esrally.rally INFO OS [uname_result(system='Linux', node='es-benchmark-796b5bbbbb-8gw5r', release='5.4.0-81-generic', version='#91-Ubuntu SMP Thu Jul 15 19:09:17 UTC 2021', machine='x86_64')]
2024-06-03 15:38:34,512 -not-actor-/PID:1072 esrally.rally INFO Python [namespace(name='cpython', cache_tag='cpython-310', version=sys.version_info(major=3, minor=10, micro=12, releaselevel='final', serial=0), hexversion=50990320, _multiarch='x86_64-linux-gnu')]
2024-06-03 15:38:34,512 -not-actor-/PID:1072 esrally.rally INFO Rally version [2.10.0]
2024-06-03 15:38:34,512 -not-actor-/PID:1072 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2024-06-03 15:38:34,512 -not-actor-/PID:1072 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2024-06-03 15:38:34,512 -not-actor-/PID:1072 esrally.rally INFO Cleaning track dependency directory [/home/cong/.rally/libs]...
2024-06-03 15:38:34,513 -not-actor-/PID:1072 esrally.rally INFO Killing running Rally processes
2024-06-03 15:38:34,515 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [206] and command line [[]].
2024-06-03 15:38:37,519 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [207] and command line [[]].
2024-06-03 15:38:40,522 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [222] and command line [[]].
2024-06-03 15:38:43,526 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [223] and command line [[]].
2024-06-03 15:38:46,528 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [224] and command line [[]].
2024-06-03 15:38:49,532 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [227] and command line [[]].
2024-06-03 15:38:52,536 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [249] and command line [[]].
2024-06-03 15:38:55,540 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [250] and command line [[]].
2024-06-03 15:38:58,544 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [251] and command line [[]].
2024-06-03 15:39:01,548 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [252] and command line [[]].
2024-06-03 15:39:04,550 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [253] and command line [[]].
2024-06-03 15:39:07,555 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [254] and command line [[]].
2024-06-03 15:39:10,558 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [255] and command line [[]].
2024-06-03 15:39:13,563 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [256] and command line [[]].
2024-06-03 15:39:16,567 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [257] and command line [[]].
2024-06-03 15:39:19,571 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [258] and command line [[]].
2024-06-03 15:39:22,575 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [259] and command line [[]].
2024-06-03 15:39:25,579 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [260] and command line [[]].
2024-06-03 15:39:28,583 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [269] and command line [[]].
2024-06-03 15:39:31,587 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [364] and command line [[]].
2024-06-03 15:39:34,591 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [365] and command line [[]].
2024-06-03 15:39:37,594 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [369] and command line [[]].
2024-06-03 15:39:40,598 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [391] and command line [[]].
2024-06-03 15:39:43,602 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [392] and command line [[]].
2024-06-03 15:39:46,605 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [393] and command line [[]].
2024-06-03 15:39:49,609 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [394] and command line [[]].
2024-06-03 15:39:52,612 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [396] and command line [[]].
2024-06-03 15:39:55,615 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [397] and command line [[]].
2024-06-03 15:39:58,620 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [398] and command line [[]].
2024-06-03 15:40:01,623 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [399] and command line [[]].
2024-06-03 15:40:04,632 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [400] and command line [[]].
2024-06-03 15:40:07,636 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [401] and command line [[]].
2024-06-03 15:40:10,640 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [402] and command line [[]].
2024-06-03 15:40:13,644 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [424] and command line [[]].
2024-06-03 15:40:16,648 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [425] and command line [[]].
2024-06-03 15:40:19,652 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [426] and command line [[]].
2024-06-03 15:40:22,656 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [427] and command line [[]].
2024-06-03 15:40:25,660 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [428] and command line [[]].
2024-06-03 15:40:28,664 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [429] and command line [[]].
2024-06-03 15:40:31,668 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [430] and command line [[]].
2024-06-03 15:40:34,672 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [431] and command line [[]].
2024-06-03 15:40:37,676 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [432] and command line [[]].
2024-06-03 15:40:40,680 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [433] and command line [[]].
2024-06-03 15:40:43,684 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [434] and command line [[]].
2024-06-03 15:40:46,688 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [435] and command line [[]].
2024-06-03 15:40:49,691 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [436] and command line [[]].
2024-06-03 15:40:52,696 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [503] and command line [[]].
2024-06-03 15:40:55,700 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [504] and command line [[]].
2024-06-03 15:40:58,704 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [505] and command line [[]].
2024-06-03 15:41:01,708 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [506] and command line [[]].
2024-06-03 15:41:04,712 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [507] and command line [[]].
2024-06-03 15:41:07,715 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [508] and command line [[]].
2024-06-03 15:41:10,718 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [530] and command line [[]].
2024-06-03 15:41:13,721 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [531] and command line [[]].
2024-06-03 15:41:16,725 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [532] and command line [[]].
2024-06-03 15:41:19,728 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [533] and command line [[]].
2024-06-03 15:41:22,732 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [534] and command line [[]].
2024-06-03 15:41:25,735 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [535] and command line [[]].
2024-06-03 15:41:28,739 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [536] and command line [[]].
2024-06-03 15:41:31,742 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [537] and command line [[]].
2024-06-03 15:41:34,745 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [538] and command line [[]].
2024-06-03 15:41:37,749 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [539] and command line [[]].
2024-06-03 15:41:40,753 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [540] and command line [[]].
2024-06-03 15:41:43,757 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [541] and command line [[]].
2024-06-03 15:41:46,760 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [544] and command line [[]].
2024-06-03 15:41:49,764 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [545] and command line [[]].
2024-06-03 15:41:52,767 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [546] and command line [[]].
2024-06-03 15:41:55,771 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [547] and command line [[]].
2024-06-03 15:41:58,774 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [548] and command line [[]].
2024-06-03 15:42:01,778 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [549] and command line [[]].
2024-06-03 15:42:04,782 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [550] and command line [[]].
2024-06-03 15:42:07,785 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [551] and command line [[]].
2024-06-03 15:42:10,789 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [552] and command line [[]].
2024-06-03 15:42:13,793 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [553] and command line [[]].
2024-06-03 15:42:16,797 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [554] and command line [[]].
2024-06-03 15:42:19,801 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [555] and command line [[]].
2024-06-03 15:42:22,804 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [556] and command line [[]].
2024-06-03 15:42:25,807 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [557] and command line [[]].
2024-06-03 15:42:28,810 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [558] and command line [[]].
2024-06-03 15:42:31,814 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [559] and command line [[]].
2024-06-03 15:42:34,819 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [560] and command line [[]].
2024-06-03 15:42:37,822 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [561] and command line [[]].
2024-06-03 15:42:40,826 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [562] and command line [[]].
2024-06-03 15:42:43,829 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [563] and command line [[]].
2024-06-03 15:42:46,833 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [564] and command line [[]].
2024-06-03 15:42:49,837 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [565] and command line [[]].
2024-06-03 15:42:52,841 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [566] and command line [[]].
2024-06-03 15:42:55,844 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [567] and command line [[]].
2024-06-03 15:42:58,848 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [568] and command line [[]].
2024-06-03 15:43:01,852 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [569] and command line [[]].
2024-06-03 15:43:04,856 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [570] and command line [[]].
2024-06-03 15:43:07,860 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [571] and command line [[]].
2024-06-03 15:43:10,863 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [572] and command line [[]].
2024-06-03 15:43:13,866 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [573] and command line [[]].
2024-06-03 15:43:16,870 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [574] and command line [[]].
2024-06-03 15:43:19,873 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [575] and command line [[]].
2024-06-03 15:43:22,877 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [646] and command line [[]].
2024-06-03 15:43:25,880 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [647] and command line [[]].
2024-06-03 15:43:28,883 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [651] and command line [[]].
2024-06-03 15:43:31,888 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [835] and command line [[]].
2024-06-03 15:43:34,892 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [836] and command line [[]].
2024-06-03 15:43:37,896 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [839] and command line [[]].
2024-06-03 15:43:40,900 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [840] and command line [[]].
2024-06-03 15:43:43,904 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [862] and command line [[]].
2024-06-03 15:43:46,908 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [863] and command line [[]].
2024-06-03 15:43:49,912 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [864] and command line [[]].
2024-06-03 15:43:52,916 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [865] and command line [[]].
2024-06-03 15:43:55,920 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [866] and command line [[]].
2024-06-03 15:43:58,924 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [867] and command line [[]].
2024-06-03 15:44:01,928 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [868] and command line [[]].
2024-06-03 15:44:04,932 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [869] and command line [[]].
2024-06-03 15:44:07,936 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [870] and command line [[]].
2024-06-03 15:44:10,940 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [871] and command line [[]].
2024-06-03 15:44:13,944 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [872] and command line [[]].
2024-06-03 15:44:16,948 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [873] and command line [[]].
2024-06-03 15:44:19,952 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [876] and command line [[]].
2024-06-03 15:44:22,955 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [877] and command line [[]].
2024-06-03 15:44:25,958 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [878] and command line [[]].
2024-06-03 15:44:28,962 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [879] and command line [[]].
2024-06-03 15:44:31,965 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [880] and command line [[]].
2024-06-03 15:44:34,970 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [903] and command line [[]].
2024-06-03 15:44:37,972 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [955] and command line [[]].
2024-06-03 15:44:40,976 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [956] and command line [[]].
2024-06-03 15:44:43,980 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [983] and command line [[]].
2024-06-03 15:44:46,984 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [984] and command line [[]].
2024-06-03 15:44:49,987 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [987] and command line [[]].
2024-06-03 15:44:52,991 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [988] and command line [[]].
2024-06-03 15:44:55,995 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [1024] and command line [[]].
2024-06-03 15:44:58,999 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [1025] and command line [[]].
2024-06-03 15:45:02,3 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [1026] and command line [[]].
2024-06-03 15:45:05,6 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [1027] and command line [[]].
2024-06-03 15:45:08,10 -not-actor-/PID:1072 esrally.utils.process INFO Killing lingering process with PID [1028] and command line [[]].
2024-06-03 15:45:11,15 -not-actor-/PID:1072 esrally.rally INFO Actor system already running locally? [False]
2024-06-03 15:45:11,15 -not-actor-/PID:1072 esrally.actor INFO Starting actor system with system base [multiprocTCPBase] and capabilities [{'coordinator': True, 'ip': '127.0.0.1', 'Convention Address.IPv4': '127.0.0.1:1900'}].
2024-06-03 15:45:11,35 -not-actor-/PID:1082 root INFO ++++ Actor System gen (3, 10) started, admin @ ActorAddr-(T|:1900)
2024-06-03 15:45:11,49 -not-actor-/PID:1072 esrally.racecontrol INFO Race id is [2904b7fc-41c9-47a9-94a1-eed60bfab825]
2024-06-03 15:45:11,49 -not-actor-/PID:1072 esrally.racecontrol INFO User specified pipeline [benchmark-only].
2024-06-03 15:45:11,49 -not-actor-/PID:1072 esrally.racecontrol INFO Using configured hosts [{'host': 'x.x.x.x', 'port': 9200}]
2024-06-03 15:45:11,51 ActorAddr-(T|:1900)/PID:1082 esrally.actor DEBUG Capabilities [{'coordinator': True, 'ip': '127.0.0.1', 'Convention Address.IPv4': '127.0.0.1:1900', 'Thespian ActorSystem Name': 'multiprocTCPBase', 'Thespian ActorSystem Version': 2, 'Thespian Watch Supported': True, 'Python Version': (3, 10, 12, 'final', 0), 'Thespian Generation': (3, 10), 'Thespian Version': '1717429511027'}] match requirements [{'coordinator': True}].
2024-06-03 15:45:11,63 ActorAddr-(T|:37357)/PID:1084 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:11,289 ActorAddr-(T|:37357)/PID:1084 esrally.racecontrol INFO Automatically derived distribution flavor [default], version [8.2.3], and build hash [9905bfb62a3f0b044948376b4f607f70a8a151b4]
2024-06-03 15:45:11,291 ActorAddr-(T|:37357)/PID:1084 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:11,307 ActorAddr-(T|:37357)/PID:1084 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmpcm_3dky2.json'.
2024-06-03 15:45:11,317 ActorAddr-(T|:37357)/PID:1084 esrally.metrics INFO Creating in-memory metrics store
2024-06-03 15:45:11,317 ActorAddr-(T|:37357)/PID:1084 esrally.metrics INFO Opening metrics store for race timestamp=[20240603T153834Z], track=[track_search], challenge=[default], car=[['external']]
2024-06-03 15:45:11,317 ActorAddr-(T|:37357)/PID:1084 esrally.metrics INFO Creating file race store
2024-06-03 15:45:11,317 ActorAddr-(T|:37357)/PID:1084 esrally.actor INFO Asking mechanic to start the engine.
2024-06-03 15:45:11,328 ActorAddr-(T|:41311)/PID:1085 esrally.actor INFO Received signal from race control to start engine.
2024-06-03 15:45:11,330 ActorAddr-(T|:37357)/PID:1084 esrally.actor INFO Mechanic has started engine successfully.
2024-06-03 15:45:11,329 ActorAddr-(T|:41311)/PID:1085 esrally.actor INFO Cluster will not be provisioned by Rally.
2024-06-03 15:45:11,333 ActorAddr-(T|:37357)/PID:1084 esrally.actor INFO Telling driver to prepare for benchmarking.
2024-06-03 15:45:11,341 ActorAddr-(T|:34409)/PID:1086 esrally.metrics INFO Creating in-memory metrics store
2024-06-03 15:45:11,343 ActorAddr-(T|:34409)/PID:1086 esrally.metrics INFO Opening metrics store for race timestamp=[20240603T153834Z], track=[track_search], challenge=[default], car=[['external']]
2024-06-03 15:45:11,343 ActorAddr-(T|:34409)/PID:1086 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****', 'retry_on_timeout': True}]
2024-06-03 15:45:11,345 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO Checking if REST API is available.
2024-06-03 15:45:11,355 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO REST API is available.
2024-06-03 15:45:11,358 ActorAddr-(T|:34409)/PID:1086 esrally.actor INFO Starting prepare track process on hosts [['localhost']]
2024-06-03 15:45:11,367 ActorAddr-(T|:36991)/PID:1087 esrally.actor INFO Track Preparator started
2024-06-03 15:45:11,373 ActorAddr-(T|:36991)/PID:1087 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:11,388 ActorAddr-(T|:36991)/PID:1087 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmpftxtxvbt.json'.
2024-06-03 15:45:11,398 ActorAddr-(T|:36991)/PID:1087 esrally.actor INFO Preparing track [track_search]
2024-06-03 15:45:11,399 ActorAddr-(T|:36991)/PID:1087 esrally.actor INFO Reloading track [track_search] to ensure plugins are up-to-date.
2024-06-03 15:45:11,399 ActorAddr-(T|:36991)/PID:1087 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:11,411 ActorAddr-(T|:36991)/PID:1087 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmpykihktjf.json'.
2024-06-03 15:45:26,626 ActorAddr-(T|:37357)/PID:1084 esrally.actor INFO Telling driver to start benchmark.
2024-06-03 15:45:26,627 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO Benchmark is about to start.
2024-06-03 15:45:26,627 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO Attaching cluster-level telemetry devices.
2024-06-03 15:45:26,653 ActorAddr-(T|:34409)/PID:1086 esrally.telemetry INFO JvmStatsSummary on benchmark start
2024-06-03 15:45:26,668 ActorAddr-(T|:34409)/PID:1086 esrally.telemetry WARNING merges_total_time is 848721 ms indicating that the cluster is not in a defined clean state. Recorded index time metrics may be misleading.
2024-06-03 15:45:26,668 ActorAddr-(T|:34409)/PID:1086 esrally.telemetry WARNING merges_total_throttled_time is 348291 ms indicating that the cluster is not in a defined clean state. Recorded index time metrics may be misleading.
2024-06-03 15:45:26,668 ActorAddr-(T|:34409)/PID:1086 esrally.telemetry WARNING indexing_total_time is 580285 ms indicating that the cluster is not in a defined clean state. Recorded index time metrics may be misleading.
2024-06-03 15:45:26,668 ActorAddr-(T|:34409)/PID:1086 esrally.telemetry WARNING refresh_total_time is 188899 ms indicating that the cluster is not in a defined clean state. Recorded index time metrics may be misleading.
2024-06-03 15:45:26,669 ActorAddr-(T|:34409)/PID:1086 esrally.telemetry WARNING flush_total_time is 12268 ms indicating that the cluster is not in a defined clean state. Recorded index time metrics may be misleading.
2024-06-03 15:45:26,669 ActorAddr-(T|:34409)/PID:1086 esrally.telemetry INFO Gathering Ingest Pipeline stats at benchmark start
2024-06-03 15:45:26,673 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO Cluster-level telemetry devices are now attached.
2024-06-03 15:45:26,708 ActorAddr-(T|:35539)/PID:1122 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,710 ActorAddr-(T|:33113)/PID:1123 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,673 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO Benchmark consists of [1] steps executed by [10] clients.
2024-06-03 15:45:26,711 ActorAddr-(T|:41267)/PID:1124 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,722 ActorAddr-(T|:35539)/PID:1122 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmp0xjsk8rs.json'.
2024-06-03 15:45:26,716 ActorAddr-(T|:41369)/PID:1127 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,731 ActorAddr-(T|:35539)/PID:1122 esrally.actor INFO Worker[0] is about to start.
2024-06-03 15:45:26,723 ActorAddr-(T|:33113)/PID:1123 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmp1cac_zey.json'.
2024-06-03 15:45:26,725 ActorAddr-(T|:41267)/PID:1124 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmp3936zkk0.json'.
2024-06-03 15:45:26,732 ActorAddr-(T|:33113)/PID:1123 esrally.actor INFO Worker[1] is about to start.
2024-06-03 15:45:26,733 ActorAddr-(T|:41267)/PID:1124 esrally.actor INFO Worker[2] is about to start.
2024-06-03 15:45:26,730 ActorAddr-(T|:41369)/PID:1127 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmpn9deyjzx.json'.
2024-06-03 15:45:26,738 ActorAddr-(T|:41369)/PID:1127 esrally.actor INFO Worker[5] is about to start.
2024-06-03 15:45:26,713 ActorAddr-(T|:46871)/PID:1125 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,715 ActorAddr-(T|:40963)/PID:1126 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,718 ActorAddr-(T|:39795)/PID:1128 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,720 ActorAddr-(T|:44583)/PID:1129 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,722 ActorAddr-(T|:37535)/PID:1130 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,723 ActorAddr-(T|:43781)/PID:1131 esrally.track.loader INFO Reading track specification file [/home/cong/.rally/benchmarks/index_xxx/track_search.json].
2024-06-03 15:45:26,735 ActorAddr-(T|:46871)/PID:1125 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmp6b_u1t88.json'.
2024-06-03 15:45:26,736 ActorAddr-(T|:40963)/PID:1126 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmph01k_gf2.json'.
2024-06-03 15:45:26,751 ActorAddr-(T|:46871)/PID:1125 esrally.actor INFO Worker[3] is about to start.
2024-06-03 15:45:26,751 ActorAddr-(T|:40963)/PID:1126 esrally.actor INFO Worker[4] is about to start.
2024-06-03 15:45:26,741 ActorAddr-(T|:39795)/PID:1128 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmpcacp9h_0.json'.
2024-06-03 15:45:26,756 ActorAddr-(T|:39795)/PID:1128 esrally.actor INFO Worker[6] is about to start.
2024-06-03 15:45:26,742 ActorAddr-(T|:44583)/PID:1129 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmp6kip56ek.json'.
2024-06-03 15:45:26,744 ActorAddr-(T|:37535)/PID:1130 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmpsgbrt5vk.json'.
2024-06-03 15:45:26,746 ActorAddr-(T|:43781)/PID:1131 esrally.track.loader INFO Final rendered track for '/home/cong/.rally/benchmarks/index_xxx/track_search.json' has been written to '/tmp/tmpy3p3bs22.json'.
2024-06-03 15:45:26,757 ActorAddr-(T|:44583)/PID:1129 esrally.actor INFO Worker[7] is about to start.
2024-06-03 15:45:26,760 ActorAddr-(T|:37535)/PID:1130 esrally.actor INFO Worker[8] is about to start.
2024-06-03 15:45:26,768 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO All workers completed their tasks until join point [0/1].
2024-06-03 15:45:26,761 ActorAddr-(T|:43781)/PID:1131 esrally.actor INFO Worker[9] is about to start.
2024-06-03 15:45:26,769 ActorAddr-(T|:37357)/PID:1084 esrally.racecontrol INFO Bulk adding request metrics to metrics store.
2024-06-03 15:45:27,770 ActorAddr-(T|:35539)/PID:1122 esrally.driver.driver INFO Creating time-period based schedule with [None] distribution for [search_by_file_id] with a warmup period of [0] seconds and a time period of [600] seconds.
2024-06-03 15:45:27,770 ActorAddr-(T|:40963)/PID:1126 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,770 ActorAddr-(T|:33113)/PID:1123 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,771 ActorAddr-(T|:41267)/PID:1124 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,771 ActorAddr-(T|:46871)/PID:1125 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,772 ActorAddr-(T|:41369)/PID:1127 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,772 ActorAddr-(T|:39795)/PID:1128 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,772 ActorAddr-(T|:44583)/PID:1129 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,772 ActorAddr-(T|:37535)/PID:1130 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,772 ActorAddr-(T|:43781)/PID:1131 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,772 ActorAddr-(T|:35539)/PID:1122 esrally.client.factory INFO Creating ES client connected to [{'host': 'x.x.x.x', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-03 15:45:27,777 ActorAddr-(T|:40963)/PID:1126 esrally.driver.driver INFO Worker[4] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,777 ActorAddr-(T|:41267)/PID:1124 esrally.driver.driver INFO Worker[2] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,778 ActorAddr-(T|:46871)/PID:1125 esrally.driver.driver INFO Worker[3] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,777 ActorAddr-(T|:41369)/PID:1127 esrally.driver.driver INFO Worker[5] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,779 ActorAddr-(T|:37535)/PID:1130 esrally.driver.driver INFO Worker[8] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,776 ActorAddr-(T|:33113)/PID:1123 esrally.driver.driver INFO Worker[1] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,778 ActorAddr-(T|:39795)/PID:1128 esrally.driver.driver INFO Worker[6] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,777 ActorAddr-(T|:44583)/PID:1129 esrally.driver.driver INFO Worker[7] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,778 ActorAddr-(T|:43781)/PID:1131 esrally.driver.driver INFO Worker[9] executing tasks: ['search_by_file_id']
2024-06-03 15:45:27,777 ActorAddr-(T|:35539)/PID:1122 esrally.driver.driver INFO Worker[0] executing tasks: ['search_by_file_id']
2024-06-03 15:55:27,778 ActorAddr-(T|:35539)/PID:1122 esrally.driver.driver INFO Worker[0] finished executing tasks ['search_by_file_id'] in 600.000377 seconds
2024-06-03 15:55:27,778 ActorAddr-(T|:39795)/PID:1128 esrally.driver.driver INFO Worker[6] finished executing tasks ['search_by_file_id'] in 600.000343 seconds
2024-06-03 15:55:27,778 ActorAddr-(T|:41267)/PID:1124 esrally.driver.driver INFO Worker[2] finished executing tasks ['search_by_file_id'] in 600.000645 seconds
2024-06-03 15:55:27,779 ActorAddr-(T|:46871)/PID:1125 esrally.driver.driver INFO Worker[3] finished executing tasks ['search_by_file_id'] in 600.001322 seconds
2024-06-03 15:55:27,783 ActorAddr-(T|:33113)/PID:1123 esrally.driver.driver INFO Worker[1] finished executing tasks ['search_by_file_id'] in 600.006288 seconds
2024-06-03 15:55:27,783 ActorAddr-(T|:41369)/PID:1127 esrally.driver.driver INFO Worker[5] finished executing tasks ['search_by_file_id'] in 600.005343 seconds
2024-06-03 15:55:27,783 ActorAddr-(T|:43781)/PID:1131 esrally.driver.driver INFO Worker[9] finished executing tasks ['search_by_file_id'] in 600.004794 seconds
2024-06-03 15:55:27,783 ActorAddr-(T|:40963)/PID:1126 esrally.driver.driver INFO Worker[4] finished executing tasks ['search_by_file_id'] in 600.006210 seconds19
2024-06-03 15:55:27,784 ActorAddr-(T|:44583)/PID:1129 esrally.driver.driver INFO Worker[7] finished executing tasks ['search_by_file_id'] in 600.005887 seconds
2024-06-03 15:55:27,785 ActorAddr-(T|:37535)/PID:1130 esrally.driver.driver INFO Worker[8] finished executing tasks ['search_by_file_id'] in 600.005873 seconds
2024-06-03 15:55:29,20 ActorAddr-(T|:34409)/PID:1086 esrally.driver.driver INFO All workers completed their tasks until join point [1/1].

esrally has been running for more than 2 hours and has not yet ended.

cong        1025  1.6  0.0      0     0 ?        Z    Jun03   2:40 [esrally] <defunct>
cong        1026  1.7  0.0      0     0 ?        Z    Jun03   2:53 [esrally] <defunct>
cong        1027  1.7  0.0      0     0 ?        Z    Jun03   2:46 [esrally] <defunct>
cong        1028  1.7  0.0      0     0 ?        Z    Jun03   2:54 [esrally] <defunct>
cong        1072  0.0  0.0  54264 42196 pts/13   S    Jun03   0:00 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1081  0.0  0.0      0     0 ?        Zs   Jun03   0:00 [esrally] <defunct>
cong        1082  0.0  0.0  54264 38164 ?        S    Jun03   0:00 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1083  0.0  0.0  54264 38052 ?        S    Jun03   0:00 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1084  0.0  0.0  59076 43352 ?        S    Jun03   0:00 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1085  0.0  0.0  59076 43144 ?        S    Jun03   0:00 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1122  1.9  0.0 136856 49016 ?        Sl   Jun03   2:26 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1123  1.8  0.0 136652 48768 ?        Sl   Jun03   2:24 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1124  1.9  0.0 136640 48836 ?        Sl   Jun03   2:30 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1125  1.9  0.0 136640 48832 ?        Sl   Jun03   2:27 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1126  2.0  0.0 136292 48548 ?        Sl   Jun03   2:36 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1127  2.0  0.0 136292 48604 ?        Sl   Jun03   2:35 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1128  1.8  0.0 137052 49116 ?        Sl   Jun03   2:25 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1129  1.9  0.0 137308 49492 ?        Sl   Jun03   2:28 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1130  1.9  0.0 136280 48608 ?        Sl   Jun03   2:32 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1131  1.8  0.0 136280 48492 ?        Sl   Jun03   2:22 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track_search.json --pipeline=benchmark-only --track-params=track_search_param.json  --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'elastic',basic_auth_password:'x.x.x.x' --report-format=csv --report-file=result.csv --kill-running-processes
cong        1296  0.0  0.0   3600  1628 pts/18   S+   01:53   0:00 grep --color=auto esrally

If the run is complete, there will be defuncts process, and the number of defuncts is the same as the client number. And no report result this time, as if it is waiting for something?

Check it out, my wise friend. good luck to u

ok, I cant immediately say why the processes are hanging around, from the log it seems that rally thinks there are clients still running. There are though a few things I would look at first:

The target throughput you are setting is saying that you expect each client to achieve 500 requests / second, ie one request every 2 ms. When setting target_throughput rally will add a request to the queue to achieve that, however if the client is still dealing with a previous request, then it will just wait. You will be able to see longer time in latency (as this includes the time in the queue + service_time).
Since the clients seem to complete exactly after ten minutes, and you haven't got anything limiting the step to ten minutes, it seems to suggest that the 110 iterations (default 100 warmup, plus the 10 measurement iterations you set in parameters), are taking, by chance, exactly ten minutes. This seems odd.

How long does a single request take, when you test via curl / kibana dev tools?

wow, thanks for your help, and I understand what you said. answer your question first： a single request take 2ms.

I reconfigured the parameters and generated fewer defuncts. but there are still defuncts. is this a bug? I understand that defunct should not be generated anyway, and if the run is completed, the unprocessed requests can be forcibly closed and a report can be generated.

In addition, I want to know whether the above run will end? I encountered this problem again. After running, no report was generated. I ran for more than 3 hours. the last log is as follows

2024-06-05 15:08:47,289 ActorAddr-(T|:39899)/PID:374 esrally.driver.driver INFO Worker[20] finished executing tasks ['search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11'] in 124.391677 seconds
2024-06-05 15:08:47,670 ActorAddr-(T|:37631)/PID:379 esrally.driver.driver INFO Worker[25] finished executing tasks ['search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11'] in 124.790102 seconds
2024-06-05 15:08:47,683 ActorAddr-(T|:37271)/PID:360 esrally.driver.driver INFO Worker[6] finished executing tasks ['search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11'] in 124.802407 seconds
2024-06-05 15:08:47,851 ActorAddr-(T|:45055)/PID:356 esrally.driver.driver INFO Worker[2] finished executing tasks ['search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11'] in 124.967352 seconds
2024-06-05 15:08:47,915 ActorAddr-(T|:33799)/PID:358 esrally.driver.driver INFO Worker[4] finished executing tasks ['search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11', 'search_all_step_11'] in 125.026384 seconds
2024-06-05 15:08:48,124 ActorAddr-(T|:40791)/PID:305 esrally.driver.driver INFO All workers completed their tasks until join point [24/24].
2024-06-05 15:08:51,253 ActorAddr-(T|:40791)/PID:305 esrally.telemetry INFO Gathering index stats for all primaries on benchmark stop.
2024-06-05 15:08:51,902 ActorAddr-(T|:40791)/PID:305 esrally.telemetry INFO Gathering Ingest Pipeline stats at benchmark end
2024-06-05 15:08:51,906 ActorAddr-(T|:40791)/PID:305 esrally.driver.driver INFO All steps completed.
2024-06-05 15:08:59,119 ActorAddr-(T|:40791)/PID:305 esrally.metrics INFO Closing metrics store.

Esrally process did not exit, I don't know what it is doing.

    446 cong      20   0    7312   3412   2836 S   0.3   0.0   0:03.60 top                                                                            
      1 root      20   0    2820    956    860 S   0.0   0.0   0:00.44 tail                                                                           
      7 root      20   0    2888    916    820 S   0.0   0.0   0:00.01 sh                                                                             
    275 root      20   0    2888   1000    900 S   0.0   0.0   0:00.00 sh                                                                             
    291 cong      20   0    4360   2000   1700 S   0.0   0.0   0:00.00 test_search_ind                                                                
    292 cong      20   0   54264  42800   9788 S   0.0   0.0   0:00.59 esrally                                                                        
    300 cong      20   0       0      0      0 Z   0.0   0.0   0:00.00 esrally                                                                        
    301 cong      20   0   54332  38360   5132 S   0.0   0.0   0:00.40 esrally                                                                        
    302 cong      20   0   54264  38240   4940 S   0.0   0.0   0:01.36 esrally                                                                        
    304 cong      20   0   59760  44088   5168 S   0.0   0.0   0:00.01 esrally                                                                        
    305 cong      20   0  919128 824616   6276 S   0.0   0.6   5:39.71 esrally                                                                        
    340 root      20   0    2888    964    864 S   0.0   0.0   0:00.01 sh                                                                             
    346 root      20   0    6212   2208   1784 S   0.0   0.0   0:00.00 su                                                                             
    347 cong      20   0    4624   2556   1892 S   0.0   0.0   0:00.01 bash                                                                           
    354 cong      20   0  138972  71136   7036 S   0.0   0.1  20:38.13 esrally                                                                        
    355 cong      20   0  138076  67004   7036 S   0.0   0.1  21:01.98 esrally                                                                        
    356 cong      20   0  137724  50756   7032 S   0.0   0.0   4:38.35 esrally                                                                        
    357 cong      20   0  137724  50752   7028 S   0.0   0.0   4:40.72 esrally                                                                        
    358 cong      20   0  137720  50808   7032 S   0.0   0.0   4:36.14 esrally                                                                        
    359 cong      20   0  137720  50772   7024 S   0.0   0.0   4:41.58 esrally                                                                        
    360 cong      20   0  137720  50788   7028 S   0.0   0.0   4:42.38 esrally                                                                        
    361 cong      20   0  137720  50788   7028 S   0.0   0.0   4:42.97 esrally                                                                        
    362 cong      20   0  137720  50616   6952 S   0.0   0.0   4:39.68 esrally                                                                        
    363 cong      20   0  137720  50788   7028 S   0.0   0.0   4:41.09 esrally                                                                        
    364 cong      20   0  137720  50856   7028 S   0.0   0.0   4:42.17 esrally

Will this wait eventually stop and produce a report ? give some advice, thank you.

I want to test the read and write performance of my index table, the read and write performance under different index data amount, and observe the throughput and latency. the track file is as follows。

I am newer to esrally and have some questions about it, looking forward to your reply！

The way to test the benchmark of ES，Is there a better way by esrally tool?
Whether operations can be looped in the track file, without listing all operators？
Can esrally just randomly query ES doc. because read from the file system buffer for repeated queries, or is there any way to read ES doc from disk?

trakck.json

{% import "rally.helpers" as rally with context %}
{
"version": 2,
"description": "Tracker-generated track for xxx_index",
"indices": [
{
  "name": "{{index}}",
  "body": "xxx_index.json"
}
],
"corpora": [
{
  "name": "{{index}}",
  "documents": [
      {
        "target-index": "{{index}}",
        "source-file": "xxx_index.json.bz2",
        "document-count": 5273641,
        "compressed-bytes": 1236188280,
        "uncompressed-bytes": 16089171936
    }
  ]
}
],
"schedule": [
{
  "operation": "delete-index"
},
{
  "operation": "create-index"
},
{
  "operation": "bulk_step_1",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_1",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_2",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_2",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_3",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_3",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_4",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_4",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_5",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_5",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_6",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_6",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_7",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_7",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_8",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_8",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_9",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_9",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_10",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_10",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
},
{
  "operation": "bulk_step_11",
  "clients": {{bulk_clients | default(10)}}
},
{
  "operation": "search_all_step_11",
  "clients": {{search_clients | default(10)}},
  "warmup-iterations": {{warmup_iterations | default(100)}},
  "iterations": {{iterations | default(2000)}},
  "target-throughput": {{target_throughput | default(5000)}}
}
],
"operations": [
{
  "name": "delete-index",
  "operation-type": "delete-index"
},
{
  "name": "create-index",
  "operation-type": "create-index"
},
{
  "name": "bulk_step_1",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_1",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_2",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_2",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_3",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_3",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_4",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_4",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_5",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_5",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_6",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_6",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_7",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_7",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_8",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_8",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_9",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_9",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_10",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_10",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
},
{
  "name": "bulk_step_11",
  "operation-type": "bulk",
  "bulk-size": {{bulk_size | default(100)}},
  "ingest-percentage": {{ingest_percentage | default(100)}}
},    
{
  "name": "search_all_step_11",
  "operation-type": "search",
  "index": "{{index}}",
  "body": {
    "query": {
      "match_all": {}
    }
  }
}
]
}

I'm encountering a recurring issue where, after all operations have been completed, the process doesn't exit as expected and no report is generated. This issue is significantly affecting my work. Could anyone provide some guidance on this? Thank you in advance.

cong         489  1.6  0.1 292320 204280 ?       S    16:03   3:11 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         522  0.0  0.0      0     0 ?        Z    16:03   0:00 [esrally] <defunct>
cong         527  8.5  0.0 137412 55812 ?        Sl   16:03  16:42 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         528  8.6  0.0 136204 55024 ?        Sl   16:03  16:46 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         529  8.6  0.0 136248 55064 ?        Sl   16:03  16:50 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         530  8.6  0.0 136504 55052 ?        Sl   16:03  16:54 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         531  8.5  0.0 136480 57764 ?        Sl   16:03  16:41 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         532  8.6  0.0 136208 54804 ?        Sl   16:03  16:46 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         533  8.6  0.0 136536 55444 ?        Sl   16:03  16:48 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         534  1.8  0.0 136092 54248 ?        Sl   16:03   3:41 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         570  0.0  0.0   3600  1620 pts/2    S+   19:18   0:00 grep --color=auto esrally

last log，after several hours of completion, there is still no result.

2024-06-09 09:47:08,935 ActorAddr-(T|:33121)/PID:533 esrally.client.factory INFO Creating ES client connected to [{'host': '10.194.43.46', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-09 09:47:08,933 ActorAddr-(T|:39901)/PID:528 esrally.driver.driver INFO Worker[1] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,935 ActorAddr-(T|:43279)/PID:530 esrally.client.factory INFO Creating ES client connected to [{'host': '10.194.43.46', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-09 09:47:08,933 ActorAddr-(T|:38639)/PID:529 esrally.driver.driver INFO Worker[2] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,935 ActorAddr-(T|:39749)/PID:532 esrally.driver.driver INFO Worker[5] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,935 ActorAddr-(T|:33583)/PID:531 esrally.driver.driver INFO Worker[4] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,936 ActorAddr-(T|:33273)/PID:527 esrally.driver.driver INFO Worker[0] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,936 ActorAddr-(T|:33121)/PID:533 esrally.driver.driver INFO Worker[6] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,937 ActorAddr-(T|:43279)/PID:530 esrally.driver.driver INFO Worker[3] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:48:09,688 ActorAddr-(T|:33583)/PID:531 esrally.driver.driver INFO Worker[4] finished executing tasks ['search_step_client_7_c_59'] in 60.753376 seconds
2024-06-09 09:48:17,191 ActorAddr-(T|:33273)/PID:527 esrally.driver.driver INFO Worker[0] finished executing tasks ['search_step_client_7_c_59'] in 68.254558 seconds
2024-06-09 09:48:17,389 ActorAddr-(T|:39901)/PID:528 esrally.driver.driver INFO Worker[1] finished executing tasks ['search_step_client_7_c_59'] in 68.455478 seconds
2024-06-09 09:48:17,449 ActorAddr-(T|:39749)/PID:532 esrally.driver.driver INFO Worker[5] finished executing tasks ['search_step_client_7_c_59'] in 68.513133 seconds
2024-06-09 09:48:17,556 ActorAddr-(T|:33121)/PID:533 esrally.driver.driver INFO Worker[6] finished executing tasks ['search_step_client_7_c_59'] in 68.619407 seconds
2024-06-09 09:48:17,858 ActorAddr-(T|:38639)/PID:529 esrally.driver.driver INFO Worker[2] finished executing tasks ['search_step_client_7_c_59'] in 68.924048 seconds
2024-06-09 09:48:17,903 ActorAddr-(T|:43279)/PID:530 esrally.driver.driver INFO Worker[3] finished executing tasks ['search_step_client_7_c_59'] in 68.965168 seconds
2024-06-09 09:48:19,31 ActorAddr-(T|:46433)/PID:489 esrally.driver.driver INFO All workers completed their tasks until join point [122/122].
2024-06-09 09:48:19,170 ActorAddr-(T|:46433)/PID:489 esrally.telemetry INFO Gathering index stats for all primaries on benchmark stop.
2024-06-09 09:48:19,476 ActorAddr-(T|:46433)/PID:489 esrally.telemetry INFO Gathering Ingest Pipeline stats at benchmark end
2024-06-09 09:48:19,480 ActorAddr-(T|:46433)/PID:489 esrally.driver.driver INFO All steps completed.
2024-06-09 09:48:20,120 ActorAddr-(T|:46433)/PID:489 esrally.metrics INFO Closing metrics store.

cong         489  1.6  0.1 292320 204280 ?       S    16:03   3:11 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         522  0.0  0.0      0     0 ?        Z    16:03   0:00 [esrally] <defunct>
cong         527  8.5  0.0 137412 55812 ?        Sl   16:03  16:42 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         528  8.6  0.0 136204 55024 ?        Sl   16:03  16:46 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         529  8.6  0.0 136248 55064 ?        Sl   16:03  16:50 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         530  8.6  0.0 136504 55052 ?        Sl   16:03  16:54 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         531  8.5  0.0 136480 57764 ?        Sl   16:03  16:41 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         532  8.6  0.0 136208 54804 ?        Sl   16:03  16:46 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         533  8.6  0.0 136536 55444 ?        Sl   16:03  16:48 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         534  1.8  0.0 136092 54248 ?        Sl   16:03   3:41 /usr/bin/python3 /usr/local/bin/esrally race --track-path=track.json --pipeline=benchmark-only --user-tag=init:init --target-hosts=x.x.x.x:9200 --client-options=basic_auth_user:'xxxxxx',basic_auth_password:'xxxxxx' --telemetry=disk-usage --report-format=csv --report-file=result.csv --kill-running-processes
cong         570  0.0  0.0   3600  1620 pts/2    S+   19:18   0:00 grep --color=auto esrally

last log，after several hours of completion, there is still no result.

2024-06-09 09:47:08,935 ActorAddr-(T|:33121)/PID:533 esrally.client.factory INFO Creating ES client connected to [{'host': '10.194.43.46', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-09 09:47:08,933 ActorAddr-(T|:39901)/PID:528 esrally.driver.driver INFO Worker[1] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,935 ActorAddr-(T|:43279)/PID:530 esrally.client.factory INFO Creating ES client connected to [{'host': '10.194.43.46', 'port': 9200}] with options [{'timeout': 60, 'basic_auth_user': 'elastic', 'basic_auth_password': '*****'}]
2024-06-09 09:47:08,933 ActorAddr-(T|:38639)/PID:529 esrally.driver.driver INFO Worker[2] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,935 ActorAddr-(T|:39749)/PID:532 esrally.driver.driver INFO Worker[5] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,935 ActorAddr-(T|:33583)/PID:531 esrally.driver.driver INFO Worker[4] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,936 ActorAddr-(T|:33273)/PID:527 esrally.driver.driver INFO Worker[0] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,936 ActorAddr-(T|:33121)/PID:533 esrally.driver.driver INFO Worker[6] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:47:08,937 ActorAddr-(T|:43279)/PID:530 esrally.driver.driver INFO Worker[3] executing tasks: ['search_step_client_7_c_59']
2024-06-09 09:48:09,688 ActorAddr-(T|:33583)/PID:531 esrally.driver.driver INFO Worker[4] finished executing tasks ['search_step_client_7_c_59'] in 60.753376 seconds
2024-06-09 09:48:17,191 ActorAddr-(T|:33273)/PID:527 esrally.driver.driver INFO Worker[0] finished executing tasks ['search_step_client_7_c_59'] in 68.254558 seconds
2024-06-09 09:48:17,389 ActorAddr-(T|:39901)/PID:528 esrally.driver.driver INFO Worker[1] finished executing tasks ['search_step_client_7_c_59'] in 68.455478 seconds
2024-06-09 09:48:17,449 ActorAddr-(T|:39749)/PID:532 esrally.driver.driver INFO Worker[5] finished executing tasks ['search_step_client_7_c_59'] in 68.513133 seconds
2024-06-09 09:48:17,556 ActorAddr-(T|:33121)/PID:533 esrally.driver.driver INFO Worker[6] finished executing tasks ['search_step_client_7_c_59'] in 68.619407 seconds
2024-06-09 09:48:17,858 ActorAddr-(T|:38639)/PID:529 esrally.driver.driver INFO Worker[2] finished executing tasks ['search_step_client_7_c_59'] in 68.924048 seconds
2024-06-09 09:48:17,903 ActorAddr-(T|:43279)/PID:530 esrally.driver.driver INFO Worker[3] finished executing tasks ['search_step_client_7_c_59'] in 68.965168 seconds
2024-06-09 09:48:19,31 ActorAddr-(T|:46433)/PID:489 esrally.driver.driver INFO All workers completed their tasks until join point [122/122].
2024-06-09 09:48:19,170 ActorAddr-(T|:46433)/PID:489 esrally.telemetry INFO Gathering index stats for all primaries on benchmark stop.
2024-06-09 09:48:19,476 ActorAddr-(T|:46433)/PID:489 esrally.telemetry INFO Gathering Ingest Pipeline stats at benchmark end
2024-06-09 09:48:19,480 ActorAddr-(T|:46433)/PID:489 esrally.driver.driver INFO All steps completed.
2024-06-09 09:48:20,120 ActorAddr-(T|:46433)/PID:489 esrally.metrics INFO Closing metrics store.

@gareth-ellis

Hello,

Apologies I was out for a long weekend.

There seems to be quite a few different versions of the track, and then logs that don't necessarily match track versions that have been posted. I suggest we concentrate on a simple version - ie here https://github.com/elastic/rally/issues/1856#issuecomment-2145809224 since, as I understand it you experience the issue there. Please correct me if there are multiple issues experienced by different versions of the track.

I will try and recreate your track locally, with some dummy data.

I have run with your track (albeit not your data). I am not able to reproduce the hang. To confirm, the steps I took were:

esrally install --distribution-version=8.14.0 --node-name="rally-node-0" --network-host="127.0.0.1" --http-port=39200 --master-nodes="rally-node-0" --seed-hosts="127.0.0.1:39300"

You then get an environment id back, start elasticsearch by:

esrally start --installation-id 5721cbfe-34c2-4f8f-99e8-c7e32366211a --race-id 123456

Then I generated some data (I used the geonames track, but you could use the data you use in your track) Finally I ran the track from https://github.com/elastic/rally/issues/1856#issuecomment-2145809224

2024-06-10 09:31:22,939 ActorAddr-(T|:63807)/PID:13391 esrally.driver.driver INFO Worker[2] finished executing tasks ['search_by_file_id'] in 0.243900 seconds
2024-06-10 09:31:27,687 ActorAddr-(T|:63762)/PID:13332 esrally.driver.driver INFO All workers completed their tasks until join point [1/1].
2024-06-10 09:31:27,705 ActorAddr-(T|:63762)/PID:13332 esrally.telemetry INFO Gathering index stats for all primaries on benchmark stop.
2024-06-10 09:31:28,659 ActorAddr-(T|:63750)/PID:13326 esrally.racecontrol INFO Benchmark is complete.
2024-06-10 09:31:28,629 ActorAddr-(T|:63762)/PID:13332 esrally.telemetry INFO Gathering Ingest Pipeline stats at benchmark end
2024-06-10 09:31:28,637 ActorAddr-(T|:63762)/PID:13332 esrally.driver.driver INFO All steps completed.
2024-06-10 09:31:28,658 ActorAddr-(T|:63762)/PID:13332 esrally.metrics INFO Closing metrics store.
2024-06-10 09:31:28,678 ActorAddr-(T|:63762)/PID:13332 esrally.actor INFO Main driver received ActorExitRequest and will terminate all load generators.
2024-06-10 09:31:28,659 ActorAddr-(T|:63750)/PID:13326 esrally.racecontrol INFO Bulk adding request metrics to metrics store.
2024-06-10 09:31:28,675 ActorAddr-(T|:63750)/PID:13326 esrally.metrics INFO Creating no-op results store
2024-06-10 09:31:28,681 -not-actor-/PID:13316 esrally.racecontrol INFO Benchmark has finished successfully.
2024-06-10 09:31:28,681 -not-actor-/PID:13316 esrally.racecontrol INFO Telling benchmark actor to exit.
2024-06-10 09:31:28,676 ActorAddr-(T|:63750)/PID:13326 esrally.reporter INFO ESC[1m
------------------------------------------------------
    _______             __   _____
   / ____(_)___  ____ _/ /  / ___/_________  ________
  / /_  / / __ \/ __ `/ /   \__ \/ ___/ __ \/ ___/ _ \
 / __/ / / / / / /_/ / /   ___/ / /__/ /_/ / /  /  __/
/_/   /_/_/ /_/\__,_/_/   /____/\___/\____/_/   \___/
------------------------------------------------------
            ESC[0m
2024-06-10 09:31:28,676 ActorAddr-(T|:63750)/PID:13326 esrally.reporter INFO Metric,Task,Value,Unit
Cumulative indexing time of primary shards,,0.009533333333333333,min
Min cumulative indexing time across primary shards,,0.001,min
Median cumulative indexing time across primary shards,,0.00165,min
Max cumulative indexing time across primary shards,,0.00295,min
Cumulative indexing throttle time of primary shards,,0,min
Min cumulative indexing throttle time across primary shards,,0,min
Median cumulative indexing throttle time across primary shards,,0,min
Max cumulative indexing throttle time across primary shards,,0,min
Cumulative merge time of primary shards,,0,min
Cumulative merge count of primary shards,,0,
Min cumulative merge time across primary shards,,0,min
Median cumulative merge time across primary shards,,0,min
Max cumulative merge time across primary shards,,0,min
Cumulative merge throttle time of primary shards,,0,min
Min cumulative merge throttle time across primary shards,,0,min
Median cumulative merge throttle time across primary shards,,0,min
Max cumulative merge throttle time across primary shards,,0,min
Cumulative refresh time of primary shards,,0.005183333333333333,min
Cumulative refresh count of primary shards,,40,
Min cumulative refresh time across primary shards,,0.0008333333333333334,min
Median cumulative refresh time across primary shards,,0.0010166666666666666,min
Max cumulative refresh time across primary shards,,0.0011666666666666668,min
Cumulative flush time of primary shards,,0.00285,min
Cumulative flush count of primary shards,,5,
Min cumulative flush time across primary shards,,0.00045,min
Median cumulative flush time across primary shards,,0.0006,min
Max cumulative flush time across primary shards,,0.0006666666666666666,min
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,
Store size,,0.00038978271186351776,GB
Translog size,,2.561137080192566e-07,GB
Heap used for segments,,0,MB
Heap used for doc values,,0,MB
Heap used for terms,,0,MB
Heap used for norms,,0,MB
Heap used for points,,0,MB
Heap used for stored fields,,0,MB
Segment count,,11,
Total Ingest Pipeline count,,0,
Total Ingest Pipeline time,,0,s
Total Ingest Pipeline failed,,0,
Min Throughput,search_by_file_id,3992.38,ops/s
Mean Throughput,search_by_file_id,3992.38,ops/s
Median Throughput,search_by_file_id,3992.38,ops/s
Max Throughput,search_by_file_id,3992.38,ops/s
50th percentile latency,search_by_file_id,23.96991699999873,ms
90th percentile latency,search_by_file_id,35.20344999999879,ms
99th percentile latency,search_by_file_id,37.01540959000116,ms
100th percentile latency,search_by_file_id,37.093083999998555,ms
50th percentile service time,search_by_file_id,1.4831664999999106,ms
90th percentile service time,search_by_file_id,1.9874046999991182,ms
99th percentile service time,search_by_file_id,2.2892534200013177,ms
100th percentile service time,search_by_file_id,2.6031250000002615,ms
error rate,search_by_file_id,0.00,%

2024-06-10 09:31:28,677 ActorAddr-(T|:63750)/PID:13326 esrally.metrics INFO Closing metrics store.
2024-06-10 09:31:28,678 ActorAddr-(T|:63750)/PID:13326 esrally.actor INFO Asking mechanic to stop the engine.
2024-06-10 09:31:28,680 ActorAddr-(T|:63750)/PID:13326 esrally.actor INFO Mechanic has stopped engine successfully.
2024-06-10 09:31:28,684 ActorAddr-(T|:63762)/PID:13332 esrally.actor INFO Main driver received ActorExitRequest and will terminate all load generators.
2024-06-10 09:31:31,687 -not-actor-/PID:13316 esrally.rally INFO Attempting to shutdown internal actor system.
2024-06-10 09:31:31,691 -not-actor-/PID:13325 root INFO ActorSystem Logging Shutdown
2024-06-10 09:31:31,716 -not-actor-/PID:13316 esrally.rally INFO Actor system is still running. Waiting...
2024-06-10 09:31:31,715 -not-actor-/PID:13324 root INFO ---- Actor System shutdown
2024-06-10 09:31:32,719 -not-actor-/PID:13316 esrally.rally INFO Shutdown completed.

As a next step, I think if you enable more logging, it may suggest what is going on.

Take a copy of your logging.json file in $HOME/.rally/logging.json (e.g save as $HOME/.rally/logging.json.original)

Update the logging.json file to change WARNING to DEBUG, this will give us some extra log messages after the test is finished which may suggest what it is up to on your machine.

elastic / rally

there are many defunct process while esrally race success. #1856