Improving cold start times

[nitsujri]

Hey @metaskills,

It's been a while, but thanks for your continued work on this! At my company, we're pretty interested in seeing if we can make our production app work on lambda.

The trouble I'm running into is the cold start time (classic, right?). I'm hovering at ~21-23s with Bootsnap enabled, which for a website is obviously terrible.

I broke out the entire cold start sequence into a huge, terrible script and then attached a bunch of puts w/ the CloudWatch logs timestamps only showing the seconds.

Some Notes

• This is running non-standard container; Ubuntu, Ruby 3.0.3, Rails 6.1 w/ aws_lambda_ric gem manually added.
• The app seems to initialize twice. Once during AWS::Lambda and again AWS::Lambda::Function. You can see the Skipped bootstraping TelemetryLog twice which is part of aws_lambda_ric. If you look below everything up to GROUP 1 (added spaces to make it easier to see) gets loaded twice, but the 2nd time it happens it's only ~1s vs ~9s. Not sure if you've seen a way to prevent this during what I believe to the Extension Init but I'm losing ~1s to a double load?
• GROUP 1, 2, 3, 4 are manual requires of all the gems we use.
• The function does nothing but print "HIHIHI"

High Level Timings

• 8s - full rails load (until GROUP 1)
• 1s - "extra" load, see above
• 4s - require gems (line by line)
• 8s - Rails.application.initialize! (from inside config/environment.rb)

Things I've Tried

From the Cold Start guide:

• Testing it's running a massive 8000 memory for 4vcpu. Nothing of note
• Image size does not seem to have any problems. Our image is ~1GB and an empty ruby function in the same image takes 4s vs the 21s due to the Rails loading.

I'm aware of provisioned concurrency and keep warm AWS::Events::Rule, but I wanted to see if I could lower this insane start time first and admittedly out of ideas. 10s boot seems like a pipedream.

Any recommendations, tips? Thanks again!

=========================

36.167	Skipped bootstraping TelemetryLog
36.167	Executing 'aws/lambda/app_test_4.handler' in function directory '/app'
36.209	FILE LOADED
36.209	BUNDLER
36.209	BOOTSNAP
38.846	RAILS
43.365	ACTIVEMODEL
43.406	ACTIVEJOB
43.466	ACTIVERECORD
43.840	active_storage
44.047	action_text
44.156	action_controller
44.156	action_mailer
44.158	action_view
44.158	action_cable
44.159	GROUP 1

44.329	START RequestId: ca259483-99c2-42ca-92a0-fd4c449a6dba Version: $LATEST
44.864	Skipped bootstraping TelemetryLog
44.864	Executing 'aws/lambda/app_test_4.handler' in function directory '/app'
44.869	FILE LOADED
44.869	BUNDLER
44.869	BOOTSNAP
45.085	RAILS
45.161	ACTIVEMODEL
45.162	ACTIVEJOB
45.166	ACTIVERECORD
45.199	active_storage
45.222	action_text
45.238	action_controller
45.238	action_mailer
45.239	action_view
45.239	action_cable
45.240	GROUP 1

45.750	GROUP 2
46.368	GROUP 3
48.558	GROUP 4
49.291	RAILS APP
49.304	ENDS RAILS APP
49.304	START ENV
50.105	I, [2022-01-22T05:45:50.105338 #9] INFO -- : OXR START
51.186	I, [2022-01-22T05:45:51.186129 #9] INFO -- : OXR END
57.140	END ENV
57.140	START $app
57.140	END $app
57.141	HIHIHI
57.145	END RequestId: ca259483-99c2-42ca-92a0-fd4c449a6dba
57.145	REPORT RequestId: ca259483-99c2-42ca-92a0-fd4c449a6dba Duration: 12813.40 ms Billed Duration: 12814 ms Memory Size: 7168 MB Max Memory Used: 472 MB XRAY TraceId: 1-61eb99fd-7980bcdd0b24cba130c3bfac SegmentId: 546071201dc777f3 Sampled: true

[metaskills]

and then attached a bunch of puts w/ the CloudWatch logs

Pro move! Love me some puts :)

The app seems to initialize twice.

Yup, the whole init phase has a timeout of 10s. What is likely happening is that "Function init" phase is being called twice because the first one timed out. The second time is faster because files have already been required, etc. I've seen this before in some edge cases in our functions but it happened so infrequently given our apps init ~3-5s. Some helpful links here on the topics.

• https://docs.aws.amazon.com/lambda/latest/dg/runtimes-context.html
• https://docs.aws.amazon.com/lambda/latest/dg/runtimes-extensions-api.html

Any recommendations, tips? Thanks again!

Maybe start with these?

• Have you tried using BOOTSNAP_LOG to make sure it is being used well and there are no misses?
• Have you tried ensuring your initialized network connections are as fast as possible and/or lazy? I think redis and memcached are both not as lazy as ActiveRecord. For example, a small DB instance is slower to connect. Also, true for resources outside the VPC.

[nitsujri]

Questions

• How do you handle imagemagick or other heavy load gems like it? Separate single, function lambdas?
• config.eager_load = false doesn't seem to do anything in terms of load times for me, have you? I may need to dig deeper.
• Do you load different gem sets for Web vs API?

Yup, the whole init phase has a timeout of 10s.

AH! Thanks so much for this. I was pulling my hair out trying to understand why this was happening. Glad to know it's a nothing-burger if I get the boot times down.

Have you tried using BOOTSNAP_LOG to make sure it is being used well and there are no misses?

Found some tiny misses w/ action_cable, but nothing that would come near ~18s.

ImageMagick

I found that mini_magick and image_processing combined w/ the image_magick binaries were contributing ~12s and 500MB disk. Simply removing those brought the boot time beneath the Init phase. That's nutso!

After fighting our production repo too much, I pushed an empty container running ruby:3.0.3-slim-buster and only the gems. w/ no gems I got 3.5s boot.

My guess is w/ these two gems enabled, Rail's detects this and init time skyrockets.

Bumbler

Tried using Bumbler to see local initialization times, but it sent me in the wrong direction compared to seeing ImageMagick & related gem's times.

[metaskills]

How do you handle imagemagick or other heavy load gems like it?

In a few ways. In general I recommend using Libvips for image processing. But even those gems will use FFI. In general a regular Rails app with these gems have no issues cold starting for Lambda. So in general I've never had to optimize for that due to it. That said, I do enjoy breaking out very purpose built functions that need to scale like crazy using Node and Libvips with Sharp. Seems faster than Ruby because of how FFI works.

Do you load different gem sets for Web vs API?

Nope.

I found that mini_magick and image_processing combined w/ the image_magick binaries were contributing ~12s and 500MB disk. Simply removing those brought the boot time beneath the Init phase. That's nutso!

That does not surprise me at all. If you are using Lambda Containers and have the ability to use Libvips with image_processing then something like this may be useful in your Dockerfile(s).

RUN yum install -y libpng libpng12 libpng-devel lcms2 lcms2-devel

My guess is w/ these two gems enabled, Rail's detects this and init time skyrockets.

Likely FFI and/or the shared libraries? Would love to know more.