mirror of
https://github.com/andwati/zitadel.git
synced 2026-11-06 22:32:16 +00:00
3be21ccbf0
Publishes the v4.17.1 benchmark sweep and the harness fixes the sweep uncovered. ## Results All 11 published targets ran for 30 minutes each against a fixed 7-container deployment (vCPU 6 / 6 Gi, psql v17.4, US1 client and server), at 600 VUs except where noted. Latencies are `http_req_duration` over the test phase. | target | VUs | iter/s | p50 | p95 | p99 | failed requests | |:---|---:|---:|---:|---:|---:|:---| | machine_pat_login | 600 | 3452 | 24.53ms | 872ms | 1.00s | 29 / 6,335,633 (0.00%) | | user_info | 600 | 3217 | 29.32ms | 943ms | 1.13s | 66 / 5,800,788 (0.00%) | | introspect | 600 | 2297 | 46.49ms | 1.16s | 1.36s | 1,400 / 4,159,863 (0.03%) | | machine_jwt_profile_grant | 600 | 1076 | 85.34ms | 2.57s | 2.93s | 97 / 1,986,156 (0.00%) | | machine_client_credentials_login | 600 | 834 | 56.78ms | 1.74s | 2.42s | 1,789 / 3,073,497 (0.05%) | | add_session | 600 | 767 | 95.25ms | 3.53s | 4.15s | 1 / 1,416,546 (0.00%) | | oidc_session | 600 | 326 | 77.47ms | 3.41s | 4.43s | 3 / 1,767,162 (0.00%) | | otp_session | 600 | 84 | 47.80ms | 13.83s | 20.22s | 182 / 466,756 (0.03%) | | password_session | 600 | 68 | 408.63ms | 20.00s | 24.05s | 1 / 253,280 (0.00%) | | human_password_login | 600 | 49 | 146.67ms | 4.08s | 1m0s | 9,227 / 683,256 (1.35%) | | manipulate_user | **200** | 19 | 304.58ms | 10.23s | 38.43s | 225 / 171,987 (0.13%) | Against the goals: - **#8352 is met.** `machine_jwt_profile_grant` reached **1076/s** against the 1000/s goal, with p50 at 85ms. - **#4424 is not met.** `human_password_login` runs at **49/s** against a 1200/s goal. The sweep ran with `improvedPerformance` enabled (`PROJECT_GRANT`, `PROJECT`, `USER_GRANT`, `ORG_DOMAIN_VERIFIED`), captured from the instance before the first target rather than assumed; the full flag set is on every page. ## What the observability rows show The containers were never the constraint. ZITADEL CPU sat at 9–50% (p50), memory at 6–7% (p50, peaking at 16%) of 6 GiB, and instance count was flat at 7 with no container startups in any window. Database CPU was at **86–98% median on nine of eleven targets**. Any "ZITADEL achieves N/s" figure that omits which resource ran out is true and misleading, so the pages say. The query breakdown then shows what the CPU numbers cannot: **advisory lock wait is the single largest category of database time across the sweep (91,857 s accumulated)**, ahead of event reads (64,805 s), event push (26,411 s) and projection reads (14,625 s). The three locks are the projection handler lock (`handler/v2/handler.go`), the eventstore read barrier (`repository/sql/query.go`) and the shared lock every push takes (`eventstore/v3/push.go`). That is what sets the `flowchart outcome` on each page, and it is not uniform: - **Scale** on the seven targets where a resource genuinely ran out — database CPU at 92–98% with 0% lock share. - **Potential issues** on `human_password_login`, `password_session`, `otp_session` and `manipulate_user`, where 45–74% of the top query time is lock wait. `password_session` runs at 51% database CPU and 50% container CPU and still only manages 68 iter/s; adding vCPU there buys nothing. Autovacuum is cleared as a contributor: 93.9% median DB CPU in buckets containing a vacuum against 93.1% without, within noise. The new v4.17 eventstore autovacuum is barely triggered — `events2` is not in the top twenty vacuumed tables. ## Harness fixes Defects found during the sweep, all of which corrupted published numbers or aborted runs: 1. **Colliding check names.** `updateHuman`, `lockUser` and `deleteUser` all registered checks as `update user is status ok`, two of them asserting `status === 201` against endpoints returning 200. k6 aggregates checks by name, so this produced a permanent, fictional 28% failure rate. Each check now has its own name and accepts 2xx. 2. **User-creation read-after-write race**, in three variants, each found after the previous fix. The read-back resolved `undefined` when the projection was behind, surfacing much later as `Cannot read property '0' of undefined`; then an unguarded `res.json()` turned every request timeout into a killed iteration; then a *partial* read — a valid user object with `loginNames` not yet projected — passed an `if (user)` guard and failed identically. `readUserAfterCreate()` now guards status and body before parsing, requires the field rather than the object, and retries with backoff, rejecting with the user id and username. 3. **Metric cardinality.** Id-bearing URLs produced 800k+ time series against k6's suggested 100k, driving k6 to 6.8 GB and an OOM mid-run. All 16 such call sites now set a grouped `name` tag. 4. **`password_session` wrote its CSV to `otp_session`'s filename** in the Makefile, silently overwriting the previous target's output. The read-back race is not only a harness defect: at 600 VUs it measures real load-induced projection lag, exceeding 25 s for login-name projection and 100 s for the user projection, against instant reads on an unloaded instance. ## Stable v2 user API Four calls in `benchmark/src/user.ts` still went to `/v2beta/users` — update, lock, delete and the machine read-back. They date from the original load-test bootstrap in April 2024 (#7635), when the user service was still v2beta, and were never moved when it was promoted; they surfaced in this diff only because the read-after-write fix rewrote the surrounding functions. All four are now on stable v2. `updateHuman` is the one that changed shape: `PUT /v2beta/users/{id}` is `UpdateHumanUser`, whose stable-v2 counterpart `PUT /v2/users/human/{id}` is deprecated in the proto, so it now calls `PATCH /v2/users/{id}` (`UpdateUser`) and `manipulate_user` nests the profile under `human`. Both RPCs land on `command.ChangeUserHuman`, so the measured work is unchanged. `lockUser`, `deleteUser` and the `createMachine` read-back move over unchanged in method and payload. No published result is affected: per-endpoint latencies come from custom Trends, and `run-bench.sh` drops the `name` system tag, so no artefact ever recorded a v2beta URL. The remaining `/management/v1` and `/admin/v1` calls are left alone — migrating those changes which API surface is benchmarked and would need a re-run. ## Timestamps Pages reported `Test start` as a bare `HH:MM`, so a run could not be correlated against monitoring the next day. Pages now carry the full UTC date and time and a `Test end` row, both derived from the first and last per-second row of `output.json`. `_template.mdx` is updated to match. ## Post-mortem `benchmark/postmortems/2026-08-27-503-burst.md` records two bursts of HTTP 503 `Service error -27` — an HTML page from the Google frontend, not a ZITADEL error — on `manipulate_user` and `human_password_login`, six hours apart. **The investigation is open**, and the note is explicit about what is established (no container startups; the two bursts have opposite server-side signatures), what is provisionally ruled out (restart, panic), and what is not yet known. It is included because both affected pages report the 503s as a separate population from the ZITADEL failures beside them, and that split needs its evidence somewhere. It also records two defects found by accident in the collected logs, unrelated to the 503s: `sql: transaction has already been committed or rolled back` (232 occurrences under load) and a missing i18n key, `"unable to get user by id" not found in language "en"`. ## Notes for review - **`manipulate_user` ran at 200 VUs, not 600, and the page says so.** Throughput saturates near 100 VUs; at 600 the same target produced 4,283 failed requests for identical throughput against 225 at 200 VUs. Its failure mode is degradation over sustained single-org churn — per-operation p50 climbs 1.7x–6x between the first and last five minutes of a run — not a concurrency threshold. - **Two `Observed errors` rows are hand-corrected** and deliberately differ from the generated text, on `manipulate_user` and `human_password_login`. Both cases are one generated number covering two unrelated failure populations; each page says it was corrected and why. - Org deletion failing with a 500 (`V3-C8l3V`) after heavy user churn is already tracked as #8510 and was hit repeatedly during cleanup. - **The run/publish tooling is no longer part of this PR.** It moved to a private repository, along with the cloud collection scripts, because deployment identity does not belong here. What remains is the published pages, the post-mortem findings and the harness fixes. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5 (1M context) <[email protected]>
105 lines
48 KiB
Plaintext
105 lines
48 KiB
Plaintext
---
|
|
title: manipulate user benchmark of zitadel v4.17.1
|
|
sidebar_label: manipulate user
|
|
---
|
|
|
|
import OutputSource from "./output.json";
|
|
import { BenchmarkChart } from "@/components/benchmark_chart";
|
|
|
|
Benchmark results of the v4.17.1 release of Zitadel.
|
|
|
|
## Performance test results
|
|
|
|
| Metric | Value |
|
|
| :------------------------------------ | :-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
|
| Baseline | none |
|
|
| Purpose | Test current performance |
|
|
| Test start | 2026-08-27 13:41:19 UTC |
|
|
| Test end | 2026-08-27 14:11:30 UTC |
|
|
| Test duration | 30min |
|
|
| Executed test | manipulate_user |
|
|
| k6 version | v2.1.0 |
|
|
| VUs | 200 |
|
|
| Client location | US1 |
|
|
| ZITADEL location | US1 |
|
|
| ZITADEL container specification | vCPU: 6<br/> Memory: 6 Gi <br/>Container min scale: 7<br/>Container max scale: 7 |
|
|
| ZITADEL Version | v4.17.1 |
|
|
| ZITADEL Settings | Eventstore autovacuum (new in v4.17): Enabled: true<br/>VacuumThreshold: 1000000<br/>AnalyzeThreshold: 1000000<br/>Tuned for the ~4,000 events/s expected during the benchmark, per the [tuning guide](https://zitadel.com/docs/self-hosting/manage/tuning#reading-events). |
|
|
| ZITADEL feature flags | Enabled: loginDefaultOrg (instance), oidcTokenExchange (system), enableBackChannelLogout (system), consoleUseV2UserApi (instance)<br/>improvedPerformance (instance): IMPROVED_PERFORMANCE_PROJECT_GRANT, IMPROVED_PERFORMANCE_PROJECT, IMPROVED_PERFORMANCE_USER_GRANT, IMPROVED_PERFORMANCE_ORG_DOMAIN_VERIFIED<br/>Disabled: loginV2 (explicitly false at instance), userSchema, debugOidcParentError, oidcSingleV1SessionTermination, permissionCheckV2<br/>Captured from the instance **before** the run (sequence 7, set 2026-08-27 13:35:31 UTC); the same capture covers `manipulate_user` at 13:41 and the rest of the sweep from 14:56, so all eleven targets ran the same configuration.<br/>This restores like-for-like comparison with the v4 pages, which ran five improvedPerformance options. The fifth, IMPROVED_PERFORMANCE_ORG_BY_ID, is `reserved` in the proto and no longer exists. |
|
|
| Database | type: psql<br />version: v17.4 |
|
|
| Database location | US1 |
|
|
| Database specification | vCPU: 8<br/> memory: 32Gib |
|
|
| ZITADEL metrics during test | CPU: p50 16%, p99 23% (peak 41%)<br/>Memory: p50 7%, peak 12%<br/>Instances: 7 (constant), no container startups recorded<br/>Server-side: 89 req/s, latency p50 300ms / p95 12.9s / p99 36.6s |
|
|
| Observed errors | 225 of 171,987 requests failed (0.13%). **Corrected by hand from the generated row, which reported these as a single population; they are two unrelated ones, 25 minutes apart.** (1) **150 platform errors, not ZITADEL errors**: HTTP 503 `Service error -27`, an HTML page from the Google frontend rather than a ZITADEL JSON error, confined entirely to a 55-second burst from 13:43:19 to 13:44:13 UTC, two minutes into the run, with no recurrence in the following 25 minutes. The shape is a container restart or replacement; a GCP post-mortem (restarts, panics, instance count) is pending and its findings so far are recorded in `benchmark/postmortems/2026-08-27-503-burst.md`. (2) **75 request timeouts** from 14:08:48 to 14:11:02 UTC, the documented degradation-over-sustained-churn behaviour of this target: the first arrives 1,658s (~28min) into the run and they cluster in the final minutes alongside a steady latency climb. The previous 200-VU run saw the equivalent 77 timeouts beginning at 1,255s. 127 of 137,522 checks failed (0.09%): create user (29), update user (41), lock user (25), delete user (32) — all of them within the two windows above. **The failed-check count is not comparable to the previous run's zero**: before commit `cdde3ab3e` a timeout killed the iteration before its check could be recorded (77 timeouts, 77 aborted iterations, 0 recorded check failures); with the response body now guarded, 75 timeouts aborted **0** iterations and the failures are recorded instead of being silently fatal. **This target ran at 200 VUs, not the 600 used for every other target**: at 600 VUs the same failure begins after 179s and produces a far higher error rate for identical throughput. |
|
|
| Top 3 most expensive database queries | 1: Query events by a multi-aggregate / event_type filter set (13,352 s)<br/>2: Projection handler advisory lock, one per projection per instance — **lock wait, not query work** (6,438 s)<br/>3: Query events by instance_id, aggregate_types, event_types, position (paged) (3,970 s)<br/>Ranked by total accumulated execution time summed across concurrent sessions (Cloud SQL Query Insights) — not CPU time; it can exceed the wall-clock window. |
|
|
| Database metrics during test | CPU: 98% median, 100% peak<br/>Memory: 40%<br/>Connections: 46<br/>Transactions: 1,487/s<br/>IOPS: read 0, write 539<br/>**CPU-saturated — the bottleneck for this target.** |
|
|
| k6 Iterations per second | 19 |
|
|
| k6 output | [output](#k6-output) |
|
|
| flowchart outcome | **Potential issues.** Not resource-bound: database CPU 98%, ZITADEL CPU 16%, yet **35% of the top-5 query time is advisory lock wait** — predominantly the projection handler lock, which serialises this workload. Additional vCPU will not help. Logged as an issue rather than blocking further scale testing. This target also shows the documented degradation over sustained single-org churn, with per-operation latency climbing across the run. |
|
|
|
|
## Endpoint latencies
|
|
|
|
<BenchmarkChart testResults={OutputSource} />
|
|
|
|
## k6 output
|
|
|
|
```bash
|
|
█ TOTAL RESULTS
|
|
|
|
checks_total.......: 137522 75.453808/s
|
|
checks_succeeded...: 99.90% 137395 out of 137522
|
|
checks_failed......: 0.09% 127 out of 137522
|
|
|
|
✓ user defined
|
|
✓ authorize status ok
|
|
✓ login name status ok
|
|
✓ login shows password page
|
|
✓ password status ok
|
|
✓ password callback
|
|
✓ code set
|
|
✓ token status ok
|
|
✓ access token created
|
|
✓ id token created
|
|
✓ info created
|
|
✓ org created
|
|
✗ create user is status ok
|
|
↳ 99% — ✓ 34370 / ✗ 29
|
|
✗ update user is status ok
|
|
↳ 99% — ✓ 34329 / ✗ 41
|
|
✗ lock user is status ok
|
|
↳ 99% — ✓ 34345 / ✗ 25
|
|
✗ delete user is status ok
|
|
↳ 99% — ✓ 34338 / ✗ 32
|
|
✓ org removed
|
|
|
|
CUSTOM
|
|
delete_user_duration.................: min=43.5ms avg=987.45ms max=17.06s p(50)=322.03ms p(95)=5.07s p(99)=8.54s
|
|
lock_user_duration...................: min=24.92ms avg=138.46ms max=4.11s p(50)=108.29ms p(95)=329.45ms p(99)=502.43ms
|
|
login_ui_enter_login_name_duration...: min=154.9ms avg=154.9ms max=154.9ms p(50)=154.9ms p(95)=154.9ms p(99)=154.9ms
|
|
login_ui_enter_password_duration.....: min=14.56ms avg=14.56ms max=14.56ms p(50)=14.56ms p(95)=14.56ms p(99)=14.56ms
|
|
login_ui_init_login_duration.........: min=109.41ms avg=109.41ms max=109.41ms p(50)=109.41ms p(95)=109.41ms p(99)=109.41ms
|
|
login_ui_token_duration..............: min=85.43ms avg=85.43ms max=85.43ms p(50)=85.43ms p(95)=85.43ms p(99)=85.43ms
|
|
org_create_org_duration..............: min=57.64ms avg=57.64ms max=57.64ms p(50)=57.64ms p(95)=57.64ms p(99)=57.64ms
|
|
update_human_duration................: min=17.01ms avg=116.71ms max=2.02s p(50)=87.97ms p(95)=291.12ms p(99)=441.72ms
|
|
user_create_human_duration...........: min=295.4ms avg=461.62ms max=2.28s p(50)=428.92ms p(95)=679.59ms p(99)=966.08ms
|
|
|
|
HTTP
|
|
http_req_duration....................: min=14.56ms avg=2.09s max=1m0s p(50)=304.58ms p(95)=10.23s p(99)=38.43s
|
|
{ expected_response:true }.........: min=14.56ms avg=2.07s max=59.92s p(50)=303.74ms p(95)=10.08s p(99)=38.08s
|
|
http_req_failed......................: 0.13% 225 out of 171987
|
|
http_reqs............................: 171987 94.363623/s
|
|
|
|
EXECUTION
|
|
iteration_duration...................: min=497.6ms avg=10.5s max=1m57s p(50)=4.22s p(95)=40.23s p(99)=55.66s
|
|
iterations...........................: 34399 18.873602/s
|
|
vus..................................: 0 min=0 max=200
|
|
vus_max..............................: 200 min=200 max=200
|
|
|
|
NETWORK
|
|
data_received........................: 98 MB 54 kB/s
|
|
data_sent............................: 31 MB 17 kB/s
|
|
|
|
running (30m22.6s), 000/200 VUs, 34399 complete and 0 interrupted iterations
|
|
default ✓ [ 100% ] 200 VUs 30m0s
|
|
```
|