-
Notifications
You must be signed in to change notification settings - Fork 1
Performance diagnostics #353
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Open
tobyhede
wants to merge
31
commits into
main
Choose a base branch
from
performance-diagnostics
base: main
Could not load branches
Branch not found: {{ refName }}
Loading
Could not load tags
Nothing to show
Loading
Are you sure you want to change the base?
Some commits from the old base branch may be removed from the timeline,
and old review comments may become outdated.
Open
Changes from all commits
Commits
Show all changes
31 commits
Select commit
Hold shift + click to select a range
4bf781c
feat(context): add PhaseTiming struct for performance breakdown
tobyhede 309528c
feat(context): add StatementMetadata for diagnostic tracking
tobyhede 91f386c
feat(log): add SLOW_STATEMENTS log target
tobyhede 64ac236
feat(config): add slow statement logging configuration
tobyhede e4fd48f
fix(log): export SLOW_STATEMENTS from log module
tobyhede f9bca38
feat(context): integrate PhaseTiming and StatementMetadata into session
tobyhede ed54387
feat(metrics): add keyset_cipher_init_duration_seconds histogram
tobyhede 2bb7346
feat(config): add slow_statements_enabled() and slow_statement_min_du…
tobyhede 31dcccf
fix(tests): fix duplicate #[test] attribute in tandem tests
tobyhede 07e7685
feat(context): add phase timing and metadata helper methods
tobyhede ca0824a
feat(io): record server/client IO durations for diagnostics
tobyhede fc3f653
feat(io): record server write duration in frontend
tobyhede e5dbc0b
feat(frontend): instrument extended protocol with timing and metadata
tobyhede d054c79
feat(frontend): record encrypt phase timing for diagnostics
tobyhede d8695a4
feat(frontend): instrument query_handler with parse timing and metadata
tobyhede 9f497e1
feat(frontend): complete instrumentation for diagnostics
tobyhede 6683afa
docs: add SLOW_STATEMENTS.md for performance troubleshooting
tobyhede b356dec
feat(metrics): add statement_type, protocol, mapped labels and slow s…
tobyhede e98eac5
test: add automated diagnostics log and metrics label checks
tobyhede da5c193
chore: update Cargo.lock with reqwest dependency
tobyhede 41e1349
fix(metrics): correct diagnostics timing and metadata recording
tobyhede 47af9db
style: apply cargo fmt formatting
tobyhede 45193f1
test(metrics): update prometheus assertions to be label-aware
tobyhede 13c49c4
Fix diagnostics attribution for pipelined sessions
tobyhede 7e5007a
Improve diagnostics metadata and integration metrics fetch
tobyhede 6959c1f
Format diagnostics frontend changes
tobyhede 321701f
test(integration): expose prometheus port for proxy-tls
tobyhede 9f07ad1
docs(context): document two-phase timing pattern in ExecuteContext
tobyhede 7808462
refactor(diagnostics): extract retry configuration to named constants
tobyhede 061bd29
refactor(frontend): improve session ID handling and reduce duplication
tobyhede e6bf1de
refactor(frontend): remove unused session_id parameter from write_to_…
tobyhede File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Oops, something went wrong.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,84 @@ | ||
| # Slow Statement Logging | ||
|
|
||
| CipherStash Proxy includes built-in slow statement logging for troubleshooting performance issues. | ||
|
|
||
| ## Configuration | ||
|
|
||
| Enable slow statement logging via environment variables: | ||
|
|
||
| ```bash | ||
| # Enable slow statement logging (required) | ||
| CS_LOG__SLOW_STATEMENTS=true | ||
|
|
||
| # Optional: Set minimum duration threshold (default: 2000ms) | ||
| CS_LOG__SLOW_STATEMENT_MIN_DURATION_MS=500 | ||
|
|
||
| # Optional: Set log level (default: warn when enabled) | ||
| CS_LOG__SLOW_STATEMENTS_LEVEL=warn | ||
|
|
||
| # Recommended: Use structured logging for parsing | ||
| CS_LOG__FORMAT=structured | ||
| ``` | ||
|
|
||
| ## Slow Statement Logs | ||
|
|
||
| When a statement exceeds the threshold, the proxy logs a detailed breakdown: | ||
|
|
||
| ```json | ||
| { | ||
| "client_id": 1, | ||
| "duration_ms": 10500, | ||
| "statement_type": "INSERT", | ||
| "protocol": "extended", | ||
| "encrypted": true, | ||
| "encrypted_values_count": 3, | ||
| "param_bytes": 1024, | ||
| "query_fingerprint": "a1b2c3d4", | ||
| "keyset_id": "uuid", | ||
| "mapping_disabled": false, | ||
| "breakdown": { | ||
| "parse_ms": 5, | ||
| "encrypt_ms": 450, | ||
| "server_write_ms": 12, | ||
| "server_wait_ms": 9800, | ||
| "server_response_ms": 233 | ||
| } | ||
| } | ||
| ``` | ||
|
|
||
| ## Prometheus Metrics | ||
|
|
||
| ### Labeled Histograms | ||
|
|
||
| Duration histograms now include labels for filtering: | ||
|
|
||
| - `statement_type`: insert, update, delete, select, other | ||
| - `protocol`: simple, extended | ||
| - `mapped`: true, false | ||
| - `multi_statement`: true, false | ||
|
|
||
| Example queries: | ||
| ```promql | ||
| # Average INSERT duration | ||
| histogram_quantile(0.5, rate(cipherstash_proxy_statements_session_duration_seconds_bucket{statement_type="insert"}[5m])) | ||
|
|
||
| # Compare encrypted vs passthrough | ||
| histogram_quantile(0.99, rate(cipherstash_proxy_statements_session_duration_seconds_bucket{mapped="true"}[5m])) | ||
| ``` | ||
|
|
||
| ### ZeroKMS Cipher Init | ||
|
|
||
| ``` | ||
| cipherstash_proxy_keyset_cipher_init_duration_seconds | ||
| ``` | ||
|
|
||
| Measures time for cipher initialization including ZeroKMS network call. High values indicate ZeroKMS connectivity issues. | ||
|
|
||
| ## Interpreting Results | ||
|
|
||
| | Symptom | Likely Cause | | ||
| |---------|--------------| | ||
| | High `encrypt_ms` | ZeroKMS latency or large payload | | ||
| | High `server_wait_ms` | Database latency | | ||
| | High `cipher_init_duration` | ZeroKMS cold start or network | | ||
| | High `parse_ms` | Complex SQL or schema lookup | |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The latest reqwest is 0.13