Waiting for UI takes long time

statiolake commented 4 years ago

Neovim-Qt takes 2 - 3 secs to startup. This is a part of startup log obtained by nvim-qt.exe -- --startuptime startup.log:

times in msec
 clock   self+sourced   self:  sourced script
 clock   elapsed:              other lines

000.028  000.028: --- NVIM STARTING ---
021.439  021.411: locale set
022.292  000.853: inits 1
022.321  000.030: window checked
022.332  000.011: parsing arguments
022.523  000.190: expanding arguments
022.602  000.079: inits 2
026.355  003.753: init highlight
027.260  000.906: waiting for UI
2700.525  2673.265: done waiting for UI
2700.551  000.026: initialized screen early for UI
2700.622  000.071: --cmd commands

(...snip...)

3151.830  000.010: --- NVIM STARTED ---

Even if I use --clean flag the result is almost same (except ommited parts on above output, as --clean doesn't load my vimrc), so I believe this is not related to my Vim configs or plugins. Also there's no problem with console version of Neovim, it takes only 30-40 msecs in waiting for UI.

Environment

OS: Windows 10 1903 18917.1000 (Insider Preview)
Antivirus software: Windows Security (builtin)
- I excluded nvim.exe, nvim-qt.exe and directory Neovim is installed in.
- Anti-malware software doesn't seem to be active during Neovim-qt is starting up according to its CPU usage, so I think it is not due to it.
Neovim version: NVIM v0.5.0-233-g76d1e9360
Neovim-Qt version: 0.2.15
- I downloaded it from "Release" tab on Github.
- The version included in Neovim distribution also has the same issue.

jgehrig commented 4 years ago

This sounds similar to Issue #606

Can you downgrade nvim.exe and see if this issue persists? nvim-qt --nvim {path to old version of nvim}

statiolake commented 4 years ago

I retried measurement with the same setting (Neovim 0.5.0 with Neovim-Qt 0.2.15):

045.724  001.054: waiting for UI
3558.373  3512.649: done waiting for UI

I don't know why it is slower than yesterday, but for now I focus on the difference between various versions.

I downloaded Neovim 0.4.3, 0.3.8 and 0.3.0. Then I ran the bundled version of Neovim-qt.

Neovim 0.4.3 (current stable):

062.247  003.056: waiting for UI
4033.856  3971.608: done waiting for UI

Neovim 0.3.8:

041.934  000.370: waiting for embedder to make request
3834.852  3792.918: done waiting for embedder

For Neovim 0.3.0, there was no entry like "waiting for UI". The behavior also seemed quite different from current version.

I don't see any significant differences between versions. All of them takes 3-4 seconds before main window appears.

It seems issue #606 is about some delay after the UI appears, but this issue is about time before the UI appears. It may be related, but I think they are not identical.

equalsraf commented 4 years ago

Interesting, any chance this is somehow specific to windows?

Here are my linux times

037.779  000.871: waiting for UI to make request
138.163  100.383: done waiting for UI

The times above (2s/3s) seem high specially if we consider at this point nvim-qt has already started and spawned nvim until it calls nvim_ui_attach() (or so I assume).

Barring some advanced tooling for profiling in windows the best we can do to debug this is probably to add some strategic timestamped debug statements and logging using NVIM_QT_LOG=nvim-qt.log. Relevant locations are:

NeovimConnector::spawn (where nvim is started)
NeovimConnector::discoverMetadata (after nvim is started, triggers discovery)
Shell::init (which calls ui_attach)
Shell::setAttached (after ui_attach completes)

jgehrig commented 4 years ago

I cannot reproduce this issue on Windows. Perhaps the specific configuration of you system has some impact on this issue?

I don't know why it is slower than yesterday

The time is in the same order of magnitude. I would consider it unchanged.

I focus on the difference between various versions.

Each version looks similar. I would guess this is not a recent regression/version issue.

Questions

What is the exact download link you used?
Where is nvim.exe? Where is nvim-qt.exe?
Is there anything unique about your system/environment?
```
> where nvim
C:\tools\neovim\Neovim\bin\nvim.exe
```

where nvim-qt C:\tools\neovim\Neovim\bin\nvim-qt.exe

statiolake commented 4 years ago

In screenshot in #606 seems way faster than mine. The log pasted there is as follows:

016.495  000.202: waiting for UI
181.086  164.591: done waiting for UI

This is not so slow. So it seems not all Windows users have this issue. A matter of hardware performance? Even though my PC is a laptop, it has i5-8250U, 12GB memory and 512GB SSD. I don't think this is so low spec.

As other possible reasons, It may related that I'm using insider build of Windows. Or this laptop has 4K display so Hi-DPI environment may matter (but even if I downscale to 1920x1080, it change nothing on this issue).

statiolake commented 4 years ago

I focus on the difference between various versions.

Each version looks similar. I would guess this is not a recent regression/version issue.

Sorry for my poor English, I also think there is almost no difference between versions.

I used this link to get newest Neovim-Qt: https://github.com/equalsraf/neovim-qt/releases/download/v0.2.15/neovim-qt.zip. To get the newest Neovim, https://github.com/neovim/neovim/releases/download/nightly/nvim-win64.zip. Both of them are from Github Release page.

Neovim/Neovim-Qt is placed at:


>where nvim.exe
C:\opt\GUI\Neovim\bin\nvim.exe

where nvim-qt.exe C:\opt\GUI\Neovim\bin\nvim-qt.exe


3. What I think is unique is in the above comment (sorry to submit the comment continuously. I thought I had submit the above comment but I hadn't, so I submit the message just now).

Just now I built Neovim-Qt on my machine. I'm not an expert but I'll try looking into it as much as I can.

statiolake commented 4 years ago

Ok, I probably found the main cause of this issue. That is the number of fonts installed on my machine. I have installed more than 1,100 fonts on my PC. I reduced them to 800, then:

026.171  000.774: waiting for UI
1293.745  1267.573: done waiting for UI

This is much faster. So I could reduce more time if I removed more fonts. but I cannot reduce fonts anymore because most of fonts left are bundled with Microsoft Office.

I built Neovim-Qt in debug mode and make some tweak in logger so that I can see when the debug log is written; Then I enable the logging (set NVIM_QT_LOG=log.txt & set QT_LOGGING_RULES=*.debug=true) and run the built Neovim-Qt. The log.txt contains many lines like below (the number surrounded by [] is elapsed msecs since the logger is called for the first time):

[154] QWindowsFontDatabase::fontEngine FONTDEF QFontDef(Family="MS UI Gothic", pointsize=9, pixelsize=12, styleHint=5, weight=50, stretch=100, hintingPreference=0) 0x362ceb0 0x0
[156] "Agency FB"
[156] "addFontToDatabase Agency FB 0 TTF=1 TRUETYPE scalable=1 Size=65535 Style=0 Weight=50 stretch=100"
[157] Adding font "Agency FB" 50 QFont::StyleNormal 0 aa false fixed false
[158] "addFontToDatabase Agency FB 0 TTF=1 TRUETYPE scalable=1 Size=65535 Style=0 Weight=75 stretch=100"
[159] Adding font "Agency FB" 75 QFont::StyleNormal 0 aa false fixed false
[160] "Alef"
[160] "addFontToDatabase Alef 0 TTF=1 TRUETYPE scalable=1 Size=65535 Style=0 Weight=50 stretch=100"
[162] Adding font "Alef" 50 QFont::StyleNormal 0 aa false fixed false

... snip ...

[2190] "ＭＳ Ｐゴシック"
[2190] "addFontToDatabase ＭＳ Ｐゴシック 128 TTF=1 TRUETYPE scalable=1 Size=65535 Style=0 Weight=50 stretch=100"
[2191] Adding font "ＭＳ Ｐゴシック" 50 QFont::StyleNormal 0 aa false fixed false
[2191] "ＭＳ Ｐ明朝"
[2192] "addFontToDatabase ＭＳ Ｐ明朝 128 TTF=1 TRUETYPE scalable=1 Size=65535 Style=0 Weight=50 stretch=100"
[2195] Adding font "ＭＳ Ｐ明朝" 50 QFont::StyleNormal 0 aa false fixed false

Based on this, it takes long time registering all fonts installed on my machine to some database. Can it be avoided?

statiolake commented 4 years ago

Update This does reduce the startup time, but same delay appears after the window appears.

I found that removing "Retry" button from ErrorWidget solves this issue (of course "Retry" button is gone):

namespace NeovimQt {

ErrorWidget::ErrorWidget(QWidget *parent)
:QWidget(parent), m_errorLabel(0), m_closeButton(0)
{
    m_errorLabel = new QLabel();
    // m_closeButton = new QPushButton(tr("Retry"));

    m_image = new QLabel();
    m_image->setPixmap(QPixmap(":/neovim.png").scaled(64, 64, Qt::KeepAspectRatio));

    // connect(m_closeButton, &QPushButton::clicked,
    //      this, &ErrorWidget::reconnectNeovim);

    QHBoxLayout *inner_layout = new QHBoxLayout();
    inner_layout->addStretch();
    inner_layout->addWidget(m_image);
    inner_layout->addWidget(m_errorLabel);
    // inner_layout->addWidget(m_closeButton);
    inner_layout->addStretch();
    QVBoxLayout *outer_layout = new QVBoxLayout();
    outer_layout->addStretch();
    outer_layout->addLayout(inner_layout);
    outer_layout->addStretch();
    setLayout(outer_layout);
}

void ErrorWidget::setText(const QString& text)
{
    m_errorLabel->setText(text);
}

void ErrorWidget::showReconnect(bool on)
{
    // m_closeButton->setVisible(on);
}

} //Namespace

After commenting out that line, now it is way faster than before. Now it launches in the same time with others.

026.789  000.804: waiting for UI
124.122  097.333: done waiting for UI

The result is same if I entirely remove ErrorWidget:

MainWindow::MainWindow(NeovimConnector *c, ShellOptions opts, QWidget *parent)
:QMainWindow(parent), m_nvim(0), m_errorWidget(0), m_shell(0),
    m_delayedShow(DelayedShow::Disabled), m_tabline(0), m_tabline_bar(0),
    m_shell_options(opts), m_neovim_requested_close(false)
{
    m_errorWidget = new ErrorWidget();
    // m_stack.addWidget(m_errorWidget); // <-- comment out
    connect(m_errorWidget, &ErrorWidget::reconnectNeovim,
            this, &MainWindow::reconnectNeovim);
    setCentralWidget(&m_stack);

    init(c);
}

Update this is not a fundamental solution at all.

I'm not sure, but it can be related to how Qt determines system font for button caption rendering. Anyway, error widget doesn't appear so often in daily use. Is it possible to stop always adding it to the MainWindow but on-demand? Or, personally I never use "retry" button, so if others doesn't use the button either, it is an option to remove the button from ErrorWidget.

For now I'll use this custom built Neovim-Qt for my daily use.

statiolake commented 4 years ago

I find a way to resolve the issue including after startup. In addition to removing retry button, disabling font merging (QFont::NoFontMerging) makes it fine:

--- a/src/gui/shellwidget/shellwidget.cpp
+++ b/src/gui/shellwidget/shellwidget.cpp
@@ -45,7 +45,7 @@ bool ShellWidget::setShellFont(const QString& family, qreal ptSize, int weight,                     
        f.setStyleName(QStringLiteral(""));

        f.setPointSizeF(ptSize);
-       f.setStyleHint(QFont::TypeWriter, QFont::StyleStrategy(QFont::PreferDefault | QFont::ForceIntegerMetrics));
+       f.setStyleHint(QFont::TypeWriter, QFont::StyleStrategy(QFont::PreferDefault | QFont::ForceIntegerMetrics | QFont::NoFontMerging));
        f.setFixedPitch(true);
        f.setKerning(false);

Of course now we cannot see glyphs that the specified font doesn't have as it disables font fallbacking (e.g. we cannot see CJK characters when "Consolas" font is selected). But personally I'm OK for that.

So both of them is required.

Removing ErrorWidget
Disabling font merging

I don't know if it is a solution for everyone because it removes some functionality I mensioned above, though.

jgehrig commented 4 years ago

@statiolake

Nice work finding the cause!

I agree, the changes aren't a good candidate for merge yet. The ErrorWidget is less of a concern, but modifying ShellWidget::setShellFont could cause characters to no longer display. I would guess this issue isn't impacting many people, but the fix might. I don't think QFont::NoFontMerging should be on by default.

I still cannot reproduce the issue on any of my Windows machines (less fonts installed). This sounds like a Qt performance issue...

I'm curious... Have you tried different Qt versions? Have you found any Qt bugs related to this scenario?

statiolake commented 4 years ago

Yes, I also think making QFont::NoFontMerging default has large impact.

I installed both normal Neovim-Qt and my tweaked Neovim-Qt to another Windows laptop and I confirmed the issue was reproduced. The log shows almost same reason --- populating fonts is slow. So far I don't know what is the difference between reproducible environment and non-reproducible one.

(It's highly uncertain and just an idea, but installing (a lot of) CJK fonts can cause the issue if the size of each font affects the time to load that font. This is because CJK fonts tends to have much larger size than English ones. If so, Japanese version of Windows can cause this issue as it is (of course) shipped with additional Japanese system fonts for Windows UI. Again this is just an idea to explain the difference between reproducible environment and non-reproducible one, no experiments to support this idea is made. Note that the second laptop I confirmed the issue is not insider preview, so it wouldn't the cause.)

I tried only Qt 5.12.6. I'm not familiar with Qt (This is the first time I use Qt), so I don't know this is a common issue for Qt. Though it seems less relevant, I hit this bug report during googling: https://bugreports.qt.io/browse/QTBUG-54180?. I would try Qt 5.6 if it were available for now, but it seems it cannot be installed with current Qt installer (minimum version was 5.9).

drichardson commented 4 years ago

Nothing really to add to the solution, but in case future me stumbles on this perf issue again, I found this PowerShell snippet useful for comparing gvim and nvim-qt startup speeds on Windows:

(Measure-Command { cmd /C "start /wait gvim --clean +q" }).TotalSeconds
(Measure-Command { cmd /C "start /wait nvim-qt -- --clean +q" }).TotalSeconds

When I ran this, I got 0.126356 for gvim and 0.9685518 for nvim-qt.

RnYi commented 3 years ago

I met with the same problem, you are right, I delete some Chinese font and then nvim-qt startup faster.

RnYi commented 3 years ago

I met with the same problem, you are right, I delete some Chinese font and then nvim-qt startup faster.

But this problem doesn't appear while using gvim and neovim without gui.

lll9p commented 3 years ago

Got the same problem.

0.4128677 for gvim and 1.989674 for nvim-qt

Nothing really to add to the solution, but in case future me stumbles on this perf issue again, I found this PowerShell snippet useful for comparing gvim and nvim-qt startup speeds on Windows:
(Measure-Command { cmd /C "start /wait gvim --clean +q" }).TotalSeconds
(Measure-Command { cmd /C "start /wait nvim-qt -- --clean +q" }).TotalSeconds
When I ran this, I got 0.126356 for gvim and 0.9685518 for nvim-qt.

tejasvi commented 2 years ago

Can font merging be done async? I won't mind seeing emojis couple of seconds later as long as it starts up fast.

akiyosi commented 2 years ago

Perhaps this issue is related to the following bug report.

https://bugreports.qt.io/browse/QTBUG-71737

Also, the Qt bug report seems to be even more relevant.

https://bugreports.qt.io/browse/QTBUG-59360 https://bugreports.qt.io/browse/QTBUG-74917

Reading these threads, it seems that the fix is working in Qt6.

FelipeLema commented 2 years ago

thanks, @akiyosi for coming all the way from goneovim to here to add this very helpful info

hinell commented 1 year ago

Weirdly, I've very fast startup time, but it feels a bit slower compared to raw konsole or xterm. The latter are much faster when I switch tabs. Some benchmarking would be handy.

akiyosi commented 1 year ago

Additional information. If we specify a font family that holds so many glyphs that font merging is not necessary as the default font for an application, the process of building the fontdatabase at startup (or when drawing with qpainter) does not seem to occur. I have confirmed that the process pointed out by https://github.com/equalsraf/neovim-qt/issues/614#issuecomment-565514722 does not occur when I specify the font Cica as the default font for the application.

UPDATE: Note that even if a font has sufficient glyphs, if italic or bold is used by colorscheme, the process of searching for italic or bold font families will be performed, and in this case, the font database construction process will also be executed, which may take a long time.

equalsraf / neovim-qt

Waiting for UI takes long time #614

Environment