COLT MCANLIS: In this episode of Cloud Performance Atlas,
we help a cloudy developer get clarity in the tracing
and high instance counts.
Does the forecast call for sunny skies?
Stay tuned to find out.
[MUSIC PLAYING]
An old friend of mine recently launched a new image service
called Partly Cloudy which provides high resolution
images of clouds for developers who need to use them
in professional presentations.
After a week of launching her open beta,
she woke up one morning to see this little gem waiting
for her in the Google Cloud developer console.
The blue line in this graph charts the number
of active App Engine instances that the application is using.
These numbers are really high, considering
the application's only job is to grab an image
and send it to the user.
But the developer of Partly Cloudy had a hunch.
She was seeing really high latency numbers
in the trace results and was assuming
that this was responsible for the high number of instances.
In some cases, high response time
can cause new instances to be spun up.
So after looking at this list of traces, I had to agree.
This looked like the obvious problem.
However, when I dug into the tracing information,
things started to get really weird.
The latency was being reported as six seconds,
but the trace information said that the sum of all RPC calls
was only taking about 180 milliseconds.
Now, while digging in more, things started to get wacky.
I added some custom tracing code around the entire response
section, which showed us that there
was no rogue code executing and taking up time.
Things were happening really fast.
The big issue here, though, was that we
weren't seeing the huge six second delays that the logs
were showing from before.
In fact, any repo I tried didn't seem
to exhibit the same slow performance numbers, even when
submitting the exact same HTTP request.
The breakthrough came when I looked
at the logging information for the slower request.
It was coming from a mobile device.
This gave me an idea.
What if the connection speed was causing the trace numbers
to be inflated?
To test this theory out, I throttled my connection speed
with a few curl commands, which you can also
do in Chrome Dev Tools, and got the following timings.
Sadly, still no changes.
When dealing with really odd discrepancies like this,
it's sometimes good to take a break.
So we grabbed some tacos.
[MUSIC PLAYING]
When we came back, we found that our quizzical error
had gotten even more complex.
The traces, which had low latency before,
suddenly had a higher value in the tracing list.
After another 30 minutes, it seemed
that the graph had updated with these new numbers.
Then I remembered something.
Sitting between user connections and your App Engine instance
is a series of App Engine front ends.
These front ends will act as a liaison between the client
and the given instance.
When the App Engine instance is done processing a request,
the data is passed back to the front end, which
stays connected to the client as long as it
takes to transfer the data.
While this is happening, the App Engine instance
can be off servicing other requests.
Now what this means to you is that regardless of how slow
the client connection is, it's not
going to impact your instance count.
Now, it makes sense then that there
will be a slight delay in the traces receiving and updating
this information.
There's lots of complex steps here.
And all that data has to be gathered and presented properly
to the tracing tool.
More importantly, this means that Partly Cloudy's instance
count was not a function of connection speed or weird code
issues.
Turns out, the reason for the high instance count
was resounding success.
When we flipped over to the traffic graph,
we saw that over the past six hours,
people have been using the Partly Cloudy service really
aggressively.
Partly Cloudy was a victim of its own success.
But still, the instances are too high.
And now that we knew that there wasn't some weird code issue,
we could get to bringing that number down.
It turns out that Partly Cloudy's architecture
was really part of the problem.
In their setup, App Engine will handle the request
from a client, do an NDB query to the data
store, which contains info on all the 20,000 images
available.
From there, the instance will randomly
pick one, fetch the full image from the GCS bucket,
send it along, back with its details, to the client.
The solution then is straightforward.
Let's find a way to spend less time
having the clients talk to App Engine and more time
having them ping GCS buckets directly, which meant
changing the access pattern.
When the client fetches an image from GAE,
append the next 10 images ID as an extra header in the field.
The client will then fetch the next 10 images directly
from GCS rather than needing to go through GAE for it.
When we're out of pre-fetched images, go back to the server
and grab the next batch.
When we flipped over to this code,
the results were better than expected.
An eight-hour run saw instance count drop
from about 16 instances on average to about 1.5.
See, that's the trick with performance improvements.
You have to eliminate all the possibilities before really
understanding the problem.
And to learn more about all the possible ways
that perf can go sideways, check out
the rest of the Cloud Performance Atlas videos.
And remember, when it comes to performance,
every millisecond counts.
[MUSIC PLAYING]