Slow parsing of template since upgrade from 2.2.0 to current version

[JuergenMang]

Hello,

first: great work!

I use this project to parse a template with ~2000 lines. I implemented it originally with the 2.2.0 version of this project. After upgrading to the current version, the parsing is much slower. It seems this is a similar issue as #69.

Attached is a obfuscated template.

template.json

[cogito-ray]

I am having the same issue with slowness. I had to upgrade from 2.2 to 3 because I needed to use --allow-function-arguments which was not working as expected in 2.2. It worked fine in 3. I use mo to process a bunch of templates in automation - all processing uses the same input file and the typical render time is usually seconds but sub 20 seconds. The only delta is the template file. Now some files take longer than others.

File size (bytes) -> Render time (minutes:seconds)

22212 -> 02:33 12876 -> 00:09 10110 -> 00:17 36411 -> 13:51

Those are my 4 largest template files.

When I moved from 2.2 to 3 I created a wrapper to mo to execute mo with the allow-function-arguments. If I have some more time I will try to further analyze my templates, their sizes and possibly do some bench marking with 2.2 and 3.0. I'll instrument my code to gather some timing and try to report back.

[cogito-ray]

Here is some profiling data - elapsed time and size for various templates that we process. The template name has been hashed. It is an sdiff - left is mo3 and right is mo2.2. I plan to start using the various different versions of mo to see if I can identify when the problem started.

ee34998a17 00:00:00 1429 ee34998a17 00:00:00 1429 d2398912a3 00:00:00 1048 | d2398912a3 00:00:01 1048 98db4a2e32 00:00:01 2831 | 98db4a2e32 00:00:00 2831 4b24233c8b 00:00:01 1559 | 4b24233c8b 00:00:00 1559 1427eb04a7 00:00:10 12876 | 1427eb04a7 00:00:01 12876 16694d2c93 00:00:01 4685 | 16694d2c93 00:00:00 4685 631d3f7090 00:00:01 5000 631d3f7090 00:00:01 5000 e45cfd9dcb 00:02:02 22212 | e45cfd9dcb 00:00:03 22212 314f9f4924 00:00:00 302 314f9f4924 00:00:00 302 b08fae1d7e 00:00:00 1145 b08fae1d7e 00:00:00 1145 a14bffd868 00:00:00 1130 a14bffd868 00:00:00 1130 11a7c0754f 00:00:00 301 11a7c0754f 00:00:00 301 1a841f5abe 00:00:01 1125 | 1a841f5abe 00:00:00 1125 cb05d50308 00:00:00 1127 cb05d50308 00:00:00 1127 9ee3f540ab 00:00:00 565 9ee3f540ab 00:00:00 565 dba1dcfbde 00:00:01 1162 dba1dcfbde 00:00:01 1162 3d369a71d7 00:00:15 10110 | 3d369a71d7 00:00:01 10110 ed9f96c032 00:00:01 1492 | ed9f96c032 00:00:00 1492 86552d567e 00:00:00 961 | 86552d567e 00:00:01 961 6e573811b8 00:00:05 5603 | 6e573811b8 00:00:00 5603 126ab4c11b 00:00:00 1013 | 126ab4c11b 00:00:01 1013 687b1dd5a1 00:00:00 1028 687b1dd5a1 00:00:00 1028 ce9d90adb7 00:00:01 1219 | ce9d90adb7 00:00:00 1219 268264fff6 00:00:00 1000 268264fff6 00:00:00 1000 704fe72a9e 00:00:00 1013 704fe72a9e 00:00:00 1013 682705aad2 00:00:00 1013 | 682705aad2 00:00:01 1013 4073dd165a 00:00:01 1043 | 4073dd165a 00:00:00 1043 16921ee225 00:00:00 1361 16921ee225 00:00:00 1361 a3a131f022 00:00:00 1513 | a3a131f022 00:00:01 1513 14eef037a9 00:00:00 1061 14eef037a9 00:00:00 1061 0bbf5cf130 00:00:05 6325 | 0bbf5cf130 00:00:01 6325 b7ef6fa7bc 00:00:02 8805 | b7ef6fa7bc 00:00:00 8805 529cc59ef9 00:00:00 1938 529cc59ef9 00:00:00 1938 6d796c091a 00:00:00 442 6d796c091a 00:00:00 442 459d03cbe4 00:00:01 1415 459d03cbe4 00:00:01 1415 1bb69883c0 00:00:00 2517 1bb69883c0 00:00:00 2517 6ba007f007 00:00:02 2646 | 6ba007f007 00:00:00 2646 58d890bfd7 00:00:00 739 | 58d890bfd7 00:00:01 739 3836a4a43d 00:00:00 1648 3836a4a43d 00:00:00 1648 49940172a2 00:00:03 4653 | 49940172a2 00:00:01 4653 4fcca2ecc5 00:00:00 1343 4fcca2ecc5 00:00:00 1343 169d40d53f 00:00:01 1343 | 169d40d53f 00:00:00 1343 4d163b112a 00:00:00 1275 4d163b112a 00:00:00 1275 abfb8125cb 00:00:00 740 abfb8125cb 00:00:00 740 ef331187f5 00:00:00 2369 ef331187f5 00:00:00 2369 c0c553405c 00:00:01 961 c0c553405c 00:00:01 961 90faa5cd43 00:00:00 1261 90faa5cd43 00:00:00 1261 04031fb92d 00:00:02 3631 | 04031fb92d 00:00:01 3631 7751af51f1 00:00:00 1103 7751af51f1 00:00:00 1103 0c12998e69 00:00:01 1529 | 0c12998e69 00:00:00 1529 2074ca568a 00:00:04 5829 | 2074ca568a 00:00:01 5829 195f5a2678 00:00:00 961 195f5a2678 00:00:00 961 afa0bb539a 00:00:08 6980 | afa0bb539a 00:00:01 6980 6c4d36e72e 00:00:00 1492 6c4d36e72e 00:00:00 1492 73d96714c1 00:00:01 1228 | 73d96714c1 00:00:00 1228 75613dd4ae 00:00:00 927 75613dd4ae 00:00:00 927 0b2438a041 00:00:11 8195 | 0b2438a041 00:00:02 8195 f6573fcc37 00:00:00 1631 f6573fcc37 00:00:00 1631 19cb507bc2 00:00:01 3709 19cb507bc2 00:00:01 3709 14217b0278 00:00:02 3581 | 14217b0278 00:00:00 3581 08c8bf98b1 00:00:00 550 08c8bf98b1 00:00:00 550 48e8805952 00:00:00 1143 | 48e8805952 00:00:01 1143 f24a226bdf 00:00:06 6232 | f24a226bdf 00:00:01 6232 381d14183c 00:00:00 1539 381d14183c 00:00:00 1539

[cogito-ray]

Slowness was introduced in 3.0.2.

[cogito-ray]

I looked at the code diffs and they are substantial enough that it would take some time to dig into it. I reverted back to 2.2.0 and figured out a different way to deal with iterator functions to loop through an array of objects. Back to speedy rendering.

[fidian]

I found an easy way to replicate this problem and #69. Use a template that has something like this

{{X}}
Lots of content here. Lots of content here. Lots of content here. Lots of content here.
...

Just copy that "Lots of content" line about a thousand times and you'll see some severe slowdowns. Using a Bash profiling tool, I was able to find what was consuming all of the time and it was a simple string replacement. Four lines similar to this one.

MO_CONTENT=${MO_CONTENT# }

I wrapped those statements in conditions to only execute the ones that are required, which helped immensely. Template processing time for my terrible example went from about 6 seconds to 0.5 seconds. I'm able to process the attached template.json in about 8 seconds instead of 30.

@JuergenMang what speeds were you expecting to see? Could you check if the new version does what you need?

[JuergenMang]

Many thanks for investigating. The new version is factor three faster than 3.0.4.

v3.0.4: 64s v3.0.5: 20s

For me it is now fast enough, but event faster would be always better ;)