Defer and cache calculation of Engine reporting signature.

This moves the Apollo Engine Reporting signature calculation (which the
Apollo Cloud uses to aggregate similar operations) to perform
asynchronously, after the response has been returned to the client, and also
caches the signature for use by additional operations which match the same
`queryHash` (which is an exact SHA-256 hex digest of the operation body
received from the client).

While the signature calculation is relatively quick on small operations, with
sustained load and more complex operations, this recurring calculation can
be more costly.

As a bit of validation to the success of this change, on a very basic
performance benchmark, using a schema with 1000 `String` fields (i.e.  a
`type Query` with `Field_1: String` through `Field_1000: String`) and an
incoming operation which selects from all 1000 of those fields (i.e
`Field_1`), this showed quite an improvement:

```
┌───────────────┬───────────────┬───────────────┐
│               │ Before        │ After         │
├───────────────┼───────────────┼───────────────┤
│ Percentile, % │ Resp. Time, s │ Resp. Time, s │
├───────────────┼───────────────┼───────────────┤
│           0.0 │         0.076 │         0.024 │
│          50.0 │         0.342 │          0.14 │
│          90.0 │         0.388 │         0.161 │
│          95.0 │          0.41 │         0.164 │
│          99.0 │         0.444 │          0.17 │
│          99.9 │         0.486 │         0.177 │
│         100.0 │         0.487 │         0.196 │
└───────────────┴───────────────┴───────────────┘
```

Of course, this is a relatively simple example and still includes actual
GraphQL execution, but the win factor is certainly there.  Other tests with
more dynamic fields and a higher cardinality of unique operations also
showed improvement, though extremely high cardinality of complex operations
(which have more expensive execution characteristics) certainly made the
_win_ factor less pronounced.

It's not surprising that this calculation is a bit expensive since it
requires a number of normalization steps.  Luckily, we can let this all
happen after the request is sent to the client and it's highly cacheable.

By default, we'll use a relatively small cache which should store a large
number of operations, and to avoid introducing configuration surface area
right now without much evidence as to the need, we'll simply log a message
periodically if we're ejecting operations.

packages/apollo-engine-reporting/src/__tests__/extension.test.ts

@@ -50,7 +50,11 @@ test('trace construction', async () => {
   enableGraphQLExtensions(schema);
 
   const traces: Array<any> = [];
-  function addTrace(signature: string, operationName: string, trace: Trace) {
+  function addTrace(
+    signature: Promise<string | null>,
+    operationName: string,
+    trace: Trace,
+  ) {
     traces.push({ signature, operationName, trace });
   }
 

packages/apollo-engine-reporting/src/agent.ts

@@ -16,6 +16,8 @@ import {
   GraphQLRequestContext,
   GraphQLServiceContext,
 } from 'apollo-server-core/dist/requestPipelineAPI';
+import { InMemoryLRUCache } from 'apollo-server-caching';
+import { defaultEngineReportingSignature } from 'apollo-graphql';
 
 export interface ClientInfo {
   clientName?: string;
@@ -128,6 +130,14 @@ export interface EngineReportingOptions<TContext> {
   generateClientInfo?: GenerateClientInfo<TContext>;
 }
 
+export interface AddTraceArgs {
+  trace: Trace;
+  operationName: string;
+  queryHash: string;
+  queryString?: string;
+  documentAST?: DocumentNode;
+}
+
 const serviceHeaderDefaults = {
   hostname: os.hostname(),
   // tslint:disable-next-line no-var-requires
@@ -149,6 +159,7 @@ export class EngineReportingAgent<TContext = any> {
   private sendReportsImmediately?: boolean;
   private stopped: boolean = false;
   private reportHeader: ReportHeader;
+  private signatureCache: InMemoryLRUCache<string>;
 
   public constructor(
     options: EngineReportingOptions<TContext> = {},
@@ -162,6 +173,11 @@ export class EngineReportingAgent<TContext = any> {
       );
     }
 
+    // Since calculating the signature for Engine reporting is potentially an
+    // expensive operation, we'll cache the signatures we generate and re-use
+    // them based on repeated traces for the same `queryHash`.
+    this.signatureCache = createSignatureCache();
+
     this.reportHeader = new ReportHeader({
       ...serviceHeaderDefaults,
       schemaHash,
@@ -196,7 +212,59 @@ export class EngineReportingAgent<TContext = any> {
     );
   }
 
-  public addTrace(signature: string, operationName: string, trace: Trace) {
+  private async getTraceSignature({
+    queryHash,
+    operationName,
+    documentAST,
+    queryString,
+  }: {
+    queryHash: string;
+    operationName: string;
+    documentAST?: DocumentNode;
+    queryString?: string;
+  }): Promise<string> {
+    if (!documentAST && !queryString) {
+      // This shouldn't happen: one of those options must be passed to runQuery.
+      throw new Error('No queryString or parsedQuery?');
+    }
+
+    // If we didn't have the signature in the cache, we'll resort to
+    // calculating it asynchronously.  The `addTrace` method will
+    // `await` the `signature` if it's a Promise, prior to putting it
+    // on the stack of traces to deliver to the cloud.
+    return this.signatureCache.get(queryHash).then(cachedSignature => {
+      if (cachedSignature) {
+        return cachedSignature;
+      }
+
+      if (!documentAST) {
+        // We didn't get an AST, possibly because of a parse failure. Let's just
+        // use the full query string.
+        //
+        // XXX This does mean that even if you use a calculateSignature which
+        //     hides literals, you might end up sending literals for queries
+        //     that fail parsing or validation. Provide some way to mask them
+        //     anyway?
+        return queryString as string;
+      }
+
+      const generatedSignature = (this.options.calculateSignature ||
+        defaultEngineReportingSignature)(documentAST, operationName);
+
+      // Intentionally not awaited so the cache can be written to at leisure.
+      this.signatureCache.set(queryHash, generatedSignature);
+
+      return generatedSignature;
+    });
+  }
+
+  public async addTrace({
+    trace,
+    queryHash,
+    documentAST,
+    operationName,
+    queryString,
+  }: AddTraceArgs): Promise<void> {
     // Ignore traces that come in after stop().
     if (this.stopped) {
       return;
@@ -208,6 +276,13 @@ export class EngineReportingAgent<TContext = any> {
     }
     const encodedTrace = Trace.encode(trace).finish();
 
+    const signature = await this.getTraceSignature({
+      queryHash,
+      documentAST,
+      queryString,
+      operationName,
+    });
+
     const statsReportKey = `# ${operationName || '-'}\n${signature}`;
     if (!this.report.tracesPerQuery.hasOwnProperty(statsReportKey)) {
       this.report.tracesPerQuery[statsReportKey] = new Traces();
@@ -226,7 +301,7 @@ export class EngineReportingAgent<TContext = any> {
       this.reportSize >=
         (this.options.maxUncompressedReportSize || 4 * 1024 * 1024)
     ) {
-      this.sendReportAndReportErrors();
+      await this.sendReportAndReportErrors();
     }
   }
 
@@ -351,3 +426,49 @@ export class EngineReportingAgent<TContext = any> {
     this.reportSize = 0;
   }
 }
+
+function createSignatureCache(): InMemoryLRUCache<string> {
+  let lastSignatureCacheWarn: Date;
+  let lastSignatureCacheDisposals: number = 0;
+  return new InMemoryLRUCache<string>({
+    // Calculate the length of cache objects by the JSON.stringify byteLength.
+    sizeCalculator(obj) {
+      return Buffer.byteLength(JSON.stringify(obj), 'utf8');
+    },
+    // 3MiB limit, very much approximately since we can't be sure how V8 might
+    // be storing these strings internally. Though this should be enough to
+    // store a fair amount of operation signatures (~10000?), depending on their
+    // overall complexity. A future version of this might expose some
+    // configuration option to grow the cache, but ideally, we could do that
+    // dynamically based on the resources available to the server, and not add
+    // more configuration surface area. Hopefully the warning message will allow
+    // us to evaluate the need with more validated input from those that receive
+    // it.
+    maxSize: Math.pow(2, 20) * 3,
+    onDispose() {
+      // Count the number of disposals between warning messages.
+      lastSignatureCacheDisposals++;
+
+      // Only show a message warning about the high turnover every 60 seconds.
+      if (
+        !lastSignatureCacheWarn ||
+        new Date().getTime() - lastSignatureCacheWarn.getTime() > 60000
+      ) {
+        // Log the time that we last displayed the message.
+        lastSignatureCacheWarn = new Date();
+        console.warn(
+          [
+            'This server is processing a high number of unique operations.  ',
+            `A total of ${lastSignatureCacheDisposals} records have been `,
+            'ejected from the Engine Reporting signature cache in the past ',
+            'interval.  If you see this warning frequently, please open an ',
+            'issue on the Apollo Server repository.',
+          ].join(''),
+        );
+
+        // Reset the disposal counter for the next message interval.
+        lastSignatureCacheDisposals = 0;
+      }
+    },
+  });
+}

packages/apollo-engine-reporting/src/extension.ts

@@ -11,8 +11,11 @@ import {
 import { GraphQLExtension, EndHandler } from 'graphql-extensions';
 import { Trace, google } from 'apollo-engine-reporting-protobuf';
 
-import { EngineReportingOptions, GenerateClientInfo } from './agent';
-import { defaultEngineReportingSignature } from 'apollo-graphql';
+import {
+  EngineReportingOptions,
+  GenerateClientInfo,
+  AddTraceArgs,
+} from './agent';
 import { GraphQLRequestContext } from 'apollo-server-core/dist/requestPipelineAPI';
 
 const clientNameHeaderKey = 'apollographql-client-name';
@@ -47,16 +50,12 @@ export class EngineReportingExtension<TContext = any>
   private queryString?: string;
   private documentAST?: DocumentNode;
   private options: EngineReportingOptions<TContext>;
-  private addTrace: (
-    signature: string,
-    operationName: string,
-    trace: Trace,
-  ) => void;
+  private addTrace: (args: AddTraceArgs) => Promise<void>;
   private generateClientInfo: GenerateClientInfo<TContext>;
 
   public constructor(
     options: EngineReportingOptions<TContext>,
-    addTrace: (signature: string, operationName: string, trace: Trace) => void,
+    addTrace: (args: AddTraceArgs) => Promise<void>,
   ) {
     this.options = {
       ...options,
@@ -102,14 +101,18 @@ export class EngineReportingExtension<TContext = any>
     variables?: Record<string, any>;
     context: TContext;
     extensions?: Record<string, any>;
-    requestContext: WithRequired<GraphQLRequestContext<TContext>, 'metrics'>;
+    requestContext: WithRequired<
+      GraphQLRequestContext<TContext>,
+      'metrics' | 'queryHash'
+    >;
   }): EndHandler {
     this.trace.startTime = dateToTimestamp(new Date());
     this.startHrTime = process.hrtime();
 
     // Generally, we'll get queryString here and not parsedQuery; we only get
     // parsedQuery if you're using an OperationStore. In normal cases we'll get
     // our documentAST in the execution callback after it is parsed.
+    const queryHash = o.requestContext.queryHash;
     this.queryString = o.queryString;
     this.documentAST = o.parsedQuery;
 
@@ -223,26 +226,14 @@ export class EngineReportingExtension<TContext = any>
         .responseCacheHit;
 
       const operationName = this.operationName || '';
-      let signature;
-      if (this.documentAST) {
-        const calculateSignature =
-          this.options.calculateSignature || defaultEngineReportingSignature;
-        signature = calculateSignature(this.documentAST, operationName);
-      } else if (this.queryString) {
-        // We didn't get an AST, possibly because of a parse failure. Let's just
-        // use the full query string.
-        //
-        // XXX This does mean that even if you use a calculateSignature which
-        //     hides literals, you might end up sending literals for queries
-        //     that fail parsing or validation. Provide some way to mask them
-        //     anyway?
-        signature = this.queryString;
-      } else {
-        // This shouldn't happen: one of those options must be passed to runQuery.
-        throw new Error('No queryString or parsedQuery?');
-      }
 
-      this.addTrace(signature, operationName, this.trace);
+      this.addTrace({
+        operationName,
+        queryHash,
+        documentAST: this.documentAST,
+        queryString: this.queryString || '',
+        trace: this.trace,
+      });
     };
   }
 

packages/apollo-server-core/src/requestPipeline.ts

@@ -197,7 +197,10 @@ export async function processGraphQLRequest<TContext>(
     context: requestContext.context,
     persistedQueryHit: metrics.persistedQueryHit,
     persistedQueryRegister: metrics.persistedQueryRegister,
-    requestContext,
+    requestContext: requestContext as WithRequired<
+      typeof requestContext,
+      'metrics' | 'queryHash'
+    >,
   });
 
   try {