Aj/cold start tracing

integration_tests/snapshots/logs/process-input-traced_node12.log

@@ -136,6 +136,28 @@ START
  "start":XXXX,
  "duration":XXXX,
  "service": "integration-tests-js-XXXX-process-input-traced_node12"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-process-input-traced_node12",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-process-input-traced_node12",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-process-input-traced_node12"
  }
  ]
  ]

integration_tests/snapshots/logs/process-input-traced_node14.log

@@ -136,6 +136,28 @@ START
  "start":XXXX,
  "duration":XXXX,
  "service": "integration-tests-js-XXXX-process-input-traced_node14"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-process-input-traced_node14",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-process-input-traced_node14",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-process-input-traced_node14"
  }
  ]
  ]

integration_tests/snapshots/logs/process-input-traced_node16.log

@@ -140,6 +140,29 @@ START
  "start":XXXX,
  "duration":XXXX,
  "service": "integration-tests-js-XXXX-process-input-traced_node16"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-process-input-traced_node16",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "version": "1.0.0",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-process-input-traced_node16",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-process-input-traced_node16"
  }
  ]
  ]

integration_tests/snapshots/logs/process-input-traced_node18.log

@@ -140,6 +140,29 @@ START
  "start":XXXX,
  "duration":XXXX,
  "service": "integration-tests-js-XXXX-process-input-traced_node18"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-process-input-traced_node18",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "version": "1.0.0",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-process-input-traced_node18",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-process-input-traced_node18"
  }
  ]
  ]

integration_tests/snapshots/logs/status-code-500s_node12.log

@@ -96,6 +96,28 @@ START
  "duration":XXXX,
  "service": "aws.lambda",
  "type": "serverless"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-status-code-500s_node12",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-status-code-500s_node12",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-status-code-500s_node12"
  }
  ]
  ]

integration_tests/snapshots/logs/status-code-500s_node14.log

@@ -96,6 +96,28 @@ START
  "duration":XXXX,
  "service": "aws.lambda",
  "type": "serverless"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-status-code-500s_node14",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-status-code-500s_node14",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-status-code-500s_node14"
  }
  ]
  ]
@@ -191,6 +213,7 @@ START
 }
 END Duration: XXXX ms Memory Used: XXXX MB
 START
+END Duration: XXXX ms Memory Used: XXXX MB
 {
  "e": XXXX,
  "m": "aws.lambda.enhanced.invocations",
@@ -277,4 +300,3 @@ START
  ]
  ]
 }
-END Duration: XXXX ms Memory Used: XXXX MB

integration_tests/snapshots/logs/status-code-500s_node16.log

@@ -98,6 +98,29 @@ START
  "duration":XXXX,
  "service": "aws.lambda",
  "type": "serverless"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-status-code-500s_node16",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "version": "1.0.0",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-status-code-500s_node16",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-status-code-500s_node16"
  }
  ]
  ]

integration_tests/snapshots/logs/status-code-500s_node18.log

@@ -98,6 +98,29 @@ START
  "duration":XXXX,
  "service": "aws.lambda",
  "type": "serverless"
+ },
+ {
+ "trace_id":"XXXX",
+ "span_id":"XXXX",
+ "parent_id":"XXXX",
+ "name": "aws.lambda.load",
+ "resource": "integration-tests-js-XXXX-status-code-500s_node18",
+ "error": 0,
+ "meta": {
+ "service": "aws.lambda",
+ "version": "1.0.0",
+ "runtime-id":"XXXX",
+ "operation_name": "aws.lambda.require",
+ "resource_names": "integration-tests-js-XXXX-status-code-500s_node18",
+ "language": "javascript"
+ },
+ "metrics": {
+ "process_id":XXXX,
+ "_sampling_priority_v1": 1
+ },
+ "start":XXXX,
+ "duration":XXXX,
+ "service": "integration-tests-js-XXXX-status-code-500s_node18"
  }
  ]
  ]

src/index.ts

@@ -7,6 +7,7 @@ import {
  MetricsListener,
 } from "./metrics";
 import { TraceConfig, TraceHeaders, TraceListener } from "./trace";
+import { subscribeToDC } from "./runtime";
 import {
  logDebug,
  logError,
@@ -36,6 +37,9 @@ export const traceExtractorEnvVar = "DD_TRACE_EXTRACTOR";
 export const defaultSiteURL = "datadoghq.com";
 export const encodeAuthorizerContextEnvVar = "DD_ENCODE_AUTHORIZER_CONTEXT";
 export const decodeAuthorizerContextEnvVar = "DD_DECODE_AUTHORIZER_CONTEXT";
+export const coldStartTracingEnvVar = "DD_COLD_START_TRACING";
+export const minColdStartTraceDurationEnvVar = "DD_MIN_COLD_START_DURATION";
+export const coldStartTraceSkipLibEnvVar = "DD_COLD_START_TRACE_SKIP_LIB";
 
 interface GlobalConfig {
  /**
@@ -75,11 +79,16 @@ export const defaultConfig: Config = {
  mergeDatadogXrayTraces: false,
  shouldRetryMetrics: false,
  siteURL: "",
+ minColdStartTraceDuration: 3,
+ coldStartTraceSkipLib: "",
 } as const;
 
 let currentMetricsListener: MetricsListener | undefined;
 let currentTraceListener: TraceListener | undefined;
 
+if (getEnvValue(coldStartTracingEnvVar, "true")) {
+ subscribeToDC();
+}
 /**
  * Wraps your AWS lambda handler functions to add tracing/metrics support
  * @param handler A lambda handler function.
@@ -120,7 +129,7 @@ export function datadog<TEvent, TResult>(
  currentTraceListener = traceListener;
 
  try {
- await traceListener.onStartInvocation(event, context);
+ traceListener.onStartInvocation(event, context);
  await metricsListener.onStartInvocation(event);
  if (finalConfig.enhancedMetrics) {
  incrementInvocationsMetric(metricsListener, context);
@@ -287,6 +296,14 @@ function getConfig(userConfig?: Partial<Config>): Config {
  config.decodeAuthorizerContext = result === "true";
  }
 
+ if (userConfig === undefined || userConfig.minColdStartTraceDuration === undefined) {
+ config.minColdStartTraceDuration = Number(getEnvValue(minColdStartTraceDurationEnvVar, "3"));
+ }
+
+ if (userConfig === undefined || userConfig.minColdStartTraceDuration === undefined) {
+ config.coldStartTraceSkipLib = getEnvValue(coldStartTraceSkipLibEnvVar, "./opentracing/tracer");
+ }
+
  return config;
 }
 

src/runtime/index.ts

@@ -1 +1,2 @@
 export { load, loadSync } from "./user-function";
+export { subscribeToDC, getTraceTree, RequireNode } from "./require-tracer"

src/runtime/require-tracer.spec.ts

@@ -0,0 +1,29 @@
+import { subscribeToDC, getTraceTree, RequireNode } from "./require-tracer";
+const dc = require('diagnostics_channel')
+
+describe('require-tracer', () => {
+ it('generates a trace tree', () => {
+ subscribeToDC()
+ const moduleLoadStartChannel = dc.channel('dd-trace:moduleLoadStart')
+ const moduleLoadEndChannel = dc.channel('dd-trace:moduleLoadEnd')
+
+ // require('myLibrary')
+ moduleLoadStartChannel.publish({
+ request: 'myLibrary'
+ })
+ // require('myChildLibrary')
+ moduleLoadStartChannel.publish({
+ request: 'myChildLibrary'
+ })
+ moduleLoadEndChannel.publish()
+ moduleLoadEndChannel.publish()
+ const res = getTraceTree()
+ expect(res).toBeDefined
+ expect(res[0].id).toBe('myLibrary')
+ const resChildren = res[0].children as RequireNode[]
+ expect(resChildren).toHaveLength(1)
+ const resChild = resChildren.pop() as RequireNode
+ expect(resChild.id).toBe('myChildLibrary')
+ })
+
+})

src/runtime/require-tracer.ts

@@ -0,0 +1,58 @@
+const dc = require('diagnostics_channel')
+
+export class RequireNode {
+ public id: string
+ public filename: string
+ public startTime: number
+ public endTime: number
+ public children: RequireNode[]
+
+ constructor(id: string, filename: string, startTime: number) {
+ this.id = id
+ this.filename = filename
+ this.startTime = startTime
+ this.endTime = startTime
+ this.children = []
+ }
+
+ public set setEnd(endTime: number) {
+ this.endTime = endTime
+ }
+}
+
+const moduleLoadStartChannel = dc.channel('dd-trace:moduleLoadStart')
+const moduleLoadEndChannel = dc.channel('dd-trace:moduleLoadEnd')
+const rootNodes: RequireNode[] = []
+
+const requireStack: RequireNode[] = []
+const pushNode = (data: any) => {
+ const startTime = Date.now()
+
+ const reqNode = new RequireNode(data.request, data.filename, startTime)
+ const maybeParent = requireStack[requireStack.length - 1]
+
+ if (maybeParent) {
+ maybeParent.children.push(reqNode)
+ }
+ requireStack.push(reqNode)
+}
+
+const popNode = () => {
+ const endTime = Date.now()
+ const reqNode = requireStack.pop()
+ if (reqNode){
+ reqNode.endTime = endTime
+ }
+ if (requireStack.length <= 0 && reqNode) {
+ rootNodes.push(reqNode)
+ }
+}
+
+export const subscribeToDC = () => {
+ moduleLoadStartChannel.subscribe(pushNode)
+ moduleLoadEndChannel.subscribe(popNode)
+}
+
+export const getTraceTree = (): RequireNode[] => {
+ return rootNodes
+}