Merge pull request rails-lambda#169 from rails-lambda/ProactiveInit

New CloudWatch Cold Start Metrics

CHANGELOG.md

@@ -2,6 +2,12 @@
 
 See this http://keepachangelog.com link for information on how we want this documented formatted.
 
+## v5.1.0
+
+### Added
+
+- New CloudWatch cold start metrics. Defaults to off. Enable with `config.cold_start_metrics = true`.
+
 ## v5.0.0
 
 ### Changed

Gemfile.lock

@@ -1,7 +1,7 @@
 PATH
   remote: .
   specs:
-    lamby (5.0.0)
+    lamby (5.1.0)
       lambda-console-ruby
       rack
 
@@ -133,6 +133,8 @@ GEM
     nio4r (2.5.9)
     nokogiri (1.14.3-aarch64-linux)
       racc (~> 1.4)
+    nokogiri (1.14.3-arm64-darwin)
+      racc (~> 1.4)
     pry (0.14.2)
       coderay (~> 1.1)
       method_source (~> 1.0)
@@ -169,6 +171,7 @@ GEM
     rake (13.0.6)
     ruby2_keywords (0.0.5)
     thor (1.2.1)
+    timecop (0.9.6)
     timeout (0.3.2)
     tzinfo (2.0.6)
       concurrent-ruby (~> 1.0)
@@ -180,6 +183,7 @@ GEM
 
 PLATFORMS
   aarch64-linux
+  arm64-darwin-22
 
 DEPENDENCIES
   aws-sdk-ssm
@@ -192,6 +196,7 @@ DEPENDENCIES
   pry
   rails
   rake
+  timecop
   webrick
 
 BUNDLED WITH

lamby.gemspec

@@ -27,5 +27,6 @@ Gem::Specification.new do |spec|
   spec.add_development_dependency 'minitest-focus'
   spec.add_development_dependency 'mocha'
   spec.add_development_dependency 'pry'
+  spec.add_development_dependency 'timecop'
   spec.add_development_dependency 'webrick'
 end

lib/lamby.rb

@@ -9,6 +9,7 @@
 require 'lamby/rack_rest'
 require 'lamby/rack_http'
 require 'lamby/debug'
+require 'lamby/cold_start_metrics'
 require 'lamby/handler'
 
 if defined?(Rails)

lib/lamby/cold_start_metrics.rb

@@ -0,0 +1,83 @@
+module Lamby
+  class ColdStartMetrics
+    NAMESPACE = 'Lamby'
+
+    @cold_start = true
+    @cold_start_time = (Time.now.to_f * 1000).to_i
+
+    class << self
+
+      def instrument!
+        return unless @cold_start
+        @cold_start = false
+        now = (Time.now.to_f * 1000).to_i
+        proactive_init = (now - @cold_start_time) > 10_000
+        new(proactive_init).instrument!
+      end
+
+      def clear!
+        @cold_start = true
+        @cold_start_time = (Time.now.to_f * 1000).to_i
+      end
+
+    end
+
+    def initialize(proactive_init)
+      @proactive_init = proactive_init
+      @metrics = []
+      @properties = {}
+    end
+
+    def instrument!
+      name = @proactive_init ? 'ProactiveInit' : 'ColdStart'
+      put_metric name, 1, 'Count'
+      puts JSON.dump(message)
+    end
+
+    private
+
+    def dimensions
+      [{ AppName: rails_app_name }]
+    end
+
+    def put_metric(name, value, unit = nil)
+      @metrics << { 'Name': name }.tap do |m|
+        m['Unit'] = unit if unit
+      end
+      set_property name, value
+    end
+
+    def set_property(name, value)
+      @properties[name] = value
+      self
+    end
+
+    def message
+      {
+        '_aws': {
+          'Timestamp': timestamp,
+          'CloudWatchMetrics': [
+            {
+              'Namespace': NAMESPACE,
+              'Dimensions': [dimensions.map(&:keys).flatten],
+              'Metrics': @metrics
+            }
+          ]
+        }
+      }.tap do |m|
+        dimensions.each { |d| m.merge!(d) }
+        m.merge!(@properties)
+      end
+    end
+
+    def timestamp
+      Time.current.strftime('%s%3N').to_i
+    end
+
+    def rails_app_name
+      Lamby.config.metrics_app_name ||
+        Rails.application.class.name.split('::').first
+    end
+
+  end
+end

lib/lamby/config.rb

@@ -41,6 +41,8 @@ def rack_app=(app)
 
     def initialize_defaults
       @rack_app = nil
+      @cold_start_metrics = false
+      @metrics_app_name = nil
       @event_bridge_handler = lambda { |event, context| puts(event) }
     end
 
@@ -64,5 +66,21 @@ def handled_proc=(proc)
       @handled_proc = proc
     end
 
+    def cold_start_metrics?
+      @cold_start_metrics
+    end
+
+    def cold_start_metrics=(bool)
+      @cold_start_metrics = bool
+    end
+
+    def metrics_app_name
+      @metrics_app_name
+    end
+
+    def metrics_app_name=(name)
+      @metrics_app_name = name
+    end
+
   end
 end

lib/lamby/handler.rb

@@ -4,6 +4,7 @@ class Handler
     class << self
 
       def call(app, event, context, options = {})
+        Lamby::ColdStartMetrics.instrument! if Lamby.config.cold_start_metrics?
         new(app, event, context, options).call.response
       end
 

lib/lamby/version.rb

@@ -1,3 +1,3 @@
 module Lamby
-  VERSION = '5.0.0'
+  VERSION = '5.1.0'
 end

test/cold_start_metrics_test.rb

@@ -0,0 +1,56 @@
+require 'test_helper'
+
+class ColdStartMetricsSpec < LambySpec
+
+  before { Lamby::ColdStartMetrics.clear! }
+
+  it 'has a config that defaults to false' do
+    refute Lamby.config.cold_start_metrics?
+  end
+
+  it 'calling instrument for the first time will output a CloudWatch count metric for ColdStart' do
+    out = capture(:stdout) { Lamby::ColdStartMetrics.instrument! }
+    metric = JSON.parse(out)
+    expect(metric['AppName']).must_equal 'Dummy'
+    expect(metric['ColdStart']).must_equal 1
+    metrics = metric['_aws']['CloudWatchMetrics']
+    expect(metrics.size).must_equal 1
+    expect(metrics.first['Namespace']).must_equal 'Lamby'
+    expect(metrics.first['Dimensions']).must_equal [['AppName']]
+    expect(metrics.first['Metrics']).must_equal [{'Name' => 'ColdStart', 'Unit' => 'Count'}]
+  end
+
+  it 'only ever sends one metric for the lifespan of the function' do
+    assert_output(/ColdStart/) { Lamby::ColdStartMetrics.instrument! }
+    assert_output('') { Lamby::ColdStartMetrics.instrument! }
+    Timecop.travel(Time.now + 10) { assert_output('') { Lamby::ColdStartMetrics.instrument! } }
+    Timecop.travel(Time.now + 50000000) { assert_output('') { Lamby::ColdStartMetrics.instrument! } }
+  end
+
+  it 'will record a ProactiveInit metric if the function is called after 10 seconds' do
+    Timecop.travel(Time.now + 11) do
+      out = capture(:stdout) { Lamby::ColdStartMetrics.instrument! }
+      metric = JSON.parse(out)
+      expect(metric['AppName']).must_equal 'Dummy'
+      expect(metric['ProactiveInit']).must_equal 1
+      metrics = metric['_aws']['CloudWatchMetrics']
+      expect(metrics.size).must_equal 1
+      expect(metrics.first['Namespace']).must_equal 'Lamby'
+      expect(metrics.first['Dimensions']).must_equal [['AppName']]
+      expect(metrics.first['Metrics']).must_equal [{'Name' => 'ProactiveInit', 'Unit' => 'Count'}]
+    end
+  end
+
+  it 'will not record a ProactiveInit metric if the function is called before 10 seconds' do
+    Timecop.travel(Time.now + 9) do
+      assert_output(/ColdStart/) { Lamby::ColdStartMetrics.instrument! }
+    end
+  end
+
+  private
+
+  def now_ms
+    (Time.now.to_f * 1000).to_i
+  end
+
+end

test/test_helper.rb

@@ -3,6 +3,7 @@
 $LOAD_PATH.unshift File.expand_path('../../lib', __FILE__)
 require 'lamby'
 require 'pry'
+require 'timecop'
 require 'minitest/autorun'
 require 'minitest/focus'
 require 'mocha/minitest'
@@ -16,6 +17,7 @@
 
 Rails.backtrace_cleaner.remove_silencers!
 Lambdakiq::Client.default_options.merge! stub_responses: true
+Timecop.safe_mode = true
 
 class LambySpec < Minitest::Spec
   include TestHelpers::DummyAppHelpers,
@@ -28,6 +30,10 @@ class LambySpec < Minitest::Spec
     lambdakiq_client_stub_responses
   end
 
+  after do
+    Timecop.return
+  end
+
   private
 
   def encode64(v)