diff --git a/.vscode/launch.json b/.vscode/launch.json index 088ae3cf90a1a4c..9296ff142e95184 100644 --- a/.vscode/launch.json +++ b/.vscode/launch.json @@ -27,12 +27,12 @@ "outFiles": ["${workspaceFolder}/packages/next/dist/**/*"] }, { - "name": "Launch app build trace", + "name": "Launch app build trace jaeger", "type": "node", "request": "launch", "cwd": "${workspaceFolder}", "runtimeExecutable": "yarn", - "runtimeArgs": ["run", "trace-debug", "build", "test/integration/basic"], + "runtimeArgs": ["run", "clean-trace-jaeger"], "skipFiles": ["/**"], "port": 9229, "outFiles": ["${workspaceFolder}/packages/next/dist/**/*"] diff --git a/package.json b/package.json index 912463d8f1c5398..afac5023037f9b9 100644 --- a/package.json +++ b/package.json @@ -38,6 +38,7 @@ "lint-staged": "lint-staged", "next-with-deps": "./scripts/next-with-deps.sh", "next": "node --trace-deprecation --enable-source-maps packages/next/dist/bin/next", + "clean-trace-jaeger": "rm -rf test/integration/basic/.next && TRACE_TARGET=JAEGER node --trace-deprecation --enable-source-maps packages/next/dist/bin/next build test/integration/basic", "debug": "node --inspect packages/next/dist/bin/next" }, "pre-commit": "lint-staged", diff --git a/packages/next/build/index.ts b/packages/next/build/index.ts index 597edc53a3ebf37..6953e0343c07ae7 100644 --- a/packages/next/build/index.ts +++ b/packages/next/build/index.ts @@ -73,7 +73,7 @@ import { generateBuildId } from './generate-build-id' import { isWriteable } from './is-writeable' import * as Log from './output/log' import createSpinner from './spinner' -import { trace, setGlobal } from '../telemetry/trace' +import { trace, flushAllTraces, setGlobal } from '../telemetry/trace' import { collectPages, detectConflictingPaths, @@ -121,7 +121,7 @@ export default async function build( ): Promise { const nextBuildSpan = trace('next-build') - return nextBuildSpan.traceAsyncFn(async () => { + const buildResult = await nextBuildSpan.traceAsyncFn(async () => { // attempt to load global env values so they are available in next.config.js const { loadedEnvFiles } = nextBuildSpan .traceChild('load-dotenv') @@ -523,7 +523,8 @@ export default async function build( ignore: [] as string[], })) - const configs = await nextBuildSpan + const runWebpackSpan = nextBuildSpan.traceChild('run-webpack-compiler') + const configs = await runWebpackSpan .traceChild('generate-webpack-config') .traceAsyncFn(() => Promise.all([ @@ -536,6 +537,7 @@ export default async function build( pagesDir, entrypoints: entrypoints.client, rewrites, + runWebpackSpan, }), getBaseWebpackConfig(dir, { buildId, @@ -546,6 +548,7 @@ export default async function build( pagesDir, entrypoints: entrypoints.server, rewrites, + runWebpackSpan, }), ]) ) @@ -567,24 +570,22 @@ export default async function build( let result: CompilerResult = { warnings: [], errors: [] } // We run client and server compilation separately to optimize for memory usage - await nextBuildSpan - .traceChild('run-webpack-compiler') - .traceAsyncFn(async () => { - const clientResult = await runCompiler(clientConfig) - // Fail build if clientResult contains errors - if (clientResult.errors.length > 0) { - result = { - warnings: [...clientResult.warnings], - errors: [...clientResult.errors], - } - } else { - const serverResult = await runCompiler(configs[1]) - result = { - warnings: [...clientResult.warnings, ...serverResult.warnings], - errors: [...clientResult.errors, ...serverResult.errors], - } + await runWebpackSpan.traceAsyncFn(async () => { + const clientResult = await runCompiler(clientConfig) + // Fail build if clientResult contains errors + if (clientResult.errors.length > 0) { + result = { + warnings: [...clientResult.warnings], + errors: [...clientResult.errors], } - }) + } else { + const serverResult = await runCompiler(configs[1]) + result = { + warnings: [...clientResult.warnings, ...serverResult.warnings], + errors: [...clientResult.errors, ...serverResult.errors], + } + } + }) const webpackBuildEnd = process.hrtime(webpackBuildStart) if (buildSpinner) { @@ -1669,6 +1670,11 @@ export default async function build( .traceChild('telemetry-flush') .traceAsyncFn(() => telemetry.flush()) }) + + // Ensure all traces are flushed before finishing the command + await flushAllTraces() + + return buildResult } export type ClientSsgManifest = Set diff --git a/packages/next/build/webpack-config.ts b/packages/next/build/webpack-config.ts index 6ca7fe421a2c5ea..9930e79977e32d9 100644 --- a/packages/next/build/webpack-config.ts +++ b/packages/next/build/webpack-config.ts @@ -53,6 +53,7 @@ import WebpackConformancePlugin, { import { WellKnownErrorsPlugin } from './webpack/plugins/wellknown-errors-plugin' import { regexLikeCss } from './webpack/config/blocks/css' import { CopyFilePlugin } from './webpack/plugins/copy-file-plugin' +import type { Span } from '../telemetry/trace' type ExcludesFalse = (x: T | false) => x is T @@ -227,6 +228,7 @@ export default async function getBaseWebpackConfig( entrypoints, rewrites, isDevFallback = false, + runWebpackSpan, }: { buildId: string config: NextConfigComplete @@ -238,6 +240,7 @@ export default async function getBaseWebpackConfig( entrypoints: WebpackEntrypoints rewrites: CustomRoutes['rewrites'] isDevFallback?: boolean + runWebpackSpan?: Span } ): Promise { const hasRewrites = @@ -1297,7 +1300,7 @@ export default async function getBaseWebpackConfig( new BuildStatsPlugin({ distDir, }), - new ProfilingPlugin(), + new ProfilingPlugin({ runWebpackSpan }), config.optimizeFonts && !dev && isServer && diff --git a/packages/next/build/webpack/plugins/profiling-plugin.ts b/packages/next/build/webpack/plugins/profiling-plugin.ts index a091ec83a35153a..812f8732ea06cd6 100644 --- a/packages/next/build/webpack/plugins/profiling-plugin.ts +++ b/packages/next/build/webpack/plugins/profiling-plugin.ts @@ -1,5 +1,5 @@ import { webpack, isWebpack5 } from 'next/dist/compiled/webpack/webpack' -import { trace, stackPush, stackPop, Span } from '../../../telemetry/trace' +import { trace, Span } from '../../../telemetry/trace' const pluginName = 'ProfilingPlugin' export const spans = new WeakMap() @@ -15,7 +15,11 @@ function getNormalModuleLoaderHook(compilation: any) { export class ProfilingPlugin { compiler: any + runWebpackSpan: Span | undefined + constructor({ runWebpackSpan }: { runWebpackSpan: Span | undefined }) { + this.runWebpackSpan = runWebpackSpan + } apply(compiler: any) { this.traceTopLevelHooks(compiler) this.traceCompilationHooks(compiler) @@ -26,12 +30,19 @@ export class ProfilingPlugin { spanName: string, startHook: any, stopHook: any, - attrs?: any, - onSetSpan?: (span: Span) => void + { + parentSpan, + attrs, + onSetSpan, + }: { + parentSpan?: () => Span | undefined + attrs?: any + onSetSpan?: (span: Span) => void + } = {} ) { let span: Span | undefined startHook.tap(pluginName, () => { - span = stackPush(this.compiler, spanName, attrs) + span = trace(spanName, parentSpan?.()?.id, attrs ? attrs() : attrs) onSetSpan?.(span) }) stopHook.tap(pluginName, () => { @@ -41,56 +52,39 @@ export class ProfilingPlugin { if (!span) { return } - stackPop(this.compiler, span) - }) - } - - traceLoopedHook(spanName: string, startHook: any, stopHook: any) { - let span: Span | undefined - startHook.tap(pluginName, () => { - if (!span) { - span = stackPush(this.compiler, spanName) - } - }) - stopHook.tap(pluginName, () => { - stackPop(this.compiler, span) + span.stop() }) } traceTopLevelHooks(compiler: any) { this.traceHookPair( - 'webpack-compile', - compiler.hooks.compile, - compiler.hooks.done, - () => { - return { name: compiler.name } - }, - (span) => spans.set(compiler, span) - ) - this.traceHookPair( - 'webpack-prepare-env', - compiler.hooks.environment, - compiler.hooks.afterEnvironment + 'webpack-compilation', + isWebpack5 ? compiler.hooks.beforeCompile : compiler.hooks.compile, + isWebpack5 ? compiler.hooks.afterCompile : compiler.hooks.done, + { + parentSpan: () => this.runWebpackSpan, + attrs: () => ({ name: compiler.name }), + onSetSpan: (span) => spans.set(compiler, span), + } ) + if (compiler.options.mode === 'development') { this.traceHookPair( 'webpack-invalidated', compiler.hooks.invalid, compiler.hooks.done, - () => ({ name: compiler.name }) + { attrs: () => ({ name: compiler.name }) } ) } } traceCompilationHooks(compiler: any) { - if (isWebpack5) { - this.traceHookPair( - 'webpack-compilation', - compiler.hooks.beforeCompile, - compiler.hooks.afterCompile, - () => ({ name: compiler.name }) - ) - } + this.traceHookPair( + 'webpack-emit', + compiler.hooks.emit, + compiler.hooks.afterEmit, + { parentSpan: () => this.runWebpackSpan } + ) compiler.hooks.compilation.tap(pluginName, (compilation: any) => { compilation.hooks.buildModule.tap(pluginName, (module: any) => { @@ -107,8 +101,8 @@ export class ProfilingPlugin { getNormalModuleLoaderHook(compilation).tap( pluginName, (loaderContext: any, module: any) => { - const parentSpan = spans.get(module) - loaderContext.currentTraceSpan = parentSpan + const moduleSpan = spans.get(module) + loaderContext.currentTraceSpan = moduleSpan } ) @@ -119,32 +113,38 @@ export class ProfilingPlugin { this.traceHookPair( 'webpack-compilation-chunk-graph', compilation.hooks.beforeChunks, - compilation.hooks.afterChunks + compilation.hooks.afterChunks, + { parentSpan: () => this.runWebpackSpan } ) this.traceHookPair( 'webpack-compilation-optimize', compilation.hooks.optimize, - compilation.hooks.reviveModules + compilation.hooks.reviveModules, + { parentSpan: () => this.runWebpackSpan } ) - this.traceLoopedHook( + this.traceHookPair( 'webpack-compilation-optimize-modules', compilation.hooks.optimizeModules, - compilation.hooks.afterOptimizeModules + compilation.hooks.afterOptimizeModules, + { parentSpan: () => this.runWebpackSpan } ) - this.traceLoopedHook( + this.traceHookPair( 'webpack-compilation-optimize-chunks', compilation.hooks.optimizeChunks, - compilation.hooks.afterOptimizeChunks + compilation.hooks.afterOptimizeChunks, + { parentSpan: () => this.runWebpackSpan } ) this.traceHookPair( 'webpack-compilation-optimize-tree', compilation.hooks.optimizeTree, - compilation.hooks.afterOptimizeTree + compilation.hooks.afterOptimizeTree, + { parentSpan: () => this.runWebpackSpan } ) this.traceHookPair( 'webpack-compilation-hash', compilation.hooks.beforeHash, - compilation.hooks.afterHash + compilation.hooks.afterHash, + { parentSpan: () => this.runWebpackSpan } ) }) } diff --git a/packages/next/telemetry/trace/autoparent.ts b/packages/next/telemetry/trace/autoparent.ts deleted file mode 100644 index 16081f4b5e44855..000000000000000 --- a/packages/next/telemetry/trace/autoparent.ts +++ /dev/null @@ -1,72 +0,0 @@ -import { trace, Span } from './trace' -import { debugLog } from './shared' - -const stacks = new WeakMap>() -const stoppedSpansSets = new WeakMap>() - -export function stackPush(keyObj: any, spanName: string, attrs?: any): Span { - let stack = stacks.get(keyObj) - let span - - if (!stack) { - stack = [] - stacks.set(keyObj, stack) - span = trace(spanName, undefined, attrs ? attrs() : undefined) - } else { - const parent = stack[stack.length - 1] - if (parent) { - span = trace(spanName, parent.id, attrs ? attrs() : undefined) - } else { - span = trace(spanName, undefined, attrs ? attrs() : undefined) - } - } - - stack.push(span) - return span -} - -export function stackPop(keyObj: any, span: any): void { - let stack = stacks.get(keyObj) - if (!stack) { - debugLog( - 'Attempted to pop from non-existent stack. Key reference must be bad.' - ) - return - } - - let stoppedSpans = stoppedSpansSets.get(keyObj) - if (!stoppedSpans) { - stoppedSpans = new Set() - stoppedSpansSets.set(keyObj, stoppedSpans) - } - if (stoppedSpans.has(span)) { - debugLog( - `Attempted to terminate tracing span that was already stopped for ${span.name}` - ) - return - } - - while (true) { - let poppedSpan = stack.pop() - - if (poppedSpan && poppedSpan === span) { - stoppedSpans.add(poppedSpan) - span.stop() - stoppedSpans.add(span) - break - } else if (poppedSpan === undefined || stack.indexOf(span) === -1) { - // We've either reached the top of the stack or the stack doesn't contain - // the span for another reason. - debugLog(`Tracing span was not found in stack for: ${span.name}`) - stoppedSpans.add(span) - span.stop() - break - } else if (stack.indexOf(span) !== -1) { - debugLog( - `Attempted to pop span that was not at top of stack for: ${span.name}` - ) - stoppedSpans.add(poppedSpan) - poppedSpan.stop() - } - } -} diff --git a/packages/next/telemetry/trace/index.ts b/packages/next/telemetry/trace/index.ts index 4f03fdcaa5bb138..e242e19c9041f4e 100644 --- a/packages/next/telemetry/trace/index.ts +++ b/packages/next/telemetry/trace/index.ts @@ -1,5 +1,4 @@ -import { trace, Span, SpanStatus } from './trace' +import { trace, flushAllTraces, Span, SpanStatus } from './trace' import { SpanId, setGlobal } from './shared' -import { stackPush, stackPop } from './autoparent' -export { trace, SpanId, Span, SpanStatus, stackPush, stackPop, setGlobal } +export { trace, flushAllTraces, SpanId, Span, SpanStatus, setGlobal } diff --git a/packages/next/telemetry/trace/report/index.ts b/packages/next/telemetry/trace/report/index.ts index 216b0e43002914d..2f77f93b7fcdd9e 100644 --- a/packages/next/telemetry/trace/report/index.ts +++ b/packages/next/telemetry/trace/report/index.ts @@ -4,14 +4,17 @@ import reportToZipkin from './to-zipkin' import reportToJaeger from './to-jaeger' import reportToTelemetry from './to-telemetry' -type Reporter = ( - spanName: string, - duration: number, - timestamp: number, - id: SpanId, - parentId?: SpanId, - attrs?: Object -) => void +type Reporter = { + flushAll: () => Promise | void + report: ( + spanName: string, + duration: number, + timestamp: number, + id: SpanId, + parentId?: SpanId, + attrs?: Object + ) => void +} const target = process.env.TRACE_TARGET && process.env.TRACE_TARGET in TARGET @@ -24,13 +27,14 @@ if (process.env.TRACE_TARGET && !target) { ) } -export let report: Reporter +export let reporter: Reporter + if (target === TARGET.CONSOLE) { - report = reportToConsole + reporter = reportToConsole } else if (target === TARGET.ZIPKIN) { - report = reportToZipkin + reporter = reportToZipkin } else if (target === TARGET.JAEGER) { - report = reportToJaeger + reporter = reportToJaeger } else { - report = reportToTelemetry + reporter = reportToTelemetry } diff --git a/packages/next/telemetry/trace/report/to-console.ts b/packages/next/telemetry/trace/report/to-console.ts index 1f53bfd53acf201..bc40b6c33ab278c 100644 --- a/packages/next/telemetry/trace/report/to-console.ts +++ b/packages/next/telemetry/trace/report/to-console.ts @@ -23,4 +23,7 @@ const reportToConsole = ( console.log(`[trace] ${spanName} took ${duration} μs${parentStr}${attrsStr}`) } -export default reportToConsole +export default { + flushAll: () => {}, + report: reportToConsole, +} diff --git a/packages/next/telemetry/trace/report/to-jaeger.ts b/packages/next/telemetry/trace/report/to-jaeger.ts index 7d94ebff3104ad2..809c80b13cd1423 100644 --- a/packages/next/telemetry/trace/report/to-jaeger.ts +++ b/packages/next/telemetry/trace/report/to-jaeger.ts @@ -2,6 +2,8 @@ import retry from 'next/dist/compiled/async-retry' import { randomBytes } from 'crypto' import fetch from 'node-fetch' import * as Log from '../../../build/output/log' +// Jaeger uses Zipkin's reporting +import { batcher } from './to-zipkin' let traceId = process.env.TRACE_ID let batch: ReturnType | undefined @@ -16,32 +18,10 @@ const zipkinUrl = `http://${localEndpoint.ipv4}:${localEndpoint.port}` const jaegerWebUiUrl = `http://${localEndpoint.ipv4}:16686` const zipkinAPI = `${zipkinUrl}/api/v2/spans` -type Event = { - traceId: string - parentId?: string - name: string - id: string - timestamp: number - duration: number - localEndpoint: typeof localEndpoint - tags?: Object -} - -// Batch events as zipkin allows for multiple events to be sent in one go -function batcher(reportEvents: (evts: Event[]) => void) { - const events: Event[] = [] - let timeout: ReturnType | undefined - return (event: Event) => { - events.push(event) - // setTimeout is used instead of setInterval to ensure events sending does not block exiting the program - if (!timeout) { - timeout = setTimeout(() => { - reportEvents(events.slice()) - events.length = 0 - timeout = undefined - }, 1500) - } - } +function logWebUrl() { + Log.info( + `Jaeger trace will be available on ${jaegerWebUiUrl}/trace/${traceId}` + ) } const reportToLocalHost = ( @@ -54,28 +34,37 @@ const reportToLocalHost = ( ) => { if (!traceId) { traceId = process.env.TRACE_ID = randomBytes(8).toString('hex') - Log.info( - `Jaeger trace will be available on ${jaegerWebUiUrl}/trace/${traceId}` - ) + logWebUrl() } if (!batch) { batch = batcher((events) => { + const eventsJson = JSON.stringify(events) // Ensure ECONNRESET error is retried 3 times before erroring out - retry( + return retry( () => // Send events to zipkin fetch(zipkinAPI, { method: 'POST', headers: { 'Content-Type': 'application/json' }, - body: JSON.stringify(events), + body: eventsJson, }), { minTimeout: 500, retries: 3, factor: 1 } - ).catch(console.log) + ) + .then(async (res: any) => { + if (res.status !== 202) { + console.log({ + status: res.status, + body: await res.text(), + events: eventsJson, + }) + } + }) + .catch(console.log) }) } - batch({ + batch.report({ traceId, parentId, name, @@ -87,4 +76,8 @@ const reportToLocalHost = ( }) } -export default reportToLocalHost +export default { + flushAll: () => + batch ? batch.flushAll().then(() => logWebUrl()) : undefined, + report: reportToLocalHost, +} diff --git a/packages/next/telemetry/trace/report/to-telemetry.ts b/packages/next/telemetry/trace/report/to-telemetry.ts index 8486c1354057fda..a308fc758baddb1 100644 --- a/packages/next/telemetry/trace/report/to-telemetry.ts +++ b/packages/next/telemetry/trace/report/to-telemetry.ts @@ -24,4 +24,7 @@ const reportToTelemetry = (spanName: string, duration: number) => { }) } -export default reportToTelemetry +export default { + flushAll: () => {}, + report: reportToTelemetry, +} diff --git a/packages/next/telemetry/trace/report/to-zipkin.ts b/packages/next/telemetry/trace/report/to-zipkin.ts index f438677fbdfaa6e..b34edec3eb6f3be 100644 --- a/packages/next/telemetry/trace/report/to-zipkin.ts +++ b/packages/next/telemetry/trace/report/to-zipkin.ts @@ -26,19 +26,28 @@ type Event = { } // Batch events as zipkin allows for multiple events to be sent in one go -function batcher(reportEvents: (evts: Event[]) => void) { +export function batcher(reportEvents: (evts: Event[]) => Promise) { const events: Event[] = [] - let timeout: ReturnType | undefined - return (event: Event) => { - events.push(event) - // setTimeout is used instead of setInterval to ensure events sending does not block exiting the program - if (!timeout) { - timeout = setTimeout(() => { - reportEvents(events.slice()) + // Promise queue to ensure events are always sent on flushAll + const queue = new Set() + return { + flushAll: async () => { + await Promise.all(queue) + if (events.length > 0) { + await reportEvents(events) events.length = 0 - timeout = undefined - }, 1500) - } + } + }, + report: (event: Event) => { + events.push(event) + + if (events.length > 100) { + const report = reportEvents(events.slice()) + events.length = 0 + queue.add(report) + report.then(() => queue.delete(report)) + } + }, } } @@ -60,7 +69,7 @@ const reportToLocalHost = ( if (!batch) { batch = batcher((events) => { // Ensure ECONNRESET error is retried 3 times before erroring out - retry( + return retry( () => // Send events to zipkin fetch(zipkinAPI, { @@ -73,7 +82,7 @@ const reportToLocalHost = ( }) } - batch({ + batch.report({ traceId, parentId, name, @@ -85,4 +94,7 @@ const reportToLocalHost = ( }) } -export default reportToLocalHost +export default { + flushAll: () => (batch ? batch.flushAll() : undefined), + report: reportToLocalHost, +} diff --git a/packages/next/telemetry/trace/trace.ts b/packages/next/telemetry/trace/trace.ts index 5874dda8ea9352f..19d16d85b0b3578 100644 --- a/packages/next/telemetry/trace/trace.ts +++ b/packages/next/telemetry/trace/trace.ts @@ -1,6 +1,6 @@ import { randomBytes } from 'crypto' import { SpanId } from './shared' -import { report } from './report' +import { reporter } from './report' const NUM_OF_MICROSEC_IN_SEC = BigInt('1000') @@ -45,7 +45,7 @@ export class Span { throw new Error(`Duration is too long to express as float64: ${duration}`) } const timestamp = this._start / NUM_OF_MICROSEC_IN_SEC - report( + reporter.report( this.name, Number(duration), Number(timestamp), @@ -60,7 +60,7 @@ export class Span { } setAttribute(key: string, value: any) { - this.attrs[key] = value + this.attrs[key] = String(value) } traceFn(fn: any) { @@ -83,3 +83,5 @@ export class Span { export const trace = (name: string, parentId?: SpanId, attrs?: Object) => { return new Span(name, parentId, attrs) } + +export const flushAllTraces = () => reporter.flushAll()