diff --git a/README.md b/README.md index 22b83bb..d5c6e6f 100644 --- a/README.md +++ b/README.md @@ -32,6 +32,7 @@ rerun it and check every figure a post cites. | [`clickstack-e2e-gaps/`](clickstack-e2e-gaps/) | The six questions the end to end run left open, each over the whole capture: what a day predicate prunes across thirty days of objects, whether Vector can write the cold branch, whether the Retriever indexes and queries that layout, what a container killed mid-stream costs line by line, which dashboard answers change when rows leave the hot table, and how the per-type policy compares with a collector-only policy on insert and merge CPU. Plus a second pass on four of them: Vector 0.58.0 writing Parquet beside JSON with the Parquet reader's own counters, a `GROUP BY` and an `ORDER BY ... LIMIT` through the Merge table, the collector configured as its code owners prescribe, the `TTL TO VOLUME 'cold'` alternative costed on the same capture, and ClickHouse issue 116888 demonstrated with its guard. | Current. Not behind a post. | | [`clickstack-rows-gate/`](clickstack-rows-gate/) | Which ClickHouse system table counts the rows written into the logs table to the row, with the Receiver regulating in lines with a service total: `system.part_log` NewPart rows equals the hot count in both runs, `system.query_log` written_rows drifts with the exporter's async-insert entries; the totals held to the row, a policy rewrite mid-window reset nothing, and the events unit takes effect only from the config or an engine option. | Current. The meter for the ClickHouse rows run. Not behind a post. | | [`clickstack-rows/`](clickstack-rows/) | The ClickHouse rows run, metered: rows written into ClickStack held at a rate an hour while load grew 2.5x with a storm and a new service, read on ClickHouse's own `system.part_log`. FAIL as registered: the rate held at 0.99 to 1.04 of R in every complete 10-minute window but one, the floor has no allowance in the 10-minute test, one service's 1,422 new statements in a window passed their always-pass sample, and 33 rows were inserted twice. Rerun with the regulator's sample bound (config `baselineMaxOverTotal` 50): every 4-minute window under its bound, 10-minute windows 0.97 to 1.07 of R/6, every returned record stored once; fails as registered on the 10-minute sum alone. | Three runs. The first failed as registered (one 10-minute window at 1.36, 33 duplicates). With the sample bound, the rate held at 0.97 to 1.07 of R in every complete 10-minute window, none over, no duplicates. Beside a collector rule under the same 2.5x step, the hold read 0.91 to 1.13 (one window over the 1.10 bound, the storm's first) against the rule's 2.95 to 3.42; insert-plus-merge CPU did not separate the arms on this rig. | +| [`clickhouse-cloud-elasticity/`](clickhouse-cloud-elasticity/) | How far does a ClickHouse Cloud service's compute fall, in units and in billed dollars, when the rows written into its logs table fall, above the smallest size, and how long does the autoscaler take? One service in AWS us-east-1, the ClickStack `otel_logs` schema under a fixed query load, two arms that differ only in the rows written (all of the replay, or the 65.3% the Receiver kept), four pairs, read on the replicas' own system tables and on `usageCost`. | Current. Not behind a post. From a 4-unit start the cut took the service from 4 units to 3, 0.75 in units and 0.749 in billed compute, in each of three pairs, 2.9 to 4.3 h after the cut; from a 3-unit start it read no change in 10.25 h. | | [`splunk-license/`](splunk-license/) | Splunk bills on what its licence meter counts, not on a file size. What does the 10x Receiver in front of Splunk do to that number? The same capture through the same Universal Forwarder into the same instance, twice, raw and compact, measured from `license_usage.log` and from the Monitoring Console's own searches, with every compact event read back through the 10x Splunk app and compared to the text that went in. | Current. Not behind a post. | | [`datadog-flex-accounting/`](datadog-flex-accounting/) | Datadog bills Standard indexing per million events. When the 10x Receiver moves events from Standard to Flex Logs under the plan the 10x MCP writes, how many events and GB move, and what do they cost at Datadog's list prices? The released engine and MCP on one capture at three targets, counted two independent ways, priced per million events moved, with the custom metrics the Datadog metric output creates. Computed from the engine's counts at list price; no Datadog account needed. | Current. Not behind a post. | | [`datadog-service-control/`](datadog-service-control/) | Inside one service a Datadog service filter cannot split the volume, so the rules a person writes are filters on the service's logger names. On the kafka container of two public captures of the same code, what does the per-pattern plan the 10x MCP writes move against the fewest `@logger.name` filters that move as many events, and what does each do on the second capture with nothing re-tuned? Computed from the engine's counts; no Datadog account needed. | Current. Not behind a post. | @@ -62,6 +63,7 @@ each resolves its paths relative to itself, so a benchmark can be run from anywh | `clickhouse-clickstack/` | `./run.sh` | pinned engine image digest and a ClickHouse Docker image | `results/` | the `otel-sample-v2` release asset from `log-10x/config`, fetched into `data/` on first run | | `clickstack-e2e/` | `./run.sh` | pinned ClickStack, engine, collector and MinIO images | `results/` | the `otel-sample-v2` release asset from `log-10x/config`, fetched into `data/` on first run | | `clickstack-e2e-gaps/` | `./gap_*.sh` | the same images by digest, plus Vector by digest; the receiver is the published `edge-10x` image | `results/` | the same `otel-sample-v2` asset, read from `../clickstack-e2e/data` | +| `clickhouse-cloud-elasticity/` | `cloud/arms.py`, after the split, stage and meters in its README | the engine and collector images by digest (`results/images.txt`), Python 3.12+, a `clickhouse` client binary | `results/` | the `otel-sample-200mb.log` asset from `log-10x/config` tag `otel-sample-v1`, checked by sha256; a ClickHouse Cloud organization | | `splunk-license/` | `./run.sh` | pinned engine, Splunk and forwarder images, and the 10x Splunk app | `results/` | the `otel-sample-v2` release asset from `log-10x/config`, fetched into `data/` on first run | | `datadog-flex-accounting/` | `./run.sh` | pinned engine image digest, log10x-mcp from npm at a pinned version, and the shared scripts in `accounting-lib/` | `results/` | the `otel-sample-200mb.log` asset from `log-10x/config` tag `otel-sample-v1`, checked by sha256 | | `datadog-ceiling/` | `rig/run.sh` phases, `rig/budget-phase.sh` | the engine image by digest, log10x-mcp 1.30.71 from npm, the demo at tag 3.1.0 | `results/` | a Datadog org with Flex Logs; the demo's own logs | diff --git a/clickhouse-cloud-elasticity/.gitignore b/clickhouse-cloud-elasticity/.gitignore new file mode 100644 index 0000000..9f6c592 --- /dev/null +++ b/clickhouse-cloud-elasticity/.gitignore @@ -0,0 +1,5 @@ +data/ +build/ +split/build/ +split/build-*/ +__pycache__/ diff --git a/clickhouse-cloud-elasticity/README.md b/clickhouse-cloud-elasticity/README.md new file mode 100644 index 0000000..0294eb4 --- /dev/null +++ b/clickhouse-cloud-elasticity/README.md @@ -0,0 +1,37 @@ +# ClickHouse Cloud elasticity + +One benchmark in the [log10x benchmarks](../) repository. It asks how far a ClickHouse Cloud service's compute falls, in units and in billed dollars, when the rows written into its logs table fall, above the smallest size, and how long the autoscaler takes to lower it. + +**Result: from a 4-unit start, writing 0.653 of the rows took the service from 4 units to 3, a ratio of 0.75, and billed compute to 0.749, in each of three pairs; the step down was done 2.9 to 4.3 hours after the cut. From a 3-unit start the same cut read no change in 10.25 hours.** At 3 units both arms sit inside the autoscaler's no-action band; at 4 units arm B sits below it. Every figure, with the file and field it was read from, is in [RESULT.md](RESULT.md). + +ClickHouse Cloud, AWS us-east-1, Scale tier, ClickHouse 26.6, 2 replicas, vertical autoscaling 8 to 32 GiB per replica, idle after 5 minutes. The ClickStack `otel_logs` schema under seven queries a minute. Arm A writes every record of the 215 MB OTel replay at 70,000 rows/s; arm B writes the 65.3% the Receiver (`log10x/edge-10x:1.1.153`) kept, at 45,716 rows/s. 2026-11-02 19:48 to 2026-11-05 03:47 UTC. The service was deleted at the end (`results/raw/teardown.jsonl`). + +| Pair | Arm A's size | Units, A to B | Ratio | usageCost computeCHC per 15 minutes, A to B | Cut to step down done | +|---|---|---|---|---|---| +| 1 | the autoscaler's | 4.0 to 2.997 | 0.749 | 0.298 to 0.224 | 4.33 h | +| 2 | the autoscaler's, where pair 1 left it | 3.0 to 3.0 | 1.0 | 0.224 to 0.224 | no step in 10.25 h | +| 3 | 16 GiB by config, released at the cut | 4.0 to 3.0 | 0.750 | 0.298 to 0.224 | 4.21 h | +| 4 | 16 GiB by config, released at the cut | 4.0 to 3.0 | 0.750 | 0.298 to 0.224 | 2.91 h | + +## Rerun + +Needs a ClickHouse Cloud organization and API key, Docker, Python 3.12 or later and a `clickhouse` client binary (26.8 here). `cloud_api.py` reads the key from SSM or from `CHC_KEY_ID` and `CHC_KEY_SECRET` and never prints it. The scripts keep the service password and client config under `~/git/l1x-co/.claude-tmp/chce-secrets/` by default; `CHC_SECRET_FILE`, `CLIENT` and `CONF` move them. + +1. **Split.** `split/run_slices.sh` replays the `otel-sample-200mb.log` asset from `log-10x/config` tag `otel-sample-v1` (checked by sha256) through four Receivers side by side and joins what they returned into `split/build/wire/returned.json`, in about an hour. +2. **Service.** Put the runner's address in `cloud/service.json`, then run `CHC_SECRET_FILE= python3 cloud_api.py create cloud/service.json`. The service password goes to that file (mode 600), not to the terminal. +3. **Tables.** Apply `cloud/schema.sql` with the client, then `cloud/stage.sh` and `cloud/stage_b.sh`. +4. **Meters**, left running, each with `--service ` and an `--out` under `results/raw/`: `cloud/sample.py`, `cloud/meter.py --every 60 --lag 30` and `cloud/usage_poll.py`. +5. **Feed and queries**, left running: `cloud/load.py` and `cloud/queries.py --overlap 3`. Both follow `results/raw/control.json`, which `cloud/phase.py` writes. +6. **Probe.** `cloud/probe.py` with steps of 2,000 to 70,000 rows/s, 10 minutes each. +7. **Arms.** `cloud/arms.py`. Its docstring gives both forms this run used: `--pairs` for the natural pairs, `--forced` for the pairs with arm A's size set by config, then the read calibration. +8. **Report.** `cloud/arms_report.py --raw results/raw --lag-min 30` for every phase, segment and pair; `cloud/curve.py` for the probe. Both read the committed `.jsonl.gz` files as they are. + +## Files + +| Path | What | +|---|---| +| `RESULT.md` | Every figure, the file and field it came from, and what was not measured | +| `split/` | The engine split | +| `cloud/` | The service request, schema, stage, feed, queries, meters, driver and reports | +| `results/` | The split and stage readings, the service creation response | +| `results/raw/` | Every log the scripts wrote: `events.jsonl` (phases and size changes), `scaling-patches.jsonl`, `usage.jsonl`, `teardown.jsonl`, and the meter, feed, sampler and query logs gzipped | diff --git a/clickhouse-cloud-elasticity/RESULT.md b/clickhouse-cloud-elasticity/RESULT.md new file mode 100644 index 0000000..e6b261d --- /dev/null +++ b/clickhouse-cloud-elasticity/RESULT.md @@ -0,0 +1,469 @@ +# ClickHouse Cloud: compute against rows written + +A logs workload ran on one ClickHouse Cloud service under a fixed query load, in two arms that +differ only in the rows written. Arm A inserts every row. Arm B inserts only the rows the +engine's regulator kept: 65.3% of arm A's rows and 61.2% of its message bytes. The question is +how far the autoscaler's compute falls when the rows fall, above the smallest size, and how long +it takes to fall. + +Every figure below names the file and field it was read from. A figure the run did not produce +is written "not measured". + +## The finding + +**The same cut gave a step down or no change, depending on the size the service started from.** + +- **Starting at 4 units.** Arm A at 70,000 rows/s held 2 x 16 GiB (4 units), with the busiest + replica at a median 0.455 of its CPU. Cutting to arm B's 65.3% of the rows dropped it below the + autoscaler's 37.5% low watermark (0.340). The service stepped down to 2 x 12 GiB (3 units) + 4.20 h after the cut. Pair 3 repeated it with arm A held at 4 units by config: arm B at 0.337 + stepped down to 3 units, the new replicas booting 4.07 h after the cut. Pair 4 repeated it + again at 0.351, booting 2.78 h after the cut. +- **Starting at 3 units.** Arm A at the same 70,000 rows/s also held 3 units for 90 min, at + 0.637. That is inside the 37.5% to 75% band, where the autoscaler takes no action. Arm B on + 3 units ran at 0.427 and 0.455, also inside the band, and did not step in its 4.5 h hold, or + in the 10.25 h it ran in all while the run waited for SSO. +- **Why it depends on the start.** Arm A's load holds steady at both 3 and 4 units. Arm B's + load holds steady only at 3. From a 3-unit start, the 34.7% cut in rows reads no change in + compute. + +| | Units | Ratio to arm A | Fall in compute / fall in rows (0.653) | Fall in compute / fall in bytes (0.612) | +|---|---|---|---|---| +| Pair 1, from a 4-unit start | 4.0 to 2.997 | 0.749 | 0.723 | 0.646 | +| Pair 2, from a 3-unit start | 3.0 to 3.0 | 1.0 | 0 | 0 | +| Pair 3, arm A pinned at 4 units by config | 4.0 to 3.0 | 0.750 | 0.721 | 0.644 | +| Pair 4, arm A pinned at 4 units by config | 4.0 to 3.0 | 0.750 | 0.721 | 0.644 | + +Pair 1 is the only pair in which every size was the autoscaler's own choice, so it is reported +first. In pair 2, arm A's 3-unit size was where pair 1 left the service. In pairs 3 and 4, arm A's +size was set by config (`minReplicaMemoryGb` 16) and released to 8 at each arm B cut, so arm A's +size came from config and every step down was the autoscaler's own. + +Dollars give the same ratio as units, read two ways, the billed postings first: + +- **usageCost computeCHC** (`results/raw/usage.jsonl`, 10-minute poll of + `/organizations/{org}/usageCost`). It posts in 15-minute steps: 0.298 to 0.299 at 4 units, and + 0.223 to 0.224 at 3 units, in each of pairs 1, 3 and 4. That is $1.196/h against $0.896/h, + ratio 0.749. +- **Unit-hours x $0.2985**, the published Scale compute rate per unit-hour in AWS N. Virginia + (us-east-1), where one compute unit is 8 GiB of RAM and 2 vCPUs (clickhouse.com/pricing, read + 2026-11-05, `results/raw/pricing-quotes.md`). That gives $1.194/h against $0.8955/h, ratio + 0.750. The postings match the rate: a quarter-hour is 0.2985 at 4 units and 0.2239 at 3. + +The other figures, each from a section below: + +- **Scale-down lag.** The step was done 4.33, 4.21 and 2.91 h after the cut in pairs 1, 3 and 4; + the new replicas booted 4.20, 4.07 and 2.78 h after it. +- **Write share W**, (insert + merge) / (insert + merge + select) cores, mean over replicas: 0.65 + to 0.67 in both arms. On the busiest replica 0.47 to 0.51 in arm A and 0.54 to 0.55 in arm B. +- **Memory.** About 2 GiB used per replica, of 12 to 16 GiB, in every arm. +- **Floor.** 2 units, $0.60/h at $0.2985. Both arms cost the floor below the load that lifts arm A + off 2 units, which lies between 50,000 and 70,000 rows/s. +- **Credit.** $42.61 of the $300 credit spent, against the run's $200 cap. chce-elasticity was + deleted at the end. + +## Setup + +- **Service.** `chce-elasticity`, AWS us-east-1, organization tier SCALE (usageCost + `organizationTier`), ClickHouse 26.6, 2 replicas, vertical autoscaling configured 8 to 32 GiB + per replica, idle after 5 minutes (`cloud/service.json`, `results/create-response.json`). One + unit is 8 GiB and 2 vCPU. The API requires at least 2 replicas for the first service in a + warehouse. The IP allow-list held the runner's /32, redacted to `` in the committed + files. +- **Feed.** The 215 MB OTel replay (197,430 lines, 171,807 records after multi-line folding), + split once, locally, by engine `log10x/edge-10x:1.1.153` with `baselineMaxOverTotal` 50 + (`split/`, `results/split-count.json`, `results/rate-settings.txt`). It ran as four contiguous + quarters on four engines side by side at 14 lines/s each. The regulator decides per node per + 4-minute window, so each node saw what one node at that pace would. Kept share by slice: 0.595, + 0.671, 0.674, 0.674. Every record came back 1.0 to 2.5 s after its line was written, with + 0 duplicate sequence numbers. +- **Staging.** + - `bench.stage` holds all 171,807 rows with the kept flag. Kept rows are 112,205, a share of + 0.6531 (`results/stage.json`: `kept_share`). Bytes are 24,706,958 of 40,379,948 body bytes, + 0.612 (`kept_body_bytes`, `body_bytes`). + - `bench.stage_b` holds the 112,205 kept rows only, so arm B reads only what it writes + (`results/stage_b.json`). It matches the kept rows of `bench.stage` row for row + (`results/stage_b-check.json`: 0 mismatched). +- **Inserts.** Native `INSERT ... SELECT` from the stage tables into the ClickStack `otel_logs` + schema (`cloud/schema.sql`), with timestamps shifted to now. Four connections each run one + insert every 2 s: + - Arm A: 35,000 rows per insert, 70,000 rows/s. + - Arm B: 22,858 rows per insert, 45,716 rows/s. + - Every insert is logged with `written_rows` (`results/raw/load.jsonl`). +- **Query load.** Seven queries every 60 s in both arms (`cloud/queries.py`): a per-minute + histogram, top services, a count by service and severity, a service window, a recent tail, a + word search and a substring scan, over 15-minute and 1-hour windows ending now. From the start + of arm A each cycle runs on its own connection on the 60 s grid, up to 3 in flight + (`--overlap 3`), so both arms run the same number of cycles an hour. No cycle was skipped + (`results/raw/queries.jsonl`: 0 `skipped`, 0 `error`). +- **Meters.** + - Size: the Prometheus endpoint every 60 s, which does not wake an idle service + (`results/raw/size.jsonl`: per replica `mem_total`, `cpu`, `cg_user`, `cg_system`, `uptime`). + - CPU and sources: each replica's own system tables, pulled every 60 s with a 30 s lag + (`results/raw/meter.jsonl`): + - `asynchronous_metric_log`: CGroupUserTime, CGroupSystemTime, CGroupMaxCPU, + CGroupMemoryTotal + - `metric_log`: OSCPUVirtualTimeMicroseconds + - `query_log`: CPU and `written_rows` by `log_comment` + - `part_log`: MergeParts + - Billing: usageCost and creditBalances every 10 minutes (`results/raw/usage.jsonl`). +- **Utilisation** is (CGroupUserTime + CGroupSystemTime) / CGroupMaxCPU per replica per minute, + the median of a phase's settled minutes (`cloud/curve.py`). It is reported for the busiest + replica and as the mean over replicas at every reading, because neither source says which one + the recommender reads. The CGroup ratio reads in cores: under rising load it rose about as much + as `metric_log` OSCPUVirtualTime (x1.4 to 1.8). The CGroup carries about 0.1 core more than the + process counters. + +## Per phase + +From `cloud/arms_report.py --raw results/raw --lag-min 30`. Busiest and mean are utilisation; +cores are the busiest replica's median minute. + +| Phase | Window (UTC) | Rows/s | Size | Busiest median | Busiest peak minute | Mean | Busiest cores: insert / select / merge | Unit-hours | $ at 0.2985 | +|---|---|---|---|---|---|---|---|---|---| +| A1 | 11-02 21:40:16 to 11-03 00:55:25 | 70,000 | 2 x 16 GiB | 0.455 | 0.688 | 0.358 | 0.214 / 0.774 / 0.481 | 12.93 | 3.86 | +| B1 before the step | 00:55:25 to 05:08:35 | 45,716 | 2 x 16 GiB | 0.340 | 0.509 | 0.255 | 0.155 / 0.510 / 0.469 | 16.83 | 5.02 | +| B1 after the step | 05:15:35 to 06:15:38 | 45,716 | 2 x 12 GiB | 0.427 | 0.593 | 0.336 | | 2.89 | 0.86 | +| A2 | 06:15:38 to 07:45:42 | 70,000 | 2 x 12 GiB | 0.637 | 0.844 | 0.549 | 0.220 / 0.729 / 0.534 | 4.45 | 1.33 | +| B2 (4.5 h hold) | 07:45:42 to 12:15:51 | 45,716 | 2 x 12 GiB | 0.455 | 0.682 | 0.349 | 0.161 / 0.512 / 0.459 | 13.44 | 4.01 | +| B2 continued, waiting for SSO | 12:15:51 to 18:00:25 | 45,459 (load.jsonl) | 2 x 12 GiB | 0.457 | 0.754 | 0.354 | 0.157 / 0.506 / 0.460 | 17.20 | 5.13 | +| A3, pinned at 16 GiB from 11:18:06 | 11-04 11:25:37 to 14:33:23 | 70,000 | 2 x 16 GiB | 0.440 | 0.657 | 0.349 | 0.226 / 0.768 / 0.504 | 12.43 | 3.71 | +| B3 before the step | 14:33:23 to 18:38:35 | 45,716 | 2 x 16 GiB | 0.337 | 0.539 | 0.258 | | 16.28 | 4.86 | +| B3 after the step | 18:45:46 to 19:45:51 | 45,716 | 2 x 12 GiB | 0.505 | 0.740 | 0.447 | | 2.89 | 0.86 | +| A4, pinned at 16 GiB from 19:45:52 | 19:53:53 to 23:01:11 | 70,000 | 2 x 16 GiB | 0.486 | 0.687 | 0.392 | 0.232 / 0.803 / 0.565 | 12.37 | 3.69 | +| B4 before the step | 23:01:11 to 11-05 01:48:37 | 45,716 | 2 x 16 GiB | 0.351 | 0.541 | 0.273 | | 11.20 | 3.34 | +| B4 after the step | 01:56:03 to 02:56:09 | 45,716 | 2 x 12 GiB | 0.450 | 0.741 | 0.348 | | 2.86 | 0.85 | + +- **B1 as a whole** (5.34 h): 20.38 unit-hours, $6.08. usageCost over the same window, shifted + 30 minutes, reads 6.123. +- **A1 as a whole:** usageCost reads 4.218 against $3.86. Suspicion: the window's first reading + straddles the probe's last postings, which include the 6-unit overlap of its step up. +- **A3:** utilisation and unit-hours are the 2 x 16 GiB segment. The core split is the whole + phase's, whose 194 meter minutes include the 2 x 16 GiB segment's 185. +- **B3 as a whole** (5.21 h): 19.83 unit-hours, $5.92; busiest cores 0.158 / 0.510 / 0.446. + usageCost shifted 30 minutes reads 6.123, and A3's reads 3.641 against $3.91. The two sum to + 9.764 against $9.83. Suspicion: the 10-minute poll of 15-minute postings put one 4-unit + quarter (0.298) on B3's side of the boundary. +- **B3 after the step** reads above B1 after the step (0.505 and 0.447 against 0.427 and + 0.336), as read. Suspicion, not measured: the new replicas' first hour. +- **A4** reads above A1 and A3 on the same size and load (busiest 0.486 against 0.455 and + 0.440; busiest cores 1.945 against 1.821 and 1.759), most of the difference in merge (0.565 + against 0.481 and 0.504). A4 followed B3 directly, where A3 followed a 17-hour idle. Reported + as read; the cause is not measured. Its core split is the whole phase's, as for A3. +- **A2:** 12 of its 89 minutes had the busiest replica at 0.75 or more, the longest run 6 minutes, + and the service did not step up (`events.jsonl`: `no_step_up`, 90 minutes). + +## Where the CPU went: the write share W + +Cores by source, median minute, from `query_log` tags and `part_log` MergeParts +(`cloud/curve.py`; `arms_report.py` `mean_cores`, `busiest_cores`). Insert is the tagged +`INSERT ... SELECT`, which includes reading the stage table. Merge is the background merges of +the parts the inserts wrote. Select is the seven-query load. W is (insert + merge) / (insert + +merge + select). Each source's median is taken separately, so the columns do not sum to the +cgroup. + +Mean over replicas: + +| Phase | Cgroup cores | Insert | Merge | Select | W | (insert + merge) / cgroup | +|---|---|---|---|---|---|---| +| A1 | 1.431 | 0.226 | 0.489 | 0.387 | 0.649 | 0.500 | +| B1 | 1.012 | 0.160 | 0.333 | 0.255 | 0.659 | 0.487 | +| A2 | 1.648 | 0.225 | 0.483 | 0.367 | 0.659 | 0.430 | +| B2 | 1.054 | 0.161 | 0.344 | 0.254 | 0.665 | 0.479 | +| A3 | 1.386 | 0.228 | 0.475 | 0.384 | 0.647 | 0.507 | +| B3 | 1.044 | 0.160 | 0.335 | 0.255 | 0.660 | 0.474 | +| A4 | 1.568 | 0.242 | 0.501 | 0.401 | 0.649 | 0.474 | +| B4 | 1.080 | 0.168 | 0.343 | 0.262 | 0.661 | 0.473 | + +- **W is 0.65 to 0.67 in both arms**, on the mean over replicas. Select lands mostly on one + replica: the busiest replica's select cores are 0.73 to 0.80 in arm A against a mean of 0.37 to + 0.40, so its W is lower, 0.47 to 0.51 in arm A and 0.54 to 0.55 in arm B. +- **Every source fell with the rows.** B over A, mean over replicas, pairs 1, 3 and 4: insert + 0.694 to 0.708, merge 0.681 to 0.705, select 0.653 to 0.664, cgroup 0.689 to 0.753, against + rows 0.653. Select fell too because arm B's queries read a table holding fewer rows. +- **The units fell less than the cores.** The cgroup cores fell to about 0.7 of arm A's. The + service stepped once, from 4 units to 3, which is 0.75. +- **Untagged CPU** (the cgroup less the three sources) is 0.22 to 0.35 of the cgroup in every + phase. What it is was not measured. + +The stage read inside the insert, from the `mode=read` calibration at the end of the run (15 +minutes each on 2 x 12 GiB, the stage slices read into a `Null` table and nothing inserted; +`events.jsonl` phases `cal-readA`, `cal-readB`, `cal-readBfilter`, `curve.py` `read`): + +| Calibration | Reads | Rows/s | Read cores, busiest | Read cores, mean | Arm insert cores, mean | +|---|---|---|---|---|---| +| `cal-readA` | `bench.stage` | 70,000 | 0.030 | 0.028 | A: 0.225 to 0.242 | +| `cal-readB` | `bench.stage_b` | 45,716 | 0.020 | 0.022 | B: 0.160 to 0.168 | +| `cal-readBfilter` | `bench.stage`, kept rows only | 70,000 read, 45,716 kept | 0.026 | 0.031 | | + +The stage read is 12 to 14% of the insert cores in both arms. Taking it out of the insert lowers +W by about 0.01 in each arm (A1 0.649 to 0.640, B1 0.659 to 0.649). Reading arm B's rows from +`bench.stage` with a filter would have cost about 0.009 cores more than reading `bench.stage_b`. +The calibration's select cores are not comparable with the arms': with inserts stopped at 02:56:09Z, the queries' windows ending now held fewer rows in each +phase (busiest select 0.413, 0.277, 0.161). + +## Step lags + +**Step down, pair 1** (`results/raw/events.jsonl`: `step_down_started`, `step_down_done`; +`size.jsonl`: `uptime`). + +| Time | What happened | +|---|---| +| 00:55:25 | Arm B1's cut. | +| 03:55:25 | The 3-hour small window first held only arm B. | +| 05:07:32 and 05:07:47 | The two 12 GiB replicas booted (sample time minus `uptime`): 4.20 h after the cut, 1.2 h after the small window held only arm B. | +| 05:14:21 sample | First 16 GiB replica gone. | +| 05:15:21 sample | Second 16 GiB replica gone, 4.33 h after the cut. | + +The step was 4 GiB and 1 vCPU per replica. While both sizes served, the service carried 7 units +for about 6 minutes, then 5 units for 1 minute. + +**Step up, probe step 7** (2 x 8 GiB, 70,000 rows/s). + +| Time | What happened | +|---|---| +| 20:54:43 | Step 7 began. | +| 21:03 | The first minute at 0.75 or more on either replica. | +| 21:07, and 21:10 to 21:12 | Sustained 0.79 to 0.88. | +| 21:17:24 and 21:17:26 | Two 16 GiB replicas booted: 22.7 min after the step, about 14 min after the first minute over 75%, about 7 min after the sustained run. | +| between 21:24:19 and 21:25:19 | The 8 GiB pair left. | + +While both pairs served, the sampler read 6 units (8 + 8 + 16 + 16 GiB). No activity entry was +logged for either step. + +**Pair 2.** No step down within 4.5 h at a busiest median of 0.455 on 2 x 12 GiB +(`events.jsonl`: `no_step_down`, pair 2, 4.5 h), nor in the 5.75 h after it at 0.457 while the +run waited for SSO. + +**Pairs 3 and 4.** Arm A's size was set by config: the driver PATCHed `replicaScaling` at each +arm A start and back at each arm B cut (`results/raw/scaling-patches.jsonl`, all status 200): + +| Time (UTC) | Phase | Request | Response state, min, max | +|---|---|---|---| +| 11-04 11:18:05 | A3 start | `{"minReplicaMemoryGb":16,"maxReplicaMemoryGb":32}` | idle, 16, 32 | +| 11-04 14:33:23 | B3 cut | `{"minReplicaMemoryGb":8,"maxReplicaMemoryGb":32}` | running, 8, 32 | +| 11-04 19:45:51 | A4 start | `{"minReplicaMemoryGb":16,"maxReplicaMemoryGb":32}` | running, 16, 32 | +| 11-04 23:01:11 | B4 cut | `{"minReplicaMemoryGb":8,"maxReplicaMemoryGb":32}` | running, 8, 32 | + +The service woke 91 s into A3 already mid-step, two 12 GiB and two 16 GiB replicas at +11:19:32Z, and held 2 x 16 GiB from 11:25:37Z (`step_up_started`, `step_up_done`, 452 s after +the phase start). A3 as a whole, including the wake and the overlap: 3.26 h, 13.10 unit-hours, +$3.91. Every step down after a cut is the autoscaler's own. + +**Step down, pair 3**, from 2 x 16 GiB after the release to 8 (`events.jsonl`, +`size.jsonl` `uptime`): + +| Time | What happened | +|---|---| +| 14:33:23 | Arm B3's cut, with `minReplicaMemoryGb` 8 in the same second. | +| 17:33:23 | The 3-hour small window first held only arm B. | +| 18:37:42 and 18:37:48 | The two 12 GiB replicas booted: 4.07 h after the cut. | +| 18:38:35 sample | `step_down_started`, 7 units: 4.09 h. | +| 18:45:35 sample | `step_down_done`, both 16 GiB replicas gone: 4.21 h. | + +usageCost postings per 15 minutes across pair 3 (`usage.jsonl`, consecutive readings): 0.298 to +0.299 through 19:02, one 0.378 at 19:22 (the overlap), then 0.223 to 0.224. The quarters at +A3's wake read 0.03, 0.03 and 0.328. + +A4 stepped up from B3's 2 x 12 GiB: the first 16 GiB replica joined at the 19:46:35Z sample +(61 s), and the service held 2 x 16 GiB from the 19:53:35Z sample (`step_up_done`, 481 s). + +**Step down, pair 4**, from 2 x 16 GiB after the release to 8: + +| Time | What happened | +|---|---| +| 11-04 23:01:11 | Arm B4's cut, with `minReplicaMemoryGb` 8 in the same second. | +| 11-05 01:47:46 and 01:47:54 | The two 12 GiB replicas booted: 2.78 h after the cut. | +| 01:48:37 sample | `step_down_started`, 7 units: 2.80 h. | +| 01:55:37 sample | `step_down_done`, both 16 GiB replicas gone: 2.91 h. | + +This step came 1.3 h sooner than in pairs 1 and 3, while the 3-hour small window still held +A4's last 13 minutes. B4 at 4 units read 0.351 against 0.340 and 0.337 for B1 and B3. Reported as +read; why it came sooner is not measured. usageCost postings across pair 4: 0.298 to 0.299 +through 02:24, one 0.363 at 02:34 (the overlap), then 0.223 to 0.224. + +| Step down | Cut to new replicas booted | Cut to old replicas gone | Arm B busiest median at 4 units | +|---|---|---|---| +| Pair 1 | 4.20 h | 4.33 h | 0.340 | +| Pair 3 | 4.07 h | 4.21 h | 0.337 | +| Pair 4 | 2.78 h | 2.91 h | 0.351 | + +## The floor and the load curve + +On 2 x 8 GiB (2 units, the configured minimum), the probe raised arm A in 10-minute steps +(`cloud/probe.py`, `events.jsonl` phases `probe-1` to `probe-7`): + +| Rows/s | Busiest median | Busiest peak minute | Mean | Busiest cores: insert / select / merge | +|---|---|---|---|---| +| 2,000 | 0.130 | 0.133 | 0.111 | 0.030 / 0.005 / 0.085 | +| 5,000 | 0.159 | 0.181 | 0.137 | 0.041 / 0.013 / 0.118 | +| 10,000 | 0.201 | 0.215 | 0.171 | 0.053 / 0.000 / 0.176 | +| 20,000 | 0.285 | 0.404 | 0.237 | 0.043 / 0.048 / 0.316 | +| 35,000 | 0.400 | 0.425 | 0.329 | 0.067 / 0.113 / 0.387 | +| 50,000 | 0.529 | 0.620 | 0.450 | 0.089 / 0.182 / 0.550 | +| 70,000, before the step | 0.698 | 0.877 | 0.581 | 0.219 / 0.308 / 0.587 | + +- **Where the arms cost the same.** The service held 2 units through 50,000 rows/s and stepped + up at 70,000. Below the load that lifts arm A off 2 units, both arms cost the floor. Read over + 10-minute steps, that load lies between 50,000 and 70,000 rows/s. +- **Floor cost.** 2 units is $0.60/h, $14.3 a day at $0.2985. An idle service bills no compute. +- **Memory** was not binding: about 2 GiB resident of 8 during the probe. + +### Memory per arm + +GiB per replica, the median minute (`cloud/arms_report.py`: `memory_gib`, and per segment +`used_gib_mean`, `resident_gib_mean`, `used_gib_top`). The fields are `asynchronous_metric_log` +CGroupMemoryTotal, CGroupMemoryUsed and MemoryResident. "Used, top replica" is the replica +using the most. + +| Segment | Hours | Memory per replica | Used, mean | Resident, mean | Used, top replica | +|---|---|---|---|---|---| +| A1 at 4 units | 3.25 | 16 | 1.904 | 2.480 | 1.991 | +| B1 at 4 units | 4.22 | 16 | 1.900 | 2.466 | 1.994 | +| B1 at 3 units | 1.00 | 12 | 1.602 | 2.190 | 1.653 | +| A2 at 3 units | 1.50 | 12 | 2.036 | 2.630 | 2.125 | +| B2 at 3 units (4.5 h hold) | 4.50 | 12 | 1.954 | 2.562 | 2.026 | +| B2 continued | 5.74 | 12 | 2.126 | 2.731 | 2.299 | +| A3 at 4 units | 3.13 | 16 | 1.889 | 2.497 | 1.984 | +| B3 at 4 units | 4.09 | 16 | 1.949 | 2.582 | 2.065 | +| B3 at 3 units | 1.00 | 12 | 2.076 | 2.654 | 2.400 | +| A4 at 4 units | 3.12 | 16 | 2.090 | 2.700 | 2.154 | +| B4 at 4 units | 2.80 | 16 | 2.045 | 2.687 | 2.096 | +| B4 at 3 units | 1.00 | 12 | 1.786 | 2.338 | 1.838 | + +At every size, each arm used about 2 GiB of 12 to 16 GiB, under a fifth. The band quoted in +`results/raw/autoscaler-doc-quotes.md` is on CPU alone, and a unit fixes memory to CPU at +8 GiB to 2 vCPU. So the memory each arm paid for was set by its CPU. Whether the recommender +reads memory as well is not measured. + +## Why the service ran at 16 GiB before the run + +Both replicas ran at 16 GiB and 4 vCPU from creation (11-02 14:38:37Z) through both of the +first awake stretches. At the next wake, 19:48Z, they started at 8 GiB, the configured minimum +(`results/raw/replica-history-size-minutes.jsonl`). + +The configured range never changed, and `/activities` logs no scaling event. Whether that was an +autoscaler decision or a creation-time size cannot be separated from what the API and the system +tables show. The run starts from the 8 GiB wake. + +## Billing, as read + +- **First stretch.** usageCost 11-02 for `chce-elasticity`, before the run, read computeCHC 0.398 + for the two stretches at 4 units. + - Against the activity log's running-to-idle span, 1.130 unit-hours, it is $0.337 at $0.2985. + The read is 18% above. + - Against the replicas' own first-to-last log samples, 1.428 unit-hours, it is $0.426. The + read is 7% below. + - Suspicion: metering covers part of the roughly 2 minutes each replica ran past + `service_idle`. No rate is inferred from it. +- **Posting lag.** A 0.378 posting at 05:53:15 was followed by 0.224 at 06:03:18, and the + step's overlap ran 05:07:32 to 05:15:21. If the 0.378 is the 05:00 to 05:15 quarter, postings + land 28 to 33 minutes after the quarter closes. That attribution is a reading, not a published + lag. + +## Autoscaler rules, quoted + +From the ClickHouse Cloud docs and the blog post of 2026-03-24, verbatim in +`results/raw/autoscaler-doc-quotes.md`: + +- CPU target 53%, high watermark 75%, low watermark 37.5%. +- "If the CPU utilization is between 37.5%–75% of allocated capacity, no scaling action is + taken." +- A 3-hour small window "enables faster scale-down". A 30-hour large window ensures a single-step + scale up to the window's peak. +- In the blog's merge table, "No change | Scale-down" goes to a hunting check that trusts the + small window unless it is trending up. + +Neither source says how often the recommender runs, whether it reads the busiest replica or the +mean, or how "maximum usage" is aggregated. + +## Harness notes + +- **Host pacer defect.** The first split fed the collector from a pacer on the host. Docker + Desktop's file sharing did not surface the host's appends to the collector's filelog until + something inside the VM touched the file, so the engine got the feed in four hourly bursts. + Its kept share read 0.0584. Proven at 18:41 to 18:42Z: with 1,616 lines in the feed, filelog + had accepted 0; one touch from a container and it accepted 1,828. The pacer now runs in a + container (`split/run.sh`). The invalid split is kept as evidence + (`results/split-hostpacer.json`). +- **Connection pinning.** After the probe's step up, kept-alive HTTPS connections stayed on the + old replicas and the new pair took no work. From 21:20:26 connections reopen every 30 s + (`cloud/chhttp.py`, `CHC_CONN_MAX_AGE`). Real clients pool connections too, so this is a + harness choice for clean attribution. +- **Lost system tables.** A removed replica takes its system tables with it. The old 8 GiB + replicas' 21:18 to 21:24 records are lost, because the meter had pulled only to 21:17. From + 21:35 the meter pulls every 60 s with a 30 s lag, so a step loses at most about 1.5 minutes of + the departing replicas. At the 05:14 step one old replica's last minute or two is missing. +- **Query overlap.** On 2 vCPU a serial query cycle reached 38.8 s, so `--overlap 3` was on from + the start of A1, keeping both arms' cycle count equal. +- **Arm B's stage.** Arm B reads `bench.stage_b`, so it reads only what it writes. The + calibration in the write share section measures the stage read in each arm and for arm B read + from `bench.stage` through a filter. +- **SSO.** The AWS SSO session that holds the Cloud API key in SSM expired during B2. Running + processes kept the key in their environment, but the driver could not PATCH `replicaScaling` + for A3. B2's load continued past its 4.5 h hold. B2 ran 10.25 h on 3 units in all, with no step + down. The continuation's row in the table is cut from `events.jsonl` `no_step_down` + (12:15:51Z) to the idle phase (18:00:25Z); its rows a second are counted client side from + `load.jsonl`, since its inserts carry B2's tag. At 18:00:25Z, with SSO still expired, the + driver logged `forced_idle_no_sso`. It stopped load and queries and paused the meter, whose + SQL pulls would otherwise keep the service awake. The meter paused at 18:02:55Z + (`meter_paused`). `size.jsonl` reads `running` at 18:07:26Z and `idle`, 0 units, at 18:08:26Z. + SSO primed at 11:18:05Z on 11-04 (`sso_primed`), after 17.3 h of idle, and pair 3 started from + the idle service. The first PATCH reached the service while it was still idle (response + `"state":"idle"`). The A3 phase note's "replicas at start" is the last size before the idle, + not a reading at the restart. A live GET at 11:18:33Z read My first service's allow-list as + the single runner /32 set on 11-02. The renewed session expired again at 11-04 19:17:35Z (the + SSO token cache's `expiresAt`); the run was unaffected, since every running process held the + key. For the deletion, one process read the key at 11-05 03:20:39Z, once the session was + renewed, and held it until the end (`results/raw/teardown.jsonl`: `key_loaded`). + +## Not measured + +- The wire parse of real inserts. Both arms insert from a stage table, so network parse CPU is + absent from both. +- The select share at steady state during the probe. The probe's 10-minute steps never filled + the 1-hour query windows. The arms' select cores above are from phases of 1.5 h and more. +- Which replica the recommender reads. Busiest and mean are reported at every reading. +- The recommender's cadence. +- Why pair 4's step down came 1.3 h sooner than pairs 1 and 3, why A4 read higher merge cores + than A1 and A3, why B3's first hour at 3 units read above B1's, and what the untagged CPU is. + Each is reported as read where it appears. + +## What this does not show + +- A production query mix: this was seven queries a minute. +- The collector and engine path live: the feed was pre-split. +- More than one region, schema or service shape: us-east-1, ClickStack `otel_logs`, 2 replicas. +- Loads between the probe's steps. +- A size below 2 x 8 GiB. + +## Credit + +- **Spent.** $42.61 of the $300 credit, against the run's $200 cap: creditBalances `amountSpent`, + the same in every poll from 11-05 04:25:02Z to the last at 05:35:23Z (`results/raw/usage.jsonl`). + It read $42.15 just after the deletion, with postings still landing + (`results/raw/teardown.jsonl`: `credit_after_delete`). +- **chce-elasticity's billing.** usageCost totalCHC 41.714, of which computeCHC 41.680: computeCHC + 4.288, 18.196, 14.878 and 4.318 on 11-02 to 11-05, each day's last reading in + `results/raw/usage.jsonl`. Its last change landed by the 04:25:02Z poll. +- **Unit-hours.** 137.15 by the meter (from 11-02 19:48Z, when it started) and 138.56 by the + sampler (from 14:51Z), $40.94 and $41.36 at $0.2985. +- **The rest.** amountSpent is $0.90 above the service's totalCHC. usageCost `grandTotalCHC` read + 0.17 to 0.53 CHC above the service's own rows in each poll's window; the poller kept only the + service's rows, so which entity billed the difference is not measured. +- **Deletion.** chce-elasticity was sent the stop command at 11-05 03:44:15Z (HTTP 200), read + stopped at 03:46:57Z and was deleted then (HTTP 200). A GET of it returned 404 and the services + listing held only "My first service" (`results/raw/teardown.jsonl`). +- **Kept.** "My first service", created at sign-up in us-west-2, had its allow-list narrowed from + 0.0.0.0/0 to the runner's /32 at 11-02 19:51:57Z and was not deleted + (`results/raw/first-service-ip-patch.json`). + +## Files + +- `split/`: the engine split. +- `cloud/`: the service, stage, feed, queries, meters, driver and reports. +- `results/`: the split and stage readings, the creation response. +- `results/raw/`: every raw log the scripts wrote. `meter`, `load`, `size`, `queries` and + `replica-memory-all` are committed as `.jsonl.gz`; `arms_report.py` and `curve.py` read them as + they are. `teardown.jsonl` holds the stop, the deletion and the service list after it. + `autoscaler-doc-quotes.md` and `pricing-quotes.md` quote the docs and the pricing page as read. diff --git a/clickhouse-cloud-elasticity/cloud/arms.py b/clickhouse-cloud-elasticity/cloud/arms.py new file mode 100644 index 0000000..38fa400 --- /dev/null +++ b/clickhouse-cloud-elasticity/cloud/arms.py @@ -0,0 +1,306 @@ +#!/usr/bin/env python3 +"""The two arms, run to a schedule, then the stage-read calibration. + +Natural pairs (pair 1, and pair 2's arm B): + A1 (arm A, every staged row at --rate) until --a-until; then for each pair r: + B arm B: bench.stage_b at --rate x --kept-share, so it carries the same + records a second as arm A and reads only what it writes. Runs until the + service has stepped down (every replica smaller than at the phase start) + and --b-after-step minutes have passed at the new size, or --b-max hours. + A arm A again for --a-again minutes; a step up that has started by then + (a replica larger than at the phase start) extends it until every replica + is at the new size plus 15 minutes, at most --a-again-max minutes. + +Resuming (--resume-b r --b-cut --b-hold h): B was labelled at the cut by +an earlier driver; hold it h hours from the cut, longer only if a step down has +started (then as above, within --b-max of the cut). No arm A after it. + +Forced pairs (--forced n ...), after the natural ones: for each n, + A PATCH replicaScaling minReplicaMemoryGb --pin (16) at the phase start, so + arm A's size is set by config; arm A at --rate for --a-hold hours, and at + least --a-settled hours after every replica reached the pinned size. + B PATCH minReplicaMemoryGb back to --floor (8) at the cut, so every step + down is the autoscaler's own; then as a natural B. +Every PATCH is logged with its time, request, status and the scaling fields of the +response to --patch-log and as an event. The API key is read from SSM once, into +this process, as soon as SSO allows; until then a forced pair waits in the phase it +is in and logs that it is waiting. At --idle-at, if SSO has still not primed, the +phase becomes "idle" (no load, no queries), the meter is paused (SIGSTOP) so its +SQL does not keep the service awake, and the service idles; once SSO primes the +meter resumes (SIGCONT) and the forced pair starts from the cold service. + + cal-readA, cal-readB, cal-readBfilter: mode=read for --calibrate minutes each: + arm A's slices of bench.stage, arm B's of bench.stage_b, and arm B's + slices filtered from bench.stage (what arm B would read without stage_b). + stop. + +The size is the sampler's size.jsonl: each sample lists every replica serving with +its memory. Every change in that list is logged to the events file, so the step +times and the make-before-break overlap are read from it afterwards. + + arms.py --control c.json --events e.jsonl --size size.jsonl --a-until [--pairs 3] + arms.py ... --pairs 0 --resume-b 2 --b-cut --b-hold 4.5 --forced 3 4 --service --patch-log p.jsonl +""" +import argparse +import json +import os +import pathlib +import signal +import subprocess +import sys +import time + +HERE = pathlib.Path(__file__).resolve().parent +sys.path.insert(0, str(HERE.parent)) +import cloud_api # noqa: E402 + +SCALING = ("id", "state", "minReplicaMemoryGb", "maxReplicaMemoryGb", "numReplicas", "autoscalingMode", + "idleScaling", "idleTimeoutMinutes") + + +def latest(path): + last = None + with open(path) as fh: + for line in fh: + try: + r = json.loads(line) + except ValueError: + continue + if r.get("hosts"): + last = r + return last + + +def sizes(sample): + return {h: round(v["mem_total"] / 2**30) for h, v in sample["hosts"].items()} + + +class Run: + def __init__(self, args): + self.a = args + self.seen = None + self.oid = None + for line in open(args.events): + r = json.loads(line) + if r.get("event") == "size": + self.seen = r["replicas"] + + def phase(self, name, arm, rate, note, *extra): + subprocess.run([sys.executable, str(HERE / "phase.py"), self.a.control, self.a.events, name, arm, str(rate), note, + *extra], check=True) + + def log(self, rec): + t = time.time() + with open(self.a.events, "a") as fh: + fh.write(json.dumps({"t": round(t, 1), "at": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(t)), **rec}) + "\n") + + def poll(self): + s = latest(self.a.size) + if s is None: + return None + cur = sizes(s) + if cur != self.seen: + self.log({"event": "size", "sample_at": s["at"], "replicas": cur, "units": s.get("units")}) + self.seen = cur + return cur + + def wait_until(self, until): + while time.time() < until: + self.poll() + self.prime() + time.sleep(30) + + def prime(self): + if self.oid or not self.a.service: + return bool(self.oid) + try: + cloud_api._AUTH = cloud_api._AUTH or cloud_api.auth() + self.oid = cloud_api.org_id() + except (SystemExit, Exception) as e: + if not getattr(self, "waiting_logged", False): + self.log({"event": "sso_waiting", "error": str(e)[:200]}) + self.waiting_logged = True + return False + self.log({"event": "sso_primed"}) + return True + + def patch(self, phase, floor): + body = {"minReplicaMemoryGb": floor, "maxReplicaMemoryGb": self.a.max_gb} + t = time.time() + out = cloud_api.call("PATCH", f"/organizations/{self.oid}/services/{self.a.service}/replicaScaling", body) + res = out.get("result") or {} + rec = {"t": round(t, 1), "at": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(t)), "phase": phase, + "request": body, "status": out.get("status") or out.get("httpStatus"), + "response": {k: res[k] for k in SCALING if k in res}, "error": out.get("error") or out.get("text")} + with open(self.a.patch_log, "a") as fh: + fh.write(json.dumps(rec) + "\n") + self.log({"event": "patch", **{k: rec[k] for k in ("phase", "request", "status", "response", "error")}}) + if rec["status"] != 200: + sys.exit(f"replicaScaling PATCH returned {rec['status']}") + + def hold_b(self, r, t0, end, top): + started = done = None + cap = t0 + self.a.b_max * 3600 + while time.time() < end: + cur = self.poll() + if cur and top: + if started is None and min(cur.values()) < top: + started = time.time() + end = cap + self.log({"event": "step_down_started", "pair": r, "replicas": cur, "after_s": round(started - t0)}) + if started is not None and done is None and max(cur.values()) < top: + done = time.time() + end = min(cap, done + self.a.b_after_step * 60) + self.log({"event": "step_down_done", "pair": r, "replicas": cur, "after_s": round(done - t0)}) + self.prime() + time.sleep(30) + if done is None: + self.log({"event": "no_step_down", "pair": r, "hours": round((time.time() - t0) / 3600, 2), "replicas": self.poll()}) + + def b(self, r, release=False): + rate = round(self.a.rate * self.a.kept_share) + start = self.poll() or {} + top = max(start.values()) if start else None + note = f"arm B pair {r}: bench.stage_b at {rate} rows/s; replicas at start {start}" + if release: + note += f"; minReplicaMemoryGb back to {self.a.floor} at the cut" + self.phase(f"B{r}", "B", rate, note, "stage=bench.stage_b") + t0 = time.time() + if release: + self.patch(f"B{r}", self.a.floor) + end = t0 + self.a.b_max * 3600 + self.hold_b(r, t0, end, top) + + def resume_b(self, r, cut, hold): + start = self.poll() or {} + top = max(start.values()) if start else None + self.log({"event": "resume", "phase": f"B{r}", "cut": cut, "hold_h": hold, "replicas": start}) + self.hold_b(r, cut, cut + hold * 3600, top) + + def a_again(self, n): + start = self.poll() or {} + top = max(start.values()) if start else None + self.phase(f"A{n}", "A", self.a.rate, f"arm A again: bench.stage at {self.a.rate} rows/s; replicas at start {start}") + t0 = time.time() + base = end = t0 + self.a.a_again * 60 + cap = t0 + self.a.a_again_max * 60 + started = done = None + while time.time() < end: + cur = self.poll() + if cur and top: + if started is None and max(cur.values()) > top: + started = time.time() + self.log({"event": "step_up_started", "phase": f"A{n}", "replicas": cur, "after_s": round(started - t0)}) + if started is not None and done is None and min(cur.values()) > top: + done = time.time() + self.log({"event": "step_up_done", "phase": f"A{n}", "replicas": cur, "after_s": round(done - t0)}) + if started is not None and done is None: + end = cap + elif done is not None: + end = min(max(base, done + 15 * 60), cap) + time.sleep(30) + if started is None: + self.log({"event": "no_step_up", "phase": f"A{n}", "minutes": round((time.time() - t0) / 60), "replicas": self.poll()}) + + def forced_a(self, n): + if not self.prime(): + self.log({"event": "forced_waiting_sso", "phase": f"A{n}", "current": json.load(open(self.a.control)).get("phase")}) + idled = False + while not self.prime(): + self.poll() + if not idled and self.a.idle_at and time.time() >= self.a.idle_at: + self.phase("idle", "-", 0, "forced_idle_no_sso: no load, no queries, meter paused until SSO primes") + self.log({"event": "forced_idle_no_sso", "before": f"A{n}"}) + time.sleep(150) + os.kill(int(open(self.a.meter_pid).read()), signal.SIGSTOP) + self.log({"event": "meter_paused"}) + idled = True + time.sleep(30) + if idled: + os.kill(int(open(self.a.meter_pid).read()), signal.SIGCONT) + self.log({"event": "meter_resumed", "before": f"A{n}"}) + start = self.poll() or {} + self.phase(f"A{n}", "A", self.a.rate, f"arm A pair {n}: bench.stage at {self.a.rate} rows/s; minReplicaMemoryGb " + f"{self.a.pin} at the phase start; replicas at start {start}") + t0 = time.time() + self.patch(f"A{n}", self.a.pin) + end = t0 + self.a.a_hold * 3600 + cap = t0 + self.a.a_hold_max * 3600 + started = done = None + while time.time() < end: + cur = self.poll() + if cur: + if started is None and max(cur.values()) >= self.a.pin and min(start.values() or [0]) < self.a.pin: + started = time.time() + self.log({"event": "step_up_started", "phase": f"A{n}", "replicas": cur, "after_s": round(started - t0)}) + if done is None and min(cur.values()) >= self.a.pin: + done = time.time() + end = min(cap, max(end, done + self.a.a_settled * 3600)) + self.log({"event": "step_up_done", "phase": f"A{n}", "replicas": cur, "after_s": round(done - t0)}) + time.sleep(30) + if done is None: + self.log({"event": "pin_not_reached", "phase": f"A{n}", "hours": round((time.time() - t0) / 3600, 2), + "replicas": self.poll()}) + + def calibrate(self): + rate_b = round(self.a.rate * self.a.kept_share) + for name, arm, rate, extra in (("cal-readA", "A", self.a.rate, ["mode=read"]), + ("cal-readB", "B", rate_b, ["mode=read", "stage=bench.stage_b"]), + ("cal-readBfilter", "B", self.a.rate, ["mode=read"])): + self.phase(name, arm, rate, "stage read calibration: slices read into Null, nothing inserted", *extra) + self.wait_until(time.time() + self.a.calibrate * 60) + + +def main() -> int: + ap = argparse.ArgumentParser() + ap.add_argument("--control", required=True) + ap.add_argument("--events", required=True) + ap.add_argument("--size", required=True) + ap.add_argument("--a-until", type=float) + ap.add_argument("--pairs", type=int, default=3) + ap.add_argument("--rate", type=int, default=70000) + ap.add_argument("--kept-share", type=float, default=112205 / 171807) + ap.add_argument("--b-max", type=float, default=6) + ap.add_argument("--b-after-step", type=float, default=60) + ap.add_argument("--a-again", type=float, default=90) + ap.add_argument("--a-again-max", type=float, default=150) + ap.add_argument("--resume-b", type=int) + ap.add_argument("--b-cut", type=float) + ap.add_argument("--b-hold", type=float, default=4.5) + ap.add_argument("--forced", type=int, nargs="*", default=[]) + ap.add_argument("--service") + ap.add_argument("--patch-log") + ap.add_argument("--pin", type=int, default=16) + ap.add_argument("--floor", type=int, default=8) + ap.add_argument("--max-gb", type=int, default=32) + ap.add_argument("--a-hold", type=float, default=3.25) + ap.add_argument("--a-settled", type=float, default=3) + ap.add_argument("--a-hold-max", type=float, default=4) + ap.add_argument("--idle-at", type=float) + ap.add_argument("--meter-pid") + ap.add_argument("--calibrate", type=float, default=15) + args = ap.parse_args() + if args.forced and not (args.service and args.patch_log): + ap.error("--forced needs --service and --patch-log") + if args.idle_at and not args.meter_pid: + ap.error("--idle-at needs --meter-pid") + run = Run(args) + run.poll() + run.prime() + if args.a_until: + run.wait_until(args.a_until) + for r in range(1, args.pairs + 1): + run.b(r) + run.a_again(r + 1) + if args.resume_b: + run.resume_b(args.resume_b, args.b_cut, args.b_hold) + for n in args.forced: + run.forced_a(n) + run.b(n, release=True) + run.calibrate() + subprocess.run([sys.executable, str(HERE / "phase.py"), args.control, args.events, "stop"], check=True) + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/clickhouse-cloud-elasticity/cloud/arms_report.py b/clickhouse-cloud-elasticity/cloud/arms_report.py new file mode 100644 index 0000000..21b29ca --- /dev/null +++ b/clickhouse-cloud-elasticity/cloud/arms_report.py @@ -0,0 +1,218 @@ +#!/usr/bin/env python3 +"""Per-phase units, unit-hours and dollars, and the arm pairs' elasticity. + +Units are 8 GiB of replica memory (2 vCPU each), summed over every replica serving. +Two meters, read independently: + + meter the replicas' own asynchronous_metric_log, CGroupMemoryTotal per minute: + each replica-minute counts its memory for the seconds it was sampled (n/60), + so a make-before-break overlap counts all four replicas + size the sampler's Prometheus scrape every 60 s (size.jsonl), units x the gap to + the next sample, gaps over 180 s not counted + +Dollars are unit-hours x --price (0.2985, the published Scale compute rate per unit-hour +in AWS us-east-1, results/raw/pricing-quotes.md) and, separately, the change in usageCost +computeCHC between the poller's readings, shifted by --lag-min (the posting lag read +off the usage series; 0 prints the unshifted change), left out until the poller +has a reading past the phase's end plus that lag. + +For each phase: hours, unit-hours both ways, mean units, the units over the last +--tail minutes (the size it settled at), and the CPU summary from curve.py. Each +phase is also cut at the driver's size events into segments named @u +(a make-before-break overlap is its own segment), each with its hours, unit-hours +and CPU and memory, so a phase's settled size has its own utilisation. Memory is GiB per +replica, median minute: CGroupMemoryUsed and MemoryResident averaged over replicas, and +the used memory of the replica using the most. For each pair B against A (the arm +A run just before it) and A (just after, only when it starts at B's end, so not +across an idle): the units ratio and the fall in units against the fall in rows (0.653) +and bytes (0.612). meter.jsonl and size.jsonl are read as committed, gzipped, when the +plain file is absent. + + arms_report.py --raw results/raw [--price 0.2985] [--lag-min 0] [--tail 30] +""" +import argparse +import collections +import gzip +import json +import pathlib +import subprocess +import sys +import tempfile + +HERE = pathlib.Path(__file__).resolve().parent +ROWS, BYTES = 112205 / 171807, 24706958 / 40379948 + + +def src(raw, name): + p = raw / name + return p if p.exists() else raw / (name + ".gz") + + +def lines(path): + return gzip.open(path, "rt") if str(path).endswith(".gz") else open(path) + + +def phases(events): + out = [r for r in map(json.loads, open(events)) if "phase" in r and "event" not in r] + return [(a, b["t"] if b else None) for a, b in zip(out, out[1:] + [None])] + + +def segments(events): + evs = list(map(json.loads, open(events))) + sizes = [(r["t"], r.get("units")) for r in evs if r.get("event") == "size"] + out = [] + for p, end in phases(events): + a, b = p["t"], end or 1e12 + cur = ([u for t, u in sizes if t <= a] or [None])[-1] + cuts = [(a, cur)] + [(t, u) for t, u in sizes if a < t < b] + for (t0, u), nxt in zip(cuts, cuts[1:] + [(b, None)]): + out.append({"t": t0, "end": nxt[0], "phase": f"{p['phase']}@{u:g}u" if u else p["phase"], "of": p["phase"], + "arm": p.get("arm"), "rows_per_s": p.get("rows_per_s"), "mode": p.get("mode", "insert")}) + return out + + +def curve(meter, events): + out = subprocess.run([sys.executable, str(HERE / "curve.py"), "--meter", str(meter), "--events", str(events)], + capture_output=True, text=True, check=True).stdout + return {r["phase"]: r for r in map(json.loads, out.splitlines())} + + +def meter_units(path): + per = collections.defaultdict(float) + for line in lines(path): + r = json.loads(line) + if r.get("src") == "async" and r.get("metric") == "CGroupMemoryTotal": + per[r["m"]] += r["avg"] / 2**33 * r.get("n", 60) / 60 + return per + + +def size_units(path): + pts = [] + for line in lines(path): + try: + r = json.loads(line) + except ValueError: + continue + if r.get("hosts"): + pts.append((r["t"], sum(v["mem_total"] for v in r["hosts"].values()) / 2**33)) + return pts + + +def usage(path): + """Cumulative computeCHC at each poll. A poll covers yesterday and today (UTC); a day that + leaves the window keeps its last value, so the series does not drop at midnight.""" + pts, days = [], {} + for line in open(path): + r = json.loads(line) + if "days" in r: + days.update({k: v["computeCHC"] or 0 for k, v in r["days"].items()}) + pts.append((r["t"], sum(days.values()), r.get("amountSpent"))) + return pts + + +def at(pts, t): + last = None + for p in pts: + if p[0] > t: + break + last = p + return last + + +def main() -> int: + ap = argparse.ArgumentParser() + ap.add_argument("--raw", required=True) + ap.add_argument("--price", type=float, default=0.2985) + ap.add_argument("--lag-min", type=float, default=0) + ap.add_argument("--tail", type=float, default=30) + args = ap.parse_args() + raw = pathlib.Path(args.raw) + meter = src(raw, "meter.jsonl") + mu, su, us = meter_units(meter), size_units(src(raw, "size.jsonl")), usage(raw / "usage.jsonl") + cpu = curve(meter, raw / "events.jsonl") + segs = segments(raw / "events.jsonl") + with tempfile.NamedTemporaryFile("w", suffix=".jsonl", delete=False) as fh: + for g in segs: + fh.write(json.dumps({k: v for k, v in g.items() if k not in ("end", "of")}) + "\n") + fh.write(json.dumps({"t": segs[-1]["end"], "phase": "stop"}) + "\n") + seg_cpu = curve(meter, fh.name) + pathlib.Path(fh.name).unlink() + rows, spans = {}, {} + for p, end in phases(raw / "events.jsonl"): + name = p["phase"] + if name == "stop" or not (name[0] in "AB" and name[1:].isdigit() or name.startswith("cal-")): + continue + a, b = p["t"], end or max(mu) + 60 + ms = [m for m in mu if a <= m and m + 60 <= b] + uh_meter = sum(mu[m] for m in ms) / 60 + uh_size = 0.0 + for (t0, u0), (t1, _) in zip(su, su[1:]): + if a <= t0 < b and t1 - t0 <= 180: + uh_size += u0 * (min(t1, b) - t0) / 3600 + tail = [mu[m] for m in ms if m >= b - args.tail * 60] + rec = {"phase": name, "arm": p.get("arm"), "mode": p.get("mode", "insert"), "stage": p.get("stage", "bench.stage"), + "set_rows_per_s": p.get("rows_per_s"), "start": p["at"], "hours": round((b - a) / 3600, 3), + "meter_minutes": len(ms), "unit_hours_meter": round(uh_meter, 3), "unit_hours_size": round(uh_size, 3), + "mean_units": round(uh_meter * 60 / len(ms), 3) if ms else None, + "tail_units": round(sum(tail) / len(tail), 3) if tail else None, + "usd_meter": round(uh_meter * args.price, 3), "usd_size": round(uh_size * args.price, 3)} + u0, u1 = at(us, a + args.lag_min * 60), at(us, b + args.lag_min * 60) + if u0 and u1 and u1[0] > u0[0] and us[-1][0] >= b + args.lag_min * 60: + rec["usage_computeCHC"] = round(u1[1] - u0[1], 3) + rec["usage_readings"] = [round(u0[0]), round(u1[0])] + c = cpu.get(name) + if c: + rec["rows_per_s"] = c["rows_per_s"] + rec["busiest_util"], rec["busiest_util_max"], rec["mean_util"] = ( + c["busiest"]["util"], c["busiest_util_max"], c["mean"]["util"]) + rec["busiest_cores"] = {k: c["busiest"][k] for k in ("cg_cores", "insert", "select", "merge", "read")} + rec["mean_cores"] = {k: c["mean"][k] for k in ("cg_cores", "insert", "select", "merge", "read")} + rec["memory_gib"] = {"total": c["mean"]["gib"], "used_mean": c["mean"]["used_gib"], + "resident_mean": c["mean"]["resident_gib"], "used_top": c["used_gib_top"]} + rec["segments"] = [] + for g in segs: + if g["of"] != name or g["phase"] == name: + continue + gm = [m for m in ms if g["t"] <= m and m + 60 <= min(g["end"], b)] + sr = {"segment": g["phase"], "from": g["t"], "hours": round((min(g["end"], b) - g["t"]) / 3600, 3), + "unit_hours_meter": round(sum(mu[m] for m in gm) / 60, 3)} + c = seg_cpu.get(g["phase"]) + if c: + sr.update(minutes=c["minutes"], busiest_util=c["busiest"]["util"], busiest_util_max=c["busiest_util_max"], + mean_util=c["mean"]["util"], busiest_cg_cores=c["busiest"]["cg_cores"], + mean_cg_cores=c["mean"]["cg_cores"], total_gib=c["mean"]["gib"], + used_gib_mean=c["mean"]["used_gib"], resident_gib_mean=c["mean"]["resident_gib"], + used_gib_top=c["used_gib_top"]) + rec["segments"].append(sr) + rows[name], spans[name] = rec, (a, end) + print(json.dumps(rec)) + for r in range(1, 10): + b = rows.get(f"B{r}") + if not b: + break + for an in (f"A{r}", f"A{r + 1}"): + a = rows.get(an) + if not a or not a["tail_units"] or not b["tail_units"]: + continue + if an == f"A{r + 1}" and spans[f"B{r}"][1] != spans[an][0]: + continue + pair = {"pair": r, "B": f"B{r}", "A": an} + for k in ("tail_units", "mean_units"): + ratio = b[k] / a[k] + pair[k] = {"A": a[k], "B": b[k], "ratio": round(ratio, 3), + "fall_over_rows_fall": round((1 - ratio) / (1 - ROWS), 3), + "fall_over_bytes_fall": round((1 - ratio) / (1 - BYTES), 3)} + if a.get("usage_computeCHC") and b.get("usage_computeCHC"): + ratio = (b["usage_computeCHC"] / b["hours"]) / (a["usage_computeCHC"] / a["hours"]) + pair["usage_per_hour"] = {"A": round(a["usage_computeCHC"] / a["hours"], 3), + "B": round(b["usage_computeCHC"] / b["hours"], 3), "ratio": round(ratio, 3), + "fall_over_rows_fall": round((1 - ratio) / (1 - ROWS), 3), + "fall_over_bytes_fall": round((1 - ratio) / (1 - BYTES), 3)} + print(json.dumps(pair)) + if us: + print(json.dumps({"usage_last": {"t": round(us[-1][0]), "computeCHC_cum": round(us[-1][1], 3), "amountSpent": us[-1][2]}})) + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/clickhouse-cloud-elasticity/cloud/chhttp.py b/clickhouse-cloud-elasticity/cloud/chhttp.py new file mode 100644 index 0000000..f627611 --- /dev/null +++ b/clickhouse-cloud-elasticity/cloud/chhttp.py @@ -0,0 +1,60 @@ +"""A keep-alive HTTPS client for the service's HTTP interface. + +Credentials come from the secret file the create step wrote (CHC_SECRET_FILE, +default ~/git/l1x-co/.claude-tmp/chce-secrets/service.json); nothing is printed. + +A connection is reopened once it is max_age seconds old (CHC_CONN_MAX_AGE, default +30), so the load balancer places each new connection on the replicas serving at +that moment. A kept-alive connection stays on its replica, and after a scale event +that is the old replica until it is removed. +""" +import base64 +import http.client +import json +import os +import ssl +import time +import urllib.parse + +SECRET = os.environ.get("CHC_SECRET_FILE", os.path.expanduser("~/git/l1x-co/.claude-tmp/chce-secrets/service.json")) + + +class CH: + def __init__(self, timeout=600, max_age=None): + s = json.load(open(SECRET)) + self.host = [e["host"] for e in s["endpoints"] if e["protocol"] == "https"][0] + self.auth = "Basic " + base64.b64encode(f"{s['user']}:{s['password']}".encode()).decode() + self.timeout = timeout + self.max_age = float(max_age if max_age is not None else os.environ.get("CHC_CONN_MAX_AGE", 30)) + self.conn = None + self.born = 0.0 + + def _connect(self): + self.conn = http.client.HTTPSConnection(self.host, 8443, timeout=self.timeout, context=ssl.create_default_context()) + self.born = time.time() + + def query(self, sql, settings=None, retries=2): + """Run one statement; returns (body text, summary header dict). Raises on a server error.""" + params = {"default_format": "TabSeparated"} + params.update({k: str(v) for k, v in (settings or {}).items()}) + path = "/?" + urllib.parse.urlencode(params) + last = None + for attempt in range(retries + 1): + try: + if self.conn is not None and time.time() - self.born > self.max_age: + self.conn.close() + self.conn = None + if self.conn is None: + self._connect() + self.conn.request("POST", path, body=sql.encode(), headers={"Authorization": self.auth}) + r = self.conn.getresponse() + body = r.read().decode(errors="replace") + summary = json.loads(r.getheader("X-ClickHouse-Summary") or "{}") + if r.status != 200: + raise RuntimeError(f"HTTP {r.status}: {body[:500]}") + return body, summary + except (http.client.HTTPException, OSError) as e: + last = e + self.conn = None + time.sleep(2 * (attempt + 1)) + raise RuntimeError(f"connection failed: {last!r}") diff --git a/clickhouse-cloud-elasticity/cloud/curve.py b/clickhouse-cloud-elasticity/cloud/curve.py new file mode 100644 index 0000000..a873c6a --- /dev/null +++ b/clickhouse-cloud-elasticity/cloud/curve.py @@ -0,0 +1,111 @@ +#!/usr/bin/env python3 +"""Per-phase load and CPU from the meter's per-minute readings. + +Phases come from the events log (each phase.py line starts one). Minutes wholly +inside a phase, after the first --settle minutes, are summarised per replica: + + rows_per_s written rows a second, from query_log inserts tagged with the phase + util (CGroupUserTime + CGroupSystemTime) / CGroupMaxCPU, the minute's average + cg_cores CGroupUserTime + CGroupSystemTime: cores busy in the replica's cgroup + proc_cores metric_log OSCPUVirtualTimeMicroseconds: cores busy in ClickHouse's threads + insert, select, read, merge, other cores by source: query_log tagged inserts, + tagged selects, tagged stage reads, part_log MergeParts, untagged queries + gib CGroupMemoryTotal + used_gib CGroupMemoryUsed + resident_gib MemoryResident: ClickHouse's resident set + +and printed as one JSON line per phase with the median minute of each figure, +for the busiest replica and the mean over replicas, plus used_gib_top, the median minute +of the replica using the most memory. A phase named @