mirror of
https://github.com/stablyai/orca.git
synced 2026-10-30 16:47:34 +00:00
feat(relay): log the director's zone and round-trip speed on each runtime line (#33372)
<!-- orca-pr-loc -->
<!-- Programmatic LoC summary. Do not edit by hand; rewritten on every commit. -->
| | Files | Added | Deleted | Net |
| :--- | ---: | ---: | ---: | ---: |
| Test | 3 | $\color{#1a7f37}{\Huge{\mathbf{+}}}$45 | 0 | $\color{#1a7f37}{\Huge{\mathbf{+}}}$45 |
| Prod | 3 | $\color{#1a7f37}{\Huge{\mathbf{+}}}$48 | 0 | $\color{#1a7f37}{\Huge{\mathbf{+}}}$48 |
<!-- /orca-pr-loc -->
## ELI5
Some relay director instances talk to the database about twice as slowly as the rest. Those slow ones are where almost all the single-instance stalls happen. Today the logs can't tell us where an instance is running, so we can't work out why some are slow. This PR adds two numbers to the log line every director already writes every 30 seconds: the zone the instance runs in, and the instance's typical database round-trip time.
## What Changed
- **Before:** the director's `orca_relay_runtime_metrics` line had per-connection statement timings but nothing about where the instance runs. Getting one per-instance speed number meant pooling those connection timings by hand.
- **After:** two new fields on that line.
- `instanceZone`: read once at boot from the Cloud Run metadata server (`instance/zone`). It's only read when `K_SERVICE` is set, so GCE cells and local runs skip it. If the read fails, the field is simply left off.
- `stickyStatementMsP50`: the median duration of every sticky-lane database statement in the window, across all connections. It comes from a new window-wide sample of up to 1024 statements, the same kind already kept per connection.
- **Unchanged:** behaviour. The zone read is fire-and-forget with a 3 s timeout and never blocks or fails boot. No request path reads either field.
## Why
In 7 days of director logs (10-17 to 10-25), each instance's median per-statement time sat at either about 1.7 ms or about 3.6 ms. An instance sometimes switched between the two mid-life, with no deploy. 74 of the 81 single-instance stalls happened while the instance was at the slow speed: about 15x the rate at the fast speed.
- CPU, the event loop, the pg pool and database locks were all ruled out. That leaves the network path between the instance and Cloud SQL, and we can't confirm it without knowing each instance's zone.
- With zone and speed on the same line, a couple of days of logs will show whether "slow" follows the zone or the host. That decides between the next fixes: changing the Cloud Run sandbox generation, using a private IP, or cutting round trips per assignment.
- **Alternative considered:** a boot-time-only zone log line. It would force every analysis to join two log streams, and the field on each line costs a few bytes.
- **Alternative considered:** logging a "fast/slow" label instead of the raw median. That would bake today's thresholds into the image.
## Linked Issue
N/A (internal investigation of director single-instance stalls).
## Visual Proof
N/A: log-only change on a backend service, with no UI.
## Testing
- `pnpm typecheck` for `@orca-cloud/relay`.
- The full relay vitest suite: 1348 passed, 201 skipped (postgres-backed suites skip without a database).
- New tests cover:
- parsing the zone from the metadata answer, and returning nothing on a refused, unreachable or malformed answer;
- the zone appearing only once it is known;
- the pooled statement median.
- The floating-promise census lists the zone read as settling its own failures.
- [ ] I manually tested these changes locally
- [x] Automated tests added/updated, or explained why not below
## AI Disclosure
## Review
## Agent skill upstream boundary
- [x] Not applicable, or this change copies or mechanically translates no upstream skill-installer source, tests, fixtures, registry entries, path tables, comments, or documentation.
## Notes
- **Wire compatibility:** none affected. These are new optional fields on a log line, and the existing watchers read named fields only.
- **SSH, mobile, desktop:** not affected.
- **Rollout:** rides the next director image. No pin or deploy is part of this PR.
## Checklist
- [x] This PR is small and focused
- [x] I explained what changed and why (ELI5, the user-facing before/after, the mechanism, and why over the alternatives)
- [x] Before/after screenshots or videos attached for UI changes, or `N/A` with reason
- [x] Self-reviewed for correctness, security, and performance
- [x] Cross-platform, SSH/remote, and path/shortcut impact considered (or N/A)
- [x] `pnpm lint`, `pnpm typecheck`, `pnpm test`, and `pnpm build` pass (or CI will cover; local preferred)
This commit is contained in:
@@ -0,0 +1,28 @@
|
||||
import { describe, expect, it, vi } from 'vitest'
|
||||
import { readCloudRunInstanceZone } from './cloud-run-instance-zone.js'
|
||||
|
||||
const answering = (status: number, body: string): typeof fetch =>
|
||||
vi.fn(async () => new Response(body, { status }))
|
||||
|
||||
describe('readCloudRunInstanceZone', () => {
|
||||
it('returns the zone from the metadata path', async () => {
|
||||
const fetchImpl = answering(200, 'projects/123456/zones/us-central1-f')
|
||||
await expect(readCloudRunInstanceZone(fetchImpl)).resolves.toBe('us-central1-f')
|
||||
expect(fetchImpl).toHaveBeenCalledWith(
|
||||
'http://metadata.google.internal/computeMetadata/v1/instance/zone',
|
||||
expect.objectContaining({ headers: { 'Metadata-Flavor': 'Google' } })
|
||||
)
|
||||
})
|
||||
|
||||
it('returns undefined when the metadata server refuses or is unreachable', async () => {
|
||||
await expect(readCloudRunInstanceZone(answering(404, 'not found'))).resolves.toBeUndefined()
|
||||
const unreachable: typeof fetch = vi.fn(async () => {
|
||||
throw new TypeError('fetch failed')
|
||||
})
|
||||
await expect(readCloudRunInstanceZone(unreachable)).resolves.toBeUndefined()
|
||||
})
|
||||
|
||||
it('returns undefined for a body that is not a zone name', async () => {
|
||||
await expect(readCloudRunInstanceZone(answering(200, '<html>'))).resolves.toBeUndefined()
|
||||
})
|
||||
})
|
||||
@@ -0,0 +1,22 @@
|
||||
const INSTANCE_ZONE_URL = 'http://metadata.google.internal/computeMetadata/v1/instance/zone'
|
||||
const REQUEST_TIMEOUT_MS = 3_000
|
||||
|
||||
// The metadata server answers `projects/<number>/zones/<zone>`. Undefined on any failure:
|
||||
// the zone only labels log lines, so it must never hold up or fail a boot.
|
||||
export async function readCloudRunInstanceZone(
|
||||
fetchImpl: typeof fetch = fetch
|
||||
): Promise<string | undefined> {
|
||||
try {
|
||||
const response = await fetchImpl(INSTANCE_ZONE_URL, {
|
||||
headers: { 'Metadata-Flavor': 'Google' },
|
||||
signal: AbortSignal.timeout(REQUEST_TIMEOUT_MS)
|
||||
})
|
||||
if (!response.ok) {
|
||||
return undefined
|
||||
}
|
||||
const zone = (await response.text()).trim().split('/').at(-1)
|
||||
return zone && /^[a-z0-9-]+$/.test(zone) ? zone : undefined
|
||||
} catch {
|
||||
return undefined
|
||||
}
|
||||
}
|
||||
@@ -10,6 +10,7 @@ import { describe, expect, it } from 'vitest'
|
||||
// Exempt: functions written to settle every failure themselves. Keyed file#name.
|
||||
const NEVER_REJECTS = new Map([
|
||||
['relay-background-operation.ts#runRelayBackgroundOperation', 'catches and logs every failure'],
|
||||
['cloud-run-instance-zone.ts#readCloudRunInstanceZone', 'one try/catch; resolves undefined on any failure'],
|
||||
['assignment-cleanup-steps.ts#runAssignmentCleanup', 'runs each step through the above'],
|
||||
['cell-heartbeat-client.ts#send', 'one try/catch around the whole send'],
|
||||
['cell-reserve-client.ts#send', 'one try/catch around the request; resolves every item'],
|
||||
|
||||
@@ -14,6 +14,7 @@ import {
|
||||
cellFlagParser
|
||||
} from './cell-flags.js'
|
||||
import { startControlFlagChannel } from './relay-control-flag-channel.js'
|
||||
import { readCloudRunInstanceZone } from './cloud-run-instance-zone.js'
|
||||
import {
|
||||
reconcileCellAdmissionAtStartup,
|
||||
roleOwnsAssignmentMaintenance
|
||||
@@ -76,6 +77,10 @@ const {
|
||||
cellIncarnation,
|
||||
shadowSeatPoller
|
||||
} = createRelayServer(config, database, { cellFlags: cellFlagChannel?.applied })
|
||||
// Cloud Run sets K_SERVICE; GCE cells and local runs skip the metadata read.
|
||||
if (process.env.K_SERVICE) {
|
||||
void readCloudRunInstanceZone().then((zone) => observability.setInstanceZone(zone))
|
||||
}
|
||||
// Same owner as the assignment sweep: the cleanup only expires credentials that every reader
|
||||
// already re-checks at read time, so running it in all 23 cells multiplied one table scan by 23
|
||||
// without changing any answer.
|
||||
|
||||
@@ -316,6 +316,8 @@ describe('relay observability', () => {
|
||||
stickySqlMsP99: 198,
|
||||
stickyStatementsP50: 14,
|
||||
stickyStatementsMax: 14,
|
||||
// 50 statements at 300 ms and 100 at 5-6 ms: the pooled median is the fast connection's.
|
||||
stickyStatementMsP50: 6,
|
||||
stickySqlByConnection: {
|
||||
'1': {
|
||||
requests: 50,
|
||||
@@ -332,6 +334,20 @@ describe('relay observability', () => {
|
||||
expect(entries[1]).not.toHaveProperty('stickySqlByConnection')
|
||||
})
|
||||
|
||||
it('stamps the instance zone once it is known', () => {
|
||||
const entries: Record<string, unknown>[] = []
|
||||
const observability = new RelayObservability(
|
||||
{ role: 'director', cellId: 'director', region: 'us-central1' },
|
||||
(entry) => entries.push(entry)
|
||||
)
|
||||
observability.flush(counts)
|
||||
observability.setInstanceZone('us-central1-a')
|
||||
observability.flush(counts)
|
||||
|
||||
expect(entries[0]).not.toHaveProperty('instanceZone')
|
||||
expect(entries[1]).toMatchObject({ instanceZone: 'us-central1-a' })
|
||||
})
|
||||
|
||||
it('bounds the per-connection sticky summary', () => {
|
||||
const entries: Array<Record<string, unknown>> = []
|
||||
const observability = new RelayObservability(
|
||||
|
||||
@@ -210,6 +210,8 @@ type RelayMetricDeltas = {
|
||||
stickySlotStatements: number[]
|
||||
stickySlotByConnection: Map<number, StickyConnectionStatements>
|
||||
stickySlotConnectionSamplesDropped: number
|
||||
stickyStatementMs: number[]
|
||||
stickyStatementsObserved: number
|
||||
assign503sByCause: Record<string, number>
|
||||
dbLockWaitSamples: number
|
||||
dbLockWaitersByKey: Record<string, number>
|
||||
@@ -305,6 +307,8 @@ const emptyDeltas = (): RelayMetricDeltas => ({
|
||||
stickySlotStatements: [],
|
||||
stickySlotByConnection: new Map(),
|
||||
stickySlotConnectionSamplesDropped: 0,
|
||||
stickyStatementMs: [],
|
||||
stickyStatementsObserved: 0,
|
||||
assign503sByCause: {},
|
||||
dbLockWaitSamples: 0,
|
||||
dbLockWaitersByKey: {},
|
||||
@@ -386,6 +390,7 @@ export class RelayObservability implements RelayRuntimeObserver {
|
||||
private deltas = emptyDeltas()
|
||||
private timer: ReturnType<typeof setInterval> | null = null
|
||||
private lastFlushAt = 0
|
||||
private instanceZone: string | undefined
|
||||
private lastFlushedSafety = {
|
||||
sqlFailures: 0,
|
||||
reconnects: 0,
|
||||
@@ -397,6 +402,10 @@ export class RelayObservability implements RelayRuntimeObserver {
|
||||
private readonly write: MetricWriter = (entry) => console.log(JSON.stringify(entry))
|
||||
) {}
|
||||
|
||||
setInstanceZone(zone: string | undefined): void {
|
||||
this.instanceZone = zone
|
||||
}
|
||||
|
||||
recordAuth(success: boolean): void {
|
||||
if (success) this.deltas.authSuccesses++
|
||||
else this.deltas.authFailures++
|
||||
@@ -457,6 +466,14 @@ export class RelayObservability implements RelayRuntimeObserver {
|
||||
deltas.stickySlotSqlMs.push(sample.sqlMs)
|
||||
deltas.stickySlotStatements.push(sample.statements)
|
||||
for (const [connectionId, samplesMs] of sample.statementMsByConnection) {
|
||||
for (const durationMs of samplesMs) {
|
||||
keepInReservoir(
|
||||
deltas.stickyStatementMs,
|
||||
deltas.stickyStatementsObserved++,
|
||||
durationMs,
|
||||
STICKY_STATEMENT_RESERVOIR_LIMIT
|
||||
)
|
||||
}
|
||||
let connection = deltas.stickySlotByConnection.get(connectionId)
|
||||
if (!connection) {
|
||||
if (deltas.stickySlotByConnection.size >= STICKY_CONNECTION_LIMIT) {
|
||||
@@ -679,6 +696,8 @@ export class RelayObservability implements RelayRuntimeObserver {
|
||||
role: this.identity.role,
|
||||
cellId: this.identity.cellId,
|
||||
region: this.identity.region,
|
||||
// Which zone this instance runs in; read once at boot, absent until then or off Cloud Run.
|
||||
...(this.instanceZone === undefined ? {} : { instanceZone: this.instanceZone }),
|
||||
...counts,
|
||||
forwardedBytesDelta: deltas.forwardedBytes,
|
||||
authSuccessesDelta: deltas.authSuccesses,
|
||||
@@ -871,6 +890,8 @@ function stickySlotFields(deltas: RelayMetricDeltas): Record<string, unknown> {
|
||||
stickySqlMsP99: sql.p99,
|
||||
stickyStatementsP50: statements.p50,
|
||||
stickyStatementsMax: statements.max,
|
||||
// This instance's round-trip speed over every connection; slow-speed directors are the ones that stall.
|
||||
stickyStatementMsP50: latencySummary(deltas.stickyStatementMs).p50,
|
||||
stickySqlByConnection: byConnection,
|
||||
// One per request-connection pair that found the window's table full.
|
||||
stickySqlConnectionSamplesDroppedDelta: deltas.stickySlotConnectionSamplesDropped
|
||||
|
||||
Reference in New Issue
Block a user