[MUSIC PLAYING]
DANIEL LEE: Hi, my name is Daniel.
I am part of the team that supports
Cloud Functions for Firebase.
And today, I'm super excited to talk to you about observability
in Cloud Functions for Firebase.
This topic is near and dear to my heart
because I was part of the Site Reliability Engineering team
when I first joined Google.
And you may have seen or read this book,
but Site Reliability Engineering team
is obsessed with operating the production
software as efficiently as reliably as possible.
And while in Firebase, we love talking
about how easy it is to build your service,
we often don't talk that much about how
do you operate this thing.
So and I think GCP, which the platform that Cloud Functions
for Firebase is built on top of, offers amazing tools
for operating your software.
So I want to do that.
And I think the best way to do this is with a story.
So I want you to meet Suna.
She is a developer at an e-commerce company,
and she is a Firebase enthusiast just like us.
She walks into the office one day
and the PM has a message for her.
Hey, our customers love discounts.
Can we have a feature where we calculate the total price
with the discounts supplied?
And a good engineer, Suna says, you got it.
She thinks Cloud functions for Firebase
is a perfect fit for this feature because one,
it offers zero maintenance.
It scales automatically up and down.
She doesn't have to think about the infrastructure too much.
It's private and secure, which is important in this case
because discount information is sensitive.
We don't want any customers to just access
and read the discount information.
You need a secure environment.
Cloud Functions for Firebase offers that.
Finally, she knows she'll be productive with the SDK,
the CLI, and the Emulator that all work seamlessly together.
So she writes her function in the V2
that we just talked about earlier today.
And you don't have to read the whole thing, just
let's focus on two business logics.
One is calculating the total price.
So you get list of product IDs that you want
to calculate the total for.
We have the products collection with documents that specify
the price of the product.
So we're going to generate document references,
grab all the documents at once, and then calculate
the total by iterating through the documents that we fetched.
That's one.
The important piece and the interesting piece
is a discount calculation.
Imagine having collection of discounts,
and each discount describes the discounted amount
and the product that it applies to.
So for each product that she has,
she's going to look up the discounts collection,
find the discounts that match this product, add it all up,
and do that again for all the products that she has.
So she wrote the function.
She has run the Emulator to test her logic.
She deploys it to her QA project.
She even does a production launch and does a QA there.
She's happy.
Everything's working great.
A launch.
High fives.
She getting kudos.
She's feeling great.
All right, so here's a twist.
The next day she walks in, PM messages her.
Hey, I'm getting this call from our big customer.
They say their checkout process is taking a long time.
Can you take a look?
I had this feeling a lot of people reporting bugs issues.
And I have this five stages of production issue.
First, you're in denial.
I was like, code is perfect.
What are you talking about?
Maybe they're wrong.
Maybe they're on a 3G network.
And then you get a little angry.
It's like, who is this customer anyway.
Like do I even have to care about this customer?
You start bargaining.
It's like, hey, like 10 seconds, not too long, right.
Like in the grand scheme of things, everything's cool.
You get a little depressed.
Like oh, I'm the worst coder in the world.
I'm the worst software engineer in the world.
Finally, you get to acceptance.
You figured out that there could be a problem,
and you're going to go search for the problem.
So where do we start?
I think a good place to start is with the dashboard.
So there is a thing called four golden signals that the SRE
folks like to talk about.
And these are the requests latency,
the utilization of CPU and memory,
request count, and the errors.
And she notices something on the request latency.
The 99th percentile is indeed super slow.
It's taking over seven seconds to respond.
And when you're using Cloud Function for Firebase,
you get all this for free because you're running
on Google Cloud platform.
So with these dashboards, she has confirmed the issue.
Yeah, the customer is not kidding.
Like there is an issue with their back end.
But you don't have any incriminating evidences yet.
Now, you start to think.
Like you built this code, so maybe
you can think through and find the bug by doing that.
So you think about your source code.
Maybe there is a bug somewhere.
You also think about the infrastructure
where your code is deployed, right.
Like everything worked perfectly in development,
maybe like when we deploy it to Google Cloud functions,
maybe this is the cold start that people are talking about.
Maybe Firestore is having a bad day.
So you're generating hypothesis about what is going on,
what is the problem.
Finally, like I think I like to jump back into logs.
I don't know if people have done this.
I do this all the time, where we write
logs to understand the code that we write, right.
Like how is it actually running when it's running on the CPU.
But the problem is that Suna didn't write any logs.
She didn't expect any logs.
Like logs are intentional.
They're explicit.
Like you're leaving breadcrumbs for yourself.
In this case, Suna didn't leave any
because she thought everything was good.
So let's recap.
We looked at dashboard.
We confirmed the issue.
We thought about our code.
We thought about the infrastructure
that is deployed.
And we have a hunch.
We have hypothesis.
And as for logs, it wasn't very helpful.
And I would say, like the Cloud Function
that Suna deployed is still a black box.
Like even though she wrote the code, the business logic,
she's relying on libraries that she didn't write.
She's relying on infrastructure that she doesn't
know the full detail of.
Only a couple of Googlers probably know that.
It's still a black box.
And this is where the concept of observability comes in.
And it's such a new hot topic, I couldn't find an Oxford
Dictionary definition for it.
But there was a book that was published earlier this year
called "Observability Engineering,"
and they had a great definition that I want to share with you.
Observability of a software system
is a measure of how well you can understand and explain
your system, no matter how novel or bizarre.
And I want us to focus on the fact that observability is not
like a set of technology or checkboxes.
It's a relationship between you as the operator
and the software that is running in production.
So if it's not making sense to you, then it's not observable.
So Suna learns about this topic.
I want to make my service observable.
How do we do that?
Well, I think the easiest place to get started is just write
some more logs.
Like we talked about how you rewrite
logs to understand how it's running in the software system.
So she's going to use the handy dandy console.log that I
hope people are familiar with.
And she's going to time how long it
takes to fetch these Firestore documents.
Maybe that's where the problem is.
So you have this log, but it's a lot of logs.
So she's getting a lot of requests.
It's just a bunch of text, right.
Like we're not really great at processing megabytes of texts
and getting insights from them.
So how do we get some help here?
Well Suna figures out that she can write--
you can import the logger that is included
with Firebase functions SDK.
And instead of writing string, she's
going to write objects, these JavaScript objects.
But when you do that, this technique
is called structure logging.
So not only is JavaScript Object readable by humans,
it's also readable by machine and understood by machine.
So when you're using Cloud Logging, you can now make--
so this is the logging payload that you get.
You will see that the JSON payload
has the object recalculated.
We have a message.
And we have the time it took to calculate this price
or discount.
And Cloud Logging allows you to write complex queries,
where you can filter by, hey, I want
only logs that are greater than or that took
more than 500 milliseconds.
This is going to help with the investigation that she's doing.
And instead of having to write regular expressions
or off to parse the logs, you can leverage the machine
to help you make investigations go more smoothly.
And what's great about it is that you can even
create custom metrics.
So you write your queries, and there
will be a little button that says create custom metrics.
And when you do this, instead of having
to integrate with Cloud monitoring or Prometheus
or what other monitoring tools that you're familiar with,
you can just go ahead and easily dump this data, the structure
data that you have, into Google Cloud monitoring
or Prometheus that also is offered by Google Cloud
platform.
So when Suna did this, she found that she
was able to graph the latency of how long it took to calculate
the price as well as how long it took to calculate the discount.
She notices that, yeah, like the tail end
behavior of calculating discount is super slow.
Price is doing pretty OK.
This is probably where the problem lies.
So at this point, Suna has honed in on a section of code
that has the problem.
So what do we do now?
Do we go back and add more logs to get even more information
about what's going on with our code?
Maybe she's going to time exactly how long
it took to make the Firebase query,
or maybe it's like in that for loop.
So she's going to make logs after this.
What I think Suna needs is a little cute dog with a camera.
And I don't mean literally, but wouldn't it
be nice if there was like an autonomous thing that
would go and take a snapshot of the system state
whenever anything interesting happens.
So whenever a request comes in, you
take a snapshot, maybe the timing information
of what's going on.
Maybe when you're making a third party API call,
you take a snapshot of this.
Basically, like writing logs, except doing it automatically
by this little cute dog.
Well, we can't have cute dogs running around the server room.
But what we can have is traces and spans.
So traces and spans are another type of monitoring signal,
where each request has--
as you follow each request, and whenever anything significant
happens, you're sort of taking a start and the end
and any metadata that is associated that you
want to put into each span.
So in our case, we get this beautiful graphic visualization
of we got the request.
And then we started calculating the price,
which issued a Firestore call.
Then we started getting discount,
which was another set of Firestore call,
and you get a nice visibility into what's actually
happening in your service.
So how do we get started with traces?
I would recommend OpenTelemetry.
OpenTelemetry is a vendor neutral, open
specification and an implementation
of all kinds of monitoring signals
like logs, monitoring, and also traces.
So traces is what I want to focus on today.
But it's built by industry leading experts
in the monitoring space and available
in a lot of languages, including JavaScript,
which is what we need.
So let's take a brief look at how it happens.
I'm going to import OpenTelemetry in my code.
I'm going to start the SDK, and I'm
going to configure it that works with Google Cloud function.
So I'm going to include instrumentation.
This is where the magic happens, where
if you want, like these significant events
that you want to automatically instrument,
you can import by saying, hey, I want any HTTP requests
to be instrumented.
I want any gRPC request to be instrumented.
I want anything express that is interesting to be automatically
generating spans.
You can add more.
You can add less.
This is what I picked, or this is what Suna picked.
We're also going to look at the trace exporters.
So when your service is generating spans,
you want that data to be available in some service
for analysis.
I'm picking Google Cloud.
Suna's picking Google Cloud Trace.
But there are other providers like Honeycomb and LightStep
who can also help you ingest these spans that
are being generated and give you the analysis tool
to investigate the problem.
So her service is now instrumented.
It's generating spans.
What does it look like in Google Cloud Trace?
Actually, one more, sorry-- so you
want to make sure that this is a Google Cloud functions V2
function where it will send you a SIGTERM signal whenever
the container is shutting down.
And this is important because when it shuts down,
you want to make sure that all the spans that you
have generated is exported to Google Cloud Trace in our case.
So I want to make sure that I capture that.
All right, so this is the good trace that I want to look at.
She looked at some of the traces that are normal.
Like 99% of them are pretty fast.
This is what's happening, like she gets an HTTP request.
She's making a Firestore call to calculate the price,
calculate discount.
The whole thing took 50 milliseconds.
Pretty good.
What about the bad case?
Uh oh.
This one took more than 6 seconds.
You're seeing a lot more spans.
Let's take a look.
We are making over 100 calls to Firestore
and doing them in a waterfall style.
Oh no.
It looks like when there are a lot of products that
need to be calculated, we're going
to make a sequential calls to Firestore
and make more than 100 calls.
That's why it's being slow.
But once you know the issue, like it's easy to fix it,
right.
So this is the code that we had originally.
We're going to apply two tricks.
First, we're going to use this operator in Firestore
array-contains-any.
So instead of looking for discounts
apply to a single product, we can have up to 10 products
that--
we can look up all the discount that
applies to 10 products at the same time.
So instead of making hundreds calls,
we can only make 10 calls.
Nice.
Another thing that I think we should do is to--
instead of having this waterfall sequential calls, why don't we
just issue all the Firestore calls at the same time
and have them come back.
So I'm going to do them concurrently
by doing an async map over it and then
doing a Promise.all to wait for all the responses to come back.
She has deployed this code.
She is looking for traces again.
And what do we see?
Exactly what we wanted, right.
The request latency has reduced back to 100 milliseconds.
That's like 6 seconds to 100 milliseconds.
Amazing stuff.
We're only issuing 10 Firestore queries.
Awesome.
And we're doing them like in parallel,
instead of doing it in sequence.
That's why we got this amazing speed up.
Suna is.
Happy PM is happy.
Everyone's happy.
Are you guys happy?
[CHEERING]
All right, so let's quickly recap.
We started from a black box.
We added some logging to make it more observable.
We added structure logging to leverage the machines.
We should definitely use the machine for our benefit.
Using Cloud Logging understand structure logs,
we can make custom metrics.
Finally, we use OpenTelemetry to generate traces, which actually
gave us the clues that we needed to debug our production issue.
So that was a really short snippet, super hard to follow.
Check out the full example that we have on the function sample
repo on GitHub.
Go to second gen, and it has a really explicit title
called Instrumenting with OpenTelemetry.
I committed it yesterday.
So you should be able to see it there.
And if you want to talk to me about this
and how you deal with your production issues, let me know.
I'll be hanging out in the Firebase lounge right
after this.
So thank you, everyone.
[APPLAUSE]
[MUSIC PLAYING]