Files
Azat KhuzhinandGitHub cb5dd45fff Merge pull request #108378 from azat/ci/perf-memory-sampling
Add JemallocSample and MemorySample flamegraphs for performance comparison
2026-06-26 10:16:38 +00:00

961 lines
38 KiB
Python
Executable File

#!/usr/bin/env python3
import argparse
import itertools
import json
import logging
import os
import random
import re
import signal
import statistics
import string
import subprocess
import sys
import time
import traceback
import xml.etree.ElementTree as et
from concurrent.futures import ThreadPoolExecutor
from threading import Thread
import clickhouse_driver
from scipy import stats
logging.basicConfig(
format="%(asctime)s: %(levelname)s: %(module)s: %(message)s", level="WARNING"
)
total_start_seconds = time.perf_counter()
stage_start_seconds = total_start_seconds
# Thread executor that does not hides exception that happens during function
# execution, and rethrows it after join()
class SafeThread(Thread):
run_exception = None
def run(self):
try:
super().run()
except:
self.run_exception = sys.exc_info()
def join(self):
super().join()
if self.run_exception:
raise self.run_exception[1]
def reportStageEnd(stage):
global stage_start_seconds, total_start_seconds
current = time.perf_counter()
print(
f"stage\t{stage}\t{current - stage_start_seconds:.3f}\t{current - total_start_seconds:.3f}"
)
stage_start_seconds = current
def tsv_escape(s):
return (
s.replace("\\", "\\\\")
.replace("\t", "\\t")
.replace("\n", "\\n")
.replace("\r", "")
)
parser = argparse.ArgumentParser(description="Run performance test.")
# Explicitly decode files as UTF-8 because sometimes we have Russian characters in queries, and LANG=C is set.
parser.add_argument(
"file",
metavar="FILE",
type=argparse.FileType("r", encoding="utf-8"),
nargs=1,
help="test description file",
)
parser.add_argument(
"--host",
nargs="*",
default=["localhost"],
help="Space-separated list of server hostname(s). Corresponds to '--port' options.",
)
parser.add_argument(
"--port",
nargs="*",
default=[9000],
help="Space-separated list of server port(s). Corresponds to '--host' options.",
)
parser.add_argument(
"--user",
default="default",
help="Username for ClickHouse authentication.",
)
parser.add_argument(
"--password",
default="",
help="Password for ClickHouse authentication.",
)
parser.add_argument(
"--secure",
action="store_true",
help="Use SSL/TLS connection.",
)
parser.add_argument(
"--binary",
nargs="*",
default=["clickhouse"],
help="Space-separated list of clickhouse binary path(s), parallel to '--host'/'--port'. "
'Used by shell-script queries (<query type="shell">) to build $CLICKHOUSE_BINARY, '
"$CLICKHOUSE_LOCAL and $CLICKHOUSE_CLIENT for the corresponding server. "
"A shorter list (e.g. a single value) is reused for every server.",
)
parser.add_argument(
"--http-port",
nargs="*",
default=[8123],
help="Space-separated list of HTTP port(s), parallel to '--host'/'--port'. "
'Used by shell-script queries (<query type="shell">) to build $CLICKHOUSE_URL '
"for the corresponding server. A shorter list is reused for every server.",
)
parser.add_argument(
"--runs", type=int, default=1, help="Number of query runs per server."
)
parser.add_argument(
"--max-queries",
type=int,
default=None,
help="Test no more than this number of queries, chosen at random.",
)
parser.add_argument(
"--queries-to-run",
nargs="*",
type=int,
default=None,
help="Space-separated list of indexes of queries to test.",
)
parser.add_argument(
"--max-query-seconds",
type=int,
default=15,
help="For how many seconds at most a query is allowed to run. The script finishes with error if this time is exceeded.",
)
parser.add_argument(
"--prewarm-max-query-seconds",
type=int,
default=180,
help="For how many seconds at most a prewarm (cold storage) query is allowed to run. The script finishes with error if this time is exceeded.",
)
parser.add_argument(
"--profile-seconds",
type=int,
default=0,
help="For how many seconds to profile a query for which the performance has changed.",
)
parser.add_argument(
"--long", action="store_true", help="Do not skip the tests tagged as long."
)
parser.add_argument(
"--print-queries", action="store_true", help="Print test queries and exit."
)
parser.add_argument(
"--print-settings", action="store_true", help="Print test settings and exit."
)
parser.add_argument(
"--keep-created-tables",
action="store_true",
help="Don't drop the created tables after the test.",
)
parser.add_argument(
"--use-existing-tables",
action="store_true",
help="Don't create or drop the tables, use the existing ones instead.",
)
parser.add_argument(
"--jemalloc-purge",
choices=["disabled", "after-fill", "before-each-query", "before-each-run"],
default="before-each-run",
help="When to issue SYSTEM JEMALLOC PURGE on all server connections. "
"Purging equalises per-process jemalloc dirty-page state between LEFT and "
"RIGHT, which otherwise diverges across the test and causes background "
"purges to do asymmetric work during measured queries.",
)
args = parser.parse_args()
reportStageEnd("start")
test_name = os.path.splitext(os.path.basename(args.file[0].name))[0]
xml_dir = os.path.dirname(os.path.abspath(args.file[0].name))
tree = et.parse(args.file[0])
root = tree.getroot()
reportStageEnd("parse")
# Process query parameters
subst_elems = root.findall("substitutions/substitution")
available_parameters = {} # { 'table': ['hits_10m', 'hits_100m'], ... }
for e in subst_elems:
name = e.find("name").text
values = [v.text for v in e.findall("values/value")]
if not values:
raise Exception(f"No values given for substitution {{{name}}}")
available_parameters[name] = values
# Takes parallel lists of templates, substitutes them with all combos of
# parameters. The set of parameters is determined based on the first list.
# Note: keep the order of queries -- sometimes we have DROP IF EXISTS
# followed by CREATE in create queries section, so the order matters.
def substitute_parameters(query_templates, other_templates=[]):
query_results = []
other_results = [[]] * (len(other_templates))
for i, q in enumerate(query_templates):
# We need stable order of keys here, so that the order of substitutions
# is always the same, and the query indexes are consistent across test
# runs.
keys = sorted(set(n for _, n, _, _ in string.Formatter().parse(q) if n))
values = [available_parameters[k] for k in keys]
combos = itertools.product(*values)
for c in combos:
with_keys = dict(zip(keys, c))
query_results.append(q.format(**with_keys))
for j, t in enumerate(other_templates):
other_results[j].append(t[i].format(**with_keys))
if len(other_templates):
return query_results, other_results
else:
return query_results
def split_sql_statements(sql):
"""Split SQL into statements on semicolons, respecting quoted literals/identifiers, -- and # comments, and /* block comments */."""
statements = []
current = []
quote_char = ""
in_line_comment = False
in_block_comment = False
i = 0
while i < len(sql):
ch = sql[i]
next_ch = sql[i + 1] if i + 1 < len(sql) else ""
if in_line_comment:
current.append(ch)
if ch == "\n":
in_line_comment = False
elif in_block_comment:
current.append(ch)
if ch == "*" and next_ch == "/":
current.append("/")
i += 1
in_block_comment = False
elif quote_char:
current.append(ch)
if ch == quote_char and next_ch == quote_char:
current.append(quote_char)
i += 1
elif ch == quote_char:
quote_char = ""
elif (ch == "-" and next_ch == "-") or (ch == "#"):
in_line_comment = True
current.append(ch)
elif ch == "/" and next_ch == "*":
in_block_comment = True
current.append(ch)
elif ch in ("'", '"', "`"):
quote_char = ch
current.append(ch)
elif ch == ";":
stmt = "".join(current).strip()
if stmt:
statements.append(stmt)
current = []
else:
current.append(ch)
i += 1
stmt = "".join(current).strip()
if stmt:
statements.append(stmt)
return statements
def first_keyword(sql):
"""Return the first SQL keyword from a statement, skipping --, #, and /* */ comments."""
i = 0
while i < len(sql):
ch = sql[i]
next_ch = sql[i + 1] if i + 1 < len(sql) else ""
if ch in (" ", "\t", "\n", "\r"):
i += 1
elif (ch == "-" and next_ch == "-") or ch == "#":
nl = sql.find("\n", i)
i = nl + 1 if nl != -1 else len(sql)
elif ch == "/" and next_ch == "*":
end = sql.find("*/", i + 2)
i = end + 2 if end != -1 else len(sql)
else:
# Found start of a token → read until whitespace or special chars
j = i
while j < len(sql) and sql[j] not in (" ", "\t", "\n", "\r", "(", ";"):
j += 1
return sql[i:j].upper()
return ""
def execute_query_group(connection, q_list, query_id, settings):
"""
Execute a group of SQL statements sequentially and return the total server-side elapsed time.
Some benchmark queries (e.g. TPC-DS Q14) consist of multiple SELECT statements in one file.
We run them together and sum the elapsed time so that they appear as a single entry in the performance report.
"""
total = 0
for q in q_list:
connection.execute(q, query_id=query_id, settings=settings)
total += connection.last_query.elapsed
return total
def load_settings_file(xml_root, base_dir):
"""Load settings from a JSON file referenced by <settings file="..."/> attribute."""
elem = xml_root.find("settings")
if elem is None or "file" not in elem.attrib:
return {}
path = os.path.join(base_dir, elem.attrib["file"])
with open(path, "r", encoding="utf-8") as f:
return json.load(f)["settings"]
# Build a list of test queries, substituting parameters to query templates.
# Queries can be specified inline or loaded from external files via the "file" attribute.
# Multi-statement files (e.g. TPC-H Q15: CREATE VIEW; SELECT; DROP VIEW) are split:
# CREATE/DROP become global setup/teardown queries, and only the SELECT becomes the timed test query.
# This is a simplification: the setup/teardown is shared across all queries, not per-query.
# This works, but will break if two query files create views with the same name.
# Not worth fixing properly unless we have such scenario, the whole perf test suite needs a rewrite.
extra_create_queries = []
extra_drop_queries = []
# Each entry is a "query item" dict describing one timed unit of work:
# {"kind": "sql", "statements": [...]} -- run over the native protocol,
# {"kind": "shell", "script": "..."} -- run as a bash script, see below.
test_queries = []
for e in root.findall("query"):
if e.get("type") == "shell":
# A shell-script query: a snippet of bash executed for each server and
# measured by its wall-clock time. This lets us benchmark things the
# native protocol cannot express -- HTTP end-to-end latency, response
# compression, tool startup time, etc. The script talks to the server
# using the $CLICKHOUSE_* environment variables (binary, host, ports,
# client, local, curl, url) prepared per-server, mirroring the stateless
# tests in tests/queries/shell_config.sh.
#
# Parameter substitution is intentionally NOT applied to shell scripts,
# because they routinely use '${var}' and '{a,b}' brace expansion that
# would collide with the '{name}' substitution syntax. Settings from the
# <settings> element are not applied either -- pass them via the URL or
# client arguments inside the script.
if not e.text or not e.text.strip():
raise Exception('Empty <query type="shell"> in the test file')
test_queries.append({"kind": "shell", "script": e.text})
continue
if "file" in e.attrib:
query_path = os.path.join(xml_dir, e.attrib["file"])
with open(query_path, "r", encoding="utf-8") as f:
full_text = f.read().strip()
statements = split_sql_statements(full_text)
select_stmts = []
for stmt in statements:
keyword = first_keyword(stmt)
if keyword in ("CREATE", "ALTER"):
extra_create_queries.append(stmt)
elif keyword in ("DROP", "TRUNCATE"):
extra_drop_queries.append(stmt)
else:
select_stmts.append(stmt)
# Some benchmark queries (e.g. TPC-DS Q14) have multiple SELECTs in one file.
# They are executed together and timed as a single entry in the report.
# Substitution parameters are expanded per-statement and then zipped, so that each group contains statements with same parameters.
# Example:
# select_stmts = ["SELECT FROM {t}.x", "SELECT FROM {t}.y"], {t} = [a, b]
# expanded = [["SELECT FROM a.x", "SELECT FROM b.x"], ["SELECT FROM a.y", "SELECT FROM b.y"]]
# zip(*expanded) -> ("SELECT FROM a.x", "SELECT FROM a.y"), ("SELECT FROM b.x", "SELECT FROM b.y")
expanded = [substitute_parameters([s]) for s in select_stmts]
for group in zip(*expanded):
test_queries.append({"kind": "sql", "statements": list(group)})
else:
test_queries += [
{"kind": "sql", "statements": [s]} for s in substitute_parameters([e.text])
]
def query_display(item):
"""Human-readable representation of a query item for the report."""
if item["kind"] == "shell":
return item["script"]
return ";\n".join(item["statements"])
# If we're given a list of queries to run, check that it makes sense.
for i in args.queries_to_run or []:
if i < 0 or i >= len(test_queries):
print(
f"There is no query no. {i} in this test, only [{0}-{len(test_queries) - 1}] are present"
)
exit(1)
# If we're only asked to print the queries, do that and exit.
if args.print_queries:
for i in args.queries_to_run or range(0, len(test_queries)):
print(query_display(test_queries[i]))
exit(0)
# If we're only asked to print the settings, do that and exit. These are settings
# for clickhouse-benchmark, so we print them as command line arguments, e.g.
# '--max_memory_usage=10000000'.
if args.print_settings:
# Settings from JSON file: <settings file="path/to/settings.json"/>
for key, value in load_settings_file(root, xml_dir).items():
print(f"--{key}={value}")
# Inline settings: <settings><key>value</key></settings> (can override file settings)
for s in root.findall("settings/*"):
print(f"--{s.tag}={s.text}")
exit(0)
# Skip long tests
if not args.long:
for tag in root.findall(".//tag"):
if tag.text == "long":
print("skipped\tTest is tagged as long.")
sys.exit(0)
# Shell-script queries do not yet carry the connection options that the SQL path
# honours. SQL queries connect through `clickhouse_driver.Client` with `--user` /
# `--password` / `--secure`, but the per-server shell environment built by
# `shell_env_for` always uses an unauthenticated, plaintext `$CLICKHOUSE_CLIENT`
# and a `http://` `$CLICKHOUSE_URL`. Running shell queries under non-default
# credentials or TLS would therefore either fail outright or, worse, measure a
# different (default plaintext) endpoint than the SQL setup/prewarm connected to,
# silently invalidating the comparison. Until the shell helpers carry these
# options, fail closed: reject the test up front rather than benchmark the wrong
# endpoint. (Done after the `--print-queries` / `--print-settings` early exits so
# those read-only paths are unaffected.)
if any(q["kind"] == "shell" for q in test_queries) and (
args.user != "default" or args.password != "" or args.secure
):
raise Exception(
'Shell-script queries (<query type="shell">) do not support the '
"--user / --password / --secure connection options yet: the shell "
"environment always connects without authentication over plaintext HTTP. "
"Remove these options, or run this test without shell-script queries."
)
# Print report threshold for the test if it is set.
ignored_relative_change = 0.05
if "max_ignored_relative_change" in root.attrib:
ignored_relative_change = float(root.attrib["max_ignored_relative_change"])
print(f"report-threshold\t{ignored_relative_change}")
reportStageEnd("before-connect")
# Open connections
servers = [
{ "host": host or args.host[0], "port": port or args.port[0], "user": args.user, "password": args.password, "secure": args.secure }
for (host, port) in itertools.zip_longest(args.host, args.port)
]
# Force settings_is_important to fail queries on unknown settings.
all_connections = [
clickhouse_driver.Client(**server, settings_is_important=True) for server in servers
]
# Long-lived workers to fan out per-connection commands (SYSTEM JEMALLOC PURGE
# etc.) in parallel so both servers see the same operation at the same wall
# clock moment.
purge_pool = ThreadPoolExecutor(max_workers=max(1, len(all_connections)))
def nth_or_first(seq, index):
"""Value parallel to server `index`, reusing the first one for a short list
(e.g. a single --binary shared by every server)."""
return seq[index] if index < len(seq) else seq[0]
def shell_env_for(conn_index):
"""Build the environment for a shell-script query targeting server
`conn_index`. The variable names mirror tests/queries/shell_config.sh so that
perf shell scripts look like ordinary stateless tests. Each server gets its
own binary, ports and derived commands, so the same script measures the LEFT
and the RIGHT build independently."""
server = servers[conn_index]
host = str(server["host"])
tcp_port = str(server["port"])
http_port = str(nth_or_first(args.http_port, conn_index))
binary = nth_or_first(args.binary, conn_index)
# Resolve a relative path (e.g. 'left/clickhouse') to an absolute one so the
# script can be run from any working directory. A bare name like 'clickhouse'
# is left untouched and resolved via $PATH.
if "/" in binary:
binary = os.path.abspath(binary)
env = dict(os.environ)
env["CLICKHOUSE_BINARY"] = binary
env["CLICKHOUSE_HOST"] = host
env["CLICKHOUSE_PORT_TCP"] = tcp_port
env["CLICKHOUSE_PORT_HTTP"] = http_port
env["CLICKHOUSE_DATABASE"] = "default"
env["CLICKHOUSE_CLIENT"] = f"{binary} client --host {host} --port {tcp_port}"
env["CLICKHOUSE_LOCAL"] = f"{binary} local"
# `--fail` makes curl exit non-zero on an HTTP 4xx/5xx response, and `-S`
# prints the error even under `-s`. Unlike tests/queries/shell_config.sh
# (which omits `--fail` because some stateless tests inspect error bodies),
# a performance benchmark must fail closed: otherwise an HTTP error response
# would be timed and reported as a fast successful sample, silently
# invalidating the comparison.
env["CLICKHOUSE_CURL"] = "curl -q -sS --fail --max-time 120"
env["CLICKHOUSE_URL"] = f"http://{host}:{http_port}/"
return env
shell_envs = {}
def run_shell_query(conn_index, script, timeout):
"""Run a shell-script query for one server and return its wall-clock time.
The script is executed with `bash -e -o pipefail` in its own session
(`start_new_session=True`), so the whole process tree it spawns shares one
process group. On timeout the entire group is killed: `subprocess` alone
would only terminate the immediate `bash`, leaving children such as `curl`
or `$CLICKHOUSE_LOCAL` running, which could keep consuming CPU/network or
hold a server-side query open and pollute later measurements. Standard
output is discarded (the script itself decides what to read and where to
write it); standard error is captured for diagnostics. A non-zero exit code
raises an exception, which the caller treats the same way as a failed SQL
query."""
env = shell_envs.setdefault(conn_index, shell_env_for(conn_index))
start = time.perf_counter()
proc = subprocess.Popen(
["bash", "-e", "-o", "pipefail", "-c", script],
env=env,
stdin=subprocess.DEVNULL,
stdout=subprocess.DEVNULL,
stderr=subprocess.PIPE,
start_new_session=True,
)
try:
_, stderr_bytes = proc.communicate(timeout=timeout)
except subprocess.TimeoutExpired:
# Kill the whole process group, not just `bash`, then reap it.
try:
os.killpg(os.getpgid(proc.pid), signal.SIGKILL)
except ProcessLookupError:
pass
proc.communicate()
raise
elapsed = time.perf_counter() - start
if proc.returncode != 0:
stderr = stderr_bytes.decode("utf-8", errors="replace").strip()
raise Exception(
f"Shell query failed on server {conn_index} with exit code "
f"{proc.returncode}:\n{stderr}"
)
return elapsed
for i, s in enumerate(servers):
ssl_status = "SSL" if s["secure"] else "no-SSL"
print(f'server\t{i}\t{s["host"]}\t{s["port"]}\t{s["user"]}\t{ssl_status}')
reportStageEnd("connect")
if not args.use_existing_tables:
# Run drop queries, ignoring errors. Do this before all other activity,
# because clickhouse_driver disconnects on error (this is not configurable),
# and the new connection loses the changes in settings.
drop_query_templates = [q.text for q in root.findall("drop_query")]
drop_query_templates += extra_drop_queries
drop_queries = substitute_parameters(drop_query_templates)
for conn_index, c in enumerate(all_connections):
for q in drop_queries:
try:
c.execute(q)
print(f"drop\t{conn_index}\t{c.last_query.elapsed}\t{tsv_escape(q)}")
except:
pass
reportStageEnd("drop-1")
# First apply JSON settings (<settings file="..."/>), then inline (<settings><key>value</key></settings>).
# Inline settings override file settings.
file_settings = load_settings_file(root, xml_dir)
inline_settings = root.findall("settings/*")
for conn_index, c in enumerate(all_connections):
for key, value in file_settings.items():
c.settings[key] = str(value)
for s in inline_settings:
c.settings[s.tag] = s.text
# We have to perform a query to make sure the settings work. Otherwise an
# unknown setting will lead to failing precondition check, and we will skip
# the test, which is wrong.
c.execute("select 1")
reportStageEnd("settings")
if not args.use_existing_tables:
# Run create and fill queries. We will run them simultaneously for both
# servers, to save time. The weird XML search + filter is because we want to
# keep the relative order of elements, and etree doesn't support the
# appropriate xpath query.
create_query_templates = [
q.text for q in root.findall("./*") if q.tag in ("create_query", "fill_query")
]
create_query_templates += extra_create_queries
create_queries = substitute_parameters(create_query_templates)
# Disallow temporary tables, because the clickhouse_driver reconnects on
# errors, and temporary tables are destroyed. We want to be able to continue
# after some errors.
for q in create_queries:
if re.search("create temporary table", q, flags=re.IGNORECASE):
print(
f"Temporary tables are not allowed in performance tests: '{q}'",
file=sys.stderr,
)
sys.exit(1)
def do_create(connection, index, queries):
for q in queries:
connection.execute(q)
print(f"create\t{index}\t{connection.last_query.elapsed}\t{tsv_escape(q)}")
threads = [
SafeThread(target=do_create, args=(connection, index, create_queries))
for index, connection in enumerate(all_connections)
]
for t in threads:
t.start()
for t in threads:
t.join()
reportStageEnd("create")
def purge_jemalloc_on_all_connections(reason):
def purge_one(indexed_conn):
conn_index, c = indexed_conn
try:
c.execute("SYSTEM JEMALLOC PURGE")
return f"purging jemalloc arenas\t{conn_index}\t{c.last_query.elapsed}\t{reason}"
except KeyboardInterrupt:
raise
except:
return None
for line in purge_pool.map(purge_one, enumerate(all_connections)):
if line:
print(line)
if args.jemalloc_purge != "disabled":
purge_jemalloc_on_all_connections("after-fill")
# Let's sync the data to avoid writeback affects performance
os.system("sync")
reportStageEnd("sync")
# By default, test all queries.
queries_to_run = range(0, len(test_queries))
if args.max_queries:
# If specified, test a limited number of queries chosen at random.
queries_to_run = random.sample(
range(0, len(test_queries)), min(len(test_queries), args.max_queries)
)
if args.queries_to_run:
# Run the specified queries.
queries_to_run = args.queries_to_run
# Run test queries.
profile_total_seconds = 0
for query_index in queries_to_run:
q_item = test_queries[query_index]
query_prefix = f"{test_name}.query{query_index}"
# We have some crazy long queries (about 100kB), so trim them to a sane
# length. This means we can't use query text as an identifier and have to
# use the test name + the test-wide query index.
query_display_name = query_display(q_item)
if len(query_display_name) > 1000:
query_display_name = f"{query_display_name[:1000]}...({query_index})"
print(f"display-name\t{query_index}\t{tsv_escape(query_display_name)}")
if args.jemalloc_purge in ("before-each-query", "before-each-run"):
purge_jemalloc_on_all_connections(f"before-query-{query_index}")
# Prewarm: run once on both servers. Helps to bring the data into memory,
# precompile the queries, etc.
# A query might not run on the old server if it uses a function added in the
# new one. We want to run them on the new server only, so that the PR author
# can ensure that the test works properly. Remember the errors we had on
# each server.
query_error_on_connection = [None] * len(all_connections)
for conn_index, c in enumerate(all_connections):
try:
prewarm_id = f"{query_prefix}.prewarm0"
if q_item["kind"] == "shell":
# A failing shell script on the old server (e.g. it uses a tool
# option added in the new build) is handled the same way as a
# failing SQL query: the run continues on the rest of the servers.
prewarm_elapsed = run_shell_query(
conn_index, q_item["script"], args.prewarm_max_query_seconds
)
else:
try:
# During the warm-up runs, we will also:
# * detect queries that are exceedingly long, to fail fast,
# * collect profiler traces, which might be helpful for analyzing
# test coverage. We disable profiler for normal runs because
# it makes the results unstable.
prewarm_elapsed = execute_query_group(
c,
q_item["statements"],
prewarm_id,
{
"max_execution_time": args.prewarm_max_query_seconds,
"query_profiler_real_time_period_ns": 10000000,
"query_profiler_cpu_time_period_ns": 10000000,
"metrics_perf_events_enabled": 1,
"memory_profiler_step": "4Mi",
},
)
except clickhouse_driver.errors.Error as e:
# Add query id to the exception to make debugging easier.
e.args = (prewarm_id, *e.args)
e.message = prewarm_id + ": " + e.message
raise
print(
f"prewarm\t{query_index}\t{prewarm_id}\t{conn_index}\t{prewarm_elapsed}"
)
except KeyboardInterrupt:
raise
except:
# FIXME the driver reconnects on error and we lose settings, so this
# might lead to further errors or unexpected behavior.
query_error_on_connection[conn_index] = traceback.format_exc()
continue
# Report all errors that occurred during prewarm and decide what to do next.
# If prewarm fails for the query on all servers -- skip the query and
# continue testing the next query.
# If prewarm fails on one of the servers, run the query on the rest of them.
no_errors = []
for i, e in enumerate(query_error_on_connection):
if e:
print(e, file=sys.stderr)
else:
no_errors.append(i)
# A shell-script query is a benchmark we control end to end, so -- unlike an
# SQL query that may legitimately use a function missing from the old server
# -- it is expected to run on every server. If it fails on any of them the
# comparison is meaningless. Previously such a failure was swallowed as a
# "partial" query: the run continued on whatever server survived and the
# query was dropped from the report and CIDB with no error anywhere (empty
# run-errors.tsv, green job), so a broken shell test looked like it simply
# produced no data. Fail loudly instead, and echo the captured error from
# each failing server to stdout as a `run-error` line so it survives in the
# archived per-test raw .tsv (the per-test stderr log is not uploaded).
# compare.sh parses raw .tsv by known leading tag and ignores the rest, so
# adding this tag is safe.
if q_item["kind"] == "shell" and len(no_errors) < len(all_connections):
failed = []
for i, e in enumerate(query_error_on_connection):
if e:
failed.append(i)
print(f"run-error\t{query_index}\t{i}\t{tsv_escape(e)}")
# Flush before raising so the diagnostics reach the raw .tsv even though
# we are about to exit through an unhandled exception.
sys.stdout.flush()
raise Exception(
f"Shell query {query_prefix} failed on server(s) {failed}: a shell "
"performance test must run on all servers to be comparable. See the "
"'run-error' lines in the raw output for the captured stderr."
)
if len(no_errors) == 0:
continue
elif len(no_errors) < len(all_connections):
print(f"partial\t{query_index}\t{no_errors}")
this_query_connections = [all_connections[index] for index in no_errors]
# Now, perform measured runs.
# Track the time spent by the client to process this query, so that we can
# notice the queries that take long to process on the client side, e.g. by
# sending excessive data.
start_seconds = time.perf_counter()
server_seconds = 0
profile_seconds = 0
run = 0
# Arrays of run times for each connection.
all_server_times = []
for conn_index, c in enumerate(this_query_connections):
all_server_times.append([])
while True:
run_id = f"{query_prefix}.run{run}"
if args.jemalloc_purge == "before-each-run":
purge_jemalloc_on_all_connections(f"before-{run_id}")
# Alternate the server order each measured run (L,R,R,L,L,R,...) so that
# the post-query / pre-purge idle time averages out between connections.
conn_order = list(enumerate(this_query_connections))
if run % 2 == 1:
conn_order = list(reversed(conn_order))
for conn_index, c in conn_order:
# conn_index addresses this_query_connections (the servers that
# survived prewarm); map it back to the real server to pick the right
# binary/ports for a shell query.
server_index = no_errors[conn_index]
if q_item["kind"] == "shell":
try:
elapsed = run_shell_query(
server_index, q_item["script"], args.max_query_seconds
)
except KeyboardInterrupt:
raise
except Exception as e:
raise Exception(f"{run_id}: {e}")
else:
try:
elapsed = execute_query_group(
c,
q_item["statements"],
run_id,
{"max_execution_time": args.max_query_seconds},
)
except clickhouse_driver.errors.Error as e:
# Add query id to the exception to make debugging easier.
e.args = (run_id, *e.args)
e.message = run_id + ": " + e.message
raise
all_server_times[conn_index].append(elapsed)
server_seconds += elapsed
print(f"query\t{query_index}\t{run_id}\t{conn_index}\t{elapsed}")
if elapsed > args.max_query_seconds:
# Do not stop processing pathologically slow queries,
# since this may hide errors in other queries.
print(
f"The query no. {query_index} is taking too long to run ({elapsed} s)",
file=sys.stderr,
)
# Be careful with the counter, after this line it's the next iteration
# already.
run += 1
avg_time_per_server = server_seconds / len(this_query_connections)
# We break if all the min stop conditions are met (1 second arg.runs iterations)
# or at lest one of the max stop conditions is met (8 seconds or 500 iterations)
if (avg_time_per_server >= 1 and run >= args.runs) or (
avg_time_per_server >= 8 or run >= 500
):
break
client_seconds = time.perf_counter() - start_seconds
print(f"client-time\t{query_index}\t{client_seconds}\t{server_seconds}")
median = [statistics.median(t) for t in all_server_times]
print(f"median\t{query_index}\t{median[0]}")
# Run additional profiling queries to collect profile data, but only if test times appeared to be different.
# We have to do it after normal runs because otherwise it will affect test statistics too much
if len(all_server_times) != 2:
continue
if len(all_server_times[0]) < 3:
# Don't fail if for some reason there are not enough measurements.
continue
pvalue = stats.ttest_ind(
all_server_times[0], all_server_times[1], equal_var=False
).pvalue
# Keep this consistent with the value used in report. Should eventually move
# to (median[1] - median[0]) / min(median), which is compatible with "times"
# difference we use in report (max(median) / min(median)).
relative_diff = (median[1] - median[0]) / median[0]
print(f"diff\t{query_index}\t{median[0]}\t{median[1]}\t{relative_diff}\t{pvalue}")
if abs(relative_diff) < ignored_relative_change or pvalue > 0.05:
continue
if q_item["kind"] == "shell":
# The server-side profiler runs cannot be attributed to a shell script
# (there is no single query to profile), so we stop after reporting the
# timing difference.
continue
# Perform profile runs for fixed amount of time. Don't limit the number
# of runs, because we also have short queries.
profile_start_seconds = time.perf_counter()
run = 0
while time.perf_counter() - profile_start_seconds < args.profile_seconds:
run_id = f"{query_prefix}.profile{run}"
for conn_index, c in enumerate(this_query_connections):
try:
profile_elapsed = execute_query_group(
c,
q_item["statements"],
run_id,
{
"query_profiler_real_time_period_ns": 10000000,
"query_profiler_cpu_time_period_ns": 10000000,
"metrics_perf_events_enabled": 1,
# Dedicated profile runs are not timed, so we can afford
# the overhead of allocation sampling to also collect
# MemorySample and JemallocSample stacks for flamegraphs.
"memory_profiler_sample_probability": 0.1,
"jemalloc_enable_profiler": 1,
"jemalloc_collect_profile_samples_in_trace_log": 1,
},
)
print(
f"profile\t{query_index}\t{run_id}\t{conn_index}\t{profile_elapsed}"
)
except clickhouse_driver.errors.Error as e:
# Add query id to the exception to make debugging easier.
e.args = (run_id, *e.args)
e.message = run_id + ": " + e.message
raise
run += 1
profile_total_seconds += time.perf_counter() - profile_start_seconds
print(f"profile-total\t{profile_total_seconds}")
reportStageEnd("run")
# Run drop queries
if not args.keep_created_tables and not args.use_existing_tables:
drop_queries = substitute_parameters(drop_query_templates)
for conn_index, c in enumerate(all_connections):
for q in drop_queries:
c.execute(q)
print(f"drop\t{conn_index}\t{c.last_query.elapsed}\t{tsv_escape(q)}")
reportStageEnd("drop-2")