Improving Wanderer perf

I’ve been on a perf improvement kick, both for work and for my own personal projects. And when I went to update my website, I saw that Wanderer was taking ~7 seconds to build this site. Which, for a site with <200 pages, seemed a little long. So, time to rabbit-hole into figuring out where to improve perf!

This took a few hours, mostly because of various missteps. So, in order, presenting what it wasn’t:

  • bottlenecks from using synchronous readFileSync rather than readFile

Node.JS is single-threaded, and so if a process actually takes CPU or any processing power (rather than waiting, e.g. for a file to be available over the network) then async doesn’t really save much, if any time.

Also, this was still only supposed to be ~160 or so pages. Even the slowest file load couldn’t be that bad, I thought.

  • Markdown processing / regexes

This site uses Smartypants to produce these “smart” quotes, as well as a markdown parser to produce the pages. Those use a lot of regexes, and I thought that maybe that was being slow?

There’s possibly more performance I can improve here, but it turned out that Markdown parsing was a miniscule part of the total time being spent.

So what was the problem?

A bug, as it turns out.

Specifically, when reading the files to produce the frontmatter configuration, I was reading the entirety of the file (since we need to find the closing tag to know when the frontmatter is ended). This is typically fine.

However, I was also doing so for every single file format, since frontmatter could exist in any text document, from .md files to .html ones. Unfortunately, without any further guards, this meant that non-text files, like images or videos, would also be processed for frontmatter – and those files were significantly larger than text files. This was enough to slow down the program!

I fixed it by introducing a function to check if any examined file is a binary file (by reading the first ~500 bytes and checking if there are any 0x00 bytes, it’s not very sophisticated). Then, if it is, discarding it from the configuration processing, and continuing otherwise.

This caused build times for this site to go from ~7 seconds to about ~1.5. Which is much more reasonable.

This is now released as Wanderer v1.4.3, which is a patch-change on top of 1.4.2, since no APIs changed.

How did I find it?

Mostly print statement debugging. Specifically, these handy functions:

console.time("label")
...
console.timeEnd("label")

…which, when wrapped around code, will print the time in milliseconds between the start and end of that label. So I wrapped every major step in the wanderer pipeline, and verified that the bottleneck was in core database-generation, not in Markdown processing or image copying.

Successive console.time calls narrowed the problem down to the generateConfig function…which was bizarre, because that shouldn’t have been expensive. So…upon logging every call in there, I realized that there were far more calls to that function than expected.

Conclusion

This bug had been a part of Wanderer for many years, and caused me to suffer (slightly long) build times for that long.

I’m not sure what the moral of the story is. Possibly don’t make your own static site generator, since no one else will fix your bugs?

At any rate, I’m pretty sure no one uses wanderer except me, but if for some reason you really want to use my little static site generator, the fix has been pushed up to NPM and to Github.