COLT MCANLIS: In this episode of Cloud Performance Atlas,
I show a fishing friend all the tools
he'll need to catch a big performance problem.
Will this be the one that got away?
Stay tuned to find out.
So my friend Carter has built a new website
called Bait & Stitch which helps fishing enthusiasts connect
with designers to make custom apparel.
After a few weeks in beta, Carter asked for some help.
He was noticing that his request latency
got significantly slower under heavy load due to the fact
that new instances took longer times to start.
Now, typically when I hear feedback like this
it means one thing--
cold boot performance.
See, when a new app engine instance
is spun up for the first time, it
has to execute a bunch of work that only
occurs during initial boot--
things like starting the debugger,
initializing global variables, or populating
some memcached data.
Performance becomes a concern here because instances
that are typically created in response to a request that
comes in.
So if an instance is booting up, the total time
to respond to that request is a function
of the normal work that needed to be done for that response,
as well as any startup work that has to be done as well.
Now, to be very, very, very clear here,
cold boot performance isn't normally a problem.
App Engine startup time is really fast.
I mean take a look at this.
I charted the cold boot time for basic Hello World Application
across various instant types.
250 milliseconds is actually pretty fast for an F2 instance
to boot up.
I mean, that's technically faster
than fetching a JavaScript file for most CDNs on a 4G
connection.
Which means GAE by itself is really good at responding
to instance creation time.
However, the users of Bait & Stitch
were noticing performance issues because of cold boot time,
which meant that it was time for Carter
and I to sit down and dig in and figure out
what was going wrong.
And our first stop was take a look at the logging data.
See, App Engine does a really good job
of logging information about each request that it receives,
most important of which is how long it took for the request
to be handled by the service.
Now, logged items which correspond to system events
are often logged in blue.
Startup time is one of those items,
so we can click on the log entry to get more data.
Startup requests will typically have a header value
of loading requests set to one.
Furthermore, these log entries are
flagged with some extra information
that tells you about the instance being spun up,
and how it will be a little bit slower than a typical request.
Now, looking at the logs we can see that there's
a group of really fast requests at the bottom of the set, which
confirms exactly what we're expecting-- the loading request
is actually pretty slow.
What we didn't expect, however, is
the batch of calls in the middle which
follow the loading request.
Those are just as slow, but sadly, at this point logging
won't give us any more information.
So it's time to switch over to something
a little more powerful.
And one of the nice things about App Engine being
a platform as a service is that it's
got a bunch of nifty other tools built into it that you don't
have to go generate yourself.
One of the more powerful ones is Stackdriver tracing.
See, in addition to being logged,
each request that comes through App Engine standard
gets its RPC call information tracked and listed
in Stackdriver.
To find loading requests we need to dig around a bit.
They typically aren't listed directly,
but they have a higher response time than normal requests
that come through.
To confirm this, you can select a trace.
If the debuglet started command is in the trace details,
then it's what you're looking for.
This block only executes when a new instance has been spawned.
So it's a clear sign that this was a request that
caused a cold boot to occur.
Now, as mentioned, any RPC calls that your app makes
will be logged here.
And we can see that this app is touching Memcache, doing
a fetch, and pushing some stuff to task queues.
None of those really look like a performance problem
at this point.
But what's really interesting here
is that there's about 900 milliseconds
before the socket was created--
to allow a connection to the instance.
This is a rough indicator of the startup time taken.
So App Engine's boot time isn't the problem,
and none of our RPC requests are the problem,
but Bait & Stitch's loading time is still about 1.2 seconds.
Hmm.
To get more insight we need to profile more of our code.
See, tracing does a great job of keeping
a tab of what RPC function calls take,
but it doesn't track all custom code that
occurs between those calls.
To do that, we need to leverage the Stackdriver trace API
that allows us to insert custom tracing data into our requests.
Carter and I were able to write a small utility class which
tracked the start and end time of various code segments,
and would turn those results into a JSON string on demand.
Adding a little entry/exit setup,
and we quickly had an API to log how long a block of code takes.
Passing that data off to the Stackdriver API
allowed us to insert custom tracing data for blocks of code
that weren't previously being logged.
Pretty neat, huh.
Now with the custom tracing setup,
we now had a very clear picture of what
was going wrong in the Bait & Stitch application's cold boot
time.
And it wasn't pretty.
But to figure out that problem we
needed to dig in a little deeper,
which is a subject for a different video.
If you want to learn more about tracking down performance
problems, 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]