Performance issue with "with" library

[cesmoak]

I'm seeing a page that took ~300ms to render on version 0.30.0 now taking over 9.5s on 0.31.2. I've confirmed all the extra time is spent in "addWith", specifically in the two times the js parse tree is walked in the lexical-scope library.

[vendethiel]

Esprima :/.

[ForbesLindesay]

Yes, compile time is a lot slower. There are a few other things that affect compile time and make it slower as well (but usually more reliable).

If we can improve it significantly by optimising lexical-scope I would be keen to do that.

At the end of the day, if you cache your compiled templates in production (which you'd better be doing) this shouldn't be a big issue for you.

[cesmoak]

It's not a huge issue for production, but the development experience is severely hampered by waiting ~10s for every page view of what I would consider only a moderately-sized page. If we can't find a way to improve the speed, I'm afraid I'm going to have to look for an alternative templating option (or not upgrade past 0.30.0). Is this change made necessary by the extra functionality in the script and style tags, and would making that optional be a possibility (maybe by making the "." optional)?

[tj]

isn't this optional? if not it could be, and use regular old gross with(){} in development

[cesmoak]

Indeed, it does seem to be skipped if setting the self option to true. From a brief look, that seems to be a suitable alternative. Thanks.

[ForbesLindesay]

Yes, the self option still disables this. We don't have an option to go back to just using the with language feature. It has slightly different semantics so I didn't really want yet another mode.

I agree 10 seconds is too long. I'm re-opening this because I think we should be able to do some caching using something like LRU-cache in with so that even with caching disabled we still cache some stuff but just cache against the actual text of the template rather than the filename.

I do think we should be able to improve on 10 seconds. Personally I've hardly ever seen more than 1 second, but then my jade templates tend to be fairly simple.

[tj]

damn that's unfortunate about the semantics, would be great if we had a quick fallback for development, then deprecate the self option since it has no point after that. How do the semantics differ for average use-cases? (not the weird with stuff that hopefully no one relies on anyway haha), locals should resolve in the same way no?

[ForbesLindesay]

There are two important differences.

1) It is impossible to replicate the behaviour of with where there are extra var statements:

with ({foo: 'bar'})
  var foo = foo || 'baz'
  assert(foo === 'bar')
}

The above works great but there's no sane way of replicating this behaviour that doesn't lead to a lot of superfluous var statements. We could prevent people relying on this by just wrapping the body of the with block in a function closure for the development mode.

2) using compile time with gets rid of nasty Reference Errors

This is actually a really useful feature because although the following throws an error, it would pass fine with the compile time with.

var buf = []
with ({bar: 'bar-val'}) {
  if (foo) {
    buf.push('foo:' + foo)
  }
  if (bar) {
    buf.push('bar:' + bar)
  }
}

In the compile time with, all the extra variables get declared, but have a value of "undefined". I don't see any easy way to work around this issue.

[ForbesLindesay]

I strongly suspect it will be possible to optimise lexical-scope (and thus with) so that the compile time with takes under half a second for even the most complex of templates. Thus far, no attempt has been made to make lexical-scope fast.

[tj]

I can't comment on the speed we're still on a pretty old jade but we don't even use variables hahaha.. we just use it as indented html basically these days, but yeah that's true the reference thing sucks

[ForbesLindesay]

Can someone provide me with a jade template that takes multiple seconds to compile? All mine take a fraction of a second cause they're all really simple. If you can then I'll add it to the test suite so that we can decide on a minimum performance level for compilation and work towards meeting that target. I want to optimize things for realistic code though, rather than trying purposefully to create a pathological case.

(/cc @cesmoak @akshayme)

[akshayme]

Sure, here's a (rather inelegant) block that now takes much longer to compile than in previous versions:

block content
    .data
        ol.sortable#contents
            each item in report
                if (!item.parent)
                    div
                        li.chapter(data-ref= item.id)
                            a(href='/admin/report/detail/' + item.id)
                                = item.name
                        - var chp = item.id
                            ol.sortable
                                each item in report
                                    if (item.parent === chp && item.type === 'section')
                                        div
                                            li.section(data-ref= item.id)
                                                a(href='/admin/report/detail/' + item.id)
                                                    = item.name
                                            - var sec = item.id
                                                ol.sortable
                                                    each item in report
                                                        if (item.parent === sec && item.type === 'page')
                                                            div
                                                                li.page(data-ref= item.id)
                                                                    a(href='/admin/report/detail/' + item.id)
                                                                        = item.name
                                                                - var page = item.id
                                                                    ol.sortable
                                                                        each item in report
                                                                            if (item.parent === page && item.type === 'subpage')
                                                                                div
                                                                                    li.subpage(data-ref= item.id)
                                                                                        a(href='/admin/report/detail/' + item.id)
                                                                                            = item.name

It should produce a hierarchical table of contents. Since the project is still in development, I've taken out all extraneous information. Here is the report object that is sent to jade from express (in the form {report: following array}):

    {
      "id": 42,
      "name": "Some Page Name",
      "type": "page",
      "parent": 40,
      "ordering": 1
    },
    {
      "id": 84,
      "name": "Some Page Name",
      "type": "page",
      "parent": 83,
      "ordering": 1
    },
    {
      "id": 29,
      "name": "Some Page Name",
      "type": "page",
      "parent": 28,
      "ordering": 1
    },
    {
      "id": 33,
      "name": "Some Page Name",
      "type": "page",
      "parent": 32,
      "ordering": 1
    },
    {
      "id": 55,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 54,
      "ordering": 1
    },
    {
      "id": 47,
      "name": "Some Page Name",
      "type": "page",
      "parent": 46,
      "ordering": 1
    },
    {
      "id": 5,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 4,
      "ordering": 1
    },
    {
      "id": 3,
      "name": "Some Page Name",
      "type": "page",
      "parent": 2,
      "ordering": 1
    },
    {
      "id": 83,
      "name": "Some Section Name",
      "type": "section",
      "parent": 80,
      "ordering": 1
    },
    {
      "id": 21,
      "name": "Some Page Name",
      "type": "page",
      "parent": 20,
      "ordering": 1
    },
    {
      "id": 63,
      "name": "Some Section Name",
      "type": "section",
      "parent": 62,
      "ordering": 1
    },
    {
      "id": 2,
      "name": "Some Section Name",
      "type": "section",
      "parent": 1,
      "ordering": 1
    },
    {
      "id": 40,
      "name": "Some Section Name",
      "type": "section",
      "parent": 36,
      "ordering": 1
    },
    {
      "id": 1,
      "name": "Some Chapter Name",
      "type": "chapter",
      "parent": null,
      "ordering": 1
    },
    {
      "id": 51,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 50,
      "ordering": 1
    },
    {
      "id": 28,
      "name": "Some Section Name",
      "type": "section",
      "parent": 1,
      "ordering": 2
    },
    {
      "id": 52,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 50,
      "ordering": 2
    },
    {
      "id": 4,
      "name": "Some Page Name",
      "type": "page",
      "parent": 2,
      "ordering": 2
    },
    {
      "id": 86,
      "name": "Some Section Name",
      "type": "section",
      "parent": 80,
      "ordering": 2
    },
    {
      "id": 36,
      "name": "Some Chapter Name",
      "type": "chapter",
      "parent": null,
      "ordering": 2
    },
    {
      "id": 64,
      "name": "Some Section Name",
      "type": "section",
      "parent": 62,
      "ordering": 2
    },
    {
      "id": 46,
      "name": "Some Section Name",
      "type": "section",
      "parent": 36,
      "ordering": 2
    },
    {
      "id": 30,
      "name": "Some Page Name",
      "type": "page",
      "parent": 28,
      "ordering": 2
    },
    {
      "id": 85,
      "name": "Some Page Name",
      "type": "page",
      "parent": 83,
      "ordering": 2
    },
    {
      "id": 56,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 54,
      "ordering": 2
    },
    {
      "id": 34,
      "name": "Some Page Name",
      "type": "page",
      "parent": 32,
      "ordering": 2
    },
    {
      "id": 48,
      "name": "Some Page Name",
      "type": "page",
      "parent": 46,
      "ordering": 2
    },
    {
      "id": 22,
      "name": "Some Page Name",
      "type": "page",
      "parent": 20,
      "ordering": 2
    },
    {
      "id": 87,
      "name": "Some Section Name",
      "type": "section",
      "parent": 80,
      "ordering": 3
    },
    {
      "id": 31,
      "name": "Some Page Name",
      "type": "page",
      "parent": 28,
      "ordering": 3
    },
    {
      "id": 35,
      "name": "Some Page Name",
      "type": "page",
      "parent": 32,
      "ordering": 3
    },
    {
      "id": 62,
      "name": "Some Chapter Name",
      "type": "chapter",
      "parent": null,
      "ordering": 3
    },
    {
      "id": 15,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 4,
      "ordering": 3
    },
    {
      "id": 23,
      "name": "Some Page Name",
      "type": "page",
      "parent": 20,
      "ordering": 3
    },
    {
      "id": 141,
      "name": "Some Page Name",
      "type": "page",
      "parent": 46,
      "ordering": 3
    },
    {
      "id": 20,
      "name": "Some Section Name",
      "type": "section",
      "parent": 1,
      "ordering": 3
    },
    {
      "id": 142,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 50,
      "ordering": 3
    },
    {
      "id": 143,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 54,
      "ordering": 3
    },
    {
      "id": 16,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 4,
      "ordering": 4
    },
    {
      "id": 32,
      "name": "Some Section Name",
      "type": "section",
      "parent": 1,
      "ordering": 4
    },
    {
      "id": 80,
      "name": "Some Chapter Name",
      "type": "chapter",
      "parent": null,
      "ordering": 4
    },
    {
      "id": 58,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 54,
      "ordering": 4
    },
    {
      "id": 50,
      "name": "Some Page Name",
      "type": "page",
      "parent": 46,
      "ordering": 4
    },
    {
      "id": 18,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 4,
      "ordering": 5
    },
    {
      "id": 59,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 54,
      "ordering": 5
    },
    {
      "id": 54,
      "name": "Some Page Name",
      "type": "page",
      "parent": 46,
      "ordering": 5
    },
    {
      "id": 19,
      "name": "Some Subpage Name",
      "type": "subpage",
      "parent": 4,
      "ordering": 6
    }
  ]

[ForbesLindesay]

I've just found a simple fix that decreases the parsing time of that function by a factor of 5 from 1 second to 250ms

[ForbesLindesay]

Right, https://github.com/substack/lexical-scope/pull/17 will make a colossal difference to performance (It should make templates take about a quarter of the time to render based on the jsperf)

[akshayme]

Awesome!

[ForbesLindesay]

I have an alternative fix now. It reduces the time taken from 1 second to about 100ms so about 10 times. It uses UglifyJS instead of esprima. This also helps as UglifyJS has very battle hardened and performant code for working out what variables reference what.