Bug 2055986 - High idle CPU usage
Summary: High idle CPU usage
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: mscore
Version: 37
Hardware: x86_64
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: Jerry James
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-02-18 06:39 UTC by alex
Modified: 2022-12-09 01:31 UTC (History)
4 users (show)

Fixed In Version: mscore-3.6.2-13.fc36 mscore-3.6.2-13.fc37
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2022-12-09 00:49:57 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description alex 2022-02-18 06:39:58 UTC
Description of problem:
After I edit some sheet music for a few minutes, MuseScore starts using up 25% of my CPU when idle.

Version-Release number of selected component (if applicable):
3.6.2-5.fc35

How reproducible:
I can't reproduce it when I try but it happens pretty often if not every time during regular usage.

Actual results:
MuseScore uses 25% of my CPU when idle.

Expected results:
Idle CPU usage should be low.

Additional info:
My CPU has 4 logical cores. Here's a core dump taken after high CPU usage starts: https://drive.google.com/uc?id=1l_1KznrLoGwO0JC29tO7S0KvfoFMSxOS&export=download.

Comment 1 Jerry James 2022-02-18 17:38:20 UTC
That core file shows every single thread except thread 1 is blocked in one of the following functions:
- __futex_abstimed_wait_common
- epoll_wait
- poll
- select
- wait4

So the culprit must be thread 1, which is doing this:
gdb) bt
#0  0x00007fb18c249883 in sysprof_collector_mark_vprintf () at /lib64/libglib-2.0.so.0
#1  0x00007fb18c2441b0 in g_trace_mark.constprop () at /lib64/libglib-2.0.so.0
#2  0x00007fb18c1f3649 in g_main_context_check () at /lib64/libglib-2.0.so.0
#3  0x00007fb18c24813b in g_main_context_iterate.constprop () at /lib64/libglib-2.0.so.0
#4  0x00007fb18c1f0853 in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#5  0x00007fb191a3dbb8 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) ()
    at /lib64/libQt5Core.so.5
#6  0x00007fb1919eb1e2 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () at /lib64/libQt5Core.so.5
#7  0x00007fb1919f3724 in QCoreApplication::exec() () at /lib64/libQt5Core.so.5
#8  0x00005629a736572e in Ms::runApplication(int&, char**) ()
#9  0x00005629a72b195e in main ()

That's the Qt5 event loop.  Did you have sysprof running when you took this core dump?

Comment 2 alex 2022-02-18 19:13:24 UTC
No, I don't have sysprof installed.

Comment 3 Jerry James 2022-02-18 20:24:58 UTC
Hmmm.  I have no idea why the Qt5 event loop would be burning so much CPU, unless it is getting a never-ending stream of events.  Let me see if I can reproduce.

Comment 4 alex 2022-02-25 08:11:00 UTC
Unfortunately, I haven't figured out how to reproduce it other than to just use MuseScore for a while. If I have time I'll try reproducing it in another user account or a virtual machine. I have the I/O set to ALSA and I'm using a MIDI keyboard to enter notes. Let me know if you need more information.

Comment 5 Jerry James 2022-02-27 04:08:53 UTC
Sorry to keep you waiting.  I have tried a few times now to reproduce, but have never seen this happen.  CPU usage stays low, usually between 1% and 2%.

What desktop are you using?  GNOME?  KDE?  Something else?

Comment 6 alex 2022-02-27 06:30:53 UTC
I'm using GNOME.

Comment 7 alex 2022-03-01 07:35:44 UTC
I figured out how to consistently reproduce the issue (on my system at least). It happens when I plug in the MIDI keyboard after I start MuseScore, and then use the "Restart Audio and MIDI Devices" button in the I/O preferences tab to get MuseScore to recognize the keyboard.

Comment 8 alex 2022-03-01 08:13:15 UTC
I successfully reproduced it on a new virtual machine. Here are the full steps:

1. Set I/O to ALSA.
2. Start MuseScore without the MIDI keyboard plugged in.
3. Click the "Restart Audio and MIDI Devices" button in the I/O preferences.

Comment 9 Ben Cotton 2022-11-29 17:55:20 UTC
This message is a reminder that Fedora Linux 35 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 35 on 2022-12-13.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '35'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 35 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Comment 10 alex 2022-11-29 18:54:55 UTC
Looks like this is still an issue. In the reproduction steps I forgot to mention that the MIDI keyboard has to be plugged in after MuseScore is started and before clicking the "Restart Audio and MIDI Devices" button.

Comment 11 Jerry James 2022-11-29 19:11:54 UTC
I'm sorry this is still giving you problems.  I'll have to see if I can find a MIDI keyboard I can borrow to try this out.  Maybe Santa Claus will bring me one. :-)

Comment 12 alex 2022-11-29 19:13:56 UTC
I just did some more testing and I think the MIDI keyboard is actually unrelated to this issue. Simply starting MuseScore with I/O set to ALSA and clicking the "Restart Audio and MIDI Devices" button seems to be enough to reproduce this.

Comment 13 Jerry James 2022-11-29 19:30:42 UTC
Yes, that works.  I can reproduce now.  Let me see if I can track the problem down.

Comment 14 Jerry James 2022-11-29 23:49:40 UTC
Sysprof shows that after pressing "Restart Audio and MIDI Devices", the musescore binary spends 98.8% of its time in this call stack:

- main(int, char **)
- Ms::runApplication(int&, char **)
- QCoreApplication::exec()
- QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>)
- QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>)
- g_main_context_iteration
- g_main_context_iterate.constprop.0
- g_main_context_dispatch
- socketNotifierSourceDispatch(_GSource *, int(*)(void *), void *)
- QCoreApplication::notifyInternal2(QObject *, QEvent *)
- QApplicationPrivate::notify_helper(QObject *, QEvent *)
- QSocketNotifier::event(QEvent *)
- QSocketNotifier::activated(int, QSocketNotifier::QPrivateSignal)
- void doActivate<false>(QObject *, int, void **)
- Ms::AlsaMidiDriver::read()
- snd_seq_event_input
- snd_seq_hw_read

GDB shows that the calls to snd_seq_event_input almost always return -11, which is EAGAIN, which means that there is no data to read (see https://www.alsa-project.org/alsa-doc/alsa-lib/group___seq_event.html#ga6421feafcd6f116d34531d6b54177c17).  However, in spite of there being no data to read, MuseScore immediately tries again, resulting in the high CPU.  MuseScore is using a socket notifier, so poll() is falsely claiming that there is data to read.

Interestingly, it works the other way, too.  If MuseScore is configured to use ALSA, then if I start it, switch it to PulseAudio and then press "Restart Audio and MIDI Devices", it starts burning 100% CPU.  This time, there are several frequently repeated call stacks.  The most repeated call stack is:

- main(int, char **)
- Ms::runApplication(int&, char **)
- QCoreApplication::exec()
- QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>)
- QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>)
- g_main_context_iteration
- g_main_context_iterate.constprop.0
- g_main_context_dispatch
- xcbSourceDispatch(_GSource*, int(*)(void *), void *)
- QWindowSystemInterface::sendWindowSystemEvents(QFlags<QEventLoop::ProcessEventFlag>)
- QGuiApplicationPrivate::processMouseEvent(QWindowSystemInterfacePrivate::MouseEvent*)
- QCoreApplication::notifyInternal2(QObject *, QEvent *)
- QApplication::notify(QObject *, QEvent *)
- QApplicationPrivate::notify_helper(QObject *, QEvent *)
- QWidget::event(QEvent *)
- QMenuPrivate::activateAction(QAction*, QAction::ActionEvent, bool)
- QMenuPrivate::activateCausedStack(QVector<QPointer<QWidget> > const&, QAction *, QAction::ActionEvent, bool)
- QAction::activate(QAction::ActionEvent)
- QAction::triggered(bool)
- doActivate<false>(QObject *, int, void **)
- Ms::MuseScore::startPreferenceDialog()
- Ms::PreferenceDialog::PreferenceDialog(QWidget *)
- Ui_PrefsDialogBase::setupUi(QDialog *)

This suggests that pressing that button somehow fools the event dispatcher into unleashing a never-ending flood of bogus events.

Aha!  Take a look at audio/drivers/mididriver.cpp, specifically AlsaMidiDriver::init().  It creates one QSocketNotifier for each ALSA file descriptor.  But there is no code anywhere to deregister those notifiers if the driver is shut down.  In fact, the pointers to the notifiers are thrown away.  See lines 174 and 175 of that file.  So those notifiers are still attached to the underlying sockets, which disappear.  And if those file descriptors are reused for the new driver, chaos ensues.

I'm going to whip up a patch to see if this is indeed the problem.  Note that the code for restarting audio drivers is either gone or moved somewhere else in git, which will soon (?) be released as version 4.0.  I also cannot find any trace of a button called "Restart Audio and MIDI Devices".  This means that there is no point in sending a patch upstream as this code has been rewritten or thrown away already.

Comment 15 Jerry James 2022-11-30 03:21:05 UTC
Sadly, cleaning up those QSocketNotifier objects did not help.  I still see 100% CPU use.  Oh well, it was worth a try.  I'll dig into it some more.

Comment 16 alex 2022-11-30 03:49:24 UTC
Sorry if I didn't make this clear earlier, but this is a pretty minor bug so I don't think it's worth spending much effort on it especially since the code is not in newer versions anyway. Thanks a lot for what you've done so far.

Comment 17 Jerry James 2022-11-30 21:48:38 UTC
No problem.  I think I have it, anyway.  Whoever wrote the audio driver code clearly expected the drivers to be initialized once when MuseScore started up and then never changed.  Drivers getting deleted or reinitialized caused file descriptor leaks, memory leaks, etc.  My attempt last night wasn't wrong; it was just incomplete.  I had to patch a few more places and now things are looking much better.  I'll push updates in a moment.

I will probably build the first release candidate of MuseScore 4.0 in COPR so people have a chance to try it out.  Watch https://copr.fedorainfracloud.org/coprs/jjames/ once the release candidate is announced.

Comment 18 Fedora Update System 2022-11-30 21:50:33 UTC
FEDORA-2022-cf8353d108 has been submitted as an update to Fedora 37. https://bodhi.fedoraproject.org/updates/FEDORA-2022-cf8353d108

Comment 19 Fedora Update System 2022-11-30 21:50:34 UTC
FEDORA-2022-eff6f35ed6 has been submitted as an update to Fedora 36. https://bodhi.fedoraproject.org/updates/FEDORA-2022-eff6f35ed6

Comment 20 Fedora Update System 2022-12-01 01:34:39 UTC
FEDORA-2022-cf8353d108 has been pushed to the Fedora 37 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2022-cf8353d108`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2022-cf8353d108

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 21 Fedora Update System 2022-12-01 02:36:32 UTC
FEDORA-2022-eff6f35ed6 has been pushed to the Fedora 36 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2022-eff6f35ed6`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2022-eff6f35ed6

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 22 Fedora Update System 2022-12-09 00:49:57 UTC
FEDORA-2022-eff6f35ed6 has been pushed to the Fedora 36 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 23 Fedora Update System 2022-12-09 01:31:26 UTC
FEDORA-2022-cf8353d108 has been pushed to the Fedora 37 stable repository.
If problem still persists, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.