From f6ee6a98946f076c6f3a04502bf86472c03712c9 Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Tue, 11 May 2021 09:13:35 -0300 Subject: [PATCH 1/9] fixed disabled logging performance hit --- .../grpc/clients/TraceReportClient.ts | 2 +- src/logging/index.ts | 33 ++++++++++++++----- src/trace/context/SpanContext.ts | 6 ++-- 3 files changed, 28 insertions(+), 13 deletions(-) diff --git a/src/agent/protocol/grpc/clients/TraceReportClient.ts b/src/agent/protocol/grpc/clients/TraceReportClient.ts index 79b19bc..8b2880d 100755 --- a/src/agent/protocol/grpc/clients/TraceReportClient.ts +++ b/src/agent/protocol/grpc/clients/TraceReportClient.ts @@ -70,7 +70,7 @@ export default class TraceReportClient implements Client { while (this.buffer.length > 0) { const segment = this.buffer.take(); if (segment) { - if (logger.isDebugEnabled()) { + if (logger._isDebugEnabled) { logger.debug('Sending segment ', { segment }); } diff --git a/src/logging/index.ts b/src/logging/index.ts index f689a7a..52d8e95 100644 --- a/src/logging/index.ts +++ b/src/logging/index.ts @@ -21,12 +21,12 @@ import * as winston from 'winston'; import { Logger } from 'winston'; type LoggerLevelAware = Logger & { - isDebugEnabled(): boolean; - isInfoEnabled(): boolean; + _isDebugEnabled: boolean; + _isInfoEnabled: boolean; }; export function createLogger(name: string): LoggerLevelAware { - const loggingLevel = process.env.SW_AGENT_LOGGING_LEVEL || (process.env.NODE_ENV !== 'production' ? 'debug' : 'info'); + const loggingLevel = (process.env.SW_AGENT_LOGGING_LEVEL || 'error').toLowerCase(); const logger = winston.createLogger({ level: loggingLevel, @@ -35,6 +35,7 @@ export function createLogger(name: string): LoggerLevelAware { file: name, }, }); + if (process.env.NODE_ENV !== 'production' || process.env.SW_LOGGING_TARGET === 'console') { logger.add( new winston.transports.Console({ @@ -49,11 +50,25 @@ export function createLogger(name: string): LoggerLevelAware { ); } - const isDebugEnabled = (): boolean => logger.levels[logger.level] >= logger.levels.debug; - const isInfoEnabled = (): boolean => logger.levels[logger.level] >= logger.levels.info; + const loggerLevel = logger.levels[logger.level]; + const _isDebugEnabled = loggerLevel >= logger.levels.debug; + const _isInfoEnabled = loggerLevel >= logger.levels.info; + + Object.assign(logger, { + _isDebugEnabled, + _isInfoEnabled, + }); + + const nop = (): void => {}; + + if (loggerLevel < logger.levels.debug) // we do this because logger still seems to stringify anything sent to it even if it is below the logging level, costing performance + (logger as any).debug = nop; + + if (loggerLevel < logger.levels.info) + (logger as any).info = nop; + + if (loggerLevel < logger.levels.warn) + (logger as any).warn = nop; - return Object.assign(logger, { - isDebugEnabled, - isInfoEnabled, - } as LoggerLevelAware); + return logger as LoggerLevelAware; } diff --git a/src/trace/context/SpanContext.ts b/src/trace/context/SpanContext.ts index 2436bd0..9519be3 100644 --- a/src/trace/context/SpanContext.ts +++ b/src/trace/context/SpanContext.ts @@ -67,7 +67,7 @@ export default class SpanContext implements Context { const spans = ContextManager.spansDup(); const parent = spans[spans.length - 1]; - if (logger.isDebugEnabled()) { + if (logger._isDebugEnabled) { logger.debug('Creating entry span', { spans, parent, @@ -103,7 +103,7 @@ export default class SpanContext implements Context { const spans = ContextManager.spansDup(); const parent = spans[spans.length - 1]; - if (logger.isDebugEnabled()) { + if (logger._isDebugEnabled) { logger.debug('Creating exit span', { operation, parent, @@ -139,7 +139,7 @@ export default class SpanContext implements Context { ContextManager.spansDup(); - if (logger.isDebugEnabled()) { + if (logger._isDebugEnabled) { logger.debug('Creating local span', { parentId: this.parentId, executionAsyncId: executionAsyncId(), From dd856c46e2d78b9114c591c73630b7d1267694a0 Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Tue, 11 May 2021 09:17:14 -0300 Subject: [PATCH 2/9] fix find top module if running in framework --- src/core/PluginInstaller.ts | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/core/PluginInstaller.ts b/src/core/PluginInstaller.ts index 07f3e57..10d4bc6 100644 --- a/src/core/PluginInstaller.ts +++ b/src/core/PluginInstaller.ts @@ -28,7 +28,12 @@ const logger = createLogger(__filename); let topModule = module; while (topModule.parent) { + const filename = topModule.filename; + topModule = topModule.parent; + + if (filename.endsWith('/skywalking-nodejs/lib/index.js')) // stop at the appropriate level in case app is being run by some other framework + break; } export default class PluginInstaller { @@ -88,7 +93,7 @@ export default class PluginInstaller { const pluginFile = path.join(this.pluginDir, file); try { - plugin = require(pluginFile).default as SwPlugin; + plugin = this.require(pluginFile).default as SwPlugin; const { isSupported, version } = this.checkModuleVersion(plugin); if (!isSupported) { From ee165c6497ee86eb4c5f2af042d1aa09813a42fa Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Tue, 11 May 2021 09:21:09 -0300 Subject: [PATCH 3/9] peer removed from Context.newExitSpan() --- src/logging/index.ts | 2 +- src/plugins/AMQPLibPlugin.ts | 2 +- src/plugins/AxiosPlugin.ts | 2 +- src/plugins/HttpPlugin.ts | 2 +- src/plugins/MongoDBPlugin.ts | 2 +- src/plugins/MongoosePlugin.ts | 2 +- src/plugins/MySQLPlugin.ts | 2 +- src/plugins/PgPlugin.ts | 2 +- src/trace/context/Context.ts | 2 +- src/trace/context/DummyContext.ts | 2 +- src/trace/context/SpanContext.ts | 4 +--- 11 files changed, 11 insertions(+), 13 deletions(-) diff --git a/src/logging/index.ts b/src/logging/index.ts index 52d8e95..68c0302 100644 --- a/src/logging/index.ts +++ b/src/logging/index.ts @@ -59,7 +59,7 @@ export function createLogger(name: string): LoggerLevelAware { _isInfoEnabled, }); - const nop = (): void => {}; + const nop = (): void => { /* a cookie for the linter */ }; if (loggerLevel < logger.levels.debug) // we do this because logger still seems to stringify anything sent to it even if it is below the logging level, costing performance (logger as any).debug = nop; diff --git a/src/plugins/AMQPLibPlugin.ts b/src/plugins/AMQPLibPlugin.ts index 079b0bc..fe91742 100644 --- a/src/plugins/AMQPLibPlugin.ts +++ b/src/plugins/AMQPLibPlugin.ts @@ -43,7 +43,7 @@ class AMQPLibPlugin implements SwPlugin { const topic = fields.exchange || ''; const queue = fields.routingKey || ''; const peer = `${this.connection.stream.remoteAddress}:${this.connection.stream.remotePort}`; - const span = ContextManager.current.newExitSpan('RabbitMQ/' + topic + '/' + queue + '/Producer', peer, Component.RABBITMQ_PRODUCER); + const span = ContextManager.current.newExitSpan('RabbitMQ/' + topic + '/' + queue + '/Producer', Component.RABBITMQ_PRODUCER); span.start(); diff --git a/src/plugins/AxiosPlugin.ts b/src/plugins/AxiosPlugin.ts index 1eedd67..a335b69 100644 --- a/src/plugins/AxiosPlugin.ts +++ b/src/plugins/AxiosPlugin.ts @@ -49,7 +49,7 @@ class AxiosPlugin implements SwPlugin { const method = (config.method || 'GET').toUpperCase(); const span = ignoreHttpMethodCheck(method) ? DummySpan.create() - : ContextManager.current.newExitSpan(operation, host, Component.AXIOS, Component.HTTP); + : ContextManager.current.newExitSpan(operation, Component.AXIOS, Component.HTTP); span.start(); diff --git a/src/plugins/HttpPlugin.ts b/src/plugins/HttpPlugin.ts index 22c37f4..a4eba60 100644 --- a/src/plugins/HttpPlugin.ts +++ b/src/plugins/HttpPlugin.ts @@ -63,7 +63,7 @@ class HttpPlugin implements SwPlugin { const method = arguments[url instanceof URL || typeof url === 'string' ? 1 : 0]?.method || 'GET'; const span = ignoreHttpMethodCheck(method) ? DummySpan.create() - : ContextManager.current.newExitSpan(operation, host, Component.HTTP); + : ContextManager.current.newExitSpan(operation, Component.HTTP); if (span.depth) // if we inherited from a higher level plugin then do nothing, higher level should do all the work and we don't duplicate here return _request.apply(this, arguments); diff --git a/src/plugins/MongoDBPlugin.ts b/src/plugins/MongoDBPlugin.ts index 923a683..c1f70b5 100644 --- a/src/plugins/MongoDBPlugin.ts +++ b/src/plugins/MongoDBPlugin.ts @@ -291,7 +291,7 @@ class MongoDBPlugin implements SwPlugin { host = db.serverConfig.s.options.servers.map((s: any) => `${s.host}:${s.port}`).join(','); // will this work for non-NativeTopology? } catch { /* nop */ } - span = ContextManager.current.newExitSpan('MongoDB/' + operation, host, Component.MONGODB); + span = ContextManager.current.newExitSpan('MongoDB/' + operation, Component.MONGODB); span.start(); diff --git a/src/plugins/MongoosePlugin.ts b/src/plugins/MongoosePlugin.ts index d8f5fd2..0b2f458 100644 --- a/src/plugins/MongoosePlugin.ts +++ b/src/plugins/MongoosePlugin.ts @@ -98,7 +98,7 @@ class MongoosePlugin implements SwPlugin { return _original.apply(this, arguments); const host = `${this.db.host}:${this.db.port}`; - span = ContextManager.current.newExitSpan('Mongoose/' + operation, host, Component.MONGOOSE, Component.MONGODB); + span = ContextManager.current.newExitSpan('Mongoose/' + operation, Component.MONGOOSE, Component.MONGODB); span.start(); diff --git a/src/plugins/MySQLPlugin.ts b/src/plugins/MySQLPlugin.ts index 0f67b04..caf0352 100644 --- a/src/plugins/MySQLPlugin.ts +++ b/src/plugins/MySQLPlugin.ts @@ -37,7 +37,7 @@ class MySQLPlugin implements SwPlugin { let query: any; const host = `${this.config.host}:${this.config.port}`; - const span = ContextManager.current.newExitSpan('mysql/query', host, Component.MYSQL); + const span = ContextManager.current.newExitSpan('mysql/query', Component.MYSQL); span.start(); diff --git a/src/plugins/PgPlugin.ts b/src/plugins/PgPlugin.ts index 7129def..ad266d0 100644 --- a/src/plugins/PgPlugin.ts +++ b/src/plugins/PgPlugin.ts @@ -44,7 +44,7 @@ class MySQLPlugin implements SwPlugin { let query: any; const host = `${this.host}:${this.port}`; - const span = ContextManager.current.newExitSpan('pg/query', host, Component.POSTGRESQL); + const span = ContextManager.current.newExitSpan('pg/query', Component.POSTGRESQL); span.start(); diff --git a/src/trace/context/Context.ts b/src/trace/context/Context.ts index 045a07e..afc9179 100644 --- a/src/trace/context/Context.ts +++ b/src/trace/context/Context.ts @@ -36,7 +36,7 @@ export default interface Context { /* if 'inherit' is specified then the span returned is marked for inheritance by an Exit span component which is created later and calls this function with a matching 'component' value. For example Axios using an Http exit connection will be merged into a single exit span, see those plugins for how this is done. */ - newExitSpan(operation: string, peer: string, component: Component, inherit?: Component): Span; + newExitSpan(operation: string, component: Component, inherit?: Component): Span; start(span: Span): Context; diff --git a/src/trace/context/DummyContext.ts b/src/trace/context/DummyContext.ts index 2d5c4fb..911cbbb 100644 --- a/src/trace/context/DummyContext.ts +++ b/src/trace/context/DummyContext.ts @@ -33,7 +33,7 @@ export default class DummyContext implements Context { return this.span; } - newExitSpan(operation: string, peer: string, component: Component, inherit?: Component): Span { + newExitSpan(operation: string, component: Component, inherit?: Component): Span { return this.span; } diff --git a/src/trace/context/SpanContext.ts b/src/trace/context/SpanContext.ts index 9519be3..09b1569 100644 --- a/src/trace/context/SpanContext.ts +++ b/src/trace/context/SpanContext.ts @@ -94,7 +94,7 @@ export default class SpanContext implements Context { return span; } - newExitSpan(operation: string, peer: string, component: Component, inherit?: Component): Span { + newExitSpan(operation: string, component: Component, inherit?: Component): Span { let span = this.ignoreCheck(operation, SpanType.EXIT); if (span) @@ -108,7 +108,6 @@ export default class SpanContext implements Context { operation, parent, spans, - peer, }); } @@ -120,7 +119,6 @@ export default class SpanContext implements Context { id: this.spanId++, parentId: this.parentId, context: this, - peer, operation, }); } From b2e3d286a9d97d3305220191fb4eceecdddd20ec Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Tue, 11 May 2021 09:22:47 -0300 Subject: [PATCH 4/9] minor ExitSpan fix to set operation from self --- src/trace/span/ExitSpan.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trace/span/ExitSpan.ts b/src/trace/span/ExitSpan.ts index a120366..1c69708 100644 --- a/src/trace/span/ExitSpan.ts +++ b/src/trace/span/ExitSpan.ts @@ -40,7 +40,7 @@ export default class ExitSpan extends Span { this.id, config.serviceName, config.serviceInstance, - ContextManager.spans[0].operation, + this.operation, this.peer, [], ); From 4bf24c4cc85712e3bc062923cc491575e821107e Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Tue, 11 May 2021 10:30:43 -0300 Subject: [PATCH 5/9] ignore propagation, span child of finished span --- src/trace/context/Context.ts | 1 + src/trace/context/ContextCarrier.ts | 18 ++-- src/trace/context/ContextManager.ts | 33 ++++--- src/trace/context/DummyContext.ts | 36 +++++-- src/trace/context/SpanContext.ts | 144 +++++++++++++--------------- src/trace/span/DummySpan.ts | 22 +++++ 6 files changed, 147 insertions(+), 107 deletions(-) diff --git a/src/trace/context/Context.ts b/src/trace/context/Context.ts index afc9179..9928895 100644 --- a/src/trace/context/Context.ts +++ b/src/trace/context/Context.ts @@ -25,6 +25,7 @@ import { ContextCarrier } from './ContextCarrier'; export default interface Context { segment: Segment; nSpans: number; + finished: boolean; newLocalSpan(operation: string): Span; diff --git a/src/trace/context/ContextCarrier.ts b/src/trace/context/ContextCarrier.ts index 8d94053..77742aa 100644 --- a/src/trace/context/ContextCarrier.ts +++ b/src/trace/context/ContextCarrier.ts @@ -68,17 +68,21 @@ export class ContextCarrier extends CarrierItem { } isValid(): boolean { - return ( - this.traceId !== undefined && - this.segmentId !== undefined && + return Boolean( + this.traceId?.rawId && + this.segmentId?.rawId && this.spanId !== undefined && - this.service !== undefined && - this.endpoint !== undefined && - this.clientAddress !== undefined + !isNaN(this.spanId) && + this.service && + this.endpoint && + this.clientAddress ); } - public static from(map: { [key: string]: string }): ContextCarrier { + public static from(map: { [key: string]: string }): ContextCarrier | undefined { + if (!map.hasOwnProperty('sw8')) + return; + const carrier = new ContextCarrier(); carrier.items.filter((item) => map.hasOwnProperty(item.key)).forEach((item) => (item.value = map[item.key])); diff --git a/src/trace/context/ContextManager.ts b/src/trace/context/ContextManager.ts index 9f3205c..2442969 100644 --- a/src/trace/context/ContextManager.ts +++ b/src/trace/context/ContextManager.ts @@ -23,7 +23,7 @@ import SpanContext from '../../trace/context/SpanContext'; import async_hooks from 'async_hooks'; -type AsyncState = { spans: Span[], valid: boolean }; +type AsyncState = { spans: Span[] }; let store: { getStore(): AsyncState | undefined; @@ -58,11 +58,10 @@ if (async_hooks.AsyncLocalStorage) { class ContextManager { get asyncState(): AsyncState { - // since `AsyncLocalStorage.getStore` may get previous state, see issue https://github.com/nodejs/node/issues/35286#issuecomment-697207158, so recreate when asyncState is not valid - // Necessary because span may "finish()" in a child async task of where the asyncState was actually created and so clearing in the child would not clear in parent and invalid asyncState would be reused in new children of that parent. let asyncState = store.getStore(); - if (!asyncState?.valid) { - asyncState = { spans: [], valid: true }; + + if (!asyncState) { + asyncState = { spans: [] }; store.enterWith(asyncState); } @@ -76,7 +75,7 @@ class ContextManager { }; get hasContext(): boolean | undefined { - return store.getStore()?.valid; + return Boolean(store.getStore()?.spans.length); } get current(): Context { @@ -92,10 +91,10 @@ class ContextManager { spansDup(): Span[] { let asyncState = store.getStore(); - if (!asyncState?.valid) { - asyncState = { spans: [], valid: true }; + if (!asyncState) { + asyncState = { spans: [] }; } else { - asyncState = { spans: [...asyncState.spans], valid: asyncState.valid }; + asyncState = { spans: [...asyncState.spans] }; } store.enterWith(asyncState); @@ -103,13 +102,19 @@ class ContextManager { return asyncState.spans; } - clear(): void { - this.asyncState.valid = false; - store.enterWith(undefined as unknown as AsyncState); + clear(span: Span): void { + const spans = this.spansDup(); // this needed to make sure async tasks created before this call will still have this span at the top of their span list + const idx = spans.indexOf(span); + + if (idx !== -1) + spans.splice(idx, 1); } - restore(context: Context, spans: Span[]): void { - store.enterWith({ spans: spans || [], valid: this.asyncState.valid }); + restore(span: Span): void { + const spans = this.spansDup(); + + if (spans.indexOf(span) === -1) + spans.push(span); } withSpan(span: Span, callback: (...args: any[]) => any, ...args: any[]): any { diff --git a/src/trace/context/DummyContext.ts b/src/trace/context/DummyContext.ts index 911cbbb..b79cffb 100644 --- a/src/trace/context/DummyContext.ts +++ b/src/trace/context/DummyContext.ts @@ -23,38 +23,54 @@ import DummySpan from '../../trace/span/DummySpan'; import Segment from '../../trace/context/Segment'; import { Component } from '../../trace/Component'; import { ContextCarrier } from './ContextCarrier'; +import ContextManager from './ContextManager'; export default class DummyContext implements Context { - span: Span = DummySpan.create(this); segment: Segment = new Segment(); nSpans = 0; + finished = false; newEntrySpan(operation: string, carrier?: ContextCarrier, inherit?: Component): Span { - return this.span; + ContextManager.spansDup(); + + return DummySpan.create(this); } newExitSpan(operation: string, component: Component, inherit?: Component): Span { - return this.span; + ContextManager.spansDup(); + + return DummySpan.create(this); } newLocalSpan(operation: string): Span { - return this.span; + ContextManager.spansDup(); + + return DummySpan.create(this); } - start(): Context { - this.nSpans++; + start(span: Span): Context { + if (!this.nSpans++) { + if (ContextManager.spans.indexOf(span) === -1) + ContextManager.spans.push(span); + } + return this; } - stop(): boolean { - return --this.nSpans === 0; + stop(span: Span): boolean { + if (--this.nSpans) + return false; + + ContextManager.clear(span); + + return true; } async(span: Span) { - return; + ContextManager.clear(span); } resync(span: Span) { - return; + ContextManager.restore(span); } } diff --git a/src/trace/context/SpanContext.ts b/src/trace/context/SpanContext.ts index 09b1569..389df85 100644 --- a/src/trace/context/SpanContext.ts +++ b/src/trace/context/SpanContext.ts @@ -25,11 +25,11 @@ import Segment from '../../trace/context/Segment'; import EntrySpan from '../../trace/span/EntrySpan'; import ExitSpan from '../../trace/span/ExitSpan'; import LocalSpan from '../../trace/span/LocalSpan'; +import SegmentRef from './SegmentRef'; +import ContextManager from './ContextManager'; import { Component } from '../../trace/Component'; import { createLogger } from '../../logging'; -import { executionAsyncId } from 'async_hooks'; import { ContextCarrier } from './ContextCarrier'; -import ContextManager from './ContextManager'; import { SpanType } from '../../proto/language-agent/Tracing_pb'; import { emitter } from '../../lib/EventEmitter'; @@ -38,90 +38,105 @@ const logger = createLogger(__filename); export default class SpanContext implements Context { spanId = 0; nSpans = 0; + finished = false; segment: Segment = new Segment(); - get parent(): Span | null { - if (ContextManager.spans.length > 0) { - return ContextManager.spans[ContextManager.spans.length - 1]; - } - return null; + ignoreCheck(operation: string, type: SpanType, carrier?: ContextCarrier): Span | undefined { + if (operation.match(config.reIgnoreOperation) || (carrier && !carrier.isValid())) + return DummySpan.create(); + + return undefined; } - get parentId(): number { - return this.parent ? this.parent.id : -1; + spanCheck(spanType: SpanType, operation: string, carrier?: ContextCarrier): [Span | null, Span?] { + const spans = ContextManager.spansDup(); + let span = this.ignoreCheck(operation, SpanType.ENTRY, carrier); + + if (span) + return [span]; + + const parent = spans[spans.length - 1]; + + if (parent instanceof DummySpan) + return [parent]; + + return [null, parent]; } - ignoreCheck(operation: string, type: SpanType): Span | undefined { - if (operation.match(config.reIgnoreOperation)) - return DummySpan.create(); + newSpan(spanClass: typeof EntrySpan | typeof ExitSpan | typeof LocalSpan, parent: Span, operation: string): Span { + const context = !this.finished ? this : new SpanContext(); - return undefined; + const span = new spanClass({ + id: context.spanId++, + parentId: this.finished ? -1 : parent?.id ?? -1, + context: context, + operation, + }); + + if (this.finished && parent) { // segment has already been closed and sent to server, if there is a parent span then need new segment to reference + const carrier = new ContextCarrier( + parent.context.segment.relatedTraces[0], + parent.context.segment.segmentId, + parent.id, + config.serviceName, + config.serviceInstance, + parent.operation, + parent.peer, + [], + ); + + const ref = SegmentRef.fromCarrier(carrier); + + context.segment.relate(carrier.traceId!); + span.refer(ref); + } + + return span; } newEntrySpan(operation: string, carrier?: ContextCarrier, inherit?: Component): Span { - let span = this.ignoreCheck(operation, SpanType.ENTRY); + let [span, parent] = this.spanCheck(SpanType.ENTRY, operation, carrier); if (span) return span; - const spans = ContextManager.spansDup(); - const parent = spans[spans.length - 1]; - if (logger._isDebugEnabled) { logger.debug('Creating entry span', { - spans, parent, }); } - if (parent && parent.type === SpanType.ENTRY && inherit && inherit === parent.component) { + if (!this.finished && parent?.type === SpanType.ENTRY && inherit && inherit === parent.component) { span = parent; parent.operation = operation; } else { - span = new EntrySpan({ - id: this.spanId++, - parentId: this.parentId, - context: this, - operation, - }); + span = this.newSpan(EntrySpan, parent!, operation); - if (carrier && carrier.isValid()) { + if (carrier && carrier.isValid()) span.extract(carrier); - } } return span; } newExitSpan(operation: string, component: Component, inherit?: Component): Span { - let span = this.ignoreCheck(operation, SpanType.EXIT); + let [span, parent] = this.spanCheck(SpanType.EXIT, operation); if (span) return span; - const spans = ContextManager.spansDup(); - const parent = spans[spans.length - 1]; - if (logger._isDebugEnabled) { logger.debug('Creating exit span', { operation, parent, - spans, }); } - if (parent && parent.type === SpanType.EXIT && component === parent.inherit) { + if (!this.finished && parent?.type === SpanType.EXIT && component === parent.inherit) span = parent; - - } else { - span = new ExitSpan({ - id: this.spanId++, - parentId: this.parentId, - context: this, - operation, - }); - } + else + span = this.newSpan(ExitSpan, parent!, operation); if (inherit) span.inherit = inherit; @@ -130,26 +145,18 @@ export default class SpanContext implements Context { } newLocalSpan(operation: string): Span { - const span = this.ignoreCheck(operation, SpanType.LOCAL); + let [span, parent] = this.spanCheck(SpanType.LOCAL, operation); if (span) return span; - ContextManager.spansDup(); - if (logger._isDebugEnabled) { logger.debug('Creating local span', { - parentId: this.parentId, - executionAsyncId: executionAsyncId(), + parentId: parent?.id ?? -1, }); } - return new LocalSpan({ - id: this.spanId++, - parentId: this.parentId, - context: this, - operation, - }); + return this.newSpan(LocalSpan, parent!, operation); } start(span: Span): Context { @@ -160,9 +167,9 @@ export default class SpanContext implements Context { }); this.nSpans += 1; - if (ContextManager.spans.every((s) => s.id !== span.id || s.context !== span.context)) { + + if (ContextManager.spans.indexOf(span) === -1) ContextManager.spans.push(span); - } return this; } @@ -175,15 +182,13 @@ export default class SpanContext implements Context { }); span.finish(this.segment); - - const idx = ContextManager.spans.indexOf(span); - if (idx !== -1) { - ContextManager.spans.splice(idx, 1); - } + ContextManager.clear(span); if (--this.nSpans === 0) { + this.finished = true; + emitter.emit('segment-finished', this.segment); - ContextManager.clear(); + return true; } @@ -197,16 +202,7 @@ export default class SpanContext implements Context { nSpans: this.nSpans, }); - const spans = ContextManager.spansDup(); // this needed to make sure async tasks created before this call will still have this span at the top of their span list - const idx = spans.indexOf(span); - - if (idx !== -1) { - spans.splice(idx, 1); - - if (!spans.length) { // this will pass the context to child async task so it doesn't mess with other tasks here - ContextManager.clear(); - } - } + ContextManager.clear(span); } resync(span: Span) { @@ -216,10 +212,6 @@ export default class SpanContext implements Context { nSpans: this.nSpans, }); - if (!ContextManager.hasContext || !ContextManager.spans.length) { - ContextManager.restore(span.context, [span]); - } else if (ContextManager.spans.every((s) => s.id !== span.id || s.context !== span.context)) { - ContextManager.spans.push(span); - } + ContextManager.restore(span); } } diff --git a/src/trace/span/DummySpan.ts b/src/trace/span/DummySpan.ts index c2b1571..c75f84a 100644 --- a/src/trace/span/DummySpan.ts +++ b/src/trace/span/DummySpan.ts @@ -32,6 +32,28 @@ export default class DummySpan extends Span { }); } + start(): any { + if (!this.depth++) + this.context.start(this); + } + + stop(block?: any): void { + if (!--this.depth) + this.context.stop(this); + } + + async(block?: any): void { + this.context.async(this); + } + + resync(): any { + this.context.resync(this); + } + + error(error: Error, statusOverride?: number): this { + return this; + } + inject(): ContextCarrier { return new ContextCarrier(); } From 0a3ba60b3ef5229f91d0c8b1448190620a9b319e Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Wed, 12 May 2021 11:02:40 -0300 Subject: [PATCH 6/9] changed method of restricting number of segments --- README.md | 4 +++- src/agent/Buffer.ts | 7 ------- src/agent/protocol/grpc/clients/TraceReportClient.ts | 2 ++ src/lib/EventEmitter.ts | 1 + src/trace/context/ContextManager.ts | 10 +++++++++- src/trace/context/SpanContext.ts | 8 +++++++- 6 files changed, 22 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index de6acf0..8757c90 100644 --- a/README.md +++ b/README.md @@ -42,7 +42,7 @@ agent.start({ }); ``` -note that all options given (including empty/null values) will override the corresponding default values, e.g. `agent.start({ collectorAddress: '' })` will override the default value of `collectorAddress` to empty string, causing errors like `DNS resolution failed`. +Note that all options given (including empty/null values) will override the corresponding default values, e.g. `agent.start({ collectorAddress: '' })` will override the default value of `collectorAddress` to empty string, causing errors like `DNS resolution failed`. - Use environment variables. @@ -66,6 +66,8 @@ Environment Variable | Description | Default | `SW_MONGO_PARAMETERS_MAX_LENGTH` | The maximum string length of mongodb parameters to log | `512` | | `SW_AGENT_MAX_BUFFER_SIZE` | The maximum buffer size before sending the segment data to backend | `'1000'` | +Note that the various ignore options like `SW_IGNORE_SUFFIX`, `SW_TRACE_IGNORE_PATH` and `SW_HTTP_IGNORE_METHOD` as well as endpoints which are not recorded due to exceeding `SW_AGENT_MAX_BUFFER_SIZE` all propagate their ignored status downstream to any other endpoints they may call. If that endpoint is running the Node Skywalking agent then regardless of its ignore settings it will not be recorded since its upstream parent was not recorded. This allows elimination of entire trees of endpoints you are not interested in as well as eliminating partial traces if a span in the chain is ignored but calls out to other endpopints which are recorded as children of ROOT instead of the actual parent. + ## Supported Libraries There are some built-in plugins that support automatic instrumentation of NodeJS libraries, the complete lists are as follows: diff --git a/src/agent/Buffer.ts b/src/agent/Buffer.ts index 99a18fb..8967ecc 100644 --- a/src/agent/Buffer.ts +++ b/src/agent/Buffer.ts @@ -18,16 +18,13 @@ */ import { createLogger } from '../logging'; -import config from '../config/AgentConfig'; const logger = createLogger(__filename); export default class Buffer { - private readonly maxSize: number; private readonly buffer: T[]; constructor() { - this.maxSize = config.maxBufferSize; this.buffer = []; } @@ -36,10 +33,6 @@ export default class Buffer { } put(element: T): boolean { - if (this.length > this.maxSize) { - logger.warn('Drop the data because of the buffer is oversize'); - return false; - } this.buffer.push(element); return true; diff --git a/src/agent/protocol/grpc/clients/TraceReportClient.ts b/src/agent/protocol/grpc/clients/TraceReportClient.ts index 8b2880d..76cf8ec 100755 --- a/src/agent/protocol/grpc/clients/TraceReportClient.ts +++ b/src/agent/protocol/grpc/clients/TraceReportClient.ts @@ -56,6 +56,8 @@ export default class TraceReportClient implements Client { start() { const reportFunction = () => { + emitter.emit('segments-sent'); // reset limiter in SpanContext + try { if (this.buffer.length === 0) { return; diff --git a/src/lib/EventEmitter.ts b/src/lib/EventEmitter.ts index 9d4f708..c801979 100644 --- a/src/lib/EventEmitter.ts +++ b/src/lib/EventEmitter.ts @@ -24,6 +24,7 @@ import Segment from '../trace/context/Segment'; declare interface SkyWalkingEventEmitter { on(event: 'segment-finished', listener: (segment: Segment) => void): this; + on(event: 'segments-sent', listener: () => void): this; } class SkyWalkingEventEmitter extends EventEmitter { diff --git a/src/trace/context/ContextManager.ts b/src/trace/context/ContextManager.ts index 2442969..fdad6ab 100644 --- a/src/trace/context/ContextManager.ts +++ b/src/trace/context/ContextManager.ts @@ -17,9 +17,11 @@ * */ +import config from '../../config/AgentConfig'; import Context from '../../trace/context/Context'; import Span from '../../trace/span/Span'; import SpanContext from '../../trace/context/SpanContext'; +import DummyContext from '../../trace/context/DummyContext'; import async_hooks from 'async_hooks'; @@ -81,7 +83,13 @@ class ContextManager { get current(): Context { const asyncState = this.asyncState; - return !asyncState.spans.length ? new SpanContext() : asyncState.spans[asyncState.spans.length - 1].context; + if (asyncState.spans.length) + return asyncState.spans[asyncState.spans.length - 1].context; + + if (SpanContext.nActiveSegments < config.maxBufferSize) + return new SpanContext(); + + return new DummyContext(); } get spans(): Span[] { diff --git a/src/trace/context/SpanContext.ts b/src/trace/context/SpanContext.ts index 389df85..9f6d7a9 100644 --- a/src/trace/context/SpanContext.ts +++ b/src/trace/context/SpanContext.ts @@ -35,7 +35,12 @@ import { emitter } from '../../lib/EventEmitter'; const logger = createLogger(__filename); +emitter.on('segments-sent', () => { + SpanContext.nActiveSegments = 0; // reset limiter +}); + export default class SpanContext implements Context { + static nActiveSegments = 0; // counter to allow only config.maxBufferSize active (non-dummy) segments per reporting frame spanId = 0; nSpans = 0; finished = false; @@ -166,7 +171,8 @@ export default class SpanContext implements Context { nSpans: this.nSpans, }); - this.nSpans += 1; + if (!this.nSpans++) + SpanContext.nActiveSegments += 1; if (ContextManager.spans.indexOf(span) === -1) ContextManager.spans.push(span); From 056ca22f42e32111555563cf2478153c813898b3 Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Wed, 12 May 2021 16:26:46 -0300 Subject: [PATCH 7/9] moved spansDup() to SpanContext.start() --- src/trace/context/DummyContext.ts | 12 ++++-------- src/trace/context/SpanContext.ts | 10 ++++++---- 2 files changed, 10 insertions(+), 12 deletions(-) diff --git a/src/trace/context/DummyContext.ts b/src/trace/context/DummyContext.ts index b79cffb..2fe73ab 100644 --- a/src/trace/context/DummyContext.ts +++ b/src/trace/context/DummyContext.ts @@ -31,27 +31,23 @@ export default class DummyContext implements Context { finished = false; newEntrySpan(operation: string, carrier?: ContextCarrier, inherit?: Component): Span { - ContextManager.spansDup(); - return DummySpan.create(this); } newExitSpan(operation: string, component: Component, inherit?: Component): Span { - ContextManager.spansDup(); - return DummySpan.create(this); } newLocalSpan(operation: string): Span { - ContextManager.spansDup(); - return DummySpan.create(this); } start(span: Span): Context { + const spans = ContextManager.spansDup(); + if (!this.nSpans++) { - if (ContextManager.spans.indexOf(span) === -1) - ContextManager.spans.push(span); + if (spans.indexOf(span) === -1) + spans.push(span); } return this; diff --git a/src/trace/context/SpanContext.ts b/src/trace/context/SpanContext.ts index 9f6d7a9..7a19781 100644 --- a/src/trace/context/SpanContext.ts +++ b/src/trace/context/SpanContext.ts @@ -54,12 +54,12 @@ export default class SpanContext implements Context { } spanCheck(spanType: SpanType, operation: string, carrier?: ContextCarrier): [Span | null, Span?] { - const spans = ContextManager.spansDup(); let span = this.ignoreCheck(operation, SpanType.ENTRY, carrier); if (span) return [span]; + const spans = ContextManager.spans; const parent = spans[spans.length - 1]; if (parent instanceof DummySpan) @@ -165,17 +165,19 @@ export default class SpanContext implements Context { } start(span: Span): Context { + const spans = ContextManager.spansDup(); + logger.debug(`Starting span ${span.operation}`, { span, - spans: ContextManager.spans, + spans, nSpans: this.nSpans, }); if (!this.nSpans++) SpanContext.nActiveSegments += 1; - if (ContextManager.spans.indexOf(span) === -1) - ContextManager.spans.push(span); + if (spans.indexOf(span) === -1) + spans.push(span); return this; } From 803ff636f288358d959e94f512dc5ef94f3291a5 Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Wed, 12 May 2021 16:33:44 -0300 Subject: [PATCH 8/9] removed unnecessary Buffer.ts --- src/agent/Buffer.ts | 44 ------------------- .../grpc/clients/TraceReportClient.ts | 26 +++++------ 2 files changed, 13 insertions(+), 57 deletions(-) delete mode 100644 src/agent/Buffer.ts diff --git a/src/agent/Buffer.ts b/src/agent/Buffer.ts deleted file mode 100644 index 8967ecc..0000000 --- a/src/agent/Buffer.ts +++ /dev/null @@ -1,44 +0,0 @@ -/*! - * - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to You under the Apache License, Version 2.0 - * (the "License"); you may not use this file except in compliance with - * the License. You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - * - */ - -import { createLogger } from '../logging'; - -const logger = createLogger(__filename); - -export default class Buffer { - private readonly buffer: T[]; - - constructor() { - this.buffer = []; - } - - get length(): number { - return this.buffer.length; - } - - put(element: T): boolean { - this.buffer.push(element); - - return true; - } - - take(): T { - return this.buffer.splice(0, 1)[0]; - } -} diff --git a/src/agent/protocol/grpc/clients/TraceReportClient.ts b/src/agent/protocol/grpc/clients/TraceReportClient.ts index 76cf8ec..810bff2 100755 --- a/src/agent/protocol/grpc/clients/TraceReportClient.ts +++ b/src/agent/protocol/grpc/clients/TraceReportClient.ts @@ -24,7 +24,6 @@ import { createLogger } from '../../../../logging'; import Client from './Client'; import { TraceSegmentReportServiceClient } from '../../../../proto/language-agent/Tracing_grpc_pb'; import AuthInterceptor from '../AuthInterceptor'; -import Buffer from '../../../../agent/Buffer'; import SegmentObjectAdapter from '../SegmentObjectAdapter'; import { emitter } from '../../../../lib/EventEmitter'; import Segment from '../../../../trace/context/Segment'; @@ -33,20 +32,18 @@ const logger = createLogger(__filename); export default class TraceReportClient implements Client { private readonly reporterClient: TraceSegmentReportServiceClient; - private readonly buffer: Buffer; + private readonly buffer: Segment[] = []; private timeout?: NodeJS.Timeout; constructor() { - this.buffer = new Buffer(); this.reporterClient = new TraceSegmentReportServiceClient( config.collectorAddress, config.secure ? grpc.credentials.createSsl() : grpc.credentials.createInsecure(), { interceptors: [AuthInterceptor] }, ); emitter.on('segment-finished', (segment) => { - if (this.buffer.put(segment)) { - this.timeout?.ref(); - } + this.buffer.push(segment); + this.timeout?.ref(); }); } @@ -69,15 +66,18 @@ export default class TraceReportClient implements Client { } }); - while (this.buffer.length > 0) { - const segment = this.buffer.take(); - if (segment) { - if (logger._isDebugEnabled) { - logger.debug('Sending segment ', { segment }); - } + try { + for (const segment of this.buffer) { + if (segment) { + if (logger._isDebugEnabled) { + logger.debug('Sending segment ', { segment }); + } - stream.write(new SegmentObjectAdapter(segment)); + stream.write(new SegmentObjectAdapter(segment)); + } } + } finally { + this.buffer.length = 0; } stream.end(); From 28868018919b003c6d2ba58275cd2b6a93867b18 Mon Sep 17 00:00:00 2001 From: Tomasz Pytel Date: Thu, 13 May 2021 09:19:03 -0300 Subject: [PATCH 9/9] ContextCarrier fix when there is no clientAddress --- src/trace/context/ContextCarrier.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trace/context/ContextCarrier.ts b/src/trace/context/ContextCarrier.ts index 77742aa..abe06a1 100644 --- a/src/trace/context/ContextCarrier.ts +++ b/src/trace/context/ContextCarrier.ts @@ -75,7 +75,7 @@ export class ContextCarrier extends CarrierItem { !isNaN(this.spanId) && this.service && this.endpoint && - this.clientAddress + this.clientAddress !== undefined ); }