From b2ac66439c4d30c7e6ae17f49bdc27c62bf99940 Mon Sep 17 00:00:00 2001 From: George Fu Date: Wed, 11 Jun 2025 12:32:59 -0400 Subject: [PATCH 1/2] chore(middleware-http-debug-log): add middleware timer --- packages/middleware-http-debug-log/README.md | 34 ++++++ .../src/getMiddlewareTimerPlugin.ts | 112 ++++++++++++++++++ .../middleware-http-debug-log/src/index.ts | 1 + 3 files changed, 147 insertions(+) create mode 100644 packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts diff --git a/packages/middleware-http-debug-log/README.md b/packages/middleware-http-debug-log/README.md index 91e2d09c9c1c..e2b5660f9a76 100644 --- a/packages/middleware-http-debug-log/README.md +++ b/packages/middleware-http-debug-log/README.md @@ -94,3 +94,37 @@ Output (data redacted): <<<=== Response Body End ====== ``` + +## Usage (middleware timing) + +```ts +import { DynamoDB } from "@aws-sdk/client-dynamodb"; +import { getMiddlewareTimerPlugin } from "@aws-sdk/middleware-http-debug-log"; + +const client = new DynamoDB(); + +const storage = {}; + +client.middlewareStack.use(getMiddlewareTimerPlugin({ storage })); + +await client.listTables({}); +await client.listTables({}); +await client.listTables({}); + +console.log({ + storage, +}); +``` + +Output: + +``` +{ + storage: { + serializerMiddleware: [ 4.506417000000056, 0.24324999999998909, 0.22945800000002237 ], + retryMiddleware: [ 0.3532910000000129, 0.06491599999992559, 0.08433399999989888 ], + httpSigningMiddleware: [ 2.129708000000022, 0.6848749999999768, 0.6588739999999689 ], + deserializerMiddleware: [ 3.7174159999999574, 0.8131239999999593, 0.9889160000001311 ] + } +} +``` diff --git a/packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts b/packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts new file mode 100644 index 000000000000..514f477eddd7 --- /dev/null +++ b/packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts @@ -0,0 +1,112 @@ +import { + HandlerExecutionContext, + InitializeHandler, + InitializeHandlerArguments, + MiddlewareStack, + SerializeHandler, + SerializeHandlerArguments, +} from "@smithy/types"; + +/** + * FOR DEBUG USE ONLY. + * This plugin logs or records the timings of the middleware named in options.middlewareNames. + * + * @param options.middlewareNames - names of the middleware to measure. + * @param options.storage - a container for the data. If non is provided, metrics will be logged to console. + * + * @beta + */ +export function getMiddlewareTimerPlugin( + options: { + middlewareNames?: string[]; + storage?: Record; + } = {} +) { + return { + applyToStack(middlewareStack: MiddlewareStack) { + const middlewareNames = + options.middlewareNames ?? + (["serializerMiddleware", "deserializerMiddleware", "httpSigningMiddleware", "retryMiddleware"] as string[]); + for (const mw of middlewareNames) { + middlewareStack.addRelativeTo( + (next: SerializeHandler, context: HandlerExecutionContext) => + async (args: SerializeHandlerArguments) => { + context.middlewareTimings[mw] = context.middlewareTimings[mw] ?? ({} as Record); + context.middlewareTimings[mw].leaderPreNext = performance.now(); + const handlerOutput = await next(args); + context.middlewareTimings[mw].leaderPostNext = performance.now(); + return handlerOutput; + }, + { + name: mw + "-before", + override: true, + toMiddleware: mw, + relation: "before", + } + ); + + middlewareStack.addRelativeTo( + (next: SerializeHandler, context: HandlerExecutionContext) => + async (args: SerializeHandlerArguments) => { + context.middlewareTimings[mw] = context.middlewareTimings[mw] ?? ({} as Record); + context.middlewareTimings[mw].trailerPreNext = performance.now(); + const r = await next(args); + context.middlewareTimings[mw].trailerPostNext = performance.now(); + return r; + }, + { + name: mw + "-after", + override: true, + toMiddleware: mw, + relation: "after", + } + ); + } + + middlewareStack.add( + (next: InitializeHandler, context: HandlerExecutionContext) => + async (args: InitializeHandlerArguments) => { + context.middlewareTimings = context.middlewareTimings ?? ({} as Record>); + const handlerOutput = await next(args); + + for (const [mw, timings] of Object.entries( + context.middlewareTimings as Record> + )) { + const { leaderPreNext, trailerPreNext, trailerPostNext, leaderPostNext } = timings; + /** + * Formula note: + * + * Let M be the middleware we are measuring. + * Let L be the middleware prior to the measured middleware, + * and T be the middleware after the measured middleware. + * + * We take timings before L calls next, after L calls next, + * before T calls next, and after T calls next. + * + * The own-time of M is therefore the period from: + * L-pre-next (before entering M from L) -> T-pre-next (after exiting M to T) + * plus + * T-post-next (return to M from T) -> L-post-next (exiting M to L) + */ + const middlewareOwnTime = trailerPreNext - leaderPreNext + leaderPostNext - trailerPostNext; + + if (options.storage) { + options.storage[mw] = options.storage[mw] ?? []; + options.storage[mw].push(middlewareOwnTime); + } else { + console.log({ + [mw]: middlewareOwnTime, + }); + } + } + return handlerOutput; + }, + { + name: "middleware-timing-logger-middleware", + override: true, + step: "initialize", + } + ); + }, + }; +} diff --git a/packages/middleware-http-debug-log/src/index.ts b/packages/middleware-http-debug-log/src/index.ts index b7940710f34c..567b06e3bed1 100644 --- a/packages/middleware-http-debug-log/src/index.ts +++ b/packages/middleware-http-debug-log/src/index.ts @@ -1 +1,2 @@ export { getHttpDebugLogPlugin, type HttpDebugLoggingOptions } from "./getHttpDebugLogPlugin"; +export { getMiddlewareTimerPlugin } from "./getMiddlewareTimerPlugin"; From 0fb7484a55d5a152933ae833fc404e849aa5fa69 Mon Sep 17 00:00:00 2001 From: George Fu Date: Wed, 11 Jun 2025 12:35:37 -0400 Subject: [PATCH 2/2] chore: typo --- .../src/getMiddlewareTimerPlugin.ts | 19 +++++++++++-------- 1 file changed, 11 insertions(+), 8 deletions(-) diff --git a/packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts b/packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts index 514f477eddd7..0d1b34916d7c 100644 --- a/packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts +++ b/packages/middleware-http-debug-log/src/getMiddlewareTimerPlugin.ts @@ -12,7 +12,7 @@ import { * This plugin logs or records the timings of the middleware named in options.middlewareNames. * * @param options.middlewareNames - names of the middleware to measure. - * @param options.storage - a container for the data. If non is provided, metrics will be logged to console. + * @param options.storage - a container for the data. If none is provided, metrics will be logged to console. * * @beta */ @@ -22,16 +22,16 @@ export function getMiddlewareTimerPlugin( storage?: Record; } = {} ) { + const middlewareNames = + options.middlewareNames ?? + (["serializerMiddleware", "deserializerMiddleware", "httpSigningMiddleware", "retryMiddleware"] as string[]); + return { applyToStack(middlewareStack: MiddlewareStack) { - const middlewareNames = - options.middlewareNames ?? - (["serializerMiddleware", "deserializerMiddleware", "httpSigningMiddleware", "retryMiddleware"] as string[]); for (const mw of middlewareNames) { middlewareStack.addRelativeTo( (next: SerializeHandler, context: HandlerExecutionContext) => async (args: SerializeHandlerArguments) => { - context.middlewareTimings[mw] = context.middlewareTimings[mw] ?? ({} as Record); context.middlewareTimings[mw].leaderPreNext = performance.now(); const handlerOutput = await next(args); context.middlewareTimings[mw].leaderPostNext = performance.now(); @@ -48,11 +48,10 @@ export function getMiddlewareTimerPlugin( middlewareStack.addRelativeTo( (next: SerializeHandler, context: HandlerExecutionContext) => async (args: SerializeHandlerArguments) => { - context.middlewareTimings[mw] = context.middlewareTimings[mw] ?? ({} as Record); context.middlewareTimings[mw].trailerPreNext = performance.now(); - const r = await next(args); + const handlerOutput = await next(args); context.middlewareTimings[mw].trailerPostNext = performance.now(); - return r; + return handlerOutput; }, { name: mw + "-after", @@ -67,6 +66,10 @@ export function getMiddlewareTimerPlugin( (next: InitializeHandler, context: HandlerExecutionContext) => async (args: InitializeHandlerArguments) => { context.middlewareTimings = context.middlewareTimings ?? ({} as Record>); + for (const mw of middlewareNames) { + context.middlewareTimings[mw] = {} as Record; + } + const handlerOutput = await next(args); for (const [mw, timings] of Object.entries(