diff --git a/lib/src/main/java/graphql/nadel/engine/instrumentation/NadelInstrumentationTimer.kt b/lib/src/main/java/graphql/nadel/engine/instrumentation/NadelInstrumentationTimer.kt index 952488079..7c714aa91 100644 --- a/lib/src/main/java/graphql/nadel/engine/instrumentation/NadelInstrumentationTimer.kt +++ b/lib/src/main/java/graphql/nadel/engine/instrumentation/NadelInstrumentationTimer.kt @@ -19,6 +19,10 @@ internal class NadelInstrumentationTimer( step: Step, function: () -> T, ): T { + if (!instrumentation.isTimingEnabled()) { + return function() + } + val start = ticker() val result = try { @@ -89,6 +93,10 @@ internal class NadelInstrumentationTimer( private var exception: Throwable? = null inline fun time(step: Step, function: () -> T): T { + if (!instrumentation.isTimingEnabled()) { + return function() + } + timings.computeIfAbsent(step) { AtomicReference(Duration.ZERO) } diff --git a/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlan.kt b/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlan.kt index d2918087f..cea265029 100644 --- a/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlan.kt +++ b/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlan.kt @@ -2,6 +2,7 @@ package graphql.nadel.engine.plan import graphql.nadel.Service import graphql.nadel.engine.transform.NadelTransform +import graphql.nadel.instrumentation.parameters.NadelInstrumentationTimingParameters import graphql.normalized.ExecutableNormalizedField internal typealias AnyNadelExecutionPlanStep = NadelExecutionPlan.Step @@ -14,6 +15,8 @@ data class NadelExecutionPlan( val service: Service, val field: ExecutableNormalizedField, val transform: NadelTransform, + val queryTransformTimingStep: NadelInstrumentationTimingParameters.Step, + val resultTransformTimingStep: NadelInstrumentationTimingParameters.Step, val state: T, ) diff --git a/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlanFactory.kt b/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlanFactory.kt index 5608c3e0c..4787383e9 100644 --- a/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlanFactory.kt +++ b/lib/src/main/java/graphql/nadel/engine/plan/NadelExecutionPlanFactory.kt @@ -20,16 +20,32 @@ import graphql.nadel.engine.transform.skipInclude.NadelSkipIncludeTransform.Comp import graphql.nadel.hooks.NadelExecutionHooks import graphql.nadel.instrumentation.parameters.NadelInstrumentationTimingParameters.ChildStep import graphql.nadel.instrumentation.parameters.NadelInstrumentationTimingParameters.RootStep.ExecutionPlanning +import graphql.nadel.instrumentation.parameters.NadelInstrumentationTimingParameters.RootStep.QueryTransforming +import graphql.nadel.instrumentation.parameters.NadelInstrumentationTimingParameters.RootStep.ResultTransforming import graphql.normalized.ExecutableNormalizedField internal class NadelExecutionPlanFactory( private val executionBlueprint: NadelOverallExecutionBlueprint, - private val transforms: List>, + transforms: List>, ) { - // This will avoid creating the ChildStep object too many times + /** + * This creates the [ChildStep] objects upfront to avoid constantly recreating them. + */ + private data class TransformWithTimingInfo( + val transform: NadelTransform, + val executionPlanTimingStep: ChildStep, + val queryTransformTimingStep: ChildStep, + val resultTransformTimingStep: ChildStep, + ) + private val transformsWithTimingStepInfo = transforms .map { transform -> - transform to ChildStep(parent = ExecutionPlanning, transform = transform) + TransformWithTimingInfo( + transform = transform, + executionPlanTimingStep = ChildStep(parent = ExecutionPlanning, transform = transform), + queryTransformTimingStep = ChildStep(parent = QueryTransforming, transform = transform), + resultTransformTimingStep = ChildStep(parent = ResultTransforming, transform = transform), + ) } /** @@ -48,7 +64,8 @@ internal class NadelExecutionPlanFactory( executionContext.timer.batch { timer -> traverseQuery(rootField) { field -> - transformsWithTimingStepInfo.forEach { (transform, timingStep) -> + transformsWithTimingStepInfo.forEach { transformWithTimingInfo -> + val transform = transformWithTimingInfo.transform // This is a patch to prevent errors // Ideally this should not happen but the proper fix requires more refactoring // See NadelSkipIncludeTransform.isApplicable for more details @@ -56,7 +73,7 @@ internal class NadelExecutionPlanFactory( return@forEach } - val state = timer.time(step = timingStep) { + val state = timer.time(step = transformWithTimingInfo.executionPlanTimingStep) { transform.isApplicable( executionContext, serviceExecutionContext, @@ -71,10 +88,12 @@ internal class NadelExecutionPlanFactory( if (state != null) { executionSteps.add( NadelExecutionPlan.Step( - service, - field, - transform, - state, + service = service, + field = field, + transform = transform, + queryTransformTimingStep = transformWithTimingInfo.queryTransformTimingStep, + resultTransformTimingStep = transformWithTimingInfo.resultTransformTimingStep, + state = state, ), ) } diff --git a/lib/src/main/java/graphql/nadel/engine/transform/query/NadelQueryTransformer.kt b/lib/src/main/java/graphql/nadel/engine/transform/query/NadelQueryTransformer.kt index 32b714c9e..1abeeba51 100644 --- a/lib/src/main/java/graphql/nadel/engine/transform/query/NadelQueryTransformer.kt +++ b/lib/src/main/java/graphql/nadel/engine/transform/query/NadelQueryTransformer.kt @@ -4,6 +4,7 @@ import graphql.nadel.Service import graphql.nadel.engine.NadelExecutionContext import graphql.nadel.engine.NadelServiceExecutionContext import graphql.nadel.engine.blueprint.NadelOverallExecutionBlueprint +import graphql.nadel.engine.instrumentation.NadelInstrumentationTimer import graphql.nadel.engine.plan.NadelExecutionPlan import graphql.nadel.engine.transform.NadelTransform import graphql.nadel.engine.transform.NadelTransformFieldResult @@ -17,6 +18,7 @@ class NadelQueryTransformer private constructor( private val serviceExecutionContext: NadelServiceExecutionContext, private val executionPlan: NadelExecutionPlan, private val transformContext: TransformContext, + private val timer: NadelInstrumentationTimer.BatchTimer, ) { companion object { suspend fun transformQuery( @@ -29,24 +31,27 @@ class NadelQueryTransformer private constructor( ): TransformResult { val transformContext = TransformContext() - val transformer = NadelQueryTransformer( - executionBlueprint, - service, - executionContext, - serviceExecutionContext, - executionPlan, - transformContext, - ) - val result = transformer.transform(field) - .also { rootFields -> - transformer.fixParentRefs(parent = null, rootFields) - } - - return TransformResult( - result = result, - artificialFields = transformContext.artificialFields, - overallToUnderlyingFields = transformContext.overallToUnderlyingFields, - ) + executionContext.timer.batch().use { timer -> + val transformer = NadelQueryTransformer( + executionBlueprint, + service, + executionContext, + serviceExecutionContext, + executionPlan, + transformContext, + timer, + ) + val result = transformer.transform(field) + .also { rootFields -> + transformer.fixParentRefs(parent = null, rootFields) + } + + return TransformResult( + result = result, + artificialFields = transformContext.artificialFields, + overallToUnderlyingFields = transformContext.overallToUnderlyingFields, + ) + } } } @@ -149,22 +154,24 @@ class NadelQueryTransformer private constructor( ): NadelTransformFieldResult { var fieldFromPreviousTransform: ExecutableNormalizedField = field var aggregatedTransformResult: NadelTransformFieldResult? = null - for ((_, _, transform, state) in transformationSteps) { - val transformResultForStep = transform.transformField( - executionContext, - serviceExecutionContext, - this, - executionBlueprint, - service, - fieldFromPreviousTransform, - state, - ) + for (transformStep in transformationSteps) { + val transformResultForStep = timer.time(transformStep.queryTransformTimingStep) { + transformStep.transform.transformField( + executionContext, + serviceExecutionContext, + this, + executionBlueprint, + service, + fieldFromPreviousTransform, + transformStep.state, + ) + } aggregatedTransformResult = if (aggregatedTransformResult == null) { transformResultForStep } else { NadelTransformFieldResult( - transformResultForStep.newField, - aggregatedTransformResult.artificialFields + transformResultForStep.artificialFields, + newField = transformResultForStep.newField, + artificialFields = aggregatedTransformResult.artificialFields + transformResultForStep.artificialFields, ) } fieldFromPreviousTransform = transformResultForStep.newField ?: break diff --git a/lib/src/main/java/graphql/nadel/engine/transform/result/NadelResultTransformer.kt b/lib/src/main/java/graphql/nadel/engine/transform/result/NadelResultTransformer.kt index 2500067c4..a4d21965a 100644 --- a/lib/src/main/java/graphql/nadel/engine/transform/result/NadelResultTransformer.kt +++ b/lib/src/main/java/graphql/nadel/engine/transform/result/NadelResultTransformer.kt @@ -2,7 +2,6 @@ package graphql.nadel.engine.transform.result import graphql.GraphQLError import graphql.incremental.DeferPayload -import graphql.nadel.NadelIncrementalServiceExecutionResult import graphql.nadel.Service import graphql.nadel.ServiceExecutionResult import graphql.nadel.engine.NadelExecutionContext @@ -28,7 +27,7 @@ internal class NadelResultTransformer(private val executionBlueprint: NadelOvera artificialFields: List, overallToUnderlyingFields: Map>, service: Service, - result: ServiceExecutionResult + result: ServiceExecutionResult, ): ServiceExecutionResult { val nodes = JsonNodes(result.data) val instructions = getMutationInstructions( @@ -53,7 +52,7 @@ internal class NadelResultTransformer(private val executionBlueprint: NadelOvera overallToUnderlyingFields: Map>, service: Service, result: ServiceExecutionResult, - deferPayload: DeferPayload + deferPayload: DeferPayload, ): DeferPayload { val nodes = JsonNodes( deferPayload.getData() ?: emptyMap(), @@ -81,31 +80,35 @@ internal class NadelResultTransformer(private val executionBlueprint: NadelOvera overallToUnderlyingFields: Map>, service: Service, result: ServiceExecutionResult, - nodes: JsonNodes + nodes: JsonNodes, ): List { val asyncInstructions = ArrayList>>() coroutineScope { - for ((field, steps) in executionPlan.transformationSteps) { - val underlyingFields = overallToUnderlyingFields[field] - if (underlyingFields.isNullOrEmpty()) continue - - for (step in steps) { - asyncInstructions.add( - async { - step.transform.getResultInstructions( - executionContext, - serviceExecutionContext, - executionBlueprint, - service, - field, - underlyingFields.first().parent, - result, - step.state, - nodes + executionContext.timer.batch { timer -> + for ((field, steps) in executionPlan.transformationSteps) { + val underlyingFields = overallToUnderlyingFields[field] + if (underlyingFields.isNullOrEmpty()) continue + + for (step in steps) { + timer.time(step.resultTransformTimingStep) { + asyncInstructions.add( + async { + step.transform.getResultInstructions( + executionContext, + serviceExecutionContext, + executionBlueprint, + service, + field, + underlyingFields.first().parent, + result, + step.state, + nodes + ) + } ) } - ) + } } } @@ -119,7 +122,6 @@ internal class NadelResultTransformer(private val executionBlueprint: NadelOvera return asyncInstructions.awaitAll().flatten() } - private fun mutate(result: ServiceExecutionResult, instructions: List) { instructions.forEach { transformation -> when (transformation) { diff --git a/lib/src/main/java/graphql/nadel/instrumentation/ChainedNadelInstrumentation.kt b/lib/src/main/java/graphql/nadel/instrumentation/ChainedNadelInstrumentation.kt index 14f5ab79a..9da2420ad 100644 --- a/lib/src/main/java/graphql/nadel/instrumentation/ChainedNadelInstrumentation.kt +++ b/lib/src/main/java/graphql/nadel/instrumentation/ChainedNadelInstrumentation.kt @@ -28,6 +28,12 @@ class ChainedNadelInstrumentation( ) : NadelInstrumentation { constructor(vararg instrumentations: NadelInstrumentation) : this(instrumentations.toList()) + override fun isTimingEnabled(): Boolean { + return instrumentations.any { + it.isTimingEnabled() + } + } + fun getInstrumentations(): List { return Collections.unmodifiableList(instrumentations) } diff --git a/lib/src/main/java/graphql/nadel/instrumentation/NadelInstrumentation.kt b/lib/src/main/java/graphql/nadel/instrumentation/NadelInstrumentation.kt index 5aa058ef5..9042956b2 100644 --- a/lib/src/main/java/graphql/nadel/instrumentation/NadelInstrumentation.kt +++ b/lib/src/main/java/graphql/nadel/instrumentation/NadelInstrumentation.kt @@ -28,6 +28,10 @@ import java.util.concurrent.CompletableFuture * operations such as fetching data and resolving it into objects. */ interface NadelInstrumentation { + fun isTimingEnabled(): Boolean { + return false + } + /** * This will be called just before execution to create an object that is given back to all instrumentation methods * to allow them to have per execution request state diff --git a/lib/src/test/kotlin/graphql/nadel/engine/instrumentation/NadelInstrumentationTimerTest.kt b/lib/src/test/kotlin/graphql/nadel/engine/instrumentation/NadelInstrumentationTimerTest.kt index c117f991c..c026d3cf2 100644 --- a/lib/src/test/kotlin/graphql/nadel/engine/instrumentation/NadelInstrumentationTimerTest.kt +++ b/lib/src/test/kotlin/graphql/nadel/engine/instrumentation/NadelInstrumentationTimerTest.kt @@ -20,6 +20,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ var instrumentationParams: NadelInstrumentationTimingParameters? = null val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { assert(instrumentationParams == null) // Ensure only invoked once instrumentationParams = parameters @@ -50,6 +54,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ var instrumentationParams: NadelInstrumentationTimingParameters? = null val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { assert(instrumentationParams == null) // Ensure only invoked once } @@ -77,6 +85,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ var instrumentationParams: NadelInstrumentationTimingParameters? = null val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { assert(instrumentationParams == null) // Ensure only invoked once instrumentationParams = parameters @@ -114,6 +126,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ var instrumentationParams: NadelInstrumentationTimingParameters? = null val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { assert(instrumentationParams == null) // Ensure only invoked once instrumentationParams = parameters @@ -157,6 +173,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ var instrumentationParams: NadelInstrumentationTimingParameters? = null val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { assert(instrumentationParams == null) // Ensure only invoked once instrumentationParams = parameters @@ -192,6 +212,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ var instrumentationParams: NadelInstrumentationTimingParameters? = null val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { assert(instrumentationParams == null) // Ensure only invoked once instrumentationParams = parameters @@ -230,6 +254,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ val instrumentationParams = mutableListOf() val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { instrumentationParams.add(parameters) } @@ -266,6 +294,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ val instrumentationParams = mutableListOf() val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { instrumentationParams.add(parameters) } @@ -308,6 +340,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ val instrumentationParams = mutableListOf() val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { instrumentationParams.add(parameters) } @@ -344,6 +380,10 @@ class NadelInstrumentationTimerTest : DescribeSpec({ val instrumentationParams = mutableListOf() val instrumentation = object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { instrumentationParams.add(parameters) } diff --git a/lib/src/test/kotlin/graphql/nadel/time/NadelInternalLatencyTrackerImplTest.kt b/lib/src/test/kotlin/graphql/nadel/time/NadelInternalLatencyTrackerImplTest.kt index c560cd8ba..e591396c2 100644 --- a/lib/src/test/kotlin/graphql/nadel/time/NadelInternalLatencyTrackerImplTest.kt +++ b/lib/src/test/kotlin/graphql/nadel/time/NadelInternalLatencyTrackerImplTest.kt @@ -17,16 +17,18 @@ class NadelInternalLatencyTrackerImplTest { @Test fun `stops time as code is running`() { val tracker = NadelInternalLatencyTrackerImpl(internalLatency) - val stopTestCountdownLatch = CountDownLatch(1) - val stopThreadCountdownLatch = CountDownLatch(1) + // Used to tell the test that the external work has started running + val externalWorkRunning = CountDownLatch(1) + // Used to stop the external work from completing until the test says so + val stopExternalWork = CountDownLatch(1) every { internalLatency.start() } returns Unit every { internalLatency.stop() } returns Unit val thread = Thread { tracker.onExternalRun { - stopTestCountdownLatch.countDown() - stopThreadCountdownLatch.await() + externalWorkRunning.countDown() + stopExternalWork.await() } } @@ -34,14 +36,14 @@ class NadelInternalLatencyTrackerImplTest { thread.start() // Then - stopTestCountdownLatch.await() + externalWorkRunning.await() verify(exactly = 1) { internalLatency.stop() } confirmVerified(internalLatency) // When - stopThreadCountdownLatch.countDown() + stopExternalWork.countDown() thread.join() // Then @@ -54,7 +56,9 @@ class NadelInternalLatencyTrackerImplTest { @Test fun `stops time as supplier is running`() { val tracker = NadelInternalLatencyTrackerImpl(internalLatency) + // Used to pause the test until the thread runs val stopTestCountdownLatch = CountDownLatch(1) + // Used to stop the thread until the test says so val stopThreadCountdownLatch = CountDownLatch(1) every { internalLatency.start() } returns Unit @@ -159,7 +163,9 @@ class NadelInternalLatencyTrackerImplTest { @Test fun `stops time as supplied future is running`() { val tracker = NadelInternalLatencyTrackerImpl(internalLatency) + // This is used to pause the supplier until it is counted down val stopSupplierCountdownLatch = CountDownLatch(1) + // This is used to pause the test until the thread runs val stopTestCountdownLatch = CountDownLatch(1) every { internalLatency.start() } returns Unit @@ -207,8 +213,10 @@ class NadelInternalLatencyTrackerImplTest { @Test fun `keeps internal latency paused if there are still external calls pending`() { val tracker = NadelInternalLatencyTrackerImpl(internalLatency) + // These are counted down when the thread actually starts val thread1RunningCountdownLatch = CountDownLatch(1) val thread2RunningCountdownLatch = CountDownLatch(1) + // These are invoked to finish the threads val finishThread1CountdownLatch = CountDownLatch(1) val finishThread2CountdownLatch = CountDownLatch(1) diff --git a/test/src/test/kotlin/graphql/nadel/tests/hooks/monitor-emits-timings.kt b/test/src/test/kotlin/graphql/nadel/tests/hooks/monitor-emits-timings.kt index a6e0ae8d6..7de172ca8 100644 --- a/test/src/test/kotlin/graphql/nadel/tests/hooks/monitor-emits-timings.kt +++ b/test/src/test/kotlin/graphql/nadel/tests/hooks/monitor-emits-timings.kt @@ -26,7 +26,6 @@ import graphql.nadel.instrumentation.parameters.NadelInstrumentationTimingParame import graphql.nadel.tests.EngineTestHook import graphql.nadel.tests.UseHook import graphql.nadel.tests.util.NadelTransformAdapter -import graphql.nadel.time.NadelInternalLatencyTracker import graphql.nadel.time.NadelInternalLatencyTrackerImpl import graphql.nadel.time.NadelStopwatch import graphql.normalized.ExecutableNormalizedField @@ -135,6 +134,10 @@ class `monitor-emits-timings` : EngineTestHook { override fun makeNadel(builder: Nadel.Builder): Nadel.Builder { return builder.instrumentation( object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } + override fun onStepTimed(parameters: NadelInstrumentationTimingParameters) { println(parameters) diff --git a/test/src/test/kotlin/graphql/nadel/tests/next/NadelIntegrationTest.kt b/test/src/test/kotlin/graphql/nadel/tests/next/NadelIntegrationTest.kt index 84f246578..936091f2d 100644 --- a/test/src/test/kotlin/graphql/nadel/tests/next/NadelIntegrationTest.kt +++ b/test/src/test/kotlin/graphql/nadel/tests/next/NadelIntegrationTest.kt @@ -272,6 +272,9 @@ abstract class NadelIntegrationTest( open fun makeInstrumentation(): NadelInstrumentation { return object : NadelInstrumentation { + override fun isTimingEnabled(): Boolean { + return true + } } }