Thu Apr 02 2020

Just How Fast is EJS?

Article size is 21.2 kB - 102 kB and is a 14 min read

With FastComments most of our server-side rendered pages are served using the EJS ExpressJS plugin. Since we're using NodeJS this makes sense for us. EJS is fast, and easy to write. The amount of abstraction is also low since the library is fairly small, and I think everyone knows how big of a fan I am of the right (and less) abstractions.

So EJS works well for our marketing site and administration app with pages being able to be rendered in single-digit milliseconds. But what about the really heavily hit stuff - the comment widget itself?

Quick Background - How The Comment Widget Works

To load the comment widget, your browser has to make the following requests:

1. embed.min.js
2. /embed endpoint
3. comment-ui.min.js
4. /comments API

The reason for a couple more calls than you might expect is because of the need of an iframe, for security reasons. That's explained in more detail in this post.

The script (#1) is needed to control the iframe - its styling, the auto resizing, etc.

The /embed endpoint (#2) loads our iframe content.

The comment-ui script (#3) contains the code for the widget and #4 is the api call to actually get the comments, current logged-in user information, and translations.

So what we're talking about here is #2.

Just cache it dude

The problem with caching in this scenario is when items fall out of the cache. For FastComments to properly live up to its name, we don't want to risk the 1% percentile latency being bad. So that /embed endpoint should always be fast.

So let's benchmark.

Benchmark - Template Literal

First let's get a baseline. Let's compare EJS to the fastest thing we can - returning a string. No caching, although in production currently we use an LRU cache.

What if the endpoint was just a string literal?

We'll use autocannon with the default settings to run our test, using and endpoint with actual parameters taken from production.

You can see it gets faster each time as we make Turbofan happy and the JIT kicks in.

We can see that after JIT compilation our max latency is 11.24ms with the lowest requests/second over ten seconds being 3887.

On kind of unrelated tangent, I wanted to show something real quick. Logging in NodeJS is slow, even with the best of frameworks. How slow?

Well, using connect w/ log4js, logging a line like this with each request:

It has an impact - surprisingly. So let's disable logging for a second.

I ran it twice, here's the second run.

Wow! Our max latency isn't much better, but our average is cut in half, and we go from 44k requests/second to 60. Anyway, you probably don't want to disable your logging. I'd rather just deploy an extra server, so let's continue the benchmarks with logging enabled. Also, the impact is so profound just because what we're testing is so light.

Benchmark - EJS

Wow, a huge difference. We can only serve half the requests in the same amount of time and latency is doubled across the board.

Again remember - it may seem crazy to optimize this. But remember that the nature of FastComments - a widget hosted on a third party page - can mean that we get flooded with tons of requests for uncached pages at once. Even with autoscaling this could cause an outage or at least a hiccup. Being able to handle twice the uncached traffic in a spike is a big deal.

So let's take a step back. What if we also add an LRU cache to our template literal?

First it starts off not so great, since the JIT hasn't warmed up yet.

But then!

Wait, isn't that the same as our string literal test? Let's check again.

Yup. Just res.send(${some} stuff) is faster than checking if an item is in the cache and sending it back in the case of our micro benchmark.

Just for giggles, what if we just used a regular map for the cache instead of this fancy lru cache?

At this point what we are seeing is that most of the time is not spent actually constructing the value, but to actually enqueue it into the event loop and send it over the wire.

So where do we go from here? Well, aside from making major architecture changes, let's revisit that logging thing. What if we disable logging for just that route? It's not a big deal - we have the logs in Nginx.

Wow! Double the requests, half the average latency. But why? I originally thought the reason is that this request has a giant query string that gets logged. Observe - if we remove that config from the query string and keep the request logs:

A little better, but not much! Logging, and express middleware, is just slow.

I think what we are going to do is what bought us the lowest latency - rewriting in Rust! Just kidding. Here:

1. Be careful caching in NodeJS. Thrashes GC, takes longer to get from cache than to reconstruct string after JIT.
2. Don't log these requests in the Node layer.
3. Template literals.
4. Cache at the proxy layer.
5. COMMENT YOUR OPTIMIZATIONS

I wouldn't apply these optimizations to other things, but really we're desperate to make sure FastComments is fast as it can be in certain areas. Engineering is all about trade-offs. Also, be a good developer. If you're going to write code that's tough to deal with, explain why:

Also, interestingly having the express.static router first slows things down by about 30%.

We could also probably get better performance out of optimizing a some code returned by the /embed endpoint, but that's for another day. :)