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
+}