Merge pull request #1923 from brefphp/cold-start-tracking

Track cold starts

Author: mnapoli

docs/runtimes/runtimes-details.mdx

@@ -93,6 +93,8 @@ So far, knowing the number of Bref invocations has helped Bref grow, be recogniz
 
 ### Data
 
+You can find the latest number of AWS Lambda invocations on the [Bref homepage](https://bref.sh/).
+
 On the month of the Bref 1.0 release, [Bref was powering 1 billion invocations per month](../../news/01-bref-1.0.md#1-billion-executions-per-month).
 
 On the month of the Bref 2.0 release, [Bref was powering 10 billion invocations per month](../../news/02-bref-2.0.md).
@@ -101,15 +103,15 @@ On the month of the Bref 2.0 release, [Bref was powering 10 billion invocations
 
 The data sent in the ping is completely anonymous. It does not contain any identifiable data about anything (the project, users, etc.).
 
-**The only data it contains is:** "A Bref invocation happened with the layer XYZ" (where XYZ is the name of the Bref layer, like "function", "fpm" or "console").
+**The only data it contains is:** A Bref invocation happened with the layer XYZ (where XYZ is the name of the Bref layer, like "function", "fpm" or "console") and whether the invocation was a cold start.
 
 Here is an example payload:
 
 ```
-Invocations_100:1|c\nLayer_fpm_100:1|c
+Invocations_100:1|c\nLayer_fpm_100:1|c\nCold_100:1\nWarm_100:0|c
 ```
 
-Anyone can inspect the code and the data sent by checking the [`Bref\Runtime\LambdaRuntime::ping()` function](https://github.com/brefphp/bref/blob/master/src/Runtime/LambdaRuntime.php#L374).
+Anyone can inspect the code and the data sent by checking the [`Bref\Runtime\LambdaRuntime::ping()` function](https://github.com/brefphp/bref/blob/master/src/Runtime/LambdaRuntime.php#L387).
 
 ### How is it sent
 

src/ConsoleRuntime/Main.php

@@ -5,6 +5,7 @@
 use Bref\Bref;
 use Bref\Context\Context;
 use Bref\LazySecretsLoader;
+use Bref\Runtime\ColdStartTracker;
 use Bref\Runtime\LambdaRuntime;
 use Symfony\Component\Process\Process;
 
@@ -15,6 +16,8 @@ class Main
 {
     public static function run(): void
     {
+        ColdStartTracker::init();
+
         LazySecretsLoader::loadSecretEnvironmentVariables();
 
         Bref::triggerHooks('beforeStartup');
@@ -30,6 +33,8 @@ public static function run(): void
 
         Bref::events()->afterStartup();
 
+        ColdStartTracker::coldStartFinished();
+
         /** @phpstan-ignore-next-line */
         while (true) {
             $lambdaRuntime->processNextEvent(function ($event, Context $context) use ($handlerFile): array {

src/FpmRuntime/Main.php

@@ -4,6 +4,7 @@
 
 use Bref\Bref;
 use Bref\LazySecretsLoader;
+use Bref\Runtime\ColdStartTracker;
 use Bref\Runtime\LambdaRuntime;
 use RuntimeException;
 use Throwable;
@@ -19,6 +20,8 @@ public static function run(): void
         ini_set('display_errors', '1');
         error_reporting(E_ALL);
 
+        ColdStartTracker::init();
+
         LazySecretsLoader::loadSecretEnvironmentVariables();
 
         Bref::triggerHooks('beforeStartup');
@@ -41,6 +44,8 @@ public static function run(): void
 
         Bref::events()->afterStartup();
 
+        ColdStartTracker::coldStartFinished();
+
         /** @phpstan-ignore-next-line */
         while (true) {
             $lambdaRuntime->processNextEvent($phpFpm);

src/FunctionRuntime/Main.php

@@ -4,6 +4,7 @@
 
 use Bref\Bref;
 use Bref\LazySecretsLoader;
+use Bref\Runtime\ColdStartTracker;
 use Bref\Runtime\LambdaRuntime;
 use Throwable;
 
@@ -14,6 +15,8 @@ class Main
 {
     public static function run(): void
     {
+        ColdStartTracker::init();
+
         LazySecretsLoader::loadSecretEnvironmentVariables();
 
         Bref::triggerHooks('beforeStartup');
@@ -31,6 +34,8 @@ public static function run(): void
 
         Bref::events()->afterStartup();
 
+        ColdStartTracker::coldStartFinished();
+
         $loopMax = getenv('BREF_LOOP_MAX') ?: 1;
         $loops = 0;
         while (true) {

src/Runtime/ColdStartTracker.php

@@ -0,0 +1,118 @@
+<?php declare(strict_types=1);
+
+namespace Bref\Runtime;
+
+/**
+ * Tracks cold starts.
+ *
+ * @internal
+ */
+class ColdStartTracker
+{
+    private const FILE = '/tmp/.bref-cold-start';
+
+    private static bool $currentInvocationIsColdStart = false;
+    private static ?float $coldStartBeginningTime = null;
+    private static ?float $coldStartEndedTime = null;
+    private static bool $hasFirstInvocationStarted = false;
+    private static bool $wasProactiveInitialization = false;
+
+    public static function init(): void
+    {
+        self::$coldStartBeginningTime = microtime(true);
+
+        // We need to use a file to track cold starts only once.
+        // This is because Bref's process can restart between invocations,
+        // so we can't rely on static variables to track cold starts.
+        self::$currentInvocationIsColdStart = ! file_exists(self::FILE);
+        if (self::$currentInvocationIsColdStart) {
+            touch(self::FILE);
+        }
+    }
+
+    /**
+     * Signals that the cold start has finished.
+     */
+    public static function coldStartFinished(): void
+    {
+        self::$coldStartEndedTime = microtime(true);
+    }
+
+    /**
+     * Signals that a Lambda invocation has started.
+     */
+    public static function invocationStarted(): void
+    {
+        // If the first invocation had happened already, then we are starting a 2nd invocation (or more)
+        // so we are no longer in the cold start invocation anymore
+        if (self::$hasFirstInvocationStarted) {
+            self::$currentInvocationIsColdStart = false;
+            return;
+        }
+
+        self::$hasFirstInvocationStarted = true;
+
+        if (self::$currentInvocationIsColdStart) {
+            // There was a cold start, let's figure out if it was a proactive initialization
+            $timeElapsedSinceColdStartEnded = microtime(true) - self::$coldStartEndedTime;
+            // If more than 100ms have passed since the cold start ended, we can assume the
+            // Lambda sandbox was paused/frozen between the cold start and the first invocation
+            // (100ms is an arbitrary value, we could use a lower value but I want to be conservative)
+            // That means the Lambda sandbox was initialized proactively
+            self::$wasProactiveInitialization = $timeElapsedSinceColdStartEnded > 0.1;
+        } else {
+            // There was no cold start, we are in a warm start
+            self::$wasProactiveInitialization = false;
+        }
+    }
+
+    /**
+     * Timestamp of the beginning of the cold start.
+     */
+    public static function getColdStartBeginningTime(): float
+    {
+        return self::$coldStartBeginningTime;
+    }
+
+    /**
+     * Timestamp of the end of the cold start.
+     */
+    public static function getColdStartEndedTime(): float
+    {
+        return self::$coldStartEndedTime;
+    }
+
+    /**
+     * Returns `true` if the current Lambda invocation contained a cold start.
+     *
+     * This is `true` even if the cold start was a proactive initialization.
+     *
+     * This is no longer `true` once the second invocation (and subsequent invocations) start.
+     */
+    public static function currentInvocationIsColdStart(): bool
+    {
+        return self::$currentInvocationIsColdStart;
+    }
+
+    /**
+     * Returns `true` if the current Lambda invocation contains a cold start that was "user-facing".
+     *
+     * "User-facing" means that the cold start duration was part of the invocation duration that the
+     * invoker of the Lambda function experienced.
+     *
+     * For example, if the application is a web application, a "user-facing" cold start of 1 second
+     * means that the response time of the first request contained a 1 second delay.
+     */
+    public static function currentInvocationIsUserFacingColdStart(): bool
+    {
+        return self::currentInvocationIsColdStart() && ! self::wasProactiveInitialization();
+    }
+
+    /**
+     * Returns `true` if this Lambda sandbox was initialized proactively.
+     */
+    public static function wasProactiveInitialization(): bool
+    {
+        return self::$wasProactiveInitialization;
+    }
+}

src/Runtime/LambdaRuntime.php

@@ -86,6 +86,8 @@ public function processNextEvent(Handler | RequestHandlerInterface | callable $h
         $this->setEnv('LAMBDA_INVOCATION_CONTEXT', json_encode($context, JSON_THROW_ON_ERROR));
 
         try {
+            ColdStartTracker::invocationStarted();
+
             Bref::triggerHooks('beforeInvoke');
             Bref::events()->beforeInvoke($handler, $event, $context);
 
@@ -400,20 +402,23 @@ private function ping(): void
             return;
         }
 
+        $isColdStart = ColdStartTracker::currentInvocationIsUserFacingColdStart() ? '1' : '0';
+        $isWarmInvocation = $isColdStart === '0' ? '1' : '0';
+
         /**
          * Here is the content sent to the Bref analytics server.
-         * It signals an invocation happened on which layer.
+         * It signals an invocation happened on which layer and whether it was a cold start.
          * Nothing else is sent.
          *
-         * `Invocations_100` is used to signal that this is 1 ping equals 100 invocations.
+         * `Invocations_100` is used to signal that 1 ping equals 100 invocations.
          * We could use statsd sample rate system like this:
          * `Invocations:1|c|@0.01`
          * but this doesn't seem to be compatible with the bridge that forwards
          * the metric into CloudWatch.
          *
          * See https://github.com/statsd/statsd/blob/master/docs/metric_types.md for more information.
          */
-        $message = "Invocations_100:1|c\nLayer_{$this->layer}_100:1|c";
+        $message = "Invocations_100:1|c\nLayer_{$this->layer}_100:1|c\nCold_100:$isColdStart|c\nWarm_100:$isWarmInvocation|c";
 
         $sock = socket_create(AF_INET, SOCK_DGRAM, SOL_UDP);
         // This IP address is the Bref server.