High CPU usage when document is large

rongcuid commented 2 years ago

Description

When a document gets up to >2000 lines, typing causes high instantaneous CPU usage and long lags in preview window

System Information

Version: 1.67.2
Commit: c3511e6c69bb39013c4a4b7b9566ec1ca73fc4d5
Date: 2022-05-17T18:23:40.286Z
Electron: 17.4.1
Chromium: 98.0.4758.141
Node.js: 16.13.0
V8: 9.8.177.13-electron.0
OS: Linux x64 5.18.10-76051810-generic

To Reproduce

Create a document with thousands of lines. Enable extension, and type in document. Monitor the CPU usage.

ggrossetie commented 2 years ago

I'm using the "AsciiDoc Syntax Quick Reference" document which has 2500 lines and I don't notice high CPU usage. Could you please share your settings? Maybe you are using a low refresh interval? Could you do a screencast?

rongcuid commented 2 years ago

Here are all settings combined:

    "asciidoc.use_kroki": true,
    "asciidoc.preview.style": ".asciidoctor/preview-stylesheet.css"

And the stylesheet (which is used to solve some incorrect character mappings from the default fonts, but that is a separate problem):

* {
    font-family: "Noto Sans CJK SC";
}

I will need to figure out how to do a screencast for this.

rongcuid commented 2 years ago

Sorry, the system monitor is not fine-grained enough to capture this. But the CPU temperature spikes 20-30 C when I type in the document. I will try to reproduce one with meaningless text

Plain document doesn't seem to have this problem. However, the text I have this problem contains a lot of blocks.

gabezal commented 1 year ago

I ran into this issue while trying to preview a large (generated) file recently. The extension would take almost 2 minutes or more to render it, during which the extension-host process (node process) would use up 100% of a CPU core.

I took some time to investigate, and realized that the extension wasn't actually using the installed asciidoctor (or asciidoctor-pdf) commands, and after toggling off all of the other options (I think I am now left with just asciidoctor-pdf enabled), the preview is rendered almost instantly. If my understanding of the extension's settings is correct, it uses some "internal renderer" by default, which probably has a bug somewhere, causing it to choke on large files.

Maybe the settings are a bit confusing in this regard, because I assumed that if asciidoctor_command and/or asciidoctorpdf_command were set correctly (they are, by default), I wouldn't have to mess with any of the other settings to get the extension to use these. There are 2 other settings that seem to affect the outcome:

use_asciidoctor_js (enabled by default; I toggled it off);
use_asciidoctorpdf (disabled by default; I toggled it on).

These should probably all be merged into a single setting, where the user can choose what to use in one go, to avoid the confusion.

I don't know why the internal renderer is so slow, but the file which reproduces this is not a complete asciidoc document, just partial content meant to be included into another document. However, the content itself is pretty simple, as it is just a really long list (as in thousands of entries) similar to this:

=== section1
section1 desc

[[link1_1]]
name1_1::
+
--
desc1_1
--
[[link1_2]]
name1_2::
+
--
desc1_2
--

=== section2
section2 desc

[[link2_1]]
name2_1::
+
--
desc2_1
--
[[link2_2]]
name2_2::
+
--
desc2_2
--

I'm using v2.8.9, via Remote-SSH, if that matters. Unless the internal renderer was updated since, I don't think this is fixed?

I do remember reading somewhere that the internal renderer is "experimental"? Maybe I didn't think much of it then, but now it seems like something that should be emphasized, and the steps required to disable it should be made more visible wherever it was that I read this.

ggrossetie commented 1 year ago

I do remember reading somewhere that the internal renderer is "experimental"? Maybe I didn't think much of it then, but now it seems like something that should be emphasized, and the steps required to disable it should be made more visible wherever it was that I read this.

Starting with 3.x, the 'internal renderer' (based Asciidoctor.js) is the default: https://github.com/asciidoctor/asciidoctor-vscode/releases/tag/v3.0.0

Could you please try to open the same document using version 3.0.3. You will have to click on "Switch to Pre-Release Version" on the installed extension.

I'm using v2.8.9, via Remote-SSH, if that matters. Unless the internal renderer was updated since, I don't think this is fixed?

The latest version is 2.9.8 and Asciidoctor.js was updated.

gabezal commented 1 year ago

v3.0.3 is a bit faster: it takes approx. 40 seconds instead of 2 minutes to render the file. The CPU usage remains high during this time.

But still not as fast as v2.8.9 with asciidoctor-js disabled: this takes only around 1 second or so to render the same file.

I've noticed that the option to disable the asciidoctor-js renderer in favor of using the asciidoctor command is also gone?

EDIT: I've also just tried v2.9.8, and it is faster than v3.0.3: rendering with asciidoctor-js enabled takes only ~14 seconds. I'll stay on this for now, since it seems to be the last version to support disabling asciidoctor-js in favor of the native command.

ggrossetie commented 1 year ago

EDIT: I've also just tried v2.9.8, and it is faster than v3.0.3: rendering with asciidoctor-js enabled takes only ~14 seconds. I'll stay on this for now, since it seems to be the last version to support disabling asciidoctor-js in favor of the native command.

When using the asciidoctor command line a few features are disabled because we only get the HTML. When using Asciidoctor.js we can retrieve document attributes, source lines, etc... in order to provide completions, scroll sync and other features.

Could you please share a sample reproduction case? Otherwise I won't be able to troubleshoot. The sample you've provided is fast to render and I didn't notice any issue.

I've noticed that the option to disable the asciidoctor-js renderer in favor of using the asciidoctor command is also gone?

Yes, you can read the release note to learn more: https://github.com/asciidoctor/asciidoctor-vscode/releases/tag/v3.0.0 Under the "Breaking changes" section, we explain how to use the asciidoctor command line using both the HTML Preview and Run on Save extensions.

gabezal commented 1 year ago

Could you please share a sample reproduction case? Otherwise I won't be able to troubleshoot. The sample you've provided is fast to render and I didn't notice any issue.

Try this:

test.zip

It's just a the previous sample, copy pasted a ton of times to get a large file. It still reproduces the issue for me, just like my original file.

I'm testing this both on an older (2010-ish) Windows 7 machine (AMD Phenom II x4 3.4GHz), and on a VirtualBox VM with XUbuntu (same host machine, but with only two of the four CPU cores allocated to the VM). The behavior is the same in both cases.

I've just noticed that even with v2.9.8, sometimes it takes around 15 seconds to show the preview, while other times it can take 40 or so seconds. It seems to take a random amount of time without even modifying anything in the file, just by closing and re-opening the preview. But AFAICT, it never takes less than ~ 15 seconds till the preview shows up.

I'm not going to re-test with v3.0.3, since IIRC, I've already noticed that it's rendering time is also somewhat random after I wrote my previous reply.

I also have a newer Ryzen 5000 laptop that I can test on (I'd have to install VS Code on it), but I think that would defeat the purpose of figuring out what the problem is?

EDIT: Here's a CPU Profile I captured of the extension while it was rendering the sample file: CPU-20221229T032414.116Z.cpuprofile.zip

I'm not a JS developer, so I can't make heads or tails of it, but maybe it helps you figure out where the problem lies.

ggrossetie commented 1 year ago

It takes ~2-3 seconds on my machine:

fast

EDIT: Here's a CPU Profile I captured of the extension while it was rendering the sample file: CPU-20221229T032414.116Z.cpuprofile.zip

Thanks, that's very useful. Apparently, a lot of time is spent on https://github.com/opal/opal/blob/9b19e21020b5f5d8ccf57896afe31483e20e6188/opal/corelib/string.rb#LL516C14-L516C40

Could you please copy/paste what you get from Help > About (it should open a popup). Thanks!

gabezal commented 1 year ago

Here you go:

Version: 1.70.2
Commit: e4503b30fc78200f846c62cf8091b76ff5547662
Date: 2022-08-16T05:35:13.448Z
Electron: 18.3.5
Chromium: 100.0.4896.160
Node.js: 16.13.2
V8: 10.0.139.17-electron.0
OS: Windows_NT x64 6.1.7601

1.70.2 is the last version of VS Code that works on Win7.

ggrossetie commented 1 year ago

Thanks! I cannot reproduce on my machine but I'm using a newer version (and I have a higher spec machine):

Version: 1.74.2 (user setup)
Commit: e8a3071ea4344d9d48ef8a4df2c097372b0c5161
Date: 2022-12-20T10:29:14.590Z
Electron: 19.1.8
Chromium: 102.0.5005.167
Node.js: 16.14.2
V8: 10.2.154.15-electron.0
OS: Windows_NT x64 10.0.19044
Sandboxed: No

I also have a newer Ryzen 5000 laptop that I can test on (I'd have to install VS Code on it), but I think that would defeat the purpose of figuring out what the problem is?

Could you still try with your newer laptop? What is the memory consumption on your older laptop? Could you please run asciidoctor on the same document prefixed by time (Linux). It should give you the time taken by the asciidoctor command. Asciidoctor.js is expected to be a bit slower but within a 10%-20% range. Please note that the extension is actually loading the document twice (once for autocompletion, and once for converting to HTML). So Asciidoctor.js takes 7 seconds to convert the document. So if asciidoctor takes 4-5seconds to convert it, that's expected.

gabezal commented 1 year ago

Could you still try with your newer laptop?

The new laptop seems to be a lot faster. The preview opens in 2 seconds or less.

Could you please run asciidoctor on the same document prefixed by time (Linux).

real    0m1.272s
user    0m1.175s
sys 0m0.096s

Asciidoctor.js is expected to be a bit slower but within a 10%-20% range.

Makes sense, but in this case the performance seems to be 6-7 times slower than asciidoctor?

What is the memory consumption on your older laptop?

I don't think memory is the bottleneck. I've only allocated 4GB to the Linux VM, but it never goes above 30-40% memory usage (plus 30-40% disk cache, which is probably irrelevant here). The swap is rarely used, even when I'm compiling large projects.

MiB Mem :   3924.0 total,   1064.5 free,   1405.9 used,   1453.6 buff/cache
MiB Swap:   4096.0 total,   4096.0 free,      0.0 used.   2217.7 avail Mem

Please note that the extension is actually loading the document twice (once for autocompletion, and once for converting to HTML). So Asciidoctor.js takes 7 seconds to convert the document.

Hm. I didn't even notice that it provides autocompletion. Probably because of https://github.com/asciidoctor/asciidoctor-vscode/issues/398.

However, it does seem that v2.9.8 is an improvement over v2.8.9, since I can no longer reproduce the sky-high 40 seconds or more preview delay.

I'm ok with using asciidoctor on the slower machine for a while. I've also been wanting to upgrade the CPU on it (it's a desktop, not a laptop), so this doesn't affect me that much.

I guess what you do about this depends on how old systems you want to support.

asciidoctor / asciidoctor-vscode