Thu Apr 02 2020

Just How Fast is EJS?

Article size is 20.5 kB and is a 13 min read

With one project 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.

For this project, EJS works well for the 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 embedded widgets this project serves?

Quick Background - How The Embedded Widgets Work

For the embedded widgets, a script is loaded, which injects a styled and dynamically resized iframe into the page.

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

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

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 this project 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.

Of course, Node has to take a lock to write to stdout since you'll have many workers writing logs, you don't want one log to be half written into another one. So we have a concurrency bottleneck with logging every request even if you have many workers.

Note that the impact is so profound just because what we're testing is so light, but it can build up. Generally "aggregated logging" or batched logs sent over the network are better for performance focused systems.

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 for the nature of this project - 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 this project 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. :)