Closed kaba2 closed 1 year ago
James-Yu
commented
1 year ago The update does not commit anything new or changed, see https://github.com/James-Yu/LaTeX-Workshop/compare/v9.4.4...v9.4.5
If you believe this be a bug, I may need your help on profiling the behavior of the extension.
By the way, the extension is not specifically built to work with so many tex files referencing to each other. It's also hard to think of how you may manage that huge number of sources.
kaba2
commented
1 year ago I am writing a mathematical text which currently has about 400 pages. Each subsection is stored in its own .tex file (I anonymized my files in the logs above), and there are about 143 .tex files. These are put together using subfiles. Until this week, Latex Workshop has worked great, even with a project of this size. I've used it for several years during this project. With a text of this size, it is essential to partition into smaller .tex files to be able to quickly jump to the things I'm interested in (using Ctrl+P). Another reason is build speed. I need to repeatedly rebuild when writing the text, and then I only need the current subsection built. So I build the subfile instead to get a fast build, instead of a very slow build for the whole text. I can help you profile it.
kaba2
commented
1 year ago To be clear, what I mean by scanning is the time it takes to produce that attached log output when I start VsCode. It opens up my previously open folder which is the Latex project. So what I do is to switch between Latex Workshop versions and look at how long it takes, and that's how I get the 4x figure.
nidrissi
commented
1 year ago @James-Yu I am also seeing a huge slowdown since the recent update. Parsing a very simple tex file which contains a reference to PGF/TikZ makes the extension use 100% of a CPU for several minutes. (PGF/TikZ is a popular library for drawing pictures in LaTeX. There are 32,546 questions tagged pgf-tikz on tex.stackexchange. This is not some random library that no-one uses, and it contains many interrelated source files.)
The slowdown starts at this line in the logs:
[15:13:49][Cacher] Cannot parse AST, use RegExp on /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common.tex .Once that happens, every group of lines of the form
[15:13:51][Cacher] Updated elements of /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common.tex .
[15:13:51][Cacher] Updated bibs of /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common.tex .
[15:13:51][Cacher] Cached /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common.tex .
[15:13:51][Cacher] Adding /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common-lists.tex .
[15:13:51][Cacher] Found /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common-lists.tex from .fls %WS1%/main.fls .
[15:13:51][Cacher] Caching /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common-lists.tex .
[15:13:51][Cacher] Updated inputs of /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common-lists.tex .
[15:13:51][Cacher][Watcher] Watched /home/najib/.texlive2022/texmf-dist/tex/generic/pgf/utilities/pgfutil-common-lists.tex .takes several seconds to complete. And there are a lot of them. This adds up very quickly, and it happens whenever I close and reopen the workspace.
This is clearly an issue with the component called "Cacher". I don't know the internal working of the extension, but e14e029247 obviously changed something between v9.4.4 and v9.5.0.
This is probably related as it started happening at the same time, but now this (simple) document doesn't get an outline anymore.
James-Yu
commented
1 year ago Your issue is different. Please create a new issue. What is your latex-workshop.latex.watch.files.ignore config?
nidrissi
commented
1 year ago @James-Yu It's exactly the same issue. The cacher apparently runs many computations for a given file, it takes too long and hangs up the rest of the extension. It's all these lines of the following form that slow down parsing:
[Cacher] Updated elements of [...]
[Cacher] Updated bibs of [...]
[Cacher] Cached [...]It's the same issue that @kaba2 encountered, except that my files are library files, whereas theirs are their own files. But the core issue is the same: if too many files are referenced, the cacher slows down the parsing.
James-Yu
commented
1 year ago @nidrissi No, you extension is including files from texmf-dist folder, which should be excluded according to the config. The OP wants to handle large number of files in a project.
James-Yu
commented
1 year ago @kaba2 After carefully checking the diff, I still cannot identify the root of issue. May you share a working example for me to profile? If your work cannot be shared publicly, you may choose to email me or make a non-secret one.
kaba2
commented
1 year ago @James-Yu Ok. I will take my actual project and create a script to turn it into nonsense. It should still have the same structure.
kaba2
commented
1 year ago I made a script to remove equations. On my project I have the following timings:
9.4.5: 8 s 9.2.2: 4 s
That's a 2x slowdown. Compare to 49s with equations on 9.4.5.
So it seems to me that scanning the equations takes most of the time in 9.4.5. Does that make sense? I'm not sure why equations would need to be scanned.
I also made a script to randomize the words in my project. The problem is that I can only provide the without-equations-and-randomized version, i.e. what is timed above, because I have no way of randomizing the equations. But it is less useful, because most of the time is spent on equations.
kaba2
commented
1 year ago My equations are quite macro-heavy, and look like this:
\begin{eqs}
\image{f}{\bred{U}_{i + 1}} & = \image{f}{\nclosure[\bred{U}_i]{U_{i, 0} \cap \bred{U}_i} \cap U_{i + 1, 1} \setminus U_{i, 0}} \\
{} & = \image{f}{\nclosure[\bred{U}_i]{U_{i, 0} \cap \bred{U}_i}} \cap \image{f}{U_{i + 1, 1}} \setminus \image{f}{U_{i, 0}} \\
{} & = \nclosure[\image{f}{\bred{U}_i}]{\image{f}{U_{i, 0} \cap \bred{U}_i}} \cap V_{i + 1, 1} \setminus V_{i, 0} \\
{} & = \nclosure[{\bred[Y]{V}_i}]{\image{f}{U_{i, 0}} \cap \image{f}{\bred{U}_i}} \cap V_{i + 1, 1} \setminus V_{i, 0} \\
{} & = \nclosure[{\bred[Y]{V}_i}]{V_{i, 0} \cap \bred[Y]{V}_i} \cap V_{i + 1, 1} \setminus V_{i, 0} \\
{} & = \bred[Y]{V}_{i + 1}.
\end{eqs}Since my project is mathematics, there are a lot of equations. I was wondering whether the slowdown could be explained by some process having its time complexity increased from 9.2.2. to 9.4.5. Perhaps we are seeing a quadratic dependence here instead of linear (or similar), so that removing equations bring the times down more than excepted.
James-Yu
commented
1 year ago The message is very helpful! Indeed we use a latex parser to parse everything in a document now, including very complex equations. I’d like to invite you to join me on developing a solution to address the problem, on which I have some ideas. Will ping you shortly.
James-Yu
commented
1 year ago Let me first confirm, are you comparing 9.4.5 with 9.2.2 or 8.2.2?
kaba2
commented
1 year ago 9.2.2. Sorry had a typo; fixed it above.
Meanwhile, I threw another about 228 page document with mathematics to Latex Workshop. It is a single .tex file, and the caching is done in 1 s in 9.4.5. So it does not seem to be the size of the tex, but rather that it is in multiple subfiles.
James-Yu
commented
1 year ago Currently, multiple files are cached sequentially, one by one. That can be an issue, as many times the parsing can be parallel. This change may require fundamental changes to the LW logic, so I am still thinking on how to handle it.
kaba2
commented
1 year ago I have 153 pages of mathematics which I can give you for testing as it is. It consists of about 50 subfiles. The timings for this one are:
9.4.5 8 s 9.2.2 4 s
I reduced it from the larger project which has the 49s timing, and at first it kept that timing, but at some point when I was pruning the files it dropped. I think I can do a kind of binary search to pinpoint the problem.
kaba2
commented
1 year ago To test the hypothesis that this is a time complexity problem, I made a duplicate subfile tree in my large project: every file was duplicated, \subfile commands in the copies were changed to refer to copies, and then I added a new root file to tie both subfile tree together. The expectation was that it should roughly double the time. However, in 9.4.5 it instead quadrupled the time. This is consistent with a process changing from linear to quadratic time complexity. Measurements:
9.4.5 5 minutes (from 49 seconds) 9.4.4 50 seconds (from 16 seconds) 9.2.2 31 seconds (from 10 seconds)
Edit: Well they all seem quadratic. But something clearly is worse in 9.4.5.
James-Yu
commented
1 year ago Another thing: what can you do during the wait, for example edit, new line, view pdf? What can’t do for example suggestion, outline?
James-Yu
commented
1 year ago You may want to try the artifact in https://github.com/James-Yu/LaTeX-Workshop/actions/runs/3978105685 and see if problem is alleviated.
Note that the branch does not reduce the time on parsing equations, which should be consistent across the versions. I still cannot identify the exact reason of 4x time between .4 and .5.
James-Yu
commented
1 year ago Another thing that can be (and can only be) done on your side is to trace down exactly which commit between .4 and .5 that deteriorates the caching. @nidrissi referred to e14e029247ced7a6658ab4102999ebcb1525cc97 , but this commit involves only name change and null checking, and does not confirm the root of cause.
edit: You can find a green tick besides the commit id or message, clicking on which show a dropdown of test suites, in which an artifact of the extension (package) can be downloaded. If it is a red x, ignore the commit.
kaba2
commented
1 year ago Writing is really hard when the scanning is ongoing. Entering single characters is ok, but pressing enter takes a long time (1s - 2s). Autocomplete does not work, so cannot use that. I guess that improves as the scanning goes forward.
Yes I could binary search over the commits. How do I get a certain commit running on vscode? I'm a developer and can use git, but don't have experience on vscode extensions.
James-Yu
commented
1 year ago Every commit is associated with a series of GitHub Actions, which will package the commit into a packaged extension in vsix file format. You can get them from e.g. https://github.com/James-Yu/LaTeX-Workshop/compare/v9.4.4...v9.4.5 and the green ticks. Click on e.g., TeXLive on Linux, then Summary on the left, scroll down to see the artifact section, download and unzip the latex-workshop, and you get the vsix. Inside vscode, the Extension tab has an action on the top-right says Install from VSIX.
To address the real issue, a binary search may really be required. Nonetheless, e14e029247ced7a6658ab4102999ebcb1525cc97 might be a remedial solution, though the root remains unsolved.
kaba2
commented
1 year ago Ok. Here are the measurements:
9.2.2: 10s
9.3.0: 11s
9.3.0 -> 9.4.0 commits:
1706976: 13s (fix updating watcher option)
2598aaa: 11s (Merge pull request from biochemist)
0b1a640: 44s (Merge branch 'master' into cache-refactor)
88d5023: 44s (Unify extension data)
0278d64: 44s (Merge pull request from cache-refactor)
840546c: 44s (Change logger to module and start organizing logs)
544adf5: 44s (fix a backquote with out string formatting)
9.4.0: 44s
9.4.1: 44s
9.4.2: 44s
9.4.3: 44s
9.4.4: 24s
9.4.4 -> 9.4.5 commits:
165d17f: 24s (A better description to latex.watch.files.ignore)
e14e029: 24s (Get a cache should possibly return undefined)
1f234f4: 25s (fix a deepscan complaint)
58e49ae: 1m 4s (New command finder should honor arg and opt list)
9b36775: 1m 4s (Ditto for fall-back regex-based newcommand parsing)
7317024: 1m 3s (event bus should only be used for tests)
7b2f1d0: 1m 4s (BibTex and LaTeX formatters are singletons)
75d132c: 1m 4s (Cirumvent last formatter test on windows)
9.4.5: 1m 4sTwo commits stand out:
9.3.0 -> 9.4.0 commits:
0b1a640: 44s (Merge branch 'master' into cache-refactor)
Time goes 11s -> 44s.
9.4.3 -> 9.4.4
Time goes 44s -> 24s.
9.4.4 -> 9.4.5 commits:
58e49ae: 1m 4s (New command finder should honor arg and opt list)
Time goes 25s -> 1m 4s.
Edit:
9.5.0: 1m 5s
sleepymalc
commented
1 year ago I'm not sure whether this is the same issue I'm facing, but I'm also experiencing a significant slowdown in the recent update. Specifically, I'm using LaTeX-Workshop with HyperSnips; before, it worked great without lagging. But now, it starts to slow down significantly when dealing with a large file (about 700 lines with line wrap).
For comparison, in a smaller file (around 200 lines):
The profiling also suggests that the lagging is due to LaTeX-Workshop:
Not going to open a new issue since it might be a weird issue caused by the interplay between LaTeX-Workshop and Hypersnips, but I think it's worth bringing this up.
James-Yu
commented
1 year ago @kaba2 Awesome profiling! That is way more than I expected!
Now it seems more clear on the root. Will look into the issue.
In the meantime, do you have a slightly better typing experience on 9.5.0? Suggestions may be still delayed, but other LW features should (I guess) be normal during the caching.
edit: my bad, the above improvements should be in the efficient-cacher branch, which has not been released.
James-Yu
commented
1 year ago I have discovered two roots of the issue that may cause notable slowdown:
In cdbbe40d65dc3775ea77476cfd94e4f9894dc324, these two issues are resolved by advancing the duplicate command check and defer the package source check. The latter is also optimized by using a semi-static array of package commands that can be shared across all commands.
Can you please try on https://github.com/James-Yu/LaTeX-Workshop/actions/runs/3984050355 and see if the problem is resolved or at least getting better @kaba2 ? Note that the performance won't come back to pre-9.2 (hopefully comparable), as we introduced the optional and mandatory argument parsing for new commands, which has to introducing new logics and leads to computation.
kaba2
commented
1 year ago @James-Yu I tried your linked commit, and timed it to 7s! That's faster than 9.2.2. I'll have to do longer writing on it to test that everything works, but if so, then by all means the issue is resolved.
James-Yu
commented
1 year ago I think it's fine to call it a day. Issue resolved!
kaba2
commented
1 year ago Yes! Thanks for the fix, and also for writing LW in the first place, I'm using it every day!
Preliminary questions [Required]
Disable all the other extensions except for LaTeX Workshop, restart VS Code, and check that you still see this issue. [Required]
You still see this issue?: Yes
Make sure to visit the wiki FAQ before filling an issue.
You visited the wiki?: Yes
If your issue is with compiling a document (not having to do with finding the root file of a project), check first that you can compile manually.
You can compile a TeX document manually?: Yes
Describe the bug [Required]
After updating from 9.4.4 to 9.4.5, the time it takes to scan my files (when opening my folder) increases from 13s to 49s, which is almost 4x. This makes the UI unresponsive during the scanning.
To Reproduce
Steps to reproduce the behavior:
Expected behavior
Same speed as 9.4.4.
Logs [Required]
LaTeX Workshop Output [Required]
Developer Tools Console [Required]
Screenshots
-
Desktop [Required]
Please write exact version numbers. Please don't write
latestinstead of exact numbers.Additional questions
Are you using VSCodium?
No
Are you using the Snap or Flatpack versions of VS Code?
No
Are you using LaTeX Workshop with VS Code Remote?
No
If the answer is Yes, please write which one you are using. Write the versions of the remote extension.
Additional context
Add any other context about the problem here.