Feat/eth send user operation timing logs (#30)

arpan-jain · web-flow · commit 3a93bdbb60e0 · 2026-05-25T18:48:11.000+05:30
* feat(timing): instrument eth_sendUserOperation handler and validator

Adds a small `timed()` helper and wraps the 6 parallel async ops in
addToMempoolIfValid plus the validator's inner simulation RPC calls
(simulateValidation + simulateHandleOp for v0.6; simulateValidation for
v0.7). Replaces the unstructured console.log with a Pino structured log
at handler entry and adds a total-duration log on exit.

This makes wall-clock latency attributable to the slowest parallel step
and surfaces debug_traceCall / simulation RPC time, which is the typical
bottleneck for first-deploy boosted userOps (factory + initCode trace).

* refactor(timing): use performance.now() for monotonic duration measurement

Date.now() is wall-clock and can jump backward on NTP corrections or
manual clock changes, producing negative or wildly inflated durations.
performance.now() is monotonic by spec and has sub-ms resolution.

Round the float delta to whole ms for log readability — sub-ms precision
isn't useful for the network/RPC timings being measured (10s-100s of ms).

* fix(logging): emit single-line JSON when Betterstack token is unset

initProductionLogger previously fell back to initDebugLogger (pino-pretty)
when BETTER_STACK_TOKEN was missing. pino-pretty splits one structured
log across multiple lines, and Render's syslog forwarder treats each
line as a separate Betterstack record -- making the structured object
impossible to filter or correlate downstream.

Switch the no-token fallback to plain pino (single-line JSON to STDOUT)
while keeping the level + customSerializer formatters. Local-dev users
who want pretty output should keep using initDebugLogger directly.

* using betterstack endpoint for logs
diff --git a/src/rpc/methods/eth_sendUserOperation.ts b/src/rpc/methods/eth_sendUserOperation.ts
@@ -11,7 +11,8 @@ import type * as validation from "@alto/types"
 import {
     calcExecutionPvgComponent,
     calcL2PvgComponent,
-    getAAError
+    getAAError,
+    timed
 } from "@alto/utils"
 import type { Hex } from "viem"
 import { getNonceKeyAndSequence, getUserOpHash } from "../../utils/userop"
@@ -97,7 +98,11 @@ export async function addToMempoolIfValid({
 }): Promise<{ userOpHash: Hex; result: "added" | "queued" }> {
     rpcHandler.ensureEntryPointIsSupported(entryPoint)
 
-    // Execute multiple async operations in parallel
+    const logCtx = { sender: userOp.sender, apiVersion, boost }
+
+    // Execute multiple async operations in parallel. Each step is timed
+    // individually so the slowest can be identified from logs (wall-clock
+    // latency = slowest step, not the sum).
     const [
         userOpHash,
         { queuedUserOps, validationResult },
@@ -106,20 +111,32 @@ export async function addToMempoolIfValid({
         [preMempoolSuccess, preMempoolError],
         [validEip7702Auth, validEip7702AuthError]
     ] = await Promise.all([
-        getUserOpHash({
-            userOp,
-            entryPointAddress: entryPoint,
-            chainId: rpcHandler.config.chainId,
-            publicClient: rpcHandler.config.publicClient
-        }),
-        getUserOpValidationResult(rpcHandler, userOp, entryPoint),
-        rpcHandler.getNonceSeq(userOp, entryPoint),
-        validatePvg(apiVersion, rpcHandler, userOp, entryPoint, boost),
-        rpcHandler.preMempoolChecks(userOp, apiVersion, boost),
-        rpcHandler.validateEip7702Auth({
-            userOp,
-            validateSender: true
-        })
+        timed(rpcHandler.logger, "getUserOpHash", logCtx, () =>
+            getUserOpHash({
+                userOp,
+                entryPointAddress: entryPoint,
+                chainId: rpcHandler.config.chainId,
+                publicClient: rpcHandler.config.publicClient
+            })
+        ),
+        timed(rpcHandler.logger, "getUserOpValidationResult", logCtx, () =>
+            getUserOpValidationResult(rpcHandler, userOp, entryPoint)
+        ),
+        timed(rpcHandler.logger, "getNonceSeq", logCtx, () =>
+            rpcHandler.getNonceSeq(userOp, entryPoint)
+        ),
+        timed(rpcHandler.logger, "validatePvg", logCtx, () =>
+            validatePvg(apiVersion, rpcHandler, userOp, entryPoint, boost)
+        ),
+        timed(rpcHandler.logger, "preMempoolChecks", logCtx, () =>
+            rpcHandler.preMempoolChecks(userOp, apiVersion, boost)
+        ),
+        timed(rpcHandler.logger, "validateEip7702Auth", logCtx, () =>
+            rpcHandler.validateEip7702Auth({
+                userOp,
+                validateSender: true
+            })
+        )
     ])
 
     // Validate eip7702Auth
@@ -222,18 +239,20 @@ export const ethSendUserOperationHandler = createMethodHandler({
     method: "eth_sendUserOperation",
     schema: sendUserOperationSchema,
     handler: async ({ rpcHandler, params, apiVersion }) => {
-        console.log("=== eth_sendUserOperation called ===")
+        const handlerStart = performance.now()
         const [userOp, entryPoint] = params
 
+        const boost =
+            userOp.maxFeePerGas === 0n && userOp.maxPriorityFeePerGas === 0n
+
+        rpcHandler.logger.info(
+            { sender: userOp.sender, apiVersion, boost, entryPoint },
+            "[timing] eth_sendUserOperation received"
+        )
+
         let status: "added" | "queued" | "rejected" = "rejected"
+        let resolvedUserOpHash: Hex | undefined
         try {
-            let boost = false
-            if (
-                userOp.maxFeePerGas === 0n &&
-                userOp.maxPriorityFeePerGas === 0n
-            ) {
-                boost = true
-            }
             const { result, userOpHash } = await addToMempoolIfValid({
                 rpcHandler,
                 userOp,
@@ -243,6 +262,7 @@ export const ethSendUserOperationHandler = createMethodHandler({
             })
 
             status = result
+            resolvedUserOpHash = userOpHash
 
             rpcHandler.eventManager.emitReceived(userOpHash)
 
@@ -257,6 +277,18 @@ export const ethSendUserOperationHandler = createMethodHandler({
                     type: userOp.eip7702Auth ? "7702" : "regular"
                 })
                 .inc()
+
+            rpcHandler.logger.info(
+                {
+                    sender: userOp.sender,
+                    apiVersion,
+                    boost,
+                    status,
+                    userOpHash: resolvedUserOpHash,
+                    ms: Math.round(performance.now() - handlerStart)
+                },
+                "[timing] eth_sendUserOperation total"
+            )
         }
     }
 })
diff --git a/src/rpc/validation/UnsafeValidator.ts b/src/rpc/validation/UnsafeValidator.ts
@@ -22,7 +22,7 @@ import {
     entryPointExecutionErrorSchema07
 } from "@alto/types"
 import type { Logger, Metrics } from "@alto/utils"
-import { isVersion06 } from "@alto/utils"
+import { isVersion06, timed } from "@alto/utils"
 import * as sentry from "@sentry/node"
 import type { StateOverride } from "viem"
 import {
@@ -311,26 +311,41 @@ export class UnsafeValidator implements InterfaceValidator {
             eip7702Override = getEip7702DelegationOverrides([userOp])
         }
 
-        const simulateValidationPromise = entryPointContract.simulate
-            .simulateValidation(
-                [userOp],
-                eip7702Override ? { stateOverride: eip7702Override } : {}
-            )
-            .catch((e) => {
-                if (e instanceof Error) {
-                    return e
-                }
-                throw e
-            })
+        const v06LogCtx = { sender: userOp.sender, entryPoint, version: "0.6" }
+
+        const simulateValidationPromise = timed(
+            this.logger,
+            "v06.simulateValidation",
+            v06LogCtx,
+            () =>
+                entryPointContract.simulate
+                    .simulateValidation(
+                        [userOp],
+                        eip7702Override
+                            ? { stateOverride: eip7702Override }
+                            : {}
+                    )
+                    .catch((e) => {
+                        if (e instanceof Error) {
+                            return e
+                        }
+                        throw e
+                    })
+        )
 
-        const runtimeValidationPromise =
-            this.gasEstimationHandler.gasEstimator06.simulateHandleOp06({
-                entryPoint,
-                userOp,
-                useCodeOverride: false, // disable code override so that call phase reverts aren't caught
-                targetAddress: zeroAddress,
-                targetCallData: "0x"
-            })
+        const runtimeValidationPromise = timed(
+            this.logger,
+            "v06.simulateHandleOp",
+            v06LogCtx,
+            () =>
+                this.gasEstimationHandler.gasEstimator06.simulateHandleOp06({
+                    entryPoint,
+                    userOp,
+                    useCodeOverride: false, // disable code override so that call phase reverts aren't caught
+                    targetAddress: zeroAddress,
+                    targetCallData: "0x"
+                })
+        )
 
         const [simulateValidationResult, runtimeValidation] = await Promise.all(
             [simulateValidationPromise, runtimeValidationPromise]
@@ -475,12 +490,17 @@ export class UnsafeValidator implements InterfaceValidator {
     > {
         const { userOp, queuedUserOps, entryPoint } = args
 
-        const simulateValidationResult =
-            await this.gasEstimationHandler.gasEstimator07.simulateValidation({
-                entryPoint,
-                userOp,
-                queuedUserOps
-            })
+        const simulateValidationResult = await timed(
+            this.logger,
+            "v07.simulateValidation",
+            { sender: userOp.sender, entryPoint, version: "0.7" },
+            () =>
+                this.gasEstimationHandler.gasEstimator07.simulateValidation({
+                    entryPoint,
+                    userOp,
+                    queuedUserOps
+                })
+        )
 
         if (simulateValidationResult.result === "failed") {
             throw new RpcError(
diff --git a/src/utils/index.ts b/src/utils/index.ts
@@ -5,4 +5,5 @@ export * from "./preVerificationGasCalulator"
 export * from "./userop"
 export * from "./helpers"
 export * from "./asyncTimeout"
+export * from "./timed"
 export type { Logger } from "pino"
diff --git a/src/utils/logger.ts b/src/utils/logger.ts
@@ -90,10 +90,17 @@ export const initDebugLogger = (level = "debug"): Logger => {
 let transport: any
 
 if (process.env.BETTER_STACK_TOKEN) {
+    const logtailOptions: { sourceToken: string; endpoint?: string } = {
+        sourceToken: process.env.BETTER_STACK_TOKEN
+    }
+    if (process.env.BETTER_STACK_ENDPOINT) {
+        logtailOptions.endpoint = process.env.BETTER_STACK_ENDPOINT
+    }
+
     // @ts-ignore - pino.transport exists at runtime but types may be incomplete
     transport = pino.transport({
         target: "@logtail/pino",
-        options: { sourceToken: process.env.BETTER_STACK_TOKEN }
+        options: logtailOptions
     })
 
     let reviving = false
@@ -110,9 +117,7 @@ if (process.env.BETTER_STACK_TOKEN) {
                         // @ts-ignore
                         const revived = pino.transport({
                             target: "@logtail/pino",
-                            options: {
-                                sourceToken: process.env.BETTER_STACK_TOKEN
-                            }
+                            options: logtailOptions
                         })
                         revived.on("error", handleTransportError)
                         transport.write = revived.write.bind(revived)
@@ -130,7 +135,18 @@ if (process.env.BETTER_STACK_TOKEN) {
 
 export const initProductionLogger = (level: string): Logger => {
     if (!transport) {
-        return initDebugLogger(level)
+        // No Betterstack token: emit single-line JSON to STDOUT so external
+        // log shippers (syslog, Render's collector) treat each log as one
+        // record. pino-pretty here splits structured objects across lines and
+        // makes them unsearchable downstream.
+        const l = pino({
+            formatters: {
+                level: logLevel,
+                log: customSerializer
+            }
+        })
+        l.level = level
+        return l
     }
     const l = pino(transport)
     l.level = level
diff --git a/src/utils/timed.ts b/src/utils/timed.ts
@@ -0,0 +1,33 @@
+import type { Logger } from "pino"
+
+// Times an async operation and emits a single structured log line on
+// completion. Used to attribute eth_sendUserOperation latency to specific
+// validator/RPC steps that otherwise run inside Promise.all and aren't
+// distinguishable from the outside.
+export async function timed<T>(
+    logger: Logger,
+    step: string,
+    context: Record<string, unknown>,
+    fn: () => T | Promise<T>
+): Promise<T> {
+    const start = performance.now()
+    try {
+        const result = await fn()
+        logger.info(
+            { ...context, step, ms: Math.round(performance.now() - start) },
+            `[timing] ${step}`
+        )
+        return result
+    } catch (err) {
+        logger.warn(
+            {
+                ...context,
+                step,
+                ms: Math.round(performance.now() - start),
+                err: err instanceof Error ? err.message : String(err)
+            },
+            `[timing] ${step} failed`
+        )
+        throw err
+    }
+}
