chore(middleware-http-debug-log): add middleware timer

Author: kuhe

packages/middleware-http-debug-log/README.md

@@ -94,3 +94,37 @@ Output (data redacted):
       </ListAllMyBucketsResult>
     <<<=== 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 ]
+  }
+}
+```

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<string, number[]>;
+  } = {}
+) {
+  return {
+    applyToStack(middlewareStack: MiddlewareStack<any, any>) {
+      const middlewareNames =
+        options.middlewareNames ??
+        (["serializerMiddleware", "deserializerMiddleware", "httpSigningMiddleware", "retryMiddleware"] as string[]);
+      for (const mw of middlewareNames) {
+        middlewareStack.addRelativeTo(
+          (next: SerializeHandler<any, any>, context: HandlerExecutionContext) =>
+            async (args: SerializeHandlerArguments<any>) => {
+              context.middlewareTimings[mw] = context.middlewareTimings[mw] ?? ({} as Record<string, number>);
+              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<any, any>, context: HandlerExecutionContext) =>
+            async (args: SerializeHandlerArguments<any>) => {
+              context.middlewareTimings[mw] = context.middlewareTimings[mw] ?? ({} as Record<string, number>);
+              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<any, any>, context: HandlerExecutionContext) =>
+          async (args: InitializeHandlerArguments<any>) => {
+            context.middlewareTimings = context.middlewareTimings ?? ({} as Record<string, Record<string, number>>);
+            const handlerOutput = await next(args);
+
+            for (const [mw, timings] of Object.entries(
+              context.middlewareTimings as Record<string, Record<string, number>>
+            )) {
+              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",
+        }
+      );
+    },
+  };
+}

packages/middleware-http-debug-log/src/index.ts

@@ -1 +1,2 @@
 export { getHttpDebugLogPlugin, type HttpDebugLoggingOptions } from "./getHttpDebugLogPlugin";
+export { getMiddlewareTimerPlugin } from "./getMiddlewareTimerPlugin";