diff --git a/CHANGELOG.md b/CHANGELOG.md index 394e0664be4..254cc4be6ad 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,7 +10,7 @@ The version headers in this history reflect the versions of Apollo Server itself ## vNEXT (minor!) - `apollo-server-core`: Usage reporting no longer sends a "client reference ID" to Apollo Studio (along with the client name and client version). This little-used feature has not been documented [since 2019](https://github.com/apollographql/apollo-server/pull/3180) and is currently entirely ignored by Apollo Studio. This is technically incompatible as the interface `ClientInfo` no longer has the field `clientReferenceId`; if you were one of the few users who explicitly set this field and you get a TypeScript compilation failure upon upgrading to v3.6.0, just stop using the field. [PR #5890](https://github.com/apollographql/apollo-server/pull/5890) -- `apollo-server-core`: Preliminary support for referenced field reporting. THIS ENTRY NEEDS TO BE EXPANDED BEFORE THE v3.6.0 RELEASE. [Issue #5708](https://github.com/apollographql/apollo-server/issues/5708) [PR #5956](https://github.com/apollographql/apollo-server/pull/5956) +- `apollo-server-core`: Preliminary support for referenced field reporting. THIS ENTRY NEEDS TO BE EXPANDED BEFORE THE v3.6.0 RELEASE. Include description of fieldLevelInstrumentation and the ability to avoid instrumentation. Include effect on `metrics` object. [Issue #5708](https://github.com/apollographql/apollo-server/issues/5708) [PR #5956](https://github.com/apollographql/apollo-server/pull/5956) - `apollo-server-core`: Remove dependency on `apollo-graphql` package (by inlining the code which generates usage reporting signatures). That package has not yet been published with a `graphql@16` peer dependency, so Apollo Server v3.5 did not fully support `graphql@16` without overriding peer dependencies. [Issue #5941](https://github.com/apollographql/apollo-server/issues/5941) [PR #5955](https://github.com/apollographql/apollo-server/pull/5955) ## v3.5.0 diff --git a/docs/source/api/plugin/usage-reporting.md b/docs/source/api/plugin/usage-reporting.md index b4209cc8485..0a2273cb655 100644 --- a/docs/source/api/plugin/usage-reporting.md +++ b/docs/source/api/plugin/usage-reporting.md @@ -105,6 +105,38 @@ The only properties of the reported error you can modify are its `message` and i +###### `fieldLevelInstrumentation` + +`async Function` or `number` + + + +This option allows you to choose if Apollo Server should calculate detailed per-field statistics for a particular request. It is only called for executable operations: operations which parse and validate properly and which do not have an unknown operation name. It is not called if an [`includeRequest`](#includerequest) hook is provided and returns false. + +You can either pass an async function or a number. The function receives a `GraphQLRequestContext`. (The effect of passing a number is described later.) Your function can return a boolean or a number; returning false is equivalent to returning 0 and returning true is equivalent to returning 1. + +Returning false (or 0) means that Apollo Server will only pay attention to overall properties of the operation, like what GraphQL operation is executing and how long the entire operation takes to execute, and not anything about field-by-field execution. + +If you return false (or 0), this operation *will* still contribute to most features of Studio, such as schema checks, the Operations page, and the "referencing operations" statistic on the Fields page, etc. + +If you return false (or 0), this operation will *not* contribute to the "field executions" statistic on the Fields page or to the execution timing hints optionally displayed in Studio Explorer or in vscode-graphql. Additionally, this operation will not produce a trace that can be viewed on the Traces section of the Operations page. + +Returning false (or 0) here for some or all operations can improve your server's performance, as the overhead of calculating complete traces is not always negligible. This is especially the case if this server is an Apollo Gateway, as captured traces are transmitted from the subgraph to the Gateway in-band inside the actual GraphQL response. + +Returning a positive number means that Apollo Server will track each field execution and send Apollo Studio statistics on how many times each field was executed and what the per-field performance was. If the number returned is less than 1, Apollo Server will also send a scaled "estimate" count for each field, equal to the number of observed field executions divided by the number returned by the hook. + +Passing a number `n` (which should be between 0 and 1 inclusive) for `fieldLevelInstrumentation` is equivalent to passing the function `async () => Math.random() < n ? n : 0`. For example, if you pass 0.01, then 99% of the time Apollo Server will not track field executions, and 1% of the time Apollo Server will track field executions and send them to Apollo Studio both as an exact observed count and as an "estimated" count which is 100 times higher. + +(Note that returning true here does *not* mean that the data derived from field-level instrumentation must be transmitted to Apollo Studio's servers in the form of a trace; it may still be aggregated locally to statistics. But either way this operation will contribute to the "field executions" statistic and timing hints.) + +The default `fieldLevelInstrumentation` is a function that always returns true. + + + + + + + ###### `includeRequest` `async Function` @@ -113,8 +145,12 @@ The only properties of the reported error you can modify are its `message` and i Specify this asynchronous function to configure which requests are included in usage reports sent to Apollo Studio. For example, you can omit requests that execute a particular operation or requests that include a particular HTTP header. + Note that returning false here means that the operation will be completely ignored by all Apollo Studio features. If you merely want to improve performance by skipping the field-level execution trace, set the [`fieldLevelInstrumentation`](#fieldlevelinstrumentation) option instead of this one. + This function is called for each received request. It takes a [`GraphQLRequestContext`](https://github.com/apollographql/apollo-server/blob/main/packages/apollo-server-types/src/index.ts#L115-L150) object and must return a `Promise` that indicates whether to include the request. It's called either after the operation is successfully resolved (via [the `didResolveOperation` event](https://www.apollographql.com/docs/apollo-server/integrations/plugins/#didresolveoperation)), or when sending the final error response if the operation was not successfully resolved (via [the `willSendResponse` event](https://www.apollographql.com/docs/apollo-server/integrations/plugins/#willsendresponse)). +If you don't want any usage reporting at all, don't use this option: instead, either avoid specifying an Apollo API key or explicitly [disable the plugin](#disabling-the-plugin). + By default, all requests are included in usage reports. diff --git a/package-lock.json b/package-lock.json index 705bd082d68..8dffac10bbb 100644 --- a/package-lock.json +++ b/package-lock.json @@ -61,6 +61,7 @@ "@types/koa-router": "7.4.4", "@types/lodash": "4.14.178", "@types/lodash.sortby": "4.7.6", + "@types/lodash.sumby": "4.6.6", "@types/lodash.xorby": "4.7.6", "@types/lru-cache": "5.1.1", "@types/memcached": "2.2.7", @@ -92,10 +93,12 @@ "jest": "27.4.5", "jest-config": "27.4.5", "jest-junit": "13.0.0", + "jest-mock-random": "1.1.1", "js-sha256": "0.9.0", "koa": "2.13.4", "koa-router": "10.1.1", "lerna": "4.0.0", + "lodash.sumby": "4.6.0", "log4js": "6.3.0", "memcached-mock": "0.1.0", "mock-req": "0.2.0", @@ -6203,6 +6206,15 @@ "@types/lodash": "*" } }, + "node_modules/@types/lodash.sumby": { + "version": "4.6.6", + "resolved": "https://registry.npmjs.org/@types/lodash.sumby/-/lodash.sumby-4.6.6.tgz", + "integrity": "sha512-C7P2OuGcbCHxQ7dfEHNWfdQUhziwosJ8X6TzDZqIUVWamqFxUZX32JhoWZ/L5Z/lZX3HLTlQs1E5MtG0l9C9cA==", + "dev": true, + "dependencies": { + "@types/lodash": "*" + } + }, "node_modules/@types/lodash.xorby": { "version": "4.7.6", "dev": true, @@ -13055,6 +13067,12 @@ "node": "^10.13.0 || ^12.13.0 || ^14.15.0 || >=15.0.0" } }, + "node_modules/jest-mock-random": { + "version": "1.1.1", + "resolved": "https://registry.npmjs.org/jest-mock-random/-/jest-mock-random-1.1.1.tgz", + "integrity": "sha512-eLduwHIZeepHCHWTgx6MGr8k4CWxTG39SN76tszzgCjX8GNu6M/05WcXMci73z1GUVqYQAsw6inz6ndgr3Gmqw==", + "dev": true + }, "node_modules/jest-pnp-resolver": { "version": "1.2.2", "resolved": "https://registry.npmjs.org/jest-pnp-resolver/-/jest-pnp-resolver-1.2.2.tgz", @@ -14829,6 +14847,12 @@ "version": "4.7.0", "license": "MIT" }, + "node_modules/lodash.sumby": { + "version": "4.6.0", + "resolved": "https://registry.npmjs.org/lodash.sumby/-/lodash.sumby-4.6.0.tgz", + "integrity": "sha1-fYdzfdshbaL35efNLdnEA6eIc0Y=", + "dev": true + }, "node_modules/lodash.template": { "version": "4.5.0", "dev": true, @@ -20549,7 +20573,7 @@ } }, "packages/apollo-datasource-rest": { - "version": "3.4.0", + "version": "3.5.0-alpha.0", "license": "MIT", "dependencies": { "apollo-datasource": "file:../apollo-datasource", @@ -20566,14 +20590,14 @@ } }, "packages/apollo-reporting-protobuf": { - "version": "3.2.0", + "version": "3.3.0-alpha.0", "license": "MIT", "dependencies": { "@apollo/protobufjs": "1.2.2" } }, "packages/apollo-server": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "apollo-server-core": "file:../apollo-server-core", @@ -20588,7 +20612,7 @@ } }, "packages/apollo-server-azure-functions": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "@azure/functions": "1.2.3", @@ -20642,7 +20666,7 @@ } }, "packages/apollo-server-cloud-functions": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "apollo-server-express": "file:../apollo-server-express", @@ -20659,7 +20683,7 @@ } }, "packages/apollo-server-cloudflare": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "apollo-server-core": "file:../apollo-server-core", @@ -20671,7 +20695,7 @@ } }, "packages/apollo-server-core": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "@apollographql/apollo-tools": "^0.5.1", @@ -20731,7 +20755,7 @@ } }, "packages/apollo-server-express": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "@types/accepts": "^1.3.5", @@ -20758,7 +20782,7 @@ } }, "packages/apollo-server-fastify": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "apollo-server-core": "file:../apollo-server-core", @@ -20779,7 +20803,7 @@ } }, "packages/apollo-server-hapi": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "@hapi/accept": "^5.0.2", @@ -20799,7 +20823,7 @@ } }, "packages/apollo-server-integration-testsuite": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "apollo-server-core": "file:../apollo-server-core", @@ -20810,7 +20834,7 @@ } }, "packages/apollo-server-koa": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "@koa/cors": "^3.1.0", @@ -20865,7 +20889,7 @@ } }, "packages/apollo-server-lambda": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "@types/aws-lambda": "^8.10.76", @@ -20885,7 +20909,7 @@ } }, "packages/apollo-server-micro": { - "version": "3.5.0", + "version": "3.6.0-alpha.0", "license": "MIT", "dependencies": { "@hapi/accept": "^5.0.2", @@ -20901,7 +20925,7 @@ } }, "packages/apollo-server-plugin-base": { - "version": "3.4.0", + "version": "3.5.0-alpha.0", "license": "MIT", "dependencies": { "apollo-server-types": "file:../apollo-server-types" @@ -20914,7 +20938,7 @@ } }, "packages/apollo-server-plugin-operation-registry": { - "version": "3.4.0", + "version": "3.5.0-alpha.0", "license": "MIT", "dependencies": { "apollo-graphql": "0.9.5", @@ -20934,7 +20958,7 @@ } }, "packages/apollo-server-plugin-response-cache": { - "version": "3.4.0", + "version": "3.5.0-alpha.0", "license": "MIT", "dependencies": { "apollo-server-caching": "file:../apollo-server-caching", @@ -20949,7 +20973,7 @@ } }, "packages/apollo-server-types": { - "version": "3.4.0", + "version": "3.5.0-alpha.0", "license": "MIT", "dependencies": { "apollo-reporting-protobuf": "file:../apollo-reporting-protobuf", @@ -25562,6 +25586,15 @@ "@types/lodash": "*" } }, + "@types/lodash.sumby": { + "version": "4.6.6", + "resolved": "https://registry.npmjs.org/@types/lodash.sumby/-/lodash.sumby-4.6.6.tgz", + "integrity": "sha512-C7P2OuGcbCHxQ7dfEHNWfdQUhziwosJ8X6TzDZqIUVWamqFxUZX32JhoWZ/L5Z/lZX3HLTlQs1E5MtG0l9C9cA==", + "dev": true, + "requires": { + "@types/lodash": "*" + } + }, "@types/lodash.xorby": { "version": "4.7.6", "dev": true, @@ -30673,6 +30706,12 @@ "@types/node": "*" } }, + "jest-mock-random": { + "version": "1.1.1", + "resolved": "https://registry.npmjs.org/jest-mock-random/-/jest-mock-random-1.1.1.tgz", + "integrity": "sha512-eLduwHIZeepHCHWTgx6MGr8k4CWxTG39SN76tszzgCjX8GNu6M/05WcXMci73z1GUVqYQAsw6inz6ndgr3Gmqw==", + "dev": true + }, "jest-pnp-resolver": { "version": "1.2.2", "resolved": "https://registry.npmjs.org/jest-pnp-resolver/-/jest-pnp-resolver-1.2.2.tgz", @@ -32036,6 +32075,12 @@ "lodash.sortby": { "version": "4.7.0" }, + "lodash.sumby": { + "version": "4.6.0", + "resolved": "https://registry.npmjs.org/lodash.sumby/-/lodash.sumby-4.6.0.tgz", + "integrity": "sha1-fYdzfdshbaL35efNLdnEA6eIc0Y=", + "dev": true + }, "lodash.template": { "version": "4.5.0", "dev": true, diff --git a/package.json b/package.json index d2f53e4f92b..0ad6bb51ec2 100644 --- a/package.json +++ b/package.json @@ -81,6 +81,7 @@ "@types/koa-router": "7.4.4", "@types/lodash": "4.14.178", "@types/lodash.sortby": "4.7.6", + "@types/lodash.sumby": "4.6.6", "@types/lodash.xorby": "4.7.6", "@types/lru-cache": "5.1.1", "@types/memcached": "2.2.7", @@ -112,10 +113,12 @@ "jest": "27.4.5", "jest-config": "27.4.5", "jest-junit": "13.0.0", + "jest-mock-random": "1.1.1", "js-sha256": "0.9.0", "koa": "2.13.4", "koa-router": "10.1.1", "lerna": "4.0.0", + "lodash.sumby": "4.6.0", "log4js": "6.3.0", "memcached-mock": "0.1.0", "mock-req": "0.2.0", diff --git a/packages/apollo-reporting-protobuf/generated/protobuf.d.ts b/packages/apollo-reporting-protobuf/generated/protobuf.d.ts index 79fb9ea0b7d..60b74d9bb65 100644 --- a/packages/apollo-reporting-protobuf/generated/protobuf.d.ts +++ b/packages/apollo-reporting-protobuf/generated/protobuf.d.ts @@ -55,6 +55,9 @@ export interface ITrace { /** Trace forbiddenOperation */ forbiddenOperation?: (boolean|null); + + /** Trace fieldExecutionScaleFactor */ + fieldExecutionScaleFactor?: (number|null); } /** Represents a Trace. */ @@ -120,6 +123,9 @@ export class Trace implements ITrace { /** Trace forbiddenOperation. */ public forbiddenOperation: boolean; + /** Trace fieldExecutionScaleFactor. */ + public fieldExecutionScaleFactor: number; + /** * Creates a new Trace instance using the specified properties. * @param [properties] Properties to set @@ -1749,6 +1755,9 @@ export interface IQueryLatencyStats { /** QueryLatencyStats forbiddenOperationCount */ forbiddenOperationCount?: (number|null); + + /** QueryLatencyStats requestsWithoutFieldInstrumentation */ + requestsWithoutFieldInstrumentation?: (number|null); } /** Represents a QueryLatencyStats. */ @@ -1796,6 +1805,9 @@ export class QueryLatencyStats implements IQueryLatencyStats { /** QueryLatencyStats forbiddenOperationCount. */ public forbiddenOperationCount: number; + /** QueryLatencyStats requestsWithoutFieldInstrumentation. */ + public requestsWithoutFieldInstrumentation: number; + /** * Creates a new QueryLatencyStats instance using the specified properties. * @param [properties] Properties to set @@ -2136,8 +2148,11 @@ export interface IFieldStat { /** FieldStat errorsCount */ errorsCount?: (number|null); - /** FieldStat count */ - count?: (number|null); + /** FieldStat observedExecutionCount */ + observedExecutionCount?: (number|null); + + /** FieldStat estimatedExecutionCount */ + estimatedExecutionCount?: (number|null); /** FieldStat requestsWithErrorsCount */ requestsWithErrorsCount?: (number|null); @@ -2161,8 +2176,11 @@ export class FieldStat implements IFieldStat { /** FieldStat errorsCount. */ public errorsCount: number; - /** FieldStat count. */ - public count: number; + /** FieldStat observedExecutionCount. */ + public observedExecutionCount: number; + + /** FieldStat estimatedExecutionCount. */ + public estimatedExecutionCount: number; /** FieldStat requestsWithErrorsCount. */ public requestsWithErrorsCount: number; diff --git a/packages/apollo-reporting-protobuf/generated/protobuf.js b/packages/apollo-reporting-protobuf/generated/protobuf.js index 68b3768bc79..53067e3e9ad 100644 --- a/packages/apollo-reporting-protobuf/generated/protobuf.js +++ b/packages/apollo-reporting-protobuf/generated/protobuf.js @@ -33,6 +33,7 @@ $root.Trace = (function() { * @property {boolean|null} [persistedQueryRegister] Trace persistedQueryRegister * @property {boolean|null} [registeredOperation] Trace registeredOperation * @property {boolean|null} [forbiddenOperation] Trace forbiddenOperation + * @property {number|null} [fieldExecutionScaleFactor] Trace fieldExecutionScaleFactor */ /** @@ -194,6 +195,14 @@ $root.Trace = (function() { */ Trace.prototype.forbiddenOperation = false; + /** + * Trace fieldExecutionScaleFactor. + * @member {number} fieldExecutionScaleFactor + * @memberof Trace + * @instance + */ + Trace.prototype.fieldExecutionScaleFactor = 0; + /** * Creates a new Trace instance using the specified properties. * @function create @@ -254,6 +263,8 @@ $root.Trace = (function() { writer.uint32(/* id 27, wireType 2 =*/218).string(message.unexecutedOperationBody); if (message.unexecutedOperationName != null && Object.hasOwnProperty.call(message, "unexecutedOperationName")) writer.uint32(/* id 28, wireType 2 =*/226).string(message.unexecutedOperationName); + if (message.fieldExecutionScaleFactor != null && Object.hasOwnProperty.call(message, "fieldExecutionScaleFactor")) + writer.uint32(/* id 31, wireType 1 =*/249).double(message.fieldExecutionScaleFactor); return writer; }; @@ -342,6 +353,9 @@ $root.Trace = (function() { case 25: message.forbiddenOperation = reader.bool(); break; + case 31: + message.fieldExecutionScaleFactor = reader.double(); + break; default: reader.skipType(tag & 7); break; @@ -445,6 +459,9 @@ $root.Trace = (function() { if (message.forbiddenOperation != null && message.hasOwnProperty("forbiddenOperation")) if (typeof message.forbiddenOperation !== "boolean") return "forbiddenOperation: boolean expected"; + if (message.fieldExecutionScaleFactor != null && message.hasOwnProperty("fieldExecutionScaleFactor")) + if (typeof message.fieldExecutionScaleFactor !== "number") + return "fieldExecutionScaleFactor: number expected"; return null; }; @@ -484,6 +501,7 @@ $root.Trace = (function() { object.queryPlan = null; object.unexecutedOperationBody = ""; object.unexecutedOperationName = ""; + object.fieldExecutionScaleFactor = 0; } if (message.endTime != null && message.hasOwnProperty("endTime")) object.endTime = $root.google.protobuf.Timestamp.toObject(message.endTime, options); @@ -524,6 +542,8 @@ $root.Trace = (function() { object.unexecutedOperationBody = message.unexecutedOperationBody; if (message.unexecutedOperationName != null && message.hasOwnProperty("unexecutedOperationName")) object.unexecutedOperationName = message.unexecutedOperationName; + if (message.fieldExecutionScaleFactor != null && message.hasOwnProperty("fieldExecutionScaleFactor")) + object.fieldExecutionScaleFactor = options.json && !isFinite(message.fieldExecutionScaleFactor) ? String(message.fieldExecutionScaleFactor) : message.fieldExecutionScaleFactor; return object; }; @@ -4310,6 +4330,7 @@ $root.QueryLatencyStats = (function() { * @property {$protobuf.ToArray.|Array.|null} [privateCacheTtlCount] QueryLatencyStats privateCacheTtlCount * @property {number|null} [registeredOperationCount] QueryLatencyStats registeredOperationCount * @property {number|null} [forbiddenOperationCount] QueryLatencyStats forbiddenOperationCount + * @property {number|null} [requestsWithoutFieldInstrumentation] QueryLatencyStats requestsWithoutFieldInstrumentation */ /** @@ -4427,6 +4448,14 @@ $root.QueryLatencyStats = (function() { */ QueryLatencyStats.prototype.forbiddenOperationCount = $util.Long ? $util.Long.fromBits(0,0,true) : 0; + /** + * QueryLatencyStats requestsWithoutFieldInstrumentation. + * @member {number} requestsWithoutFieldInstrumentation + * @memberof QueryLatencyStats + * @instance + */ + QueryLatencyStats.prototype.requestsWithoutFieldInstrumentation = $util.Long ? $util.Long.fromBits(0,0,true) : 0; + /** * Creates a new QueryLatencyStats instance using the specified properties. * @function create @@ -4511,6 +4540,8 @@ $root.QueryLatencyStats = (function() { writer.sint64(array16[i]); writer.ldelim(); } + if (message.requestsWithoutFieldInstrumentation != null && Object.hasOwnProperty.call(message, "requestsWithoutFieldInstrumentation")) + writer.uint32(/* id 17, wireType 0 =*/136).uint64(message.requestsWithoutFieldInstrumentation); return writer; }; @@ -4609,6 +4640,9 @@ $root.QueryLatencyStats = (function() { case 12: message.forbiddenOperationCount = reader.uint64(); break; + case 17: + message.requestsWithoutFieldInstrumentation = reader.uint64(); + break; default: reader.skipType(tag & 7); break; @@ -4718,6 +4752,9 @@ $root.QueryLatencyStats = (function() { if (message.forbiddenOperationCount != null && message.hasOwnProperty("forbiddenOperationCount")) if (!$util.isInteger(message.forbiddenOperationCount) && !(message.forbiddenOperationCount && $util.isInteger(message.forbiddenOperationCount.low) && $util.isInteger(message.forbiddenOperationCount.high))) return "forbiddenOperationCount: integer|Long expected"; + if (message.requestsWithoutFieldInstrumentation != null && message.hasOwnProperty("requestsWithoutFieldInstrumentation")) + if (!$util.isInteger(message.requestsWithoutFieldInstrumentation) && !(message.requestsWithoutFieldInstrumentation && $util.isInteger(message.requestsWithoutFieldInstrumentation.low) && $util.isInteger(message.requestsWithoutFieldInstrumentation.high))) + return "requestsWithoutFieldInstrumentation: integer|Long expected"; return null; }; @@ -4777,6 +4814,11 @@ $root.QueryLatencyStats = (function() { object.forbiddenOperationCount = options.longs === String ? long.toString() : options.longs === Number ? long.toNumber() : long; } else object.forbiddenOperationCount = options.longs === String ? "0" : 0; + if ($util.Long) { + var long = new $util.Long(0, 0, true); + object.requestsWithoutFieldInstrumentation = options.longs === String ? long.toString() : options.longs === Number ? long.toNumber() : long; + } else + object.requestsWithoutFieldInstrumentation = options.longs === String ? "0" : 0; } if (message.requestCount != null && message.hasOwnProperty("requestCount")) if (typeof message.requestCount === "number") @@ -4847,6 +4889,11 @@ $root.QueryLatencyStats = (function() { else object.privateCacheTtlCount[j] = options.longs === String ? $util.Long.prototype.toString.call(message.privateCacheTtlCount[j]) : options.longs === Number ? new $util.LongBits(message.privateCacheTtlCount[j].low >>> 0, message.privateCacheTtlCount[j].high >>> 0).toNumber() : message.privateCacheTtlCount[j]; } + if (message.requestsWithoutFieldInstrumentation != null && message.hasOwnProperty("requestsWithoutFieldInstrumentation")) + if (typeof message.requestsWithoutFieldInstrumentation === "number") + object.requestsWithoutFieldInstrumentation = options.longs === String ? String(message.requestsWithoutFieldInstrumentation) : message.requestsWithoutFieldInstrumentation; + else + object.requestsWithoutFieldInstrumentation = options.longs === String ? $util.Long.prototype.toString.call(message.requestsWithoutFieldInstrumentation) : options.longs === Number ? new $util.LongBits(message.requestsWithoutFieldInstrumentation.low >>> 0, message.requestsWithoutFieldInstrumentation.high >>> 0).toNumber(true) : message.requestsWithoutFieldInstrumentation; return object; }; @@ -5471,7 +5518,8 @@ $root.FieldStat = (function() { * @interface IFieldStat * @property {string|null} [returnType] FieldStat returnType * @property {number|null} [errorsCount] FieldStat errorsCount - * @property {number|null} [count] FieldStat count + * @property {number|null} [observedExecutionCount] FieldStat observedExecutionCount + * @property {number|null} [estimatedExecutionCount] FieldStat estimatedExecutionCount * @property {number|null} [requestsWithErrorsCount] FieldStat requestsWithErrorsCount * @property {$protobuf.ToArray.|Array.|null} [latencyCount] FieldStat latencyCount */ @@ -5509,12 +5557,20 @@ $root.FieldStat = (function() { FieldStat.prototype.errorsCount = $util.Long ? $util.Long.fromBits(0,0,true) : 0; /** - * FieldStat count. - * @member {number} count + * FieldStat observedExecutionCount. + * @member {number} observedExecutionCount + * @memberof FieldStat + * @instance + */ + FieldStat.prototype.observedExecutionCount = $util.Long ? $util.Long.fromBits(0,0,true) : 0; + + /** + * FieldStat estimatedExecutionCount. + * @member {number} estimatedExecutionCount * @memberof FieldStat * @instance */ - FieldStat.prototype.count = $util.Long ? $util.Long.fromBits(0,0,true) : 0; + FieldStat.prototype.estimatedExecutionCount = $util.Long ? $util.Long.fromBits(0,0,true) : 0; /** * FieldStat requestsWithErrorsCount. @@ -5560,8 +5616,8 @@ $root.FieldStat = (function() { writer.uint32(/* id 3, wireType 2 =*/26).string(message.returnType); if (message.errorsCount != null && Object.hasOwnProperty.call(message, "errorsCount")) writer.uint32(/* id 4, wireType 0 =*/32).uint64(message.errorsCount); - if (message.count != null && Object.hasOwnProperty.call(message, "count")) - writer.uint32(/* id 5, wireType 0 =*/40).uint64(message.count); + if (message.observedExecutionCount != null && Object.hasOwnProperty.call(message, "observedExecutionCount")) + writer.uint32(/* id 5, wireType 0 =*/40).uint64(message.observedExecutionCount); if (message.requestsWithErrorsCount != null && Object.hasOwnProperty.call(message, "requestsWithErrorsCount")) writer.uint32(/* id 6, wireType 0 =*/48).uint64(message.requestsWithErrorsCount); var array9; @@ -5575,6 +5631,8 @@ $root.FieldStat = (function() { writer.sint64(array9[i]); writer.ldelim(); } + if (message.estimatedExecutionCount != null && Object.hasOwnProperty.call(message, "estimatedExecutionCount")) + writer.uint32(/* id 10, wireType 0 =*/80).uint64(message.estimatedExecutionCount); return writer; }; @@ -5616,7 +5674,10 @@ $root.FieldStat = (function() { message.errorsCount = reader.uint64(); break; case 5: - message.count = reader.uint64(); + message.observedExecutionCount = reader.uint64(); + break; + case 10: + message.estimatedExecutionCount = reader.uint64(); break; case 6: message.requestsWithErrorsCount = reader.uint64(); @@ -5672,9 +5733,12 @@ $root.FieldStat = (function() { if (message.errorsCount != null && message.hasOwnProperty("errorsCount")) if (!$util.isInteger(message.errorsCount) && !(message.errorsCount && $util.isInteger(message.errorsCount.low) && $util.isInteger(message.errorsCount.high))) return "errorsCount: integer|Long expected"; - if (message.count != null && message.hasOwnProperty("count")) - if (!$util.isInteger(message.count) && !(message.count && $util.isInteger(message.count.low) && $util.isInteger(message.count.high))) - return "count: integer|Long expected"; + if (message.observedExecutionCount != null && message.hasOwnProperty("observedExecutionCount")) + if (!$util.isInteger(message.observedExecutionCount) && !(message.observedExecutionCount && $util.isInteger(message.observedExecutionCount.low) && $util.isInteger(message.observedExecutionCount.high))) + return "observedExecutionCount: integer|Long expected"; + if (message.estimatedExecutionCount != null && message.hasOwnProperty("estimatedExecutionCount")) + if (!$util.isInteger(message.estimatedExecutionCount) && !(message.estimatedExecutionCount && $util.isInteger(message.estimatedExecutionCount.low) && $util.isInteger(message.estimatedExecutionCount.high))) + return "estimatedExecutionCount: integer|Long expected"; if (message.requestsWithErrorsCount != null && message.hasOwnProperty("requestsWithErrorsCount")) if (!$util.isInteger(message.requestsWithErrorsCount) && !(message.requestsWithErrorsCount && $util.isInteger(message.requestsWithErrorsCount.low) && $util.isInteger(message.requestsWithErrorsCount.high))) return "requestsWithErrorsCount: integer|Long expected"; @@ -5717,14 +5781,19 @@ $root.FieldStat = (function() { object.errorsCount = options.longs === String ? "0" : 0; if ($util.Long) { var long = new $util.Long(0, 0, true); - object.count = options.longs === String ? long.toString() : options.longs === Number ? long.toNumber() : long; + object.observedExecutionCount = options.longs === String ? long.toString() : options.longs === Number ? long.toNumber() : long; } else - object.count = options.longs === String ? "0" : 0; + object.observedExecutionCount = options.longs === String ? "0" : 0; if ($util.Long) { var long = new $util.Long(0, 0, true); object.requestsWithErrorsCount = options.longs === String ? long.toString() : options.longs === Number ? long.toNumber() : long; } else object.requestsWithErrorsCount = options.longs === String ? "0" : 0; + if ($util.Long) { + var long = new $util.Long(0, 0, true); + object.estimatedExecutionCount = options.longs === String ? long.toString() : options.longs === Number ? long.toNumber() : long; + } else + object.estimatedExecutionCount = options.longs === String ? "0" : 0; } if (message.returnType != null && message.hasOwnProperty("returnType")) object.returnType = message.returnType; @@ -5733,11 +5802,11 @@ $root.FieldStat = (function() { object.errorsCount = options.longs === String ? String(message.errorsCount) : message.errorsCount; else object.errorsCount = options.longs === String ? $util.Long.prototype.toString.call(message.errorsCount) : options.longs === Number ? new $util.LongBits(message.errorsCount.low >>> 0, message.errorsCount.high >>> 0).toNumber(true) : message.errorsCount; - if (message.count != null && message.hasOwnProperty("count")) - if (typeof message.count === "number") - object.count = options.longs === String ? String(message.count) : message.count; + if (message.observedExecutionCount != null && message.hasOwnProperty("observedExecutionCount")) + if (typeof message.observedExecutionCount === "number") + object.observedExecutionCount = options.longs === String ? String(message.observedExecutionCount) : message.observedExecutionCount; else - object.count = options.longs === String ? $util.Long.prototype.toString.call(message.count) : options.longs === Number ? new $util.LongBits(message.count.low >>> 0, message.count.high >>> 0).toNumber(true) : message.count; + object.observedExecutionCount = options.longs === String ? $util.Long.prototype.toString.call(message.observedExecutionCount) : options.longs === Number ? new $util.LongBits(message.observedExecutionCount.low >>> 0, message.observedExecutionCount.high >>> 0).toNumber(true) : message.observedExecutionCount; if (message.requestsWithErrorsCount != null && message.hasOwnProperty("requestsWithErrorsCount")) if (typeof message.requestsWithErrorsCount === "number") object.requestsWithErrorsCount = options.longs === String ? String(message.requestsWithErrorsCount) : message.requestsWithErrorsCount; @@ -5751,6 +5820,11 @@ $root.FieldStat = (function() { else object.latencyCount[j] = options.longs === String ? $util.Long.prototype.toString.call(message.latencyCount[j]) : options.longs === Number ? new $util.LongBits(message.latencyCount[j].low >>> 0, message.latencyCount[j].high >>> 0).toNumber() : message.latencyCount[j]; } + if (message.estimatedExecutionCount != null && message.hasOwnProperty("estimatedExecutionCount")) + if (typeof message.estimatedExecutionCount === "number") + object.estimatedExecutionCount = options.longs === String ? String(message.estimatedExecutionCount) : message.estimatedExecutionCount; + else + object.estimatedExecutionCount = options.longs === String ? $util.Long.prototype.toString.call(message.estimatedExecutionCount) : options.longs === Number ? new $util.LongBits(message.estimatedExecutionCount.low >>> 0, message.estimatedExecutionCount.high >>> 0).toNumber(true) : message.estimatedExecutionCount; return object; }; diff --git a/packages/apollo-reporting-protobuf/generated/reports.proto b/packages/apollo-reporting-protobuf/generated/reports.proto index 2e97902fd1c..a486f4ffe76 100644 --- a/packages/apollo-reporting-protobuf/generated/reports.proto +++ b/packages/apollo-reporting-protobuf/generated/reports.proto @@ -232,6 +232,13 @@ message Trace { // Was this operation forbidden due to lack of safelisting? bool forbidden_operation = 25; + // Some servers don't do field-level instrumentation for every request and assign + // each request a "weight" for each request that they do instrument. When this + // trace is aggregated into field usage stats, it should count as this value + // towards the estimated_execution_count rather than just 1. 0 is treated as + // 1 for backwards compatibility. + double field_execution_scale_factor = 31; + // removed: Node parse = 12; Node validate = 13; @@ -289,6 +296,10 @@ message QueryLatencyStats { repeated sint64 private_cache_ttl_count = 16 [(js_use_toArray)=true]; uint64 registered_operation_count = 11; uint64 forbidden_operation_count = 12; + // The number of requests that were executed without field-level + // instrumentation (and thus do not contribute to `observed_execution_count` + // fields on this message's cousin-twice-removed FieldStats). + uint64 requests_without_field_instrumentation = 17; // 1, 6, 9, and 10 were old int64 histograms reserved 1, 6, 9, 10; } @@ -312,15 +323,32 @@ message ContextualizedTypeStats { message FieldStat { string return_type = 3; // required; eg "String!" for User.email:String! - // Number of errors whose path is this field. + // Number of errors whose path is this field. Note that we assume that error + // tracking does *not* require field-level instrumentation so this *will* + // include errors from requests that don't contribute to the + // `observed_execution_count` field (and does not need to be scaled by a + // sampling rate). uint64 errors_count = 4; - // Number of times that the resolver for this field is executed. - uint64 count = 5; + // Number of times that the resolver for this field is directly observed being + // executed. + uint64 observed_execution_count = 5; + // Same as `count` but potentially scaled upwards if the server was only + // performing field-level instrumentation on a sampling of operations. For + // example, if the server randomly instruments 1% of requests for this + // operation, this number will be 100 times greater than + // `observed_execution_count`. + uint64 estimated_execution_count = 10; // Number of times the resolver for this field is executed that resulted in // at least one error. "Request" is a misnomer here as this corresponds to - // resolver calls, not overall operations. + // resolver calls, not overall operations. Like `errors_count` above, this + // includes all requests rather than just requests with field-level + // instrumentation. uint64 requests_with_errors_count = 6; - repeated sint64 latency_count = 9 [(js_use_toArray)=true]; // Duration histogram; see docs/histograms.md + // Duration histogram for the latency of this field. Note that it is scaled in + // the same way as estimated_execution_count so its "total count" might be + // great than `observed_execution_count` and may not exactly equal + // `estimated_execution_count` due to rounding. + repeated sint64 latency_count = 9 [(js_use_toArray)=true]; reserved 1, 2, 7, 8; } @@ -370,7 +398,8 @@ message Report { message ContextualizedStats { StatsContext context = 1; QueryLatencyStats query_latency_stats = 2; - // Key is type name. + // Key is type name. This structure provides data for the count and latency of individual + // field executions and thus only reflects operations for which field-level tracing occurred. map per_type_stat = 3; } diff --git a/packages/apollo-reporting-protobuf/src/reports.proto b/packages/apollo-reporting-protobuf/src/reports.proto index 2e97902fd1c..a486f4ffe76 100644 --- a/packages/apollo-reporting-protobuf/src/reports.proto +++ b/packages/apollo-reporting-protobuf/src/reports.proto @@ -232,6 +232,13 @@ message Trace { // Was this operation forbidden due to lack of safelisting? bool forbidden_operation = 25; + // Some servers don't do field-level instrumentation for every request and assign + // each request a "weight" for each request that they do instrument. When this + // trace is aggregated into field usage stats, it should count as this value + // towards the estimated_execution_count rather than just 1. 0 is treated as + // 1 for backwards compatibility. + double field_execution_scale_factor = 31; + // removed: Node parse = 12; Node validate = 13; @@ -289,6 +296,10 @@ message QueryLatencyStats { repeated sint64 private_cache_ttl_count = 16 [(js_use_toArray)=true]; uint64 registered_operation_count = 11; uint64 forbidden_operation_count = 12; + // The number of requests that were executed without field-level + // instrumentation (and thus do not contribute to `observed_execution_count` + // fields on this message's cousin-twice-removed FieldStats). + uint64 requests_without_field_instrumentation = 17; // 1, 6, 9, and 10 were old int64 histograms reserved 1, 6, 9, 10; } @@ -312,15 +323,32 @@ message ContextualizedTypeStats { message FieldStat { string return_type = 3; // required; eg "String!" for User.email:String! - // Number of errors whose path is this field. + // Number of errors whose path is this field. Note that we assume that error + // tracking does *not* require field-level instrumentation so this *will* + // include errors from requests that don't contribute to the + // `observed_execution_count` field (and does not need to be scaled by a + // sampling rate). uint64 errors_count = 4; - // Number of times that the resolver for this field is executed. - uint64 count = 5; + // Number of times that the resolver for this field is directly observed being + // executed. + uint64 observed_execution_count = 5; + // Same as `count` but potentially scaled upwards if the server was only + // performing field-level instrumentation on a sampling of operations. For + // example, if the server randomly instruments 1% of requests for this + // operation, this number will be 100 times greater than + // `observed_execution_count`. + uint64 estimated_execution_count = 10; // Number of times the resolver for this field is executed that resulted in // at least one error. "Request" is a misnomer here as this corresponds to - // resolver calls, not overall operations. + // resolver calls, not overall operations. Like `errors_count` above, this + // includes all requests rather than just requests with field-level + // instrumentation. uint64 requests_with_errors_count = 6; - repeated sint64 latency_count = 9 [(js_use_toArray)=true]; // Duration histogram; see docs/histograms.md + // Duration histogram for the latency of this field. Note that it is scaled in + // the same way as estimated_execution_count so its "total count" might be + // great than `observed_execution_count` and may not exactly equal + // `estimated_execution_count` due to rounding. + repeated sint64 latency_count = 9 [(js_use_toArray)=true]; reserved 1, 2, 7, 8; } @@ -370,7 +398,8 @@ message Report { message ContextualizedStats { StatsContext context = 1; QueryLatencyStats query_latency_stats = 2; - // Key is type name. + // Key is type name. This structure provides data for the count and latency of individual + // field executions and thus only reflects operations for which field-level tracing occurred. map per_type_stat = 3; } diff --git a/packages/apollo-server-core/src/plugin/usageReporting/__tests__/__snapshots__/stats.test.ts.snap b/packages/apollo-server-core/src/plugin/usageReporting/__tests__/__snapshots__/stats.test.ts.snap index 54dfa41fbde..8e71790e5b3 100644 --- a/packages/apollo-server-core/src/plugin/usageReporting/__tests__/__snapshots__/stats.test.ts.snap +++ b/packages/apollo-server-core/src/plugin/usageReporting/__tests__/__snapshots__/stats.test.ts.snap @@ -326,6 +326,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -661,6 +662,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -996,6 +998,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -1331,6 +1334,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -1666,6 +1670,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -2001,6 +2006,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -2336,6 +2342,7 @@ OurContextualizedStats { "registeredOperationCount": 1, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -2671,6 +2678,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -3006,6 +3014,7 @@ OurContextualizedStats { "registeredOperationCount": 1, "requestCount": 1, "requestsWithErrorsCount": 1, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object { "user": OurPathErrorStats { @@ -3347,6 +3356,7 @@ OurContextualizedStats { "registeredOperationCount": 4, "requestCount": 4, "requestsWithErrorsCount": 4, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object { "account": OurPathErrorStats { @@ -3705,6 +3715,7 @@ OurContextualizedStats { "registeredOperationCount": 0, "requestCount": 6, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -3723,8 +3734,8 @@ OurContextualizedStats { "Query": OurTypeStat { "perFieldStat": Object { "user": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 0, @@ -3803,6 +3814,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "User!", }, @@ -3811,8 +3823,8 @@ OurContextualizedStats { "User": OurTypeStat { "perFieldStat": Object { "email": OurFieldStat { - "count": 2, "errorsCount": 4, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 2, @@ -3891,12 +3903,13 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 2, "returnType": "String!", }, "friends": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 2, @@ -3975,6 +3988,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "[String!]!", }, @@ -4301,6 +4315,7 @@ OurContextualizedStats { "registeredOperationCount": 2, "requestCount": 2, "requestsWithErrorsCount": 2, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object { "user": OurPathErrorStats { @@ -4331,8 +4346,8 @@ OurContextualizedStats { "Query": OurTypeStat { "perFieldStat": Object { "user": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 0, @@ -4411,6 +4426,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "User!", }, @@ -4419,8 +4435,8 @@ OurContextualizedStats { "User": OurTypeStat { "perFieldStat": Object { "email": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 2, @@ -4499,12 +4515,13 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "String!", }, "friends": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 2, @@ -4583,6 +4600,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "[String!]!", }, @@ -4909,6 +4927,7 @@ OurContextualizedStats { "registeredOperationCount": 2, "requestCount": 2, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -4927,8 +4946,8 @@ OurContextualizedStats { "Query": OurTypeStat { "perFieldStat": Object { "user": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 0, @@ -5007,6 +5026,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "User!", }, @@ -5015,8 +5035,8 @@ OurContextualizedStats { "User": OurTypeStat { "perFieldStat": Object { "email": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 2, @@ -5095,12 +5115,13 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "String!", }, "friends": OurFieldStat { - "count": 2, "errorsCount": 0, + "estimatedExecutionCount": 2, "latencyCount": DurationHistogram { "buckets": Array [ 2, @@ -5179,6 +5200,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 2, "requestsWithErrorsCount": 0, "returnType": "[String!]!", }, @@ -5505,6 +5527,7 @@ OurContextualizedStats { "registeredOperationCount": 2, "requestCount": 2, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, @@ -5523,8 +5546,8 @@ OurContextualizedStats { "Query": OurTypeStat { "perFieldStat": Object { "user": OurFieldStat { - "count": 1, "errorsCount": 0, + "estimatedExecutionCount": 1, "latencyCount": DurationHistogram { "buckets": Array [ 0, @@ -5603,6 +5626,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 1, "requestsWithErrorsCount": 0, "returnType": "User!", }, @@ -5611,8 +5635,8 @@ OurContextualizedStats { "User": OurTypeStat { "perFieldStat": Object { "email": OurFieldStat { - "count": 1, "errorsCount": 0, + "estimatedExecutionCount": 1, "latencyCount": DurationHistogram { "buckets": Array [ 1, @@ -5691,12 +5715,13 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 1, "requestsWithErrorsCount": 0, "returnType": "String!", }, "friends": OurFieldStat { - "count": 1, "errorsCount": 0, + "estimatedExecutionCount": 1, "latencyCount": DurationHistogram { "buckets": Array [ 1, @@ -5775,6 +5800,7 @@ OurContextualizedStats { 0, ], }, + "observedExecutionCount": 1, "requestsWithErrorsCount": 0, "returnType": "[String!]!", }, @@ -6101,6 +6127,7 @@ OurContextualizedStats { "registeredOperationCount": 1, "requestCount": 1, "requestsWithErrorsCount": 0, + "requestsWithoutFieldInstrumentation": 0, "rootErrorStats": OurPathErrorStats { "children": Object {}, "errorsCount": 0, diff --git a/packages/apollo-server-core/src/plugin/usageReporting/__tests__/plugin.test.ts b/packages/apollo-server-core/src/plugin/usageReporting/__tests__/plugin.test.ts index e8175ab4592..4317b035349 100644 --- a/packages/apollo-server-core/src/plugin/usageReporting/__tests__/plugin.test.ts +++ b/packages/apollo-server-core/src/plugin/usageReporting/__tests__/plugin.test.ts @@ -8,11 +8,21 @@ import { ApolloServerPluginUsageReporting, } from '../plugin'; import { Headers } from 'apollo-server-env'; -import { Trace, Report, ITrace } from 'apollo-reporting-protobuf'; +import { + Trace, + Report, + ITrace, + ITracesAndStats, + ContextualizedStats, +} from 'apollo-reporting-protobuf'; import pluginTestHarness from '../../../utils/pluginTestHarness'; +import { pluginsEnabledForSchemaResolvers } from '../../../utils/schemaInstrumentation'; import nock from 'nock'; +import sumBy from 'lodash.sumby'; +import { mockRandom, resetMockRandom } from 'jest-mock-random'; import { gunzipSync } from 'zlib'; import type { ApolloServerPluginUsageReportingOptions } from '../options'; +import type { GraphQLRequestContextDidResolveOperation } from 'apollo-server-types'; const quietLogger = loglevel.getLogger('quiet'); quietLogger.setLevel(loglevel.levels.WARN); @@ -23,11 +33,13 @@ describe('end-to-end', () => { expectReport = true, query, operationName, + schemaShouldBeInstrumented = true, }: { pluginOptions?: ApolloServerPluginUsageReportingOptions; expectReport?: boolean; query?: string; operationName?: string | null; + schemaShouldBeInstrumented?: boolean; }) { const typeDefs = ` type User { @@ -121,6 +133,11 @@ describe('end-to-end', () => { }) : null; nockScope.done(); + + expect(pluginsEnabledForSchemaResolvers(schema)).toBe( + schemaShouldBeInstrumented, + ); + return { report, context }; } @@ -141,17 +158,23 @@ describe('end-to-end', () => { [ { testName: 'fails parse for non-parseable gql', - op: { query: 'random text' }, + op: { query: 'random text', schemaShouldBeInstrumented: false }, statsReportKey: '## GraphQLParseFailure\n', }, { testName: 'validation fails for invalid operation', - op: { query: 'query q { nonExistentField }' }, + op: { + query: 'query q { nonExistentField }', + schemaShouldBeInstrumented: false, + }, statsReportKey: '## GraphQLValidationFailure\n', }, { testName: 'unknown operation error if not specified', - op: { query: 'query notQ { aString }' }, + op: { + query: 'query notQ { aString }', + schemaShouldBeInstrumented: false, + }, statsReportKey: '## GraphQLUnknownOperationName\n', }, { @@ -176,8 +199,22 @@ describe('end-to-end', () => { const queryEntries = Object.entries(report!.tracesPerQuery); expect(queryEntries).toHaveLength(1); expect(queryEntries[0][0]).toBe(statsReportKey); - const traces = queryEntries[0][1]!.trace; - expect(traces).toHaveLength(1); + const tracesAndStats = queryEntries[0][1]; + const operationsSentAsTrace = tracesAndStats.trace?.length ?? 0; + if ( + tracesAndStats.statsWithContext && + 'toArray' in tracesAndStats.statsWithContext + ) { + throw Error( + "we shouldn't get something that needs to be converted when we decode a report", + ); + } + const operationsSentAsStats = sumBy( + tracesAndStats.statsWithContext, + (contextualizedStats) => + contextualizedStats.queryLatencyStats?.requestCount ?? 0, + ); + expect(operationsSentAsTrace + operationsSentAsStats).toBe(1); }), ); @@ -190,9 +227,10 @@ describe('end-to-end', () => { return request.request.operationName === 'q'; }, }, + schemaShouldBeInstrumented: true, }); expect(Object.keys(report!.tracesPerQuery)).toHaveLength(1); - expect(context.metrics.captureTraces).toBeTruthy(); + expect(context.metrics.captureTraces).toBe(true); }); it('exclude based on operation name', async () => { const { context } = await runTest({ @@ -203,10 +241,129 @@ describe('end-to-end', () => { }, }, expectReport: false, + schemaShouldBeInstrumented: false, }); expect(context.metrics.captureTraces).toBeFalsy(); }); }); + + describe('fieldLevelInstrumentation', () => { + function containsFieldExecutionData( + tracesAndStats: ITracesAndStats, + ): boolean { + for (const trace of tracesAndStats.trace ?? []) { + if (trace instanceof Uint8Array) { + throw Error( + "test shouldn't have a pre-encoded trace after decoding!", + ); + } + if (trace.root?.child?.length) { + // We found an actual field inside a trace. + return true; + } + } + + if ( + tracesAndStats.statsWithContext && + 'toArray' in tracesAndStats.statsWithContext + ) { + throw Error( + "we shouldn't get something that needs to be converted when we decode a report", + ); + } + for (const statsWithContext of tracesAndStats.statsWithContext ?? []) { + if (Object.keys(statsWithContext.perTypeStat ?? {}).length > 0) { + // We found a TypeStat, showing that we have field execution stats. + return true; + } + } + + return false; + } + + it('include based on operation name', async () => { + const { report, context } = await runTest({ + pluginOptions: { + fieldLevelInstrumentation: async ( + requestContext: GraphQLRequestContextDidResolveOperation, + ) => { + await new Promise((res) => setTimeout(() => res(), 1)); + return requestContext.request.operationName === 'q'; + }, + }, + }); + expect(context.metrics.captureTraces).toBe(true); + expect(Object.keys(report!.tracesPerQuery)).toHaveLength(1); + expect( + containsFieldExecutionData(Object.values(report!.tracesPerQuery)[0]!), + ).toBe(true); + }); + + it('exclude based on operation name', async () => { + const { report, context } = await runTest({ + pluginOptions: { + fieldLevelInstrumentation: async ( + requestContext: GraphQLRequestContextDidResolveOperation, + ) => { + await new Promise((res) => setTimeout(() => res(), 1)); + return requestContext.request.operationName === 'not_q'; + }, + }, + schemaShouldBeInstrumented: false, + }); + // We do get a report about this operation; we just don't have field + // execution data (as trace or as TypeStat). + expect(context.metrics.captureTraces).toBe(false); + expect(Object.keys(report!.tracesPerQuery)).toHaveLength(1); + expect( + containsFieldExecutionData(Object.values(report!.tracesPerQuery)[0]!), + ).toBe(false); + }); + + describe('passing a number', () => { + afterEach(() => resetMockRandom()); + + const samplingFactor = 0.015; + it('RNG returns a small number', async () => { + mockRandom(samplingFactor * 0.99); + const { report, context } = await runTest({ + pluginOptions: { + fieldLevelInstrumentation: samplingFactor, + // Want to see this in stats so we can see the scaling. + experimental_sendOperationAsTrace: () => false, + }, + schemaShouldBeInstrumented: true, + }); + expect(context.metrics.captureTraces).toBe(true); + expect(Object.keys(report!.tracesPerQuery)).toHaveLength(1); + expect( + containsFieldExecutionData(Object.values(report!.tracesPerQuery)[0]!), + ).toBe(true); + const fieldStat = ( + Object.values(report!.tracesPerQuery)[0]! + .statsWithContext as ContextualizedStats[] + )[0].perTypeStat['Query'].perFieldStat!['aBoolean']; + expect(fieldStat.observedExecutionCount).toBe(1); + expect(fieldStat.estimatedExecutionCount).toBe( + Math.floor(1 / samplingFactor), + ); + }); + it('RNG returns a large number', async () => { + mockRandom(samplingFactor * 1.01); + const { report, context } = await runTest({ + pluginOptions: { + fieldLevelInstrumentation: samplingFactor, + }, + schemaShouldBeInstrumented: false, + }); + expect(context.metrics.captureTraces).toBe(false); + expect(Object.keys(report!.tracesPerQuery)).toHaveLength(1); + expect( + containsFieldExecutionData(Object.values(report!.tracesPerQuery)[0]!), + ).toBe(false); + }); + }); + }); }); describe('sendHeaders makeHTTPRequestHeaders helper', () => { diff --git a/packages/apollo-server-core/src/plugin/usageReporting/__tests__/stats.test.ts b/packages/apollo-server-core/src/plugin/usageReporting/__tests__/stats.test.ts index 5cdbaeb22ac..167aebf0f73 100644 --- a/packages/apollo-server-core/src/plugin/usageReporting/__tests__/stats.test.ts +++ b/packages/apollo-server-core/src/plugin/usageReporting/__tests__/stats.test.ts @@ -16,6 +16,7 @@ const baseTrace = new Trace({ root: null, signature: 'signature', details: null, + fieldExecutionScaleFactor: 1, }); // TODO: add a federated trace describe('Check query latency stats when', () => { diff --git a/packages/apollo-server-core/src/plugin/usageReporting/durationHistogram.ts b/packages/apollo-server-core/src/plugin/usageReporting/durationHistogram.ts index c19f9b54f2e..8bfbfd182fe 100644 --- a/packages/apollo-server-core/src/plugin/usageReporting/durationHistogram.ts +++ b/packages/apollo-server-core/src/plugin/usageReporting/durationHistogram.ts @@ -3,6 +3,8 @@ export interface DurationHistogramOptions { buckets?: number[]; } export class DurationHistogram { + // Note that it's legal for the values in "buckets" to be non-integers; they + // will be floored by toArray (which is called by the protobuf encoder). private readonly buckets: number[]; static readonly BUCKET_COUNT = 384; static readonly EXPONENT_LOG = Math.log(1.1); @@ -20,7 +22,7 @@ export class DurationHistogram { } else if (bufferedZeroes !== 0) { outputArray.push(-bufferedZeroes); } - outputArray.push(value); + outputArray.push(Math.floor(value)); bufferedZeroes = 0; } } @@ -39,8 +41,8 @@ export class DurationHistogram { : unboundedBucket; } - incrementDuration(durationNs: number): DurationHistogram { - this.incrementBucket(DurationHistogram.durationToBucket(durationNs)); + incrementDuration(durationNs: number, value = 1): DurationHistogram { + this.incrementBucket(DurationHistogram.durationToBucket(durationNs), value); return this; } diff --git a/packages/apollo-server-core/src/plugin/usageReporting/options.ts b/packages/apollo-server-core/src/plugin/usageReporting/options.ts index b0c9b2b5fdc..e8afa5d8f49 100644 --- a/packages/apollo-server-core/src/plugin/usageReporting/options.ts +++ b/packages/apollo-server-core/src/plugin/usageReporting/options.ts @@ -50,12 +50,84 @@ export interface ApolloServerPluginUsageReportingOptions { * by modifying it and returning the modified error. */ rewriteError?: (err: GraphQLError) => GraphQLError | null; + + // We should strongly consider changing the default to false in AS4. + + /** + * This option allows you to choose if Apollo Server should calculate detailed + * per-field statistics for a particular request. It is only called for + * executable operations: operations which parse and validate properly and + * which do not have an unknown operation name. It is not called if an + * `includeRequest` hook is provided and returns false. + * + * You can either pass an async function or a number. The function receives a + * `GraphQLRequestContext`. (The effect of passing a number is described + * later.) Your function can return a boolean or a number; returning false is + * equivalent to returning 0 and returning true is equivalent to returning 1. + * + * Returning false (or 0) means that Apollo Server will only pay attention to + * overall properties of the operation, like what GraphQL operation is + * executing and how long the entire operation takes to execute, and not + * anything about field-by-field execution. + * + * If you return false (or 0), this operation *will* still contribute to most + * features of Studio, such as schema checks, the Operations page, and the + * "referencing operations" statistic on the Fields page, etc. + * + * If you return false (or 0), this operation will *not* contribute to the + * "field executions" statistic on the Fields page or to the execution timing + * hints optionally displayed in Studio Explorer or in vscode-graphql. + * Additionally, this operation will not produce a trace that can be viewed on + * the Traces section of the Operations page. + * + * Returning false (or 0) here for some or all operations can improve your + * server's performance, as the overhead of calculating complete traces is not + * always negligible. This is especially the case if this server is an Apollo + * Gateway, as captured traces are transmitted from the subgraph to the + * Gateway in-band inside the actual GraphQL response. + * + * Returning a positive number means that Apollo Server will track each field + * execution and send Apollo Studio statistics on how many times each field + * was executed and what the per-field performance was. If the number returned + * is less than 1, Apollo Server will also send a scaled "estimate" count for + * each field, equal to the number of observed field executions divided by the + * number returned by the hook. + * + * Passing a number `n` (which should be between 0 and 1 inclusive) for + * `fieldLevelInstrumentation` is equivalent to passing the function + * `async () => Math.random() < n ? n : 0`. For example, if you pass 0.01, + * then 99% of the time Apollo Server will not track field executions, and 1% + * of the time Apollo Server will track field executions and send them to + * Apollo Studio both as an exact observed count and as an "estimated" count + * which is 100 times higher. + * + * (Note that returning true here does *not* mean that the data derived from + * field-level instrumentation must be transmitted to Apollo Studio's servers + * in the form of a trace; it may still be aggregated locally to statistics. + * But either way this operation will contribute to the "field executions" + * statistic and timing hints.) + * + * The default `fieldLevelInstrumentation` is a function that always returns + * true. + + */ + fieldLevelInstrumentation?: + | number + | (( + request: GraphQLRequestContextDidResolveOperation, + ) => Promise); + /** * This option allows you to choose if a particular request should be * represented in the usage reporting sent to Apollo servers. By default, all * requests are included. If this async predicate function is specified, its * return value will determine whether a given request is included. * + * Note that returning false here means that the operation will be completely + * ignored by all Apollo Studio features. If you merely want to improve + * performance by skipping the field-level execution trace, set the + * `fieldLevelInstrumentation` option instead of this one. + * * The predicate function receives the request context. If validation and * parsing of the request succeeds, the function will receive the request * context in the @@ -66,8 +138,8 @@ export interface ApolloServerPluginUsageReportingOptions { * [`GraphQLRequestContextWillSendResponse`](https://www.apollographql.com/docs/apollo-server/integrations/plugins/#willsendresponse) * phase: * - * (If you don't want any usage reporting, don't use this plugin; if you are - * using other plugins that require you to configure an Apollo API key, use + * (If you don't want any usage reporting at all, don't use this option: + * instead, either avoid specifying an Apollo API key, or use * ApolloServerPluginUsageReportingDisabled to prevent this plugin from being * created by default.) * diff --git a/packages/apollo-server-core/src/plugin/usageReporting/plugin.ts b/packages/apollo-server-core/src/plugin/usageReporting/plugin.ts index e296d82aea4..d7310e3f276 100644 --- a/packages/apollo-server-core/src/plugin/usageReporting/plugin.ts +++ b/packages/apollo-server-core/src/plugin/usageReporting/plugin.ts @@ -68,6 +68,21 @@ export function ApolloServerPluginUsageReporting( null, ), ): InternalApolloServerPlugin { + // Note: We'd like to change the default to false in Apollo Server 4, so that + // the default usage reporting experience doesn't include *anything* that + // could potentially be PII (like error messages) --- just operations and + // numbers. + const fieldLevelInstrumentationOption = options.fieldLevelInstrumentation; + const fieldLevelInstrumentation = + typeof fieldLevelInstrumentationOption === 'number' + ? async () => + Math.random() < fieldLevelInstrumentationOption + ? fieldLevelInstrumentationOption + : 0 + : fieldLevelInstrumentationOption + ? fieldLevelInstrumentationOption + : async () => true; + let requestDidStartHandler: ( requestContext: GraphQLRequestContext, ) => GraphQLRequestListener; @@ -225,6 +240,8 @@ export function ApolloServerPluginUsageReporting( // associated with the summarized statistics. report.endTime = dateToProtoTimestamp(new Date()); + report.ensureCountsAreIntegers(); + const protobufError = Report.verify(report); if (protobufError) { throw new Error(`Error encoding report: ${protobufError}`); @@ -380,6 +397,7 @@ export function ApolloServerPluginUsageReporting( metrics.startHrTime = treeBuilder.startHrTime; let graphqlValidationFailure = false; let graphqlUnknownOperationName = false; + let includeOperationInUsageReporting: boolean | null = null; if (http) { treeBuilder.trace.http = new Trace.HTTP({ @@ -407,31 +425,33 @@ export function ApolloServerPluginUsageReporting( } } - // After this function completes, metrics.captureTraces is defined. - async function shouldIncludeRequest( + // After this function completes, includeOperationInUsageReporting is + // defined. + async function maybeCallIncludeRequestHook( requestContext: | GraphQLRequestContextDidResolveOperation | GraphQLRequestContextWillSendResponse, ): Promise { // If this is the second call in `willSendResponse` after // `didResolveOperation`, we're done. - if (metrics.captureTraces !== undefined) return; + if (includeOperationInUsageReporting !== null) return; if (typeof options.includeRequest !== 'function') { // Default case we always report - metrics.captureTraces = true; + includeOperationInUsageReporting = true; return; } - - metrics.captureTraces = await options.includeRequest(requestContext); + includeOperationInUsageReporting = await options.includeRequest( + requestContext, + ); // Help the user understand they've returned an unexpected value, // which might be a subtle mistake. - if (typeof metrics.captureTraces !== 'boolean') { + if (typeof includeOperationInUsageReporting !== 'boolean') { logger.warn( "The 'includeRequest' async predicate function must return a boolean value.", ); - metrics.captureTraces = true; + includeOperationInUsageReporting = true; } } @@ -487,12 +507,53 @@ export function ApolloServerPluginUsageReporting( // and an unknown operation was specified. graphqlUnknownOperationName = requestContext.operation === undefined; - await shouldIncludeRequest(requestContext); + await maybeCallIncludeRequestHook(requestContext); + + if ( + includeOperationInUsageReporting && + // No need to capture traces if the operation is going to + // immediately fail due to unknown operation name. + !graphqlUnknownOperationName + ) { + // We're not completely ignoring the operation. But should we + // calculate a detailed trace of every field while we do so (either + // directly in this plugin, or in a subgraph by sending the + // apollo-federation-include-trace header)? That will allow this + // operation to contribute to the "field executions" column in the + // Studio Fields page, to the timing hints in Explorer and + // vscode-graphql, and to the traces visible under Operations. (Note + // that `true` here does not imply that this operation will + // necessarily be *sent* to the usage-reporting endpoint in the form + // of a trace --- it still might be aggregated into stats first. But + // capturing a trace will mean we can understand exactly what fields + // were executed and what their performance was, at the tradeoff of + // some overhead for tracking the trace (and transmitting it between + // subgraph and gateway). + const fieldLevelInstrumentationResult = + await fieldLevelInstrumentation(requestContext); + if ( + typeof fieldLevelInstrumentationResult === 'number' && + fieldLevelInstrumentationResult > 0 + ) { + treeBuilder.trace.fieldExecutionScaleFactor = + 1 / fieldLevelInstrumentationResult; + } else if (fieldLevelInstrumentationResult) { + treeBuilder.trace.fieldExecutionScaleFactor = 1; + } else { + treeBuilder.trace.fieldExecutionScaleFactor = 0; + } + + metrics.captureTraces = + !!treeBuilder.trace.fieldExecutionScaleFactor; + } }, async executionDidStart() { - // If we stopped tracing early, return undefined so we don't trace - // an object - if (metrics.captureTraces === false) return; + // If we're not capturing traces, don't return a willResolveField so + // that we don't build up a detailed trace inside treeBuilder. (We still + // will use treeBuilder as a convenient place to put top-level facts + // about the operation which can end up aggregated as stats, and we do + // eventually put *errors* onto the trace tree.) + if (!metrics.captureTraces) return; return { willResolveField({ info }) { @@ -513,11 +574,11 @@ export function ApolloServerPluginUsageReporting( // If we got an error before we called didResolveOperation (eg parse or // validation error), check to see if we should include the request. - await shouldIncludeRequest(requestContext); + await maybeCallIncludeRequestHook(requestContext); treeBuilder.stopTiming(); - if (metrics.captureTraces === false) return; + if (includeOperationInUsageReporting === false) return; treeBuilder.trace.fullQueryCacheHit = !!metrics.responseCacheHit; treeBuilder.trace.forbiddenOperation = !!metrics.forbiddenOperation; @@ -610,8 +671,14 @@ export function ApolloServerPluginUsageReporting( report.addTrace({ statsReportKey, trace, + // We include the operation as a trace (rather than aggregated + // into stats) only if we believe it's possible that our + // organization's plan allows for viewing traces *and* we + // actually captured this as a full trace *and* + // sendOperationAsTrace says so. asTrace: graphMightSupportTraces && + !!metrics.captureTraces && sendOperationAsTrace(trace, statsReportKey), includeTracesContributingToStats, referencedFieldsByType, diff --git a/packages/apollo-server-core/src/plugin/usageReporting/stats.ts b/packages/apollo-server-core/src/plugin/usageReporting/stats.ts index 05ecfb7bced..1e9d56bda9d 100644 --- a/packages/apollo-server-core/src/plugin/usageReporting/stats.ts +++ b/packages/apollo-server-core/src/plugin/usageReporting/stats.ts @@ -50,6 +50,12 @@ export class OurReport implements Required { // methods which increment it. readonly sizeEstimator = new SizeEstimator(); + ensureCountsAreIntegers() { + for (const tracesAndStats of Object.values(this.tracesPerQuery)) { + tracesAndStats.ensureCountsAreIntegers(); + } + } + addTrace({ statsReportKey, trace, @@ -130,6 +136,10 @@ class OurTracesAndStats implements Required { readonly trace: Uint8Array[] = []; readonly statsWithContext = new StatsByContext(); readonly internalTracesContributingToStats: Uint8Array[] = []; + + ensureCountsAreIntegers() { + this.statsWithContext.ensureCountsAreIntegers(); + } } class StatsByContext { @@ -143,6 +153,12 @@ class StatsByContext { return Object.values(this.map); } + ensureCountsAreIntegers() { + for (const contextualizedStats of Object.values(this.map)) { + contextualizedStats.ensureCountsAreIntegers(); + } + } + addTrace(trace: Trace, sizeEstimator: SizeEstimator) { this.getContextualizedStats(trace, sizeEstimator).addTrace( trace, @@ -183,11 +199,22 @@ export class OurContextualizedStats implements Required { constructor(readonly context: IStatsContext) {} + ensureCountsAreIntegers() { + for (const typeStat of Object.values(this.perTypeStat)) { + typeStat.ensureCountsAreIntegers(); + } + } + // Extract statistics from the trace, and increment the estimated report size. // We only add to the estimate when adding whole sub-messages. If it really // mattered, we could do a lot more careful things like incrementing it // whenever a numeric field on queryLatencyStats gets incremented over 0. addTrace(trace: Trace, sizeEstimator: SizeEstimator) { + const { fieldExecutionScaleFactor } = trace; + if (!fieldExecutionScaleFactor) { + this.queryLatencyStats.requestsWithoutFieldInstrumentation++; + } + this.queryLatencyStats.requestCount++; if (trace.fullQueryCacheHit) { this.queryLatencyStats.cacheLatencyCount.incrementDuration( @@ -250,48 +277,56 @@ export class OurContextualizedStats implements Required { currPathErrorStats.errorsCount += node.error.length; } - // The actual field name behind the node; originalFieldName is set - // if an alias was used, otherwise responseName. (This is falsey for - // nodes that are not fields (root, array index, etc).) - const fieldName = node.originalFieldName || node.responseName; - - // Protobuf doesn't really differentiate between "unset" and "falsey" so - // we're mostly actually checking that these things are non-empty string / - // non-zero numbers. The time fields represent the number of nanoseconds - // since the beginning of the entire trace, so let's pretend for the - // moment that it's plausible for a node to start or even end exactly when - // the trace started (ie, for the time values to be 0). This is unlikely - // in practice (everything should take at least 1ns). In practice we only - // write `type` and `parentType` on a Node when we write `startTime`, so - // the main thing we're looking out for by checking the time values is - // whether we somehow failed to write `endTime` at the end of the field; - // in this case, the `endTime >= startTime` check won't match. - if ( - node.parentType && - fieldName && - node.type && - node.endTime != null && - node.startTime != null && - node.endTime >= node.startTime - ) { - const typeStat = this.getTypeStat(node.parentType, sizeEstimator); - - const fieldStat = typeStat.getFieldStat( - fieldName, - node.type, - sizeEstimator, - ); - - fieldStat.errorsCount += node.error?.length ?? 0; - fieldStat.count++; - // Note: this is actually counting the number of resolver calls for this - // field that had at least one error, not the number of overall GraphQL - // queries that had at least one error for this field. That doesn't seem - // to match the name, but it does match the other implementations of this - // logic. - fieldStat.requestsWithErrorsCount += - (node.error?.length ?? 0) > 0 ? 1 : 0; - fieldStat.latencyCount.incrementDuration(node.endTime - node.startTime); + if (fieldExecutionScaleFactor) { + // The actual field name behind the node; originalFieldName is set + // if an alias was used, otherwise responseName. (This is falsey for + // nodes that are not fields (root, array index, etc).) + const fieldName = node.originalFieldName || node.responseName; + + // Protobuf doesn't really differentiate between "unset" and "falsey" so + // we're mostly actually checking that these things are non-empty string / + // non-zero numbers. The time fields represent the number of nanoseconds + // since the beginning of the entire trace, so let's pretend for the + // moment that it's plausible for a node to start or even end exactly when + // the trace started (ie, for the time values to be 0). This is unlikely + // in practice (everything should take at least 1ns). In practice we only + // write `type` and `parentType` on a Node when we write `startTime`, so + // the main thing we're looking out for by checking the time values is + // whether we somehow failed to write `endTime` at the end of the field; + // in this case, the `endTime >= startTime` check won't match. + if ( + node.parentType && + fieldName && + node.type && + node.endTime != null && + node.startTime != null && + node.endTime >= node.startTime + ) { + const typeStat = this.getTypeStat(node.parentType, sizeEstimator); + + const fieldStat = typeStat.getFieldStat( + fieldName, + node.type, + sizeEstimator, + ); + + fieldStat.errorsCount += node.error?.length ?? 0; + fieldStat.observedExecutionCount++; + fieldStat.estimatedExecutionCount += fieldExecutionScaleFactor; + // Note: this is actually counting the number of resolver calls for this + // field that had at least one error, not the number of overall GraphQL + // queries that had at least one error for this field. That doesn't seem + // to match the name, but it does match the other implementations of this + // logic. + fieldStat.requestsWithErrorsCount += + (node.error?.length ?? 0) > 0 ? 1 : 0; + fieldStat.latencyCount.incrementDuration( + node.endTime - node.startTime, + // The latency histogram is always "estimated"; we don't track + // "observed" and "estimated" separately. + fieldExecutionScaleFactor, + ); + } } return false; @@ -318,6 +353,7 @@ export class OurContextualizedStats implements Required { class OurQueryLatencyStats implements Required { latencyCount: DurationHistogram = new DurationHistogram(); requestCount: number = 0; + requestsWithoutFieldInstrumentation: number = 0; cacheHits: number = 0; persistedQueryHits: number = 0; persistedQueryMisses: number = 0; @@ -369,15 +405,30 @@ class OurTypeStat implements Required { this.perFieldStat[fieldName] = fieldStat; return fieldStat; } + + ensureCountsAreIntegers() { + for (const fieldStat of Object.values(this.perFieldStat)) { + fieldStat.ensureCountsAreIntegers(); + } + } } class OurFieldStat implements Required { errorsCount: number = 0; - count: number = 0; + observedExecutionCount: number = 0; + // Note that this number isn't necessarily an integer while it is being + // aggregated. Before encoding as a protobuf we call ensureCountsAreIntegers + // which floors it. + estimatedExecutionCount: number = 0; requestsWithErrorsCount: number = 0; latencyCount: DurationHistogram = new DurationHistogram(); constructor(readonly returnType: string) {} + + ensureCountsAreIntegers() { + // This is the only one that ever can receive non-integers. + this.estimatedExecutionCount = Math.floor(this.estimatedExecutionCount); + } } function estimatedBytesForString(s: string) { diff --git a/packages/apollo-server-core/src/requestPipeline.ts b/packages/apollo-server-core/src/requestPipeline.ts index 6b34182c045..51351ef6df4 100644 --- a/packages/apollo-server-core/src/requestPipeline.ts +++ b/packages/apollo-server-core/src/requestPipeline.ts @@ -344,32 +344,44 @@ export async function processGraphQLRequest( const executionDispatcher = new Dispatcher(executionListeners); - // Create a callback that will trigger the execution dispatcher's - // `willResolveField` hook. We will attach this to the context on a - // symbol so it can be invoked by our `wrapField` method during execution. - const invokeWillResolveField: GraphQLRequestExecutionListener['willResolveField'] = - (...args) => - executionDispatcher.invokeSyncDidStartHook('willResolveField', ...args); - - Object.defineProperty( - requestContext.context, - symbolExecutionDispatcherWillResolveField, - { value: invokeWillResolveField }, - ); + if (executionDispatcher.hasHook('willResolveField')) { + // Create a callback that will trigger the execution dispatcher's + // `willResolveField` hook. We will attach this to the context on a + // symbol so it can be invoked by our `wrapField` method during execution. + const invokeWillResolveField: GraphQLRequestExecutionListener['willResolveField'] = + (...args) => + executionDispatcher.invokeSyncDidStartHook( + 'willResolveField', + ...args, + ); - // If the user has provided a custom field resolver, we will attach - // it to the context so we can still invoke it after we've wrapped the - // fields with `wrapField` within `enablePluginsForSchemaResolvers` of - // the `schemaInstrumentation` module. - if (config.fieldResolver) { - Object.defineProperty(requestContext.context, symbolUserFieldResolver, { - value: config.fieldResolver, - }); - } + Object.defineProperty( + requestContext.context, + symbolExecutionDispatcherWillResolveField, + { value: invokeWillResolveField }, + ); + + // If the user has provided a custom field resolver, we will attach + // it to the context so we can still invoke it after we've wrapped the + // fields with `wrapField` within `enablePluginsForSchemaResolvers` of + // the `schemaInstrumentation` module. + if (config.fieldResolver) { + Object.defineProperty(requestContext.context, symbolUserFieldResolver, { + value: config.fieldResolver, + }); + } - // If the schema is already enabled, this is a no-op. Otherwise, the - // schema will be augmented so it is able to invoke willResolveField. - enablePluginsForSchemaResolvers(config.schema); + // If the schema is already enabled, this is a no-op. Otherwise, the + // schema will be augmented so it is able to invoke willResolveField. Note + // that if we never see a plugin with willResolveField then we will never + // need to instrument the schema, which might be a small performance gain. + // (For example, this can happen if you pass `fieldLevelInstrumentation: + // () => false` to the usage reporting plugin and disable the cache + // control plugin. We can consider changing the cache control plugin to + // have a "static cache control only" mode that doesn't use + // willResolveField too if this proves to be helpful in practice.) + enablePluginsForSchemaResolvers(config.schema); + } try { const result = await execute( diff --git a/packages/apollo-server-core/src/utils/dispatcher.ts b/packages/apollo-server-core/src/utils/dispatcher.ts index ba827d25a33..f5fcd069d70 100644 --- a/packages/apollo-server-core/src/utils/dispatcher.ts +++ b/packages/apollo-server-core/src/utils/dispatcher.ts @@ -11,11 +11,10 @@ export class Dispatcher { constructor(protected targets: T[]) {} private callTargets( - targets: T[], methodName: TMethodName, ...args: Args ): ReturnType>[] { - return targets.map((target) => { + return this.targets.map((target) => { const method = target[methodName]; if (typeof method === 'function') { return method.apply(target, args); @@ -23,6 +22,12 @@ export class Dispatcher { }); } + public hasHook(methodName: keyof T): boolean { + return this.targets.some( + (target) => typeof target[methodName] === 'function', + ); + } + public async invokeHook< TMethodName extends keyof T, THookReturn extends StripPromise>>, @@ -30,7 +35,7 @@ export class Dispatcher { methodName: TMethodName, ...args: Args ): Promise { - return Promise.all(this.callTargets(this.targets, methodName, ...args)); + return Promise.all(this.callTargets(methodName, ...args)); } public async invokeHooksUntilNonNull( @@ -60,7 +65,7 @@ export class Dispatcher { ...args: Args ): Promise> { const hookReturnValues: (AsyncDidEndHook | void)[] = - await Promise.all(this.callTargets(this.targets, methodName, ...args)); + await Promise.all(this.callTargets(methodName, ...args)); const didEndHooks = hookReturnValues.filter( (hook): hook is AsyncDidEndHook => !!hook, diff --git a/packages/apollo-server-core/src/utils/pluginTestHarness.ts b/packages/apollo-server-core/src/utils/pluginTestHarness.ts index 8f6ebd03af8..ad14c4f186c 100644 --- a/packages/apollo-server-core/src/utils/pluginTestHarness.ts +++ b/packages/apollo-server-core/src/utils/pluginTestHarness.ts @@ -250,22 +250,24 @@ export default async function pluginTestHarness({ const executionDispatcher = new Dispatcher(executionListeners); - // Create a callback that will trigger the execution dispatcher's - // `willResolveField` hook. We will attach this to the context on a - // symbol so it can be invoked by our `wrapField` method during execution. - const invokeWillResolveField: GraphQLRequestExecutionListener['willResolveField'] = - (...args) => - executionDispatcher.invokeSyncDidStartHook('willResolveField', ...args); - - Object.defineProperty( - requestContext.context, - symbolExecutionDispatcherWillResolveField, - { value: invokeWillResolveField }, - ); + if (executionDispatcher.hasHook('willResolveField')) { + // Create a callback that will trigger the execution dispatcher's + // `willResolveField` hook. We will attach this to the context on a + // symbol so it can be invoked by our `wrapField` method during execution. + const invokeWillResolveField: GraphQLRequestExecutionListener['willResolveField'] = + (...args) => + executionDispatcher.invokeSyncDidStartHook('willResolveField', ...args); + + Object.defineProperty( + requestContext.context, + symbolExecutionDispatcherWillResolveField, + { value: invokeWillResolveField }, + ); - // If the schema is already enabled, this is a no-op. Otherwise, the - // schema will be augmented so it is able to invoke willResolveField. - enablePluginsForSchemaResolvers(schema); + // If the schema is already enabled, this is a no-op. Otherwise, the + // schema will be augmented so it is able to invoke willResolveField. + enablePluginsForSchemaResolvers(schema); + } try { // `response` is readonly, so we'll cast to `any` to assign to it. diff --git a/packages/apollo-server-core/src/utils/schemaInstrumentation.ts b/packages/apollo-server-core/src/utils/schemaInstrumentation.ts index f08753fad14..3b0bfc5014a 100644 --- a/packages/apollo-server-core/src/utils/schemaInstrumentation.ts +++ b/packages/apollo-server-core/src/utils/schemaInstrumentation.ts @@ -15,12 +15,12 @@ export const symbolExecutionDispatcherWillResolveField = Symbol( 'apolloServerExecutionDispatcherWillResolveField', ); export const symbolUserFieldResolver = Symbol('apolloServerUserFieldResolver'); -export const symbolPluginsEnabled = Symbol('apolloServerPluginsEnabled'); +const symbolPluginsEnabled = Symbol('apolloServerPluginsEnabled'); export function enablePluginsForSchemaResolvers( schema: GraphQLSchema & { [symbolPluginsEnabled]?: boolean }, ) { - if (schema[symbolPluginsEnabled]) { + if (pluginsEnabledForSchemaResolvers(schema)) { return schema; } Object.defineProperty(schema, symbolPluginsEnabled, { @@ -32,6 +32,12 @@ export function enablePluginsForSchemaResolvers( return schema; } +export function pluginsEnabledForSchemaResolvers( + schema: GraphQLSchema & { [symbolPluginsEnabled]?: boolean }, +): boolean { + return !!schema[symbolPluginsEnabled]; +} + function wrapField(field: GraphQLField): void { const originalFieldResolve = field.resolve; diff --git a/packages/apollo-server-types/src/index.ts b/packages/apollo-server-types/src/index.ts index f8ed682652b..07aa911bb75 100644 --- a/packages/apollo-server-types/src/index.ts +++ b/packages/apollo-server-types/src/index.ts @@ -116,6 +116,10 @@ export interface GraphQLResponse { } export interface GraphQLRequestMetrics { + // It would be more accurate to call this fieldLevelInstrumentation (it is + // true if the hook of that name returns truthy) but for backwards + // compatibility we keep this name (this field is read by `@apollo/gateway` to + // decide whether or not to send the apollo-federation-include-trace header). captureTraces?: boolean; persistedQueryHit?: boolean; persistedQueryRegister?: boolean;