COLT MCANLIS: In this episode of Cloud Performance Atlas,
I help some fishing fashionistas get a line on their cold boot
performance problems.
Will we catch the big one?
Stay tuned to find out.
[MUSIC PLAYING]
So last episode, I helped my friend Carter
and his new website, Bait and Stitch,
which allows fishermen to meet up with local designers
to create custom apparel.
We were able to do a survey of the different ways
to profile App Engine startup time and realized a few things.
Firstly is that GAE standard startup time is fast.
There's no issues with the platform there.
Secondly, tracing was an amazing tool
to see where your time is going, to RPC or other system calls.
And thirdly, we could augment those traces with custom data
to get more info on the performance of the code.
But we didn't actually track down what the problem was yet.
So to recap, the Logging Tool showed us
that our loading requests, and a whole set of requests
afterwards, are taking significantly longer
than the average, which is about 3 to 7 milliseconds.
But upon revisiting the logs, I had a realization.
Check out those time stamps for those slow requests.
They didn't come in after the loading request,
but rather at the same time as the loading request.
The difference between the loading request and the ones
following are roughly the same millisecond.
Given this fact, the way we should really
be looking at this log data is that there's
two groups of requests-- one that
arrives at the same time as the loading requests, which
are slow, and one that arrives afterwards,
which are actually fast.
And with this shift in thinking, I suddenly
realized what was wrong--
parallel requests.
See, if you have thread safe enabled in GAE Standard,
then your application can receive parallel requests,
which will spin off to separate threads
to execute work on the same instance.
This normally is really important,
given the fact that it allows you
to maximize your usage of the instance that you have.
In Carter's case, however, this is causing a problem,
since something in the loading request
is causing the rest of the parallel request
to block until it's completed.
To confirm this, you can look at the logs in more detail.
You can see that each parallel request gets subsequently
slower while it waits.
And in some cases, it's 2x slower
than the loading request itself.
But truth is that this isn't normal behavior
for parallel requests.
After a bit more digging, the problem
materialized pretty quickly.
Carter was messing around with global variables
and parallel requests.
Turns out that in the instance initialization
for Bait and Stitch sat some code that looked like this.
When the instance booted for the first time,
it would query NDB to get some setting data that it
keeps around for use later.
Now, when you're writing client-side applications,
work like this really isn't a big deal,
since this type of thing is typically
done before your thread pools are initialized.
But in App Engine, initialization
can happen in parallel to your threading work.
The result is that each one of these threads
will be trying to initialize the global variables
at the same time.
And since they aren't thread local,
all the threads will block and wait
until the work is finished.
This has a significant performance impact,
since it turns your parallel system
into a single linear operation.
The solution came from a very simple realization-- not every
one of our requests actually used the global variable.
But since the logic was occurring globally,
all the threads and requests were blocking on it.
The fix was pretty easy at this point--
change the global variable to be lazy
initialized based on the first instance that uses it.
In this scenario, Bait and Stitch
still pays the cost, eventually, to do the NDB query.
But the trick here is that it's more performant
when the get CDN function is not causing contention
for other parallel requests.
Once we changed this code around,
we saw a significant improvement in performance.
Our loading requests no longer blocked
the rest of the parallel requests,
and didn't create the same blocking behavior.
Now, obviously this is a specific case.
But you can see how quickly cold boot time can cause problems
that impact your bottom line.
For those folks who've worked in managed languages in situations
where startup time matters, most of this information is old hat.
But in the world of cloud computing,
these small performance anomalies
have serious consequences, not only
for user perception of performance,
but also in pure costs.
Having 100 loading requests a day
at 187x slower than regular requests
starts to result in significant overhead in compute hours.
Thankfully, we were able to peel back the layers of complexity,
profile some new parts of the code,
and save Bait and Stitch some serious performance
for their users.
And if that sounds pretty awesome to you,
then make sure you check out the rest of the Cloud Performance
Atlas videos.
And don't forget-- when it comes to performance,
every millisecond counts.
[MUSIC PLAYING]