Integrating AsciiDoctor made my system very slow

[robogeek]

I'm the author of AkashaCMS, and thought to integrate AsciiDoctor support this afternoon. Unfortunately it made the software extremely slow for certain operations that are unrelated to rendering AsciiDoctor content. The integration itself is very simple, and I'm very puzzled why it would affect what was impacted.

The integration code: https://github.com/akashacms/akasharender/blob/master/render-asciidoc.js

AkashaCMS is a static website generator, with AkashaRender handling the rendering. The file linked here implements a Renderer class -- its methods are called when there's something to render. It receives an AsciiDoctor file, and is supposed to produce HTML. That's easy enough with the asciidoctor.js API.

The code which became slow is extremely unrelated to rendering AsciiDoctor content.

Part of AkashaCMS is a long list of DOM-processing functions implemented on top of Cheerio, a library which implements a subset of jQuery.

A couple of the DOM-processing functions became extremely slow. I worked on those functions for a long time and didn't get anywhere. As soon as I disabled the AsciiDoctor Renderer the problem went away.

[mojavelinux]

This is very likely related to Opal. I know that Opal modifies some built-in JavaScript objects. There's nothing we can really do to solve it in this project, so it should be taken upstream. I'm sure the Opal team would be very interested in your findings. (The lead of Asciidoctor.js is also an Opal team member).

[ggrossetie]

Hello @robogeek,

Do you have a test case or an easy way to reproduce this behavior ?

[robogeek]

I have a way to reproduce it using the test website. I am on a Mac running Node 6.10 (if that makes any difference)

Clone: https://github.com/akashacms/akashacms-example.git

Go into the akashacms-example directory, and run: npm install

Then run: npm run build

It should build within 20 seconds or so. It's very fast. That's the normal case.

In node_modules/akasharender/render.js uncomment the line for the render-asciidoc Renderer:

exports.registerRenderer(require('./render-md'));
// exports.registerRenderer(require('./render-asciidoc'));
exports.registerRenderer(require('./render-ejs'));
exports.registerRenderer(require('./render-cssless'));
exports.registerRenderer(require('./render-json'));

That enables the Asciidoc Renderer

To enable tracing of custom tag processing In node_modules/mahabhuta/index.js change this flag to true

var traceFlag = false;

You'll see the custom tag processing doing long pauses on certain tags. These tags are completely unrelated to Asciidoc, and are even in files that are not built with Asciidoc. There isn't even an Asciidoc-formatted file in the documents directory.

You'll also see that it takes a loooooooooong time to process the site, and the Mac OS X Activity Monitor shows a node process pegged at 90-100% CPU.

Run it again with the Asciidoc renderer disabled and the custom tags fly by so fast you can't see them.

There is a file named asciidoctor.html.adoc in the main directory. If you want to build the site with that file simply copy it into the documents directory. By the way, the file does render correctly.

[ggrossetie]

Perfect, I will try do debug this week, thanks for the detailed explanation. Just one question, what do you mean by "You'll see the custom tag processing doing long pauses on certain tags" ? What is a custom tag in AkashaCMS ?

[mojavelinux]

I can confirm I get similar results. There is definitely some sort of interaction going on here when Opal gets loaded.

What I recommend is starting with the simple profiler to see what function is getting hammered.

https://nodejs.org/en/docs/guides/simple-profiling/

For the record, the project is using Asciidoctor.js 1.5.6.preview.2.

[robogeek]

Re: Custom Tag processing ... AkashaCMS includes a system to do DOM processing of HTML to convert custom tags to regular HTML tags. For example <embed-resource href="...URL..."/> can retrieve the embed code for things like YouTube videos. There's a long list of these DOM processing functions. When you have the traceFlag set in Mahabhuta, the list of functions are printed as they're executed.

[mojavelinux]

I think I know what this is. It's something @hsablonniere brought to my attention a few days ago. There's a bad interaction between Opal and the clone module. Essentially, it goes into an infinite loop of cloning. This really comes down to a very poor separation of structure and data in JavaScript. It's hard to say whose fault it is since a clone library should be able to tell the difference...but that's not so easy.

The way we worked around it is to implement a smarter, custom clone that didn't dive into the Opal internals.

When I run the profiler, here's what I see at the very top:

 [JavaScript]:
   ticks  total  nonlib   name
    351    1.1%    1.4%  LazyCompile: *_clone /home/dallen/tmp/akashacms-example/node_modules/clone/clone.js:44:18
    343    1.1%    1.4%  Stub: ForInFilterStub

And I killed it only after a few seconds, so you can imagine that clone.js has an infinite number of ticks.

[mojavelinux]

...and in particular, it's the node-cache module that is triggering the use of clone.

Trace
    at clone (/home/dallen/tmp/akashacms-example/node_modules/clone/clone.js:23:11)
    at NodeCache.module.exports.NodeCache._wrap (/home/dallen/tmp/akashacms-example/node_modules/node-cache/lib/node_cache.js:342:22)
    at NodeCache._wrap (/home/dallen/tmp/akashacms-example/node_modules/node-cache/lib/node_cache.js:12:59)
    at NodeCache.module.exports.NodeCache.set (/home/dallen/tmp/akashacms-example/node_modules/node-cache/lib/node_cache.js:151:29)
    at NodeCache.set (/home/dallen/tmp/akashacms-example/node_modules/node-cache/lib/node_cache.js:12:59)
    at Object.exports.set (/home/dallen/tmp/akashacms-example/node_modules/akasharender/caching.js:8:20)
    at /home/dallen/tmp/akashacms-example/node_modules/akasharender/HTMLRenderer.js:180:19

[mojavelinux]

Is it possible to disable the cache for testing purposes?

[robogeek]

Very good. Disabling the caching is easy - edit node_modules/akasharender/caching.js and change the set method to do nothing:

exports.set = function(module, key, val) {
    return undefined;
//    return AKCache.set(`${module}-${key}`, val);
};

I just did that and it sped up considerably. Hurm, it ended up with a few errors ...

[robogeek]

I fixed the error -- edit node_modules/akasharender/documents.js and in exports.documentTree use this for loop instead

    for (let doc of documents) {
        ...
    }

[mojavelinux]

We are hitting a perf issue with preview.3 that we didn't see in preview.2. I don't have the details yet, but I just wanted to mention that something is fishy.

[ggrossetie]

@robogeek Did you fix this error ? Can we close this issue ? @mojavelinux Do you think there's something wrong in preview.3 that need to be fixed ? If that's the case, could you please elaborate your point ?

[robogeek]

Yes I did, I switched to a different caching module for AkashaRender and the error went away. However the problem would still be there for anyone using that other caching module.

[ggrossetie]

node-cache version 3.2.1 is using clone version 1.0.2. A lot of things changed in version 2.1.1 of the clone library... maybe they fix this issue 🤔

Could you please try to upgrade node-cache to version 4.1.1 (which use clone 2.x) ?

[ggrossetie]

@robogeek @mojavelinux Do you know what specific object node-cache was trying to clone ? Asciidoctor.Document ?

[mojavelinux]

I switched to a different caching module for AkashaRender and the error went away.

I'm very glad to hear that at least.

@Mogztter I'm not sure. It was happening in the application I was working on too when cloning the Document object. After switching to lodash cloneDeep the problem was solved.

[mojavelinux]

At the time I observed the problem with clone, the application was using clone 1.x.

[mojavelinux]

It seems to still happen with clone 2.x. It starts cloning but the method never returns.

[ggrossetie]

Thanks Dan. I was asking because I want to know if this issue was introduced by Opal 0.10/0.11 or if it was there from the start. I will do some testing to find out 😄

[mojavelinux]

That I'm not sure about. I'm guessing you should be able to reproduce easily just by making an attempt to clone a Document. I'd probably start with a medium to large-sized document just to be sure you trigger the condition.

[mojavelinux]

While working on Antora, I ran into this problem twice, both for the same reason.

I first hit this problem when trying to load nodegit. If Opal is loaded before nodegit, then node hangs when requiring nodegit.

require('opal-runtime')
require('nodegit')

Reverse them and you're fine.

I also hit the problem when trying to use chai expect after Opal is loaded.

require('opal-runtime')
const expect = require('chai').expect
expect(['one']).to.eql(['two'])

I solved this by monkeypatching chai (see https://gitlab.com/antora/antora/merge_requests/65)

It always comes down to the same issue. Using for (let prop in obj) when obj is any object subtype (Array, Date, String, etc). The problem is that Opal adds properties to objects that form a circular graph. This is best demonstrated by an example:

[]['$class']['$class']['$class']['$class']['$class']['$class']['$class']['$class']

A recursive object traversal will never complete unless it takes these circular references into account.

As it stands now, the rule of thumb is that you cannot naively traverse the object graph when Opal is loaded. I think this point needs to be added prominently in the developer user manual.

For background, see https://github.com/opal/opal/issues/1684.

[mojavelinux]

To clarify, the solution is to simply skip properties that start with $.

[ggrossetie]

The next version of Opal will fix this issue: https://github.com/opal/opal/pull/1821

[ggrossetie]

@robogeek It should be resolved in Asciidoctor.js 1.5.7-rc.1. Could you please give it a try ?

[ggrossetie]

@robogeek Did you have a chance to look at it ?

[ggrossetie]

I believe this issue is resolved in Asciidoctor 1.5.7-rc.1. I'm closing this issue but feel free to reopen it if you can reproduce this issue with the latest version of Asciidoctor.js