[MU4 Issue] Long delay to open Format->Style page

[charlesneimog]

Describe the bug There is a large delay between clicking the Style page and its display.

To Reproduce Steps to reproduce the behavior:

1. Go to 'Format->Style';
2. Click on it;
3. Wait...

Expected behavior I think that this could be a little more fast, because I have the feeling that the Musescore stop to work (is not the case).

Screenshots

https://user-images.githubusercontent.com/31707161/188607194-d38c332a-ed59-4a46-9588-ff3daaa5c75b.mp4

Platform information

• OS: Windows (i5, ssd, 8gb ram)

[Jojo-Schmitz]

I can confirm, even on a quite powerfull Ryzen 5900X 12 core(+HT) with 32GB RAM, Windows 11, a delay of about 4 seconds (so much shorter than for you, yet still much longer than in MU3). Self-built, MSVC, RelWithDebInfo

Edit: now some 10 seconds, with the released 4.1.1, but still just 4 seconds with a self built 4.2

[oktophonie]

Curiously, I've encountered this on one machine (a Surface Pro 7, Win 11), but on others, this dialog opens immediately.

[oMrSmith]

I don't have the issue. I'm on Windows 10, with Ryzen CPU.

[HemantAntony]

I'm dual booting with Ubuntu 22.04 LTS and Windows 11. On Ubuntu, there is a bit of delay compared to a dialog like Project Properties. But it isn't that annoying for me. It does annoy me a tiny bit

[SamYeh]

Not sure whether the following information would help: During the wait for the dialog box to appear, one thread of the MS4 process is particularly CPU intensive. The stack trace (on Windows 11) is:

0x0000000000000000 Qt5Quick.dll!QQuickDesignerSupportStates::updateStateBinding+0x3917 Qt5Quick.dll!QQuickDesignerSupportStates::updateStateBinding+0x3a4f Qt5Quick.dll!QQuickDesignerSupportStates::updateStateBinding+0x1c51 Qt5Quick.dll!QQuickDesignerSupportStates::updateStateBinding+0x15dc qwindows.dll+0x60b6f qwindows.dll+0x585b4 UIAutomationCore.dll!UiaRaiseAutomationEvent+0x73ba UIAutomationCore.dll!UiaRaiseAutomationEvent+0x6c44 UIAutomationCore.dll!UiaRaiseAutomationEvent+0x28b qwindows.dll+0x58ada Qt5Gui.dll!QAccessible::updateAccessibility+0xc2 Qt5Widgets.dll!QWidgetLineControl::emitCursorPositionChanged+0xb7 Qt5Widgets.dll!QAbstractSpinBox::timerEvent+0x4b3 Qt5Widgets.dll!QAbstractSpinBox::setSpecialValueText+0x100 Qt5Widgets.dll!QDoubleSpinBox::setValue+0x5e MuseScore4.exe!createOveStreamLoader+0x1157f49 MuseScore4.exe!createOveStreamLoader+0x108e5e7 Qt5Core.dll!QMetaType::create+0xa9 MuseScore4.exe!createOveStreamLoader+0x54eaef MuseScore4.exe!createOveStreamLoader+0x54d4e6 MuseScore4.exe!createOveStreamLoader+0x4b75ed MuseScore4.exe!createOveStreamLoader+0xfd21c8 MuseScore4.exe!createOveStreamLoader+0xc021d6 MuseScore4.exe!createOveStreamLoader+0x5d6440 MuseScore4.exe!createOveStreamLoader+0x5d78a1 MuseScore4.exe!createOveStreamLoader+0x5c1787 MuseScore4.exe!createOveStreamLoader+0xc97d17 MuseScore4.exe!createOveStreamLoader+0xc98d67 Qt5Qml.dll!QQmlNotifier::notify+0x81 Qt5Qml.dll!QQmlPropertyValueInterceptor::operator=+0xc70 Qt5Qml.dll!QQmlPropertyValueInterceptor::operator=+0x178d Qt5Qml.dll!QV4::QObjectMethod::callInternal+0x3f1 Qt5Qml.dll!QQmlObjectCreator::setupFunctions+0x13d0 Qt5Qml.dll!QQmlObjectCreator::setupFunctions+0x170a Qt5Core.dll!QObject::event+0x171 Qt5Widgets.dll!QApplicationPrivate::notify_helper+0x110 Qt5Widgets.dll!QApplication::notify+0x18b3 Qt5Core.dll!QCoreApplication::notifyInternal2+0xba Qt5Core.dll!QCoreApplicationPrivate::sendPostedEvents+0x215 qwindows.dll!qt_plugin_query_metadata+0x1fbf Qt5Core.dll!QEventDispatcherWin32::processEvents+0x6a qwindows.dll!qt_plugin_query_metadata+0x1f99 Qt5Core.dll!QEventLoop::exec+0x1bc Qt5Core.dll!QCoreApplication::exec+0x154 MuseScore4.exe!createOveStreamLoader+0xc8f059 MuseScore4.exe!createOveStreamLoader+0x3e3a9d MuseScore4.exe!createOveStreamLoader+0x1c2eb96 KERNEL32.DLL!BaseThreadInitThunk+0x10 ntdll.dll!RtlUserThreadStart+0x2b

[rgreen5]

If it's any help, I'm not getting this on Linux Mint 20.1; Styles dialog open in about a second.

(Pentium CPU 2020M @ 2.40GHz × 2 / 4Gb RAM)

[deltz025]

I'm also experiencing this issue on Windows 10 21H2, Intel(R) Core(TM) i5-9300H CPU @ 2.40GHz, 8GB RAM, GTX 1050 3GB GPU. The Style dialogue in particular takes 10-15 seconds to load, and MU4 stops responding in the mean time.

[igorkorsukov]

I can confirm, even on a quite prowerfull Ryzen 5900X 12 core(+HT) with 32GB RAM, Windows 11, a delay of about 4 seconds (so much shorter than for you, yet still much longer than in MU3). Self-built, MSVC, RelWithDebInfo

Unfortunately, the problem is not reproducible in either Linux or Windows for me, the dialog opens instantly. Could you please sort it out a bit, you need to do like this:

EditStyle::EditStyle(QWidget* parent)
    : QDialog(parent)
{
    TRACEFUNC;
    BEGIN_STEP_TIME("EditStyle");
...
    // ====================================================
    // Button Groups
    // ====================================================
    ...
    fbStyle->addButton(radioFBHistoric, 1);

    STEP_TIME("EditStyle", "End create buttons");

    ...
        { StyleId::golpeShowTabCommon, false, golpeShowTabCommon, 0 },
    };

    STEP_TIME("EditStyle", "End style widgets");

    etc...

    STEP_TIME("EditStyle", "End setup widgets");

    WidgetStateStore::restoreGeometry(this);
    STEP_TIME("EditStyle", "End restoreGeometry");
}

After opening the dialog, there will be something like this in the log:

15:32:36.498 | DEBUG | main_thread | Profiler   | EditStyle : 0.001/0.000 ms: Begin
15:32:36.690 | DEBUG | main_thread | Profiler   | EditStyle : 191.712/191.637 ms: End create buttons
15:32:36.690 | DEBUG | main_thread | Profiler   | EditStyle : 191.781/0.007 ms: End style widgets
15:32:36.713 | DEBUG | main_thread | Profiler   | EditStyle : 214.783/22.992 ms: End setup widgets
15:32:36.713 | DEBUG | main_thread | Profiler   | EditStyle : 214.911/0.066 ms: End restoreGeometry

You also need to add the macro TRACEFUNC to the beginning of the functions that can be called when opening this dialog. And then see the output of the profiler [Main Menu] Diagnostic->System->Show profiler...

[Jojo-Schmitz]

I might try, some time next week, as I'm away from my computer currently

[Jojo-Schmitz]

So 3 seconds on a single call, in a RelWithDebInfo build

[Jojo-Schmitz]

Not sure where to get the log?

[Jojo-Schmitz]

In a Debug build more than 4 seconds

[cbjeukendrup]

Logs are in %LOCALAPPDATA%\MuseScore\MuseScore4Development\logs or just the application output on the command line

[Jojo-Schmitz]

Ah!

2023-01-09T12:26:45.809 | DEBUG | main_thread | Profiler   | EditStyle : 0.001/0.000 ms: Begin
2023-01-09T12:26:49.458 | DEBUG | main_thread | Profiler   | EditStyle : 3649.659/3649.538 ms: End create buttons
2023-01-09T12:26:49.458 | DEBUG | main_thread | Profiler   | EditStyle : 3649.802/0.035 ms: End style widgets
2023-01-09T12:26:50.168 | DEBUG | main_thread | Profiler   | EditStyle : 4359.405/709.533 ms: End setup widgets
2023-01-09T12:26:50.168 | DEBUG | main_thread | Profiler   | EditStyle : 4359.695/0.193 ms: End restoreGeometry

So apparently the most time is spent in creating the buttons

[Jojo-Schmitz]

Nah, before creating the buttons:

2023-01-09T12:37:34.169 | DEBUG | main_thread | Profiler   | EditStyle : 0.001/0.000 ms: Begin
2023-01-09T12:37:37.110 | DEBUG | main_thread | Profiler   | EditStyle : 2941.271/2941.198 ms: Start create buttons
2023-01-09T12:37:37.110 | DEBUG | main_thread | Profiler   | EditStyle : 2941.422/0.022 ms: End create frenNumGroup buttons
2023-01-09T12:37:37.110 | DEBUG | main_thread | Profiler   | EditStyle : 2941.483/0.009 ms: End create ksng buttons
2023-01-09T12:37:37.110 | DEBUG | main_thread | Profiler   | EditStyle : 2941.536/0.008 ms: End create ctg buttons
2023-01-09T12:37:37.110 | DEBUG | main_thread | Profiler   | EditStyle : 2941.587/0.007 ms: End create fbAlign buttons
2023-01-09T12:37:37.110 | DEBUG | main_thread | Profiler   | EditStyle : 2941.629/0.006 ms: End create buttons
2023-01-09T12:37:37.110 | DEBUG | main_thread | Profiler   | EditStyle : 2941.699/0.036 ms: End style widgets
2023-01-09T12:37:37.271 | DEBUG | main_thread | Profiler   | EditStyle : 3101.724/159.987 ms: End setup widgets
2023-01-09T12:37:37.271 | DEBUG | main_thread | Profiler   | EditStyle : 3102.035/0.201 ms: End restoreGeometry

[Jojo-Schmitz]

OK...

2023-01-09T12:44:03.741 | DEBUG | main_thread | Profiler   | EditStyle : 0.001/0.000 ms: Begin
2023-01-09T12:44:03.741 | DEBUG | main_thread | Profiler   | EditStyle : 0.060/0.002 ms: setObjectName
2023-01-09T12:44:06.718 | DEBUG | main_thread | Profiler   | EditStyle : 2977.302/2977.205 ms: setupUi
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.142/71.725 ms: setWindowFlag
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.237/0.002 ms: setModal
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.385/0.110 ms: addButton
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.476/0.039 ms: setWidgetIcon
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.522/0.002 ms: Start create buttons
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.610/0.013 ms: End create frenNumGroup buttons
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.666/0.008 ms: End create ksng buttons
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.710/0.007 ms: End create ctg buttons
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.753/0.007 ms: End create fbAlign buttons
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.804/0.015 ms: End create buttons
2023-01-09T12:44:06.790 | DEBUG | main_thread | Profiler   | EditStyle : 3049.874/0.031 ms: End style widgets
2023-01-09T12:44:06.949 | DEBUG | main_thread | Profiler   | EditStyle : 3208.315/158.403 ms: End setup widgets
2023-01-09T12:44:06.949 | DEBUG | main_thread | Profiler   | EditStyle : 3208.609/0.206 ms: End restoreGeometry

So it is in setupUi!

[Jojo-Schmitz]

No progress on this? Also came up in https://musescore.org/en/node/339240

[cbjeukendrup]

No progress on this?

Unfortunately not. We still can't reproduce it ourselves. If you could try to find out what inside setupUi is so slow, that may be very helpful. (setupUi is defined in that Qt-generated header file of course; but I think that as long as you don't modify editstyle.ui, the header won't be regenerated so you can experiment by adding things manually. Alternatively, you can copy the definition of the setupUi method to editstyle.cpp, under a different name, and call that instead of setupUi.)

[Jojo-Schmitz]

I tried this:

    void setupUi(QDialog *TestDialog)
    {
        TRACEFUNC;
        BEGIN_STEP_TIME("setupUi");
        if (TestDialog->objectName().isEmpty())
            TestDialog->setObjectName(QString::fromUtf8("TestDialog"));
        TestDialog->resize(400, 300);
        TestDialog->setWindowTitle(QString::fromUtf8("TestDialog"));
        gridLayout = new QGridLayout(TestDialog);
        gridLayout->setObjectName(QString::fromUtf8("gridLayout"));
        buttonBox = new QDialogButtonBox(TestDialog);
        buttonBox->setObjectName(QString::fromUtf8("buttonBox"));
        buttonBox->setOrientation(Qt::Horizontal);
        buttonBox->setStandardButtons(QDialogButtonBox::Cancel|QDialogButtonBox::Ok);

        gridLayout->addWidget(buttonBox, 2, 0, 1, 1);

        label = new QLabel(TestDialog);
        label->setObjectName(QString::fromUtf8("label"));
        label->setText(QString::fromUtf8("Hello from QDialog!!!"));
        label->setAlignment(Qt::AlignCenter);

        gridLayout->addWidget(label, 0, 0, 1, 1);

        labelTestParam = new QLabel(TestDialog);
        labelTestParam->setObjectName(QString::fromUtf8("labelTestParam"));
        labelTestParam->setText(QString::fromUtf8("Test param"));
        labelTestParam->setAlignment(Qt::AlignCenter);

        gridLayout->addWidget(labelTestParam, 1, 0, 1, 1);


        STEP_TIME("setupUi", "Start retranslateUi");
        retranslateUi(TestDialog);
        STEP_TIME("setupUi", "Start connect and end retranslateUi");
        QObject::connect(buttonBox, SIGNAL(accepted()), TestDialog, SLOT(accept()));
        QObject::connect(buttonBox, SIGNAL(rejected()), TestDialog, SLOT(reject()));

        STEP_TIME("setupUi", "Start connectSlotsByName and end connect");
        QMetaObject::connectSlotsByName(TestDialog);
        STEP_TIME("setupUi", "End connectSlotsByName and setupUi");
    } // setupUi

Nothing shows in the logs though. Next step: copying it into editstyle.cpp

[cbjeukendrup]

But that is setupUi for TestDialog, not EditStyle... the correct one should be in ui_editstyle.h.

[Jojo-Schmitz]

Oops

Hmm, is seems largely to be a case of "Kleinvieh macht auch Mist", i.e. many little thing that sum up. The only single longer one is the retranslateUi(), taking about a quarter of the total time, 850ms from 3450ms. Then again that has got to quite a lot too.

[Jojo-Schmitz]

I'll attach the log, where it reads somehting like "2023-01-26T14:34:18.575 | DEBUG | main_thread | Profiler | setupUi : 2536.126/37.107 ms: 7939", that last number refers to line numbers, as I inserted a STEP_TIME("setupUi", std::to_string(__LINE__)); every ~50 lines of code, rather than a more specific one,

MuseScore_230126_143404.log

[cbjeukendrup]

Thanks for testing. So the conclusion is that the whole setupUi function is a bit slow, but it's not caused by one specific function. Maybe it has something to do with circumstances; is it possible that some other thread takes up a lot of CPU power so that the main thread runs slower at that point, or is that a nonsense idea? (I can hardly imagine that something like that can happen, even on @Jojo-Schmitz's powerful machine... but what else can it be?)

[Jojo-Schmitz]

Seems not to be threaded at all, I see most of my 2*12 cores idling. And a ~7% CPU peak usage of MuseScore4.exe

Those humps happened when opening that dialog.

BTW: for me it is (bearable) 4 seconds, there are reports in the forum about (absoluletely horrendous) 40 (!) seconds

[ecstrema]

Format->style is the same dialog as mu3, with the only difference of styled widgets. I remember reading somewhere that QStyle was overriden so that the native controls would look like the QML ones.

What if the custom styling is disabled? Is it still that slow?

[ecstrema]

This is one of the many performance regressions of MU4 which is a lot slower than MU3 in almost every aspect. But since it's also a lot more powerful, I'm willing to accept some tradeoff. However, waiting 4 seconds instead of 200ms for an identical dialog is really too much.

[cbjeukendrup]

@ecstrema Interesting thought. You can try disabling it by going to UiTheme::setupWidgetTheme() and comment the line QApplication::setStyle(this);.

[Jojo-Schmitz]

I tried it, it doesn't make a difference

[rich777300]

It also takes a long time for the Preferences page to open for me once I've clicked it...about 10s on my Windows 10 laptop (MuseScore v4.0.1).

Also if it's helpful at all, the Styles page on my laptop also takes ~8-10s to open.

[Jojo-Schmitz]

I can't confirm that, Preferences loads almost immediatelly