diff --git a/src/apps/trade-executor.mjs b/src/apps/trade-executor.mjs index bda7310..b4f1dcb 100644 --- a/src/apps/trade-executor.mjs +++ b/src/apps/trade-executor.mjs @@ -1,4 +1,5 @@ import process from 'node:process'; +import { performance } from 'node:perf_hooks'; import { createConsumer } from '../bus/kafka/consumer.mjs'; import { createProducer } from '../bus/kafka/producer.mjs'; @@ -179,6 +180,7 @@ await consumer.run({ async function handleCommand(event) { const payload = event.payload; + const timing = startExecutorTiming(event); state.last_command = payload; const existing = stateStore.get(payload.command_id); @@ -194,22 +196,22 @@ async function handleCommand(event) { } if (isMakerSuppressedForOwnRequest()) { - await publishResult(payload, { + await publishResult(payload, withExecutorTiming({ status: 'rejected', result_code: 'own_request_preflight_in_progress', note: 'Own request preflight is suppressing maker quote responses to avoid self-matching.', - }); + }, timing)); return; } if (state.paused) return; if (!state.armed) { - await publishResult(payload, { + await publishResult(payload, withExecutorTiming({ status: 'rejected', result_code: 'executor_disarmed', note: 'executor is disarmed', - }); + }, timing)); return; } @@ -222,7 +224,7 @@ async function handleCommand(event) { message: expiry.reason, }, }); - await publishResult(payload, { + await publishResult(payload, withExecutorTiming({ status: 'rejected', result_code: 'stale_execute_command', note: 'execute command deadline elapsed before relay submission', @@ -230,7 +232,7 @@ async function handleCommand(event) { command_deadline_ms: expiry.deadline_ms == null ? null : String(expiry.deadline_ms), command_deadline_at: expiry.deadline_at, stale_reason: expiry.reason, - }); + }, timing)); return; } @@ -242,27 +244,46 @@ async function handleCommand(event) { state.in_flight_count += 1; try { - const currentSaltHex = await verifierClient.currentSalt(); - const submission = buildQuoteResponseSubmission({ - command: payload, - signerAccountId: config.nearIntentsAccountId, - signer, - verifierContract: config.nearVerifierContract, - currentSaltHex, - }); + const saltStartMs = performance.now(); + let currentSaltHex; + try { + currentSaltHex = await verifierClient.currentSalt(); + } finally { + recordExecutorTiming(timing, 'current_salt_ms', saltStartMs); + } + + const signStartMs = performance.now(); + let submission; + try { + submission = buildQuoteResponseSubmission({ + command: payload, + signerAccountId: config.nearIntentsAccountId, + signer, + verifierContract: config.nearVerifierContract, + currentSaltHex, + }); + } finally { + recordExecutorTiming(timing, 'sign_ms', signStartMs); + } state.last_request = submission; - const response = await relayClient.request('quote_response', [submission], { - timeoutMs: config.executorResponseTimeoutMs, - }); + const relayStartMs = performance.now(); + let response; + try { + response = await relayClient.request('quote_response', [submission], { + timeoutMs: config.executorResponseTimeoutMs, + }); + } finally { + recordExecutorTiming(timing, 'relay_response_ms', relayStartMs); + } state.last_venue_response = response; state.last_error = null; - await publishResult(payload, { + await publishResult(payload, withExecutorTiming({ status: 'submitted', result_code: response === 'OK' ? 'quote_response_ok' : 'quote_response_ack', venue_response: response, - }); + }, timing)); stateStore.markSubmitted(payload.command_id, { quote_id: payload.quote_id, result: response, @@ -274,11 +295,11 @@ async function handleCommand(event) { quote_id: payload.quote_id, error: serializeError(error), }); - await publishResult(payload, { + await publishResult(payload, withExecutorTiming({ status: 'failed', result_code: 'submission_failed', error: serializeError(error), - }); + }, timing)); } finally { state.in_flight_count = Math.max(0, state.in_flight_count - 1); if (state.draining && state.in_flight_count === 0) { @@ -287,6 +308,52 @@ async function handleCommand(event) { } } +function startExecutorTiming(event) { + const receivedAt = new Date(); + const commandEventAtMs = Date.parse( + event?.ingested_at + || event?.observed_at + || event?.payload?.decision_at + || '', + ); + return { + received_at: receivedAt.toISOString(), + started_at_ms: performance.now(), + command_event_age_ms: Number.isFinite(commandEventAtMs) + ? roundTimingMs(receivedAt.getTime() - commandEventAtMs) + : null, + }; +} + +function recordExecutorTiming(timing, field, startedAtMs) { + if (!timing) return; + timing[field] = roundTimingMs(performance.now() - startedAtMs); +} + +function withExecutorTiming(payload, timing) { + return { + ...payload, + executor_timing: finishExecutorTiming(timing), + }; +} + +function finishExecutorTiming(timing) { + if (!timing) return null; + return { + received_at: timing.received_at, + command_event_age_ms: timing.command_event_age_ms, + current_salt_ms: timing.current_salt_ms ?? null, + sign_ms: timing.sign_ms ?? null, + relay_response_ms: timing.relay_response_ms ?? null, + executor_total_ms: roundTimingMs(performance.now() - timing.started_at_ms), + }; +} + +function roundTimingMs(value) { + const number = Number(value); + return Number.isFinite(number) ? Math.round(number * 1000) / 1000 : null; +} + async function publishResult(command, extraPayload) { const event = buildEventEnvelope({ source: 'trade-executor', diff --git a/src/core/operator-dashboard.mjs b/src/core/operator-dashboard.mjs index ce4e277..b4ce5ba 100644 --- a/src/core/operator-dashboard.mjs +++ b/src/core/operator-dashboard.mjs @@ -2415,6 +2415,7 @@ function normalizeLiveExecutionResult(payload, event) { venue_response: payload.venue_response || null, error_message: payload.error?.message || null, note: payload.note || null, + timing: payload.executor_timing || null, }; } diff --git a/src/lib/postgres.mjs b/src/lib/postgres.mjs index f8bc8b9..500c753 100644 --- a/src/lib/postgres.mjs +++ b/src/lib/postgres.mjs @@ -3617,6 +3617,7 @@ function normalizeExecutionResultRow(row) { venue_response: resultPayload.venue_response || null, error_message: resultPayload.error?.message || null, note: resultPayload.note || null, + timing: resultPayload.executor_timing || null, }; } diff --git a/src/operator-dashboard/static/pages/StrategyPage.jsx b/src/operator-dashboard/static/pages/StrategyPage.jsx index 77f4ca6..bc9de80 100644 --- a/src/operator-dashboard/static/pages/StrategyPage.jsx +++ b/src/operator-dashboard/static/pages/StrategyPage.jsx @@ -34,6 +34,29 @@ function formatRelativeAge(value, now) { return age === 'Unavailable' ? 'Age unavailable' : `${age} ago`; } +function formatTimingMs(value) { + const number = Number(value); + if (!Number.isFinite(number)) return null; + return `${number < 10 ? number.toFixed(1) : number.toFixed(0)} ms`; +} + +function formatExecutionTiming(timing) { + if (!timing) return null; + const parts = [ + ['total', timing.executor_total_ms], + ['cmd age', timing.command_event_age_ms], + ['salt', timing.current_salt_ms], + ['sign', timing.sign_ms], + ['relay', timing.relay_response_ms], + ] + .map(([label, value]) => { + const formatted = formatTimingMs(value); + return formatted ? `${label} ${formatted}` : null; + }) + .filter(Boolean); + return parts.length ? `Timing: ${parts.join(', ')}` : null; +} + function IdentifierRow({ label, value }) { if (!value) return