From 86f2c0310ce4d647ea51797f3d8ed8ba23eaf2fe Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Mon, 21 Mar 2022 20:49:45 -0400 Subject: [PATCH 1/8] Basic scripting support for debezium/perf runs. --- debezium/demo/docker-compose.yml | 1 + debezium/perf/docker-compose.yml | 1 + debezium/perf/mzcli_load.sh | 5 ++ debezium/perf/mzcli_sampling_dt.sh | 14 +++++ debezium/perf/pid_from_cmdline.py | 49 +++++++++++++++++ debezium/perf/sample_top.py | 84 ++++++++++++++++++++++++++++++ debezium/perf/start_common.sh | 5 ++ debezium/perf/start_dh.sh | 5 ++ debezium/perf/start_mz.sh | 5 ++ debezium/perf/stop_common.sh | 5 ++ debezium/perf/stop_dh.sh | 5 ++ debezium/perf/stop_mz.sh | 5 ++ debezium/scripts/sample_dt.py | 16 ++++++ debezium/scripts/sample_dt.sql | 5 ++ 14 files changed, 205 insertions(+) create mode 100755 debezium/perf/mzcli_load.sh create mode 100755 debezium/perf/mzcli_sampling_dt.sh create mode 100644 debezium/perf/pid_from_cmdline.py create mode 100644 debezium/perf/sample_top.py create mode 100755 debezium/perf/start_common.sh create mode 100755 debezium/perf/start_dh.sh create mode 100755 debezium/perf/start_mz.sh create mode 100755 debezium/perf/stop_common.sh create mode 100755 debezium/perf/stop_dh.sh create mode 100755 debezium/perf/stop_mz.sh create mode 100644 debezium/scripts/sample_dt.py create mode 100644 debezium/scripts/sample_dt.sql diff --git a/debezium/demo/docker-compose.yml b/debezium/demo/docker-compose.yml index 5927f7a2ace..e1abe7df828 100644 --- a/debezium/demo/docker-compose.yml +++ b/debezium/demo/docker-compose.yml @@ -10,6 +10,7 @@ services: service: server volumes: - ../scripts:/scripts + - ./logs:/logs web: extends: diff --git a/debezium/perf/docker-compose.yml b/debezium/perf/docker-compose.yml index 1fede60aba8..cc992598c53 100644 --- a/debezium/perf/docker-compose.yml +++ b/debezium/perf/docker-compose.yml @@ -17,6 +17,7 @@ services: # - JAVA_TOOL_OPTIONS=-agentpath:/opt/jprofiler13.0/bin/linux-x64/libjprofilerti.so=port=8849,nowait -Xmx4g -Ddeephaven.console.type=${DEEPHAVEN_CONSOLE_TYPE} -Ddeephaven.application.dir=${DEEPHAVEN_APPLICATION_DIR} volumes: - ../scripts:/scripts + - ./logs:/logs # For jprofiler sessions: (change if using different port) # ports: # - '8849:8849' diff --git a/debezium/perf/mzcli_load.sh b/debezium/perf/mzcli_load.sh new file mode 100755 index 00000000000..536bf5d5a5b --- /dev/null +++ b/debezium/perf/mzcli_load.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -ex + +exec docker-compose run -T mzcli -f /scripts/demo.sql diff --git a/debezium/perf/mzcli_sampling_dt.sh b/debezium/perf/mzcli_sampling_dt.sh new file mode 100755 index 00000000000..ffa4d1026e6 --- /dev/null +++ b/debezium/perf/mzcli_sampling_dt.sh @@ -0,0 +1,14 @@ +#!/bin/bash + +set -ex + +DATE_TAG=$(date '+%Y.%m.%d.%H.%M.%S_%Z') +DATA_TAG="mz_sample_dt" +OUT=logs/${DATE_TAG}_${DATA_TAG}.log + +(nohup docker-compose run -T --entrypoint /bin/bash mzcli -c " +while true; do + psql --csv -A -t -f /scripts/sample_dt.sql -U materialize -h materialized -p 6875 + sleep 1 +done" < /dev/null >& $OUT &) + diff --git a/debezium/perf/pid_from_cmdline.py b/debezium/perf/pid_from_cmdline.py new file mode 100644 index 00000000000..4af45090502 --- /dev/null +++ b/debezium/perf/pid_from_cmdline.py @@ -0,0 +1,49 @@ +import argparse +import datetime as dt +import os +import re +import subprocess +import sys + +parser = argparse.ArgumentParser(description='Match process command line regex to pid') +parser.add_argument('proc_specs_strs', metavar='PROCSPEC', type=str, nargs='+', + help='a string of the form "name:regex" where regex should only match one process in `ps -o command` output') + +args = parser.parse_args() + +proc_specs = {} +for proc_spec_str in args.proc_specs_strs: + name, regex_str = proc_spec_str.split(':', maxsplit=1) + proc_specs[name] = re.compile(regex_str) + +ps_lines = subprocess.run(['ps', '-ahxww', '-o', 'pid,command' ], stdout=subprocess.PIPE).stdout.decode('utf-8').splitlines() + +matches = {} +nmatches = 0 +my_pid = f'{os.getpid()}' + +for ps_line in ps_lines: + pid, cmd = ps_line.split(maxsplit=1) + if pid == my_pid: + continue + for name, regex in proc_specs.items(): + if re.search(regex, cmd) is not None: + prev = matches.get(name, None) + if prev is not None: + print(sys.argv[0] + f": found more than one match for '{name}': {prev}, {pid}, aborting", file=sys.stderr) + sys.exit(1) + matches[name] = pid + +for name in proc_specs.keys(): + if matches.get(name, None) is None: + print(sys.argv[0] + f": couldn't find a match for {name}, aborting", file=sys.stderr) + sys.exit(1) + +first = True +for name, pid in matches.items(): + s = f'{name}:{pid}' + if not first: + s = ' ' + s + print(s, end='') + first = False +print() diff --git a/debezium/perf/sample_top.py b/debezium/perf/sample_top.py new file mode 100644 index 00000000000..015da36076a --- /dev/null +++ b/debezium/perf/sample_top.py @@ -0,0 +1,84 @@ +import argparse +import datetime as dt +import re +import subprocess +import statistics as stats + +now_str = dt.datetime.now().astimezone().strftime('%Y%m%d%H%M%S_%Z') + +parser = argparse.ArgumentParser(description='Sample cpu utilization and memory consumption with top for given processes') + +parser.add_argument('tag', metavar='TAG', type=str, + help='experiment tag') +parser.add_argument('nsamples', metavar='NSAMPLES', type=int, + help='number of samples') +parser.add_argument('delay_s', metavar='DELAY_MS', type=str, + help='delay between samples, in seconds') +parser.add_argument('proc_specs_strs', metavar='PROCSPEC', type=str, nargs='+', + help='a string of the form "name:pid"') + +args = parser.parse_args() + +proc_specs = {} +pids = [] +pids_args = [] +name_pidre = {} +for proc_spec_str in args.proc_specs_strs: + name, pid = proc_spec_str.split(':', maxsplit=1) + pids.append(pid) + pids_args.append('-p') + pids_args.append(pid) + name_pidre[name] = re.compile(f'^{pid} ') + proc_specs[name] = pid + +top_out = subprocess.run( + ['top', '-Eg', '-n', f'{args.nsamples}', '-b', '-c', '-d', f'{args.delay_s}'] + pids_args, + stdout=subprocess.PIPE).stdout.decode('utf-8').splitlines() + +with open(f'logs/{now_str}_{args.tag}_top_details.log', 'w') as f: + for line in top_out: + f.write(line) + f.write('\n') + +cputag = 'CPU_PCT' +restag = 'RES_GiB' + +kib_2_gib = 1.0/(1024 * 1024) + +results={} +for line in top_out: + for name, regex in name_pidre.items(): + if re.search(regex, line) is not None: + cols = line.split(maxsplit=12) + pid = proc_specs[name] + d = results.get(name, None) + if d is None: + d = results[name] = { cputag : [], restag : [] } + cpu = float(cols[8]) + d[cputag].append(cpu) + res_str = cols[5] + if res_str.endswith('g'): + res_kib = float(res_str[:-1])*1024*1024 + elif res_str.endswith('m'): + res_kib = float(res_str[:-1])*1024 + else: + res_kib = int(res_str) + d[restag].append(res_kib * kib_2_gib) + +def format_samples(precision, samples): + first = True + s = '' + for sample in samples: + if not first: + s += ', ' + s += f'%.{precision}f' % sample + first = False + +with open(f'logs/{now_str}_{args.tag}_top_samples.log', 'w') as f: + for name, result in results.items(): + for tag, samples in result.items(): + mean = stats.mean(samples) + samples_str = format_samples(samples) + line = f'name={name}, tag={tag}, mean={mean:.2f}, samples={samples_str}' + print(line) + f.write(line + '\n') diff --git a/debezium/perf/start_common.sh b/debezium/perf/start_common.sh new file mode 100755 index 00000000000..1f74b59885b --- /dev/null +++ b/debezium/perf/start_common.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -ex + +exec docker-compose up -d mysql redpanda debezium loadgen diff --git a/debezium/perf/start_dh.sh b/debezium/perf/start_dh.sh new file mode 100755 index 00000000000..15989bf9271 --- /dev/null +++ b/debezium/perf/start_dh.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -ex + +exec docker-compose up -d mysql redpanda debezium loadgen server grpc-proxy envoy web diff --git a/debezium/perf/start_mz.sh b/debezium/perf/start_mz.sh new file mode 100755 index 00000000000..637f8bbe60e --- /dev/null +++ b/debezium/perf/start_mz.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -ex + +exec docker-compose up -d mysql redpanda debezium loadgen materialized mzcli diff --git a/debezium/perf/stop_common.sh b/debezium/perf/stop_common.sh new file mode 100755 index 00000000000..d2d7534cda9 --- /dev/null +++ b/debezium/perf/stop_common.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -ex + +exec docker-compose stop mysql redpanda debezium loadgen diff --git a/debezium/perf/stop_dh.sh b/debezium/perf/stop_dh.sh new file mode 100755 index 00000000000..5963f164243 --- /dev/null +++ b/debezium/perf/stop_dh.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -ex + +exec docker-compose stop web envoy grpc-proxy server diff --git a/debezium/perf/stop_mz.sh b/debezium/perf/stop_mz.sh new file mode 100755 index 00000000000..62d07fa247d --- /dev/null +++ b/debezium/perf/stop_mz.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -ex + +exec docker-compose stop materialized mzcli diff --git a/debezium/scripts/sample_dt.py b/debezium/scripts/sample_dt.py new file mode 100644 index 00000000000..21b7fcaf93e --- /dev/null +++ b/debezium/scripts/sample_dt.py @@ -0,0 +1,16 @@ +from deephaven import PythonListenerAdapter +import datetime as dt + +now_str = dt.datetime.now().astimezone().strftime('%Y%m%d%H%M%S_%Z') + +log = open(f'/logs/{now_str}_dh_sample_dt.log', 'w') + +def onUpdate(added_unused, modified_unused, deleted_unused): + timestamp = dt.datetime.now().astimezone().isoformat() + total = pageviews_summary.getColumn('total').get(0) + max_received_at = pageviews_summary.getColumn('max_received_at').get(0) + dt_ms = pageviews_summary.getColumn('dt_ms').get(0) + log.write(f'timestamp={timestamp}, total={total}, max_received_at={max_received_at}, dt_ms={dt_ms}\n') + log.flush() + +PythonListenerAdapter(pageviews_summary, onUpdate, replayInitialImage=False) diff --git a/debezium/scripts/sample_dt.sql b/debezium/scripts/sample_dt.sql new file mode 100644 index 00000000000..a482b392d02 --- /dev/null +++ b/debezium/scripts/sample_dt.sql @@ -0,0 +1,5 @@ +SELECT + total, + to_timestamp(max_received_at) max_received_ts, + mz_logical_timestamp() - max_received_at*1000 AS dt_ms +FROM pageviews_summary; From a328b85d04c09540887048e50b0a6bb5343c0e9c Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Mon, 21 Mar 2022 21:22:40 -0400 Subject: [PATCH 2/8] Small tweaks. --- debezium/perf/sample_top.py | 17 +++++++++++------ debezium/perf/start_common.sh | 5 +++++ debezium/perf/start_dh.sh | 5 +++++ debezium/perf/start_mz.sh | 5 +++++ debezium/perf/stop_all.sh | 3 +++ debezium/scripts/sample_dt.py | 2 +- 6 files changed, 30 insertions(+), 7 deletions(-) create mode 100755 debezium/perf/stop_all.sh diff --git a/debezium/perf/sample_top.py b/debezium/perf/sample_top.py index 015da36076a..6b60bccb02e 100644 --- a/debezium/perf/sample_top.py +++ b/debezium/perf/sample_top.py @@ -4,7 +4,7 @@ import subprocess import statistics as stats -now_str = dt.datetime.now().astimezone().strftime('%Y%m%d%H%M%S_%Z') +now_str = dt.datetime.now().astimezone().strftime('%Y.%m.%d.%H.%M.%S_%Z') parser = argparse.ArgumentParser(description='Sample cpu utilization and memory consumption with top for given processes') @@ -40,8 +40,8 @@ f.write(line) f.write('\n') -cputag = 'CPU_PCT' -restag = 'RES_GiB' +cputag = 'CPU_PCT' # CPU utilization in percentage +restag = 'RES_GiB' # Resident size in GiB kib_2_gib = 1.0/(1024 * 1024) @@ -65,20 +65,25 @@ res_kib = int(res_str) d[restag].append(res_kib * kib_2_gib) -def format_samples(precision, samples): +def format_samples(precision : int, samples): first = True s = '' for sample in samples: if not first: s += ', ' - s += f'%.{precision}f' % sample + if precision != -1: + s += f'{sample:.{precision}}' + else: + s += f'{sample}' first = False + return s with open(f'logs/{now_str}_{args.tag}_top_samples.log', 'w') as f: for name, result in results.items(): for tag, samples in result.items(): mean = stats.mean(samples) - samples_str = format_samples(samples) + precision = 4 if tag == restag else -1 + samples_str = format_samples(precision, samples) line = f'name={name}, tag={tag}, mean={mean:.2f}, samples={samples_str}' print(line) f.write(line + '\n') diff --git a/debezium/perf/start_common.sh b/debezium/perf/start_common.sh index 1f74b59885b..82464b2c913 100755 --- a/debezium/perf/start_common.sh +++ b/debezium/perf/start_common.sh @@ -2,4 +2,9 @@ set -ex +LOGS_DIR=./logs +if [ ! -d "$LOGS_DIR" ]; then + mkdir $LOGS_DIR +fi + exec docker-compose up -d mysql redpanda debezium loadgen diff --git a/debezium/perf/start_dh.sh b/debezium/perf/start_dh.sh index 15989bf9271..94ffb504bc8 100755 --- a/debezium/perf/start_dh.sh +++ b/debezium/perf/start_dh.sh @@ -2,4 +2,9 @@ set -ex +LOGS_DIR=./logs +if [ ! -d "$LOGS_DIR" ]; then + mkdir $LOGS_DIR +fi + exec docker-compose up -d mysql redpanda debezium loadgen server grpc-proxy envoy web diff --git a/debezium/perf/start_mz.sh b/debezium/perf/start_mz.sh index 637f8bbe60e..caace7ada3b 100755 --- a/debezium/perf/start_mz.sh +++ b/debezium/perf/start_mz.sh @@ -2,4 +2,9 @@ set -ex +LOGS_DIR=./logs +if [ ! -d "$LOGS_DIR" ]; then + mkdir $LOGS_DIR +fi + exec docker-compose up -d mysql redpanda debezium loadgen materialized mzcli diff --git a/debezium/perf/stop_all.sh b/debezium/perf/stop_all.sh new file mode 100755 index 00000000000..28dac5d82f2 --- /dev/null +++ b/debezium/perf/stop_all.sh @@ -0,0 +1,3 @@ +#!/bin/bash + +docker-compose stop && docker-compose down -v diff --git a/debezium/scripts/sample_dt.py b/debezium/scripts/sample_dt.py index 21b7fcaf93e..637585f6d07 100644 --- a/debezium/scripts/sample_dt.py +++ b/debezium/scripts/sample_dt.py @@ -1,7 +1,7 @@ from deephaven import PythonListenerAdapter import datetime as dt -now_str = dt.datetime.now().astimezone().strftime('%Y%m%d%H%M%S_%Z') +now_str = dt.datetime.now().astimezone().strftime('%Y.%m.%d.%H.%M.%S_%Z') log = open(f'/logs/{now_str}_dh_sample_dt.log', 'w') From 8fadcd085a7bff761a80b2b5ef889b8085c5f29f Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Mon, 21 Mar 2022 23:58:11 -0400 Subject: [PATCH 3/8] More tweaks. --- debezium/perf/dh_run_demo.sh | 5 ++ debezium/perf/dh_sample_dt.sh | 5 ++ debezium/perf/docker-compose.yml | 1 + .../perf/{mzcli_load.sh => mz_run_demo.sh} | 2 +- debezium/perf/mz_sample_dt.sh | 25 +++++++++ debezium/perf/mzcli_sampling_dt.sh | 14 ----- debezium/perf/pid_from_cmdline.py | 16 ++++-- debezium/perf/sample_top.py | 16 ++++-- debezium/perf/start_common.sh | 10 ---- debezium/perf/start_dh.sh | 10 ---- debezium/perf/start_mz.sh | 10 ---- debezium/perf/start_perf_run.sh | 55 +++++++++++++++++++ debezium/perf/stop_all.sh | 2 + debezium/perf/stop_common.sh | 5 -- debezium/perf/stop_dh.sh | 5 -- debezium/perf/stop_mz.sh | 5 -- debezium/scripts/sample_dt.py | 13 +++-- 17 files changed, 124 insertions(+), 75 deletions(-) create mode 100755 debezium/perf/dh_run_demo.sh create mode 100755 debezium/perf/dh_sample_dt.sh rename debezium/perf/{mzcli_load.sh => mz_run_demo.sh} (89%) create mode 100755 debezium/perf/mz_sample_dt.sh delete mode 100755 debezium/perf/mzcli_sampling_dt.sh delete mode 100755 debezium/perf/start_common.sh delete mode 100755 debezium/perf/start_dh.sh delete mode 100755 debezium/perf/start_mz.sh create mode 100755 debezium/perf/start_perf_run.sh delete mode 100755 debezium/perf/stop_common.sh delete mode 100755 debezium/perf/stop_dh.sh delete mode 100755 debezium/perf/stop_mz.sh diff --git a/debezium/perf/dh_run_demo.sh b/debezium/perf/dh_run_demo.sh new file mode 100755 index 00000000000..f312e41274c --- /dev/null +++ b/debezium/perf/dh_run_demo.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -eu + +exec ../../java-client/session-examples/build/install/java-client-session-examples/bin/execute-script --python ../scripts/demo.py diff --git a/debezium/perf/dh_sample_dt.sh b/debezium/perf/dh_sample_dt.sh new file mode 100755 index 00000000000..a37cb27ea67 --- /dev/null +++ b/debezium/perf/dh_sample_dt.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +set -eu + +exec ../../java-client/session-examples/build/install/java-client-session-examples/bin/execute-script --python ../scripts/sample_dt.py diff --git a/debezium/perf/docker-compose.yml b/debezium/perf/docker-compose.yml index cc992598c53..be66c91cbc1 100644 --- a/debezium/perf/docker-compose.yml +++ b/debezium/perf/docker-compose.yml @@ -12,6 +12,7 @@ services: # build: ../../jprofiler-server environment: - JAVA_TOOL_OPTIONS=-Xmx${DEEPHAVEN_HEAP} -Ddeephaven.console.type=${DEEPHAVEN_CONSOLE_TYPE} -Ddeephaven.application.dir=${DEEPHAVEN_APPLICATION_DIR} + - PERF_TAG # Used to specify a subdirectory under ./logs where to store perf samples logs # For jprofiler sessions (if you tweaked the jprofiler version in jprofiler-server/Dockerfile you need to tweak the path below): # Then use this startup options: # - JAVA_TOOL_OPTIONS=-agentpath:/opt/jprofiler13.0/bin/linux-x64/libjprofilerti.so=port=8849,nowait -Xmx4g -Ddeephaven.console.type=${DEEPHAVEN_CONSOLE_TYPE} -Ddeephaven.application.dir=${DEEPHAVEN_APPLICATION_DIR} diff --git a/debezium/perf/mzcli_load.sh b/debezium/perf/mz_run_demo.sh similarity index 89% rename from debezium/perf/mzcli_load.sh rename to debezium/perf/mz_run_demo.sh index 536bf5d5a5b..607769c9e17 100755 --- a/debezium/perf/mzcli_load.sh +++ b/debezium/perf/mz_run_demo.sh @@ -1,5 +1,5 @@ #!/bin/bash -set -ex +set -eu exec docker-compose run -T mzcli -f /scripts/demo.sql diff --git a/debezium/perf/mz_sample_dt.sh b/debezium/perf/mz_sample_dt.sh new file mode 100755 index 00000000000..019e016f1ce --- /dev/null +++ b/debezium/perf/mz_sample_dt.sh @@ -0,0 +1,25 @@ +#!/bin/bash + +set -eu + +if [ -z "$PERF_TAG" ]; then + echo "$0: PERF_TAG environment variable is not defined, aborting." 1>&2 + exit 1 +fi + +DATA_TAG="mz_sample_dt" +OUT=logs/${PERF_TAG}/${DATA_TAG}.log + +SCRIPT=$(cat <<'EOF' +while true; do + DATE_TAG=$(date -u '+%Y-%m-%d %H:%M:%S%z') + echo -n "$DATE_TAG|" + psql --csv -A -t -f /scripts/sample_dt.sql -U materialize -h materialized -p 6875 + sleep 1 +done +EOF +) + +(nohup docker-compose run -T --entrypoint /bin/bash mzcli -c "$SCRIPT" < /dev/null >& $OUT &) + +exit 0 diff --git a/debezium/perf/mzcli_sampling_dt.sh b/debezium/perf/mzcli_sampling_dt.sh deleted file mode 100755 index ffa4d1026e6..00000000000 --- a/debezium/perf/mzcli_sampling_dt.sh +++ /dev/null @@ -1,14 +0,0 @@ -#!/bin/bash - -set -ex - -DATE_TAG=$(date '+%Y.%m.%d.%H.%M.%S_%Z') -DATA_TAG="mz_sample_dt" -OUT=logs/${DATE_TAG}_${DATA_TAG}.log - -(nohup docker-compose run -T --entrypoint /bin/bash mzcli -c " -while true; do - psql --csv -A -t -f /scripts/sample_dt.sql -U materialize -h materialized -p 6875 - sleep 1 -done" < /dev/null >& $OUT &) - diff --git a/debezium/perf/pid_from_cmdline.py b/debezium/perf/pid_from_cmdline.py index 4af45090502..fc64d7b3af4 100644 --- a/debezium/perf/pid_from_cmdline.py +++ b/debezium/perf/pid_from_cmdline.py @@ -6,8 +6,11 @@ import sys parser = argparse.ArgumentParser(description='Match process command line regex to pid') -parser.add_argument('proc_specs_strs', metavar='PROCSPEC', type=str, nargs='+', - help='a string of the form "name:regex" where regex should only match one process in `ps -o command` output') +parser.add_argument( + 'proc_specs_strs', + metavar='PROCSPEC', + type=str, nargs='+', + help='a string of the form "name:regex" where regex should only match one process in `ps -o command` output') args = parser.parse_args() @@ -16,7 +19,9 @@ name, regex_str = proc_spec_str.split(':', maxsplit=1) proc_specs[name] = re.compile(regex_str) -ps_lines = subprocess.run(['ps', '-ahxww', '-o', 'pid,command' ], stdout=subprocess.PIPE).stdout.decode('utf-8').splitlines() +ps_lines = subprocess.run( + ['ps', '-ahxww', '-o', 'pid,command' ], + stdout=subprocess.PIPE).stdout.decode('utf-8').splitlines() matches = {} nmatches = 0 @@ -30,13 +35,14 @@ if re.search(regex, cmd) is not None: prev = matches.get(name, None) if prev is not None: - print(sys.argv[0] + f": found more than one match for '{name}': {prev}, {pid}, aborting", file=sys.stderr) + print(f"{sys.argv[0]}: found more than one match for '{name}': {prev}, {pid}, aborting", + file=sys.stderr) sys.exit(1) matches[name] = pid for name in proc_specs.keys(): if matches.get(name, None) is None: - print(sys.argv[0] + f": couldn't find a match for {name}, aborting", file=sys.stderr) + print(f"{sys.argv[0]}: couldn't find a match for {name}, aborting", file=sys.stderr) sys.exit(1) first = True diff --git a/debezium/perf/sample_top.py b/debezium/perf/sample_top.py index 6b60bccb02e..3cfdcdc9a62 100644 --- a/debezium/perf/sample_top.py +++ b/debezium/perf/sample_top.py @@ -1,15 +1,20 @@ import argparse import datetime as dt import re +import os import subprocess import statistics as stats +import sys -now_str = dt.datetime.now().astimezone().strftime('%Y.%m.%d.%H.%M.%S_%Z') +now_str = dt.datetime.utcnow().astimezone().strftime('%Y.%m.%d.%H.%M.%S_%Z') parser = argparse.ArgumentParser(description='Sample cpu utilization and memory consumption with top for given processes') -parser.add_argument('tag', metavar='TAG', type=str, - help='experiment tag') +perf_tag = os.environ.get('PERF_TAG', None) +if perf_tag is None: + print(f'{os.argv[0]}: PERF_TAG environment variable is not defined, aborting.', file=sys.stderr) + sys.exit(1) + parser.add_argument('nsamples', metavar='NSAMPLES', type=int, help='number of samples') parser.add_argument('delay_s', metavar='DELAY_MS', type=str, @@ -35,7 +40,8 @@ ['top', '-Eg', '-n', f'{args.nsamples}', '-b', '-c', '-d', f'{args.delay_s}'] + pids_args, stdout=subprocess.PIPE).stdout.decode('utf-8').splitlines() -with open(f'logs/{now_str}_{args.tag}_top_details.log', 'w') as f: +out_dir = f'./logs/{perf_tag}' +with open(f'{out_dir}/{now_str}_top_details.log', 'w') as f: for line in top_out: f.write(line) f.write('\n') @@ -78,7 +84,7 @@ def format_samples(precision : int, samples): first = False return s -with open(f'logs/{now_str}_{args.tag}_top_samples.log', 'w') as f: +with open(f'{out_dir}/{now_str}_top_samples.log', 'w') as f: for name, result in results.items(): for tag, samples in result.items(): mean = stats.mean(samples) diff --git a/debezium/perf/start_common.sh b/debezium/perf/start_common.sh deleted file mode 100755 index 82464b2c913..00000000000 --- a/debezium/perf/start_common.sh +++ /dev/null @@ -1,10 +0,0 @@ -#!/bin/bash - -set -ex - -LOGS_DIR=./logs -if [ ! -d "$LOGS_DIR" ]; then - mkdir $LOGS_DIR -fi - -exec docker-compose up -d mysql redpanda debezium loadgen diff --git a/debezium/perf/start_dh.sh b/debezium/perf/start_dh.sh deleted file mode 100755 index 94ffb504bc8..00000000000 --- a/debezium/perf/start_dh.sh +++ /dev/null @@ -1,10 +0,0 @@ -#!/bin/bash - -set -ex - -LOGS_DIR=./logs -if [ ! -d "$LOGS_DIR" ]; then - mkdir $LOGS_DIR -fi - -exec docker-compose up -d mysql redpanda debezium loadgen server grpc-proxy envoy web diff --git a/debezium/perf/start_mz.sh b/debezium/perf/start_mz.sh deleted file mode 100755 index caace7ada3b..00000000000 --- a/debezium/perf/start_mz.sh +++ /dev/null @@ -1,10 +0,0 @@ -#!/bin/bash - -set -ex - -LOGS_DIR=./logs -if [ ! -d "$LOGS_DIR" ]; then - mkdir $LOGS_DIR -fi - -exec docker-compose up -d mysql redpanda debezium loadgen materialized mzcli diff --git a/debezium/perf/start_perf_run.sh b/debezium/perf/start_perf_run.sh new file mode 100755 index 00000000000..60f46e1f95c --- /dev/null +++ b/debezium/perf/start_perf_run.sh @@ -0,0 +1,55 @@ +#!/bin/bash + +set -eu + +if [ $(docker ps -q | wc -l) -gt 0 ]; then + echo "$0: some docker containers seem to be running, aborting." 1>&2 + exit 1 +fi + +if [ $# -ne 2 -o \( "$1" != 'dh' -a "$1" != 'mz' \) ]; then + echo "Usage: $0 dh|mz per_second_rate" 1>&2 + exit 1 +fi + +engine=$1 +rate=$2 + +PERF_TAG=$(date -u '+%Y.%m.%d.%H.%M.%S_%Z')_${engine}_${rate} +export PERF_TAG + +LOGS_DIR=./logs +if [ ! -d "$LOGS_DIR" ]; then + mkdir $LOGS_DIR +fi + +OUT_DIR="${LOGS_DIR}/${PERF_TAG}" +mkdir -p "$OUT_DIR" + +LOG="$OUT_DIR/start.log" +rm -f $LOG + +if [ "$engine" = "mz" ]; then + docker-compose up -d mysql redpanda debezium loadgen materialized mzcli >> $LOG 2>&1 +elif [ "$engine" = "dh" ]; then + docker-compose up -d mysql redpanda debezium loadgen server grpc-proxy envoy web >> $LOG 2>&1 +else + echo "$0: Internal error, aborting." 1>&2 + exit 1 +fi + +# fire and forget; will stop when compose stops. +COMPOSE_LOG="${OUT_DIR}/docker-compose.log" +(nohup docker-compose logs -f >& $COMPOSE_LOG < /dev/null &) + +# avoid race with creation of log file above +sleep 0.2 + +# Wait till loadgen simulation started +echo -n "Waiting for loadgen simulation to start... " >> $LOG 2>&1 +tail -f "$COMPOSE_LOG" | sed -n '/loadgen.*Simulated [0-9]* pageview actions in the last/ q' +echo "done." >> $LOG 2>&1 + +echo "${PERF_TAG}" + +exit 0 diff --git a/debezium/perf/stop_all.sh b/debezium/perf/stop_all.sh index 28dac5d82f2..4a258d82866 100755 --- a/debezium/perf/stop_all.sh +++ b/debezium/perf/stop_all.sh @@ -1,3 +1,5 @@ #!/bin/bash +set -eu + docker-compose stop && docker-compose down -v diff --git a/debezium/perf/stop_common.sh b/debezium/perf/stop_common.sh deleted file mode 100755 index d2d7534cda9..00000000000 --- a/debezium/perf/stop_common.sh +++ /dev/null @@ -1,5 +0,0 @@ -#!/bin/bash - -set -ex - -exec docker-compose stop mysql redpanda debezium loadgen diff --git a/debezium/perf/stop_dh.sh b/debezium/perf/stop_dh.sh deleted file mode 100755 index 5963f164243..00000000000 --- a/debezium/perf/stop_dh.sh +++ /dev/null @@ -1,5 +0,0 @@ -#!/bin/bash - -set -ex - -exec docker-compose stop web envoy grpc-proxy server diff --git a/debezium/perf/stop_mz.sh b/debezium/perf/stop_mz.sh deleted file mode 100755 index 62d07fa247d..00000000000 --- a/debezium/perf/stop_mz.sh +++ /dev/null @@ -1,5 +0,0 @@ -#!/bin/bash - -set -ex - -exec docker-compose stop materialized mzcli diff --git a/debezium/scripts/sample_dt.py b/debezium/scripts/sample_dt.py index 637585f6d07..c9dcd1e4ab9 100644 --- a/debezium/scripts/sample_dt.py +++ b/debezium/scripts/sample_dt.py @@ -1,9 +1,7 @@ from deephaven import PythonListenerAdapter import datetime as dt - -now_str = dt.datetime.now().astimezone().strftime('%Y.%m.%d.%H.%M.%S_%Z') - -log = open(f'/logs/{now_str}_dh_sample_dt.log', 'w') +import os +import sys def onUpdate(added_unused, modified_unused, deleted_unused): timestamp = dt.datetime.now().astimezone().isoformat() @@ -13,4 +11,9 @@ def onUpdate(added_unused, modified_unused, deleted_unused): log.write(f'timestamp={timestamp}, total={total}, max_received_at={max_received_at}, dt_ms={dt_ms}\n') log.flush() -PythonListenerAdapter(pageviews_summary, onUpdate, replayInitialImage=False) +now_str = dt.datetime.utcnow().astimezone().strftime('%Y.%m.%d.%H.%M.%S_%Z') + +perf_tag = os.environ.get('PERF_TAG', None) +if perf_tag is not None: + log = open(f'/logs/{perf_tag}/{now_str}_dh_sample_dt.log', 'w') + PythonListenerAdapter(pageviews_summary, onUpdate, replayInitialImage=False) From 4564a2aedf3a01872417a6cc7bee75f85f69fe9c Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Mon, 21 Mar 2022 23:58:29 -0400 Subject: [PATCH 4/8] More scripts. --- debezium/perf/sample_top.sh | 23 +++++++++++++++++++++++ debezium/perf/set_pageviews_per_second.sh | 11 +++++++++++ 2 files changed, 34 insertions(+) create mode 100755 debezium/perf/sample_top.sh create mode 100755 debezium/perf/set_pageviews_per_second.sh diff --git a/debezium/perf/sample_top.sh b/debezium/perf/sample_top.sh new file mode 100755 index 00000000000..671b6ce2efb --- /dev/null +++ b/debezium/perf/sample_top.sh @@ -0,0 +1,23 @@ +#!/bin/bash + +set -eu + +if [ $# -ne 3 -o \( "$1" != 'dh' -a "$1" != 'mz' \) ]; then + echo "Usage: $0 mz|dh rate nsamples delay_sec" +fi + +engine=$1 +nsamples=$2 +delay_s=$3 + +if [ "$engine" = "mz" ]; then + proc_spec='materialize:^materialized redpanda:^/opt/redpanda/bin/redpanda' +elif [ "$engine" = "dh" ]; then + proc_spec='deephaven:java.*deephaven redpanda:^/opt/redpanda/bin/redpanda' +else + echo "$0: Internal error, aborting." 1>&2 + exit 1 +fi + +PROC_SPECS=$(python3 ./pid_from_cmdline.py $proc_spec) +exec python3 ./sample_top.py "$nsamples" "$delay_s" $PROC_SPECS diff --git a/debezium/perf/set_pageviews_per_second.sh b/debezium/perf/set_pageviews_per_second.sh new file mode 100755 index 00000000000..0d7d95cb98b --- /dev/null +++ b/debezium/perf/set_pageviews_per_second.sh @@ -0,0 +1,11 @@ +#!/bin/bash + +set -eu + +if [ $# -ne 1 ]; then + echo "Usage: $0 pageviews_per_second" 1>&2 + exit 1 +fi + +(echo "set pageviews_per_second $1"; echo quit) | nc localhost 8090 +exit 0 From a9e5ab17b9b27a1d3eda0684612aab0e5111d5e4 Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Tue, 22 Mar 2022 00:00:05 -0400 Subject: [PATCH 5/8] Added .gitignore. --- debezium/perf/.gitignore | 1 + 1 file changed, 1 insertion(+) create mode 100644 debezium/perf/.gitignore diff --git a/debezium/perf/.gitignore b/debezium/perf/.gitignore new file mode 100644 index 00000000000..98d8a5a6304 --- /dev/null +++ b/debezium/perf/.gitignore @@ -0,0 +1 @@ +logs From 3cbc7387b9560c062d4bfac0e30283aaae343a74 Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Tue, 22 Mar 2022 00:50:03 -0400 Subject: [PATCH 6/8] Tweaks. --- debezium/perf/run_experiment.sh | 48 +++++++++++++++++++++++++++++++++ 1 file changed, 48 insertions(+) create mode 100755 debezium/perf/run_experiment.sh diff --git a/debezium/perf/run_experiment.sh b/debezium/perf/run_experiment.sh new file mode 100755 index 00000000000..86fcddf8e2b --- /dev/null +++ b/debezium/perf/run_experiment.sh @@ -0,0 +1,48 @@ +#!/bin/sh + +set -eu + +if [ $# -ne 5 -o \( "$1" != 'dh' -a "$1" != 'mz' \) ]; then + echo "Usage: $0 dh|mz per_second_rate wait_seconds top_samples top_delay_seconds" 1>&2 + exit 1 +fi + +engine="$1" +rate_per_s="$2" +wait_s="$3" +top_samples="$4" +top_delay="$5" + +echo "Starting compose and waiting for simulation to start." +export PERF_TAG=$(./start_perf_run.sh "$engine" "$rate_per_s") +echo "Compose start done." +echo "PERF_TAG=${PERF_TAG}" + +echo "Running demo in engine and sampling delays." +if [ "$engine" = "mz" ]; then + ./mz_run_demo.sh + ./mz_sample_dt.sh +elif [ "$engine" = "dh" ]; then + ./dh_run_demo.sh + ./dh_sample_dt.sh +else + echo "$0: Internal error, aborting." 1>&2 + exit 1 +fi + +echo "Setting pageviews per second" +./set_pageviews_per_second.sh $rate_per_s + +echo "Waiting for $wait_s seconds..." +sleep "$wait_s" + +echo "Sampling top." +./sample_top.sh "$engine" "$top_samples" "$top_delay" + +echo "Stopping compose." + +./stop_all.sh + +echo "Experiemnt finished." + +exit 0 From a61d81bd2e5d14963ab4fbe133a095de914bc670 Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Tue, 22 Mar 2022 01:00:12 -0400 Subject: [PATCH 7/8] Fixed a typo. --- debezium/perf/run_experiment.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/debezium/perf/run_experiment.sh b/debezium/perf/run_experiment.sh index 86fcddf8e2b..41873a0c3eb 100755 --- a/debezium/perf/run_experiment.sh +++ b/debezium/perf/run_experiment.sh @@ -43,6 +43,6 @@ echo "Stopping compose." ./stop_all.sh -echo "Experiemnt finished." +echo "Experiment finished." exit 0 From 8465d246a0cbb1b79744ff40e1e78a2ea69df8e8 Mon Sep 17 00:00:00 2001 From: Cristian Ferretti Date: Tue, 22 Mar 2022 12:21:57 -0400 Subject: [PATCH 8/8] Updated debezium/perf/README.md; improved output of run_experiment.sh. --- debezium/perf/README.md | 135 ++++++++++++++++++++++++++++++-- debezium/perf/run_experiment.sh | 34 ++++++-- 2 files changed, 153 insertions(+), 16 deletions(-) diff --git a/debezium/perf/README.md b/debezium/perf/README.md index 909975caaf9..3b5e2d475ec 100644 --- a/debezium/perf/README.md +++ b/debezium/perf/README.md @@ -1,5 +1,4 @@ -Debezium - Kafka Perf -===================== +# Debezium - Kafka Perf The docker compose file in this directory is similar to the one in the ../demo directory, with additional @@ -19,8 +18,130 @@ analysis oriented, it has considerably larger requirements than our other feature-oriented demos. -Once the compose is running -=========================== +## Additional building steps + +On top of what is required for `../demo` (see +`../demo/README.md`), the automated testing +requires building the Deephaven Java client examples. +At the toplevel directory of your git clone (`../..`), run: + +``` +./gradlew java-client-session-examples:installDist +``` + +## Automated testing + +The script `run_experiment.sh` in this directory performs a +full test for one engine (either Deephaven or Materialize). +It will: + +- Start the containers required for a particular run (and only those). +- Ensure container logs are preserved for the run. +- Load the demo code in the respective engine and sample update delays to a log file. +- Set the given pageviews per second rate, and wait a fixed amount of time thereafter for processing to settle. +- Take multiple samples for CPU and memory utilization over a defined period. + Output from top in batch mode is sent to a log file and later post-processed. +- Stop and "reset" the containers. + +The example + +``` +cd debezium/perf +./run_experiment.sh dh 5000 20 10 1.0 +``` + +will run an experiment for Deephaven (tag `dh`; use tag `mz` for Materialize) with a target rate of 5,000 pageviews per second. +It will wait 20 seconds after setting the target rate to begin sampling CPU and memory utilization using `top` in batch mode. +10 samples will be obtained, with a delay between samples of 1.0 seconds. + +Example output from a run: + +``` +cfs@erke 12:18:20 ~/dh/oss3/deephaven-core/debezium/perf +$ ./run_experiment.sh dh 5000 20 10 1.0 +About to run an experiment for dh with 5000 pageviews/s. + +Actions that will be performed in this run: +1. Start compose services required for for dh. +2. Execute demo in dh and setup update delay logging. +3. Set 5000 pageviews per second rate. +4. Wait 20 seconds. +5. Take 10 samples for mem and CPU utilization, 1.0 seconds between samples. +6. Stop and 'reset' (down) compose. + +Running experiment. + +1. Starting compose. +PERF_TAG=2022.03.22.16.18.41_UTC_dh_5000 + +Logs are being saved to logs/2022.03.22.16.18.41_UTC_dh_5000. + +2. Running demo in dh and sampling delays. +1 compiler directives added +Table users = +Table items = +Table purchases = +Table pageviews = +Table pageviews_stg = +Table purchases_by_item = +Table pageviews_by_item = +Table item_summary = +Table top_viewed_items = +Table top_converting_items = +Table profile_views_per_minute_last_10 = +Table profile_views = +Table profile_views_enriched = +Table dd_flagged_profiles = +Table dd_flagged_profile_view = +Table high_value_users = +Table hvu_test = +Table pageviews_summary = + +1 compiler directives added +No displayable variables updated + + +3. Setting pageviews per second +LOADGEN Connected. +Setting pageviews_per_second: old value was 50, new value is 5000. +Goodbye. + +4. Waiting for 20 seconds. + +5. Sampling top. +name=redpanda, tag=CPU_PCT, mean=84.14, samples=80.0, 84.2, 85.0, 87.0, 85.0, 82.0, 85.0, 84.0, 84.2, 85.0 +name=redpanda, tag=RES_GiB, mean=0.77, samples=0.7678, 0.7698, 0.7698, 0.7698, 0.7718, 0.7718, 0.7718, 0.7718, 0.7718, 0.7776 +name=deephaven, tag=CPU_PCT, mean=35.21, samples=66.7, 31.7, 28.0, 31.0, 27.0, 23.0, 46.0, 47.0, 25.7, 26.0 +name=deephaven, tag=RES_GiB, mean=2.40, samples=2.4, 2.4, 2.4, 2.4, 2.4, 2.4, 2.4, 2.4, 2.4, 2.4 + +6. Stopping and 'reset' (down) compose. +Stopping core-debezium-perf_envoy_1 ... done +Stopping core-debezium-perf_grpc-proxy_1 ... done +Stopping core-debezium-perf_loadgen_1 ... done +Stopping core-debezium-perf_debezium_1 ... done +Stopping core-debezium-perf_server_1 ... done +Stopping core-debezium-perf_redpanda_1 ... done +Stopping core-debezium-perf_mysql_1 ... done +Stopping core-debezium-perf_web_1 ... done +Removing core-debezium-perf_envoy_1 ... done +Removing core-debezium-perf_grpc-proxy_1 ... done +Removing core-debezium-perf_loadgen_1 ... done +Removing core-debezium-perf_debezium_1 ... done +Removing core-debezium-perf_server_1 ... done +Removing core-debezium-perf_redpanda_1 ... done +Removing core-debezium-perf_mysql_1 ... done +Removing core-debezium-perf_web_1 ... done +Removing network core-debezium-perf_default + +Experiment finished. +``` + +The CPU and memory utilization samples are shown on stdout and also saved to a file in the +new directory under `logs/`, in this case `logs/2022.03.22.16.18.41_UTC_dh_5000.` + +## Manual testing + +### Once the compose is running Both Materialize and Deephaven are running. We now can make them execute their respective demo scripts. @@ -54,8 +175,7 @@ a command socket interface for loadgen; see `../demo/README.md` for instructions. -Tracking the last processed pageview timestamp -============================================== +### Tracking the last processed pageview timestamp * In DH, the `pageviews_summary` table can help track the last pageview seen. @@ -72,8 +192,7 @@ Tracking the last processed pageview timestamp FROM pageviews_summary;' -U materialize -h localhost -p 6875 ``` -Memory and CPU requirements -=========================== +## Memory and CPU requirements The parameters used for images in the docker compose file in this directory are geared towards high message throughput. While Deephaven diff --git a/debezium/perf/run_experiment.sh b/debezium/perf/run_experiment.sh index 41873a0c3eb..0f846f0fdac 100755 --- a/debezium/perf/run_experiment.sh +++ b/debezium/perf/run_experiment.sh @@ -13,12 +13,26 @@ wait_s="$3" top_samples="$4" top_delay="$5" -echo "Starting compose and waiting for simulation to start." +echo "About to run an experiment for ${engine} with ${rate_per_s} pageviews/s." +echo +echo "Actions that will be performed in this run:" +echo "1. Start compose services required for for ${engine}." +echo "2. Execute demo in ${engine} and setup update delay logging." +echo "3. Set ${rate_per_s} pageviews per second rate." +echo "4. Wait ${wait_s} seconds." +echo "5. Take ${top_samples} samples for mem and CPU utilization, ${top_delay} seconds between samples." +echo "6. Stop and 'reset' (down) compose." +echo +echo "Running experiment." +echo +echo "1. Starting compose." export PERF_TAG=$(./start_perf_run.sh "$engine" "$rate_per_s") -echo "Compose start done." echo "PERF_TAG=${PERF_TAG}" +echo +echo "Logs are being saved to logs/$PERF_TAG." +echo -echo "Running demo in engine and sampling delays." +echo "2. Running demo in ${engine} and sampling delays." if [ "$engine" = "mz" ]; then ./mz_run_demo.sh ./mz_sample_dt.sh @@ -29,20 +43,24 @@ else echo "$0: Internal error, aborting." 1>&2 exit 1 fi +echo -echo "Setting pageviews per second" +echo "3. Setting pageviews per second" ./set_pageviews_per_second.sh $rate_per_s +echo -echo "Waiting for $wait_s seconds..." +echo "4. Waiting for $wait_s seconds." sleep "$wait_s" +echo -echo "Sampling top." +echo "5. Sampling top." ./sample_top.sh "$engine" "$top_samples" "$top_delay" +echo -echo "Stopping compose." +echo "6. Stopping and 'reset' (down) compose." ./stop_all.sh - +echo echo "Experiment finished." exit 0