Traced init duration at coldstart in "AWS-Lambda" environment (#352)

src/Constants.ts

@@ -107,6 +107,7 @@ export const logLevels: any = {
 };
 
 export const DomainNames = {
+    SERVERLESS: 'Serverless',
     AWS: 'AWS',
     DB: 'DB',
     MESSAGING: 'Messaging',
@@ -128,6 +129,7 @@ export const ClassNames = {
     FIREHOSE: 'AWS-Firehose',
     S3: 'AWS-S3',
     LAMBDA: 'AWS-Lambda',
+    LAMBDA_INIT: 'AWS-Lambda-Init',
     RDB: 'RDB',
     REDIS: 'Redis',
     HTTP: 'HTTP',
@@ -178,6 +180,7 @@ export const AwsLambdaWrapperTags = {
     AWS_LAMBDA_INVOCATION_TIMEOUT: 'aws.lambda.invocation.timeout',
     AWS_LAMBDA_INVOCATION_REQUEST: 'aws.lambda.invocation.request',
     AWS_LAMBDA_INVOCATION_RESPONSE: 'aws.lambda.invocation.response',
+    AWS_LAMBDA_INIT_DURATION: 'aws.lambda.init_duration',
 };
 
 export const VercelTags = {

src/context/ExecutionContext.ts

@@ -38,6 +38,8 @@ export default class ExecutionContext {
     captureLog: boolean;
     logs: LogData[];
     reportingDisabled: boolean;
+    coldStart: boolean;
+    initDuration: number;
     timeout: boolean;
     parentContext: ExecutionContext;
     compatibleContextModes: ContextMode[] = [];

src/opentracing/Tracer.ts

@@ -167,19 +167,19 @@ class ThundraTracer extends Tracer {
                 operationName: fields.operationName || name,
                 parent: parentContext,
                 tags: Object.assign(tags, this.tags, fields.tags),
-                startTime: fields.startTime,
+                startTime: fields.startTime || Date.now(),
                 rootTraceId,
                 className: fields.className,
                 domainName: fields.domainName,
                 transactionId: this.transactionId,
             });
         } else {
             span = new ThundraSpan(this, {
-                operationName: name,
+                operationName: fields.operationName || name,
                 parent: parentSpan ? parentSpan.spanContext : null,
                 tags: Object.assign(tags, this.tags, fields.tags),
                 rootTraceId,
-                startTime: Date.now(),
+                startTime: fields.startTime || Date.now(),
                 className: fields.className,
                 domainName: fields.domainName,
                 transactionId: this.transactionId,

src/utils/LambdaUtils.ts

@@ -1,8 +1,9 @@
 import {
     AWS_SERVICE_REQUEST,
-    EnvVariableKeys,
+    EnvVariableKeys, LAMBDA_INIT_TYPE_PROVISIONED_CONCURRENCY,
 } from '../Constants';
 import Utils from './Utils';
+import PluginContext from '../plugins/PluginContext';
 
 const get = require('lodash.get');
 
@@ -41,6 +42,21 @@ export class LambdaUtils {
         }
         return false;
     }
+
+    static isColdStart(pluginContext: PluginContext): boolean {
+        const firstRequest: boolean = pluginContext.requestCount === 0;
+        if (firstRequest) {
+            const initType: string = Utils.getEnvVar(EnvVariableKeys.AWS_LAMBDA_INITIALIZATION_TYPE);
+            if (initType === LAMBDA_INIT_TYPE_PROVISIONED_CONCURRENCY) {
+                return false;
+            } else {
+                return true;
+            }
+        } else {
+            return false;
+        }
+    }
+
 }
 
 export default LambdaUtils;

src/wrappers/lambda/LambdaExecutor.ts

@@ -7,7 +7,6 @@ import ThundraSpanContext from '../../opentracing/SpanContext';
 import {
     DomainNames, ClassNames, LAMBDA_FUNCTION_PLATFORM, THUNDRA_TRACE_KEY,
     AwsTags, AwsLambdaWrapperTags, TriggerHeaderTags, HttpTags,
-    EnvVariableKeys, LAMBDA_INIT_TYPE_PROVISIONED_CONCURRENCY,
 } from '../../Constants';
 import ThundraTracer from '../../opentracing/Tracer';
 import LambdaEventUtils, { LambdaEventType } from './LambdaEventUtils';
@@ -27,6 +26,8 @@ import { LambdaPlatformUtils } from './LambdaPlatformUtils';
 import ExecutionContext from '../../context/ExecutionContext';
 import ConfigProvider from '../../config/ConfigProvider';
 import ConfigNames from '../../config/ConfigNames';
+import LambdaUtils from '../../utils/LambdaUtils';
+import { SpanOptions } from 'opentracing/lib/tracer';
 
 const get = require('lodash.get');
 
@@ -75,6 +76,7 @@ export function startTrace(pluginContext: PluginContext, execContext: ExecutionC
     execContext.triggerClassName =
         injectTriggerTags(execContext.rootSpan, pluginContext, execContext,
             lambdaEventType, originalEvent, originalContext, config);
+    execContext.coldStart = LambdaUtils.isColdStart(pluginContext);
 
     ThundraLogger.debug(
         '<LambdaExecutor> Injected trigger tags of transaction', execContext.transactionId,
@@ -86,14 +88,33 @@ export function startTrace(pluginContext: PluginContext, execContext: ExecutionC
     execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_MEMORY_LIMIT] = parseInt(originalContext.memoryLimitInMB, 10);
     execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_LOG_GROUP_NAME] = originalContext.logGroupName;
     execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_LOG_STREAM_NAME] = originalContext.logStreamName;
-    execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INVOCATION_COLDSTART] = pluginContext.requestCount === 0;
+    execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INVOCATION_COLDSTART] = execContext.coldStart;
     execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INVOCATION_REQUEST_ID] = originalContext.awsRequestId;
 
     const request = getRequest(originalEvent, execContext.triggerClassName, config);
     ThundraLogger.debug(
         '<LambdaExecutor> Captured invocation request of transaction',
         execContext.transactionId, ':', request);
     execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INVOCATION_REQUEST] = request;
+
+    if (execContext.coldStart && __PRIVATE__.isInitTracingEnabled()) {
+        const initStartTime: number = execContext.startTimestamp;
+        const initFinishTime: number = Date.now();
+        const initSpan: ThundraSpan =
+            tracer.startSpan(
+                'init',
+                {
+                    startTime: initStartTime,
+                    disableActiveStart: true,
+                    domainName: DomainNames.SERVERLESS,
+                    className: ClassNames.LAMBDA_INIT,
+                } as SpanOptions,
+            ) as ThundraSpan;
+        initSpan.finish(initFinishTime);
+
+        execContext.initDuration = initFinishTime - initStartTime;
+        execContext.rootSpan.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INIT_DURATION] = execContext.initDuration;
+    }
 }
 
 /**
@@ -143,20 +164,6 @@ export function finishTrace(pluginContext: PluginContext, execContext: Execution
     rootSpan.finishTime = finishTimestamp;
 }
 
-function isColdStart(pluginContext: PluginContext): boolean {
-    const firstRequest: boolean = pluginContext.requestCount === 0;
-    if (firstRequest) {
-        const initType: string = Utils.getEnvVar(EnvVariableKeys.AWS_LAMBDA_INITIALIZATION_TYPE);
-        if (initType === LAMBDA_INIT_TYPE_PROVISIONED_CONCURRENCY) {
-            return false;
-        } else {
-            return true;
-        }
-    } else {
-        return false;
-    }
-}
-
 /**
  * Starts invocation for AWS Lambda request
  * @param {PluginContext} pluginContext the {@link PluginContext}
@@ -177,7 +184,7 @@ export function startInvocation(pluginContext: PluginContext, execContext: Execu
     invocationData.erroneous = false;
     invocationData.errorType = '';
     invocationData.errorMessage = '';
-    invocationData.coldStart = isColdStart(pluginContext);
+    invocationData.coldStart = execContext.coldStart;
     invocationData.timeout = false;
 
     invocationData.traceId = execContext.traceId;
@@ -196,7 +203,8 @@ function setInvocationTags(invocationData: any, pluginContext: PluginContext, ex
 
     invocationData.tags[AwsTags.AWS_REGION] = pluginContext.applicationInfo.applicationRegion;
     invocationData.tags[AwsLambdaWrapperTags.AWS_LAMBDA_MEMORY_LIMIT] = pluginContext.maxMemory;
-    invocationData.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INVOCATION_COLDSTART] = pluginContext.requestCount === 0;
+    invocationData.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INVOCATION_COLDSTART] = execContext.coldStart;
+    invocationData.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INIT_DURATION] = execContext.initDuration;
     invocationData.tags[AwsLambdaWrapperTags.AWS_LAMBDA_INVOCATION_TIMEOUT] = false;
 
     if (originalContext) {
@@ -471,3 +479,11 @@ function getResponse(response: any, config: TraceConfig): any {
 
     return response;
 }
+
+/* test-code */
+export const __PRIVATE__ = {
+    isInitTracingEnabled: () => {
+        return true;
+    },
+};
+/* end-test-code */

src/wrappers/lambda/LambdaHandlerWrapper.ts

@@ -18,6 +18,7 @@ import ConfigNames from '../../config/ConfigNames';
 import ExecutionContextManager from '../../context/ExecutionContextManager';
 import ExecutionContext from '../../context/ExecutionContext';
 import HTTPUtils from '../../utils/HTTPUtils';
+import LambdaUtils from '../../utils/LambdaUtils';
 
 const path = require('path');
 
@@ -128,8 +129,17 @@ class LambdaHandlerWrapper {
 
         const execContext = ExecutionContextManager.get();
 
+        const coldStart: boolean = LambdaUtils.isColdStart(this.pluginContext);
+        const currentTimestamp: number = Date.now();
+        let startTimestamp: number = currentTimestamp;
+        if (coldStart) {
+            const upTime: number = Math.floor(1000 * process.uptime());
+            // At coldstart, start the invocation from the process start time to cover init duration
+            startTimestamp = currentTimestamp - upTime;
+        }
+
         // Execution context initialization
-        execContext.startTimestamp = Date.now();
+        execContext.startTimestamp = startTimestamp;
         execContext.request = this.originalEvent;
         execContext.platformData.originalContext = this.originalContext;
         execContext.platformData.originalEvent = this.originalEvent;

test/security.test.js

@@ -10,6 +10,7 @@ import RedisCalls from './integrations/utils/redis.integration.utils';
 import MySQLCalls from './integrations/utils/mysql.integration.utils';
 import MongoCalls from './integrations/utils/mongodb.integration.utils';
 import LambdaHandlerWrapper from '../dist/wrappers/lambda/LambdaHandlerWrapper';
+import * as LambdaExecutor from '../dist/wrappers/lambda/LambdaExecutor';
 import Recorder from '../dist/opentracing/Recorder';
 import { AWSIntegration } from '../dist/integrations/AWSIntegration';
 import ExecutionContextManager from '../dist/context/ExecutionContextManager';
@@ -18,6 +19,8 @@ import TestUtils from './utils.js';
 
 const thundra = require('../dist/index');
 
+LambdaExecutor.__PRIVATE__.isInitTracingEnabled = () => false;
+
 beforeEach(() => {
     TestUtils.clearEnvironmentVariables();
     ConfigProvider.clear();