Extremely slow startup time for PySide6 vs PySide2

duyjuwumu

The following code takes 1 minute and 14 seconds to run for PySide6==6.2.2.1

import sys

from PySide6.QtWidgets import QMainWindow, QApplication


class WritingApp(QMainWindow):
    def __init__(self):
        QMainWindow.__init__(self)


if __name__ == "__main__":
    app = QApplication([])
    mw = WritingApp()
    mw.show()
    sys.exit(app.exec())

The same exact code runs in 2 seconds for PySide2==5.15.2. The strange thing is, if I close the above app and immediately restart it, the startup time drops to 2 seconds when using PySide6

However, when I add the following basic text editing features, the startup time jumps to 3 minutes 12 seconds in PySide6

import sys

from PySide6.QtWidgets import QMainWindow, QTextEdit, QApplication, QFileDialog
from PySide6.QtCore import QCoreApplication, Slot, QDir
from PySide6.QtGui import QTextDocumentWriter, QIcon, QKeySequence


class WritingApp(QMainWindow):
    def __init__(self):
        QMainWindow.__init__(self)

        self._text_edit = QTextEdit(self)
        self.setCentralWidget(self._text_edit)

        self._file_name = ""

        toolbar = self.addToolBar("&File")
        menubar = self.menuBar().addMenu("&File")
        icon = QIcon.fromTheme("document-save")
        self._action_save = menubar.addAction(icon, "&Save", self.file_save)
        self._action_save.setShortcut(QKeySequence.Save)
        self._action_save.setEnabled(True)
        toolbar.addAction(self._action_save)

    @Slot()
    def file_save(self) -> bool:
        if not self._file_name:
            return self.file_save_as()

        writer = QTextDocumentWriter(self._file_name)
        document = self._text_edit.document()
        success = writer.write(document)
        native_filename = QDir.toNativeSeparators(self._file_name)
        if success:
            document.setModified(False)
            self.statusBar().showMessage(f"Wrote file '{native_filename}'")
        else:
            self.statusBar().showMessage(f"Could not write to file '{native_filename}'")
        return success

    @Slot()
    def file_save_as(self) -> bool:
        file_dialog = QFileDialog(self, "Save as...")
        file_dialog.setAcceptMode(QFileDialog.AcceptSave)

        file_dialog.setDefaultSuffix("rtf")
        if file_dialog.exec() != QFileDialog.Accepted:
            return False
        filename = file_dialog.selectedFiles()[0]
        self._file_name = filename
        return self.file_save()


if __name__ == "__main__":
    app = QApplication([])
    QCoreApplication.setOrganizationName("Lone Maintainer, LLC")
    QCoreApplication.setApplicationName("Writing-App Prototype")
    QCoreApplication.setApplicationVersion("0.1")

    mw = WritingApp()
    available_geometry = mw.screen().availableGeometry()
    mw.resize((available_geometry.width()), available_geometry.height())
    mw.show()
    sys.exit(app.exec())

I tried the same strategy of closing and restarting the app and got the following results

Attempt 1 - 3 minutes 12 seconds
Attempt 2 - 1 minute 29 seconds
Attempt 3 - 6 seconds
Attempt 4 - 4 seconds

I've tried running the PySide 6 Rich text example and I'm discovering the same problem. I suspect there's weird caching behavior going on but I'm not sure. I'll stick to PySide2 for the time being, but does anyone know why this might be happening? I'm on Ubuntu 20.04 by the way.

JonB

@duyjuwumu said in Extremely slow startup time for PySide6 vs PySide2:

I'm on Ubuntu 20.04 by the way.

If you want to diagnose it for yourself, run your Python from strace.

rijenkii

Not OP, but can very much reproduce.

Code:

import sys
from PySide2 import QtWidgets, QtCore

app = QtWidgets.QApplication([])
splitter = QtWidgets.QSplitter()
model = QtWidgets.QFileSystemModel()
model.setRootPath(QtCore.QDir.currentPath())
tree = QtWidgets.QTreeView(splitter)
tree.setModel(model)
tree.setRootIndex(model.index(QtCore.QDir.currentPath()))
list = QtWidgets.QListView(splitter)
list.setModel(model)
list.setRootIndex(model.index(QtCore.QDir.currentPath()))
splitter.show()
sys.exit(app.exec_())

Running with PySide2, everything starts and works correctly -- starts fast, works without any lag, file/folder icons render.
Change PySide2 to PySide6, and everything starts failing -- starts extremely slow (1-3 seconds), lags on resize, and there are no icons.

Running with strace it seems like the icons are the culprit -- output is filled with messages that look like:

access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/animations/folder.svg", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/apps/folder.png", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/apps/folder.svg", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/categories/folder.png", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/categories/folder.svg", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/devices/folder.png", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/devices/folder.svg", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/emblems/folder.png", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/emblems/folder.svg", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/emotes/folder.png", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/emotes/folder.svg", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/filesystems/folder.png", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/filesystems/folder.svg", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/intl/folder.png", F_OK) = -1 ENOENT (No such file or directory)
access("/home/rijenkii/.local/share/icons/hicolor/16x16@2/intl/folder.svg", F_OK) = -1 ENOENT (No such file or directory)

In a few seconds, file with strace output was 124 megabytes.

EDIT:
OS is Void Linux, just in case.

JonB

@rijenkii
You either want to filter strace output for something you are interested, or in your case you are only interested in what is happening during the dealy, you can afford to leave it streaming its output in a terminal because you only need to look at the latest output.

For a startup delay one of two things will be happening:

It gets stuck on one call which waits/sleeps, say a read from a pipe; or
It is going round & round some bunch of calls: maybe in your case you see it spending all its time trying to keep opening files which don't exist.

For my part I do not know why it is looking for folder.png/svg where it is, but obviously wants that file and won't take "no" for an answer :) While you wait for someone to help, you could see how it gets some folder.... file in the strace output for PySide2 instead, does it get that from somewhere else?

rijenkii

@JonB
About icons in PySide2 -- it doesn't seem that it gets them from anywhere else -- it, just like PySide6 looks around in the ~/.local/share/icons/..., but it gives up after like three tries and then just uses what looks like built-in icons (I'm guessing here, as there are no successful file accesses with name "folder").

And the start-up delay is, indeed, because of these icons -- while PySide2's strace shows three tries (like described above) and then shows the window, PySide6 just doesn't give up, but after a while just shows the window and still tries to access these icons in the background, making everything very sluggish.

EDIT: I am starting to check if this bug exists in older versions of PySide6. So far:

6.0.0: No infinite icon checking -- gives up after a couple of tries just like PySide2, works fine -- no lag. Unlike PySide2 -- there are no "default" icons.

EDIT2: I have identified the version the bug has appeared in: PySide6==6.1.1. 6.1.0 works fine.

rijenkii

@duyjuwumu please try installing PySide==6.1.0 and checking if slow startup still happens. If you're on Python 3.10, you'll also have to pass --ignore-requires-python flag to pip when installing.

duyjuwumu

@rijenkii I actually still am seeing the issue for PySide6==6.1.0. Studying strace is a delicate dance of troubleshooting, because the isssue is dependent on how recently I last tried to startup the app. I'll continue troubleshooting and report back what I find.

Strangely enough, I'm not seeing this problem on Windows 10. So I suspect this is a GNU/Linux specific problem. Do either one of you have access to a Windows 10 machine and can duplicate the behavior?

P.S. going to go turn on my email notifications, because I didn't see this thread until just now

duyjuwumu

Alright, I haven't isolated the problem but I'm a stopping point.

I used the following command, strace -T -o <FILENAME> python main.py, to initially start up the app and then immediately restart the app to see if there was a difference in strace's output. The line count for both files were roughly the same, so I don't suspect that more calls are being made.

(venv)$ wc -l first_call.txt 
10328 first_call.txt
(venv) $ wc -l second_call.txt 
10613 second_call.txt

When I timed the first call by hand I got an execution time of 1minute 40 seconds. But the summation of execution time in strace is 19.7s. For the second call, my manual measurement of execution time was 2s and the strace execution time was 6.1s. While my measurements and strace's measurements don't align, they do trend in the same direction.

After processing the output file, the longest call for the first startup attempt was:
futex(0x7ffef22fa280, FUTEX_WAIT_PRIVATE, 0, NULL) = 0 <0.756055>. After reading up on futex it makes sense that waiting for a certain condition to be true would take up a lot of time. For the second startup attempt, the longest call was : poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=12, events=POLLIN}], 4, 604) = 0 (Timeout) <0.604754>. Again it makes sense that poll timeouts would eat up time.

I'm starting to suspect that, behind the scenes, Qt is deciding to wait until a certain condition(s) is met before showing the window in the first attempt. But on the second attempt, it just shows the window while waiting on said condition(s) in the background.

That said, I've exhausted my expertise on how to debug this. I'm open to any suggestions or hints as I want the app I'm making to be cross-platform and GNU/Linux development will be necessary at some point.

rijenkii

@duyjuwumu my only suggestions as of now would be:

pinpoint the version that introduced this delay.
Try installing PySide==6.0.0 and going up from there. You can find a list of all released versions here.
check if it's PySides bug or Qts.
Try compiling and running a C++ versions of your simple tests. Or even just examples available in QtCreators library.

duyjuwumu

So after some troubleshooting, I think my problem had to do with resource consumption and may not be Qt or Ubuntu related at all. I don't have a minimal example, but the original problem machine had the worst specs of the devices I have access to. Putting Ubuntu 20.04 on more powerful machines that were originally running Windows 10 resolved the issue.

My problem may be independent of @rijenkii 's problem though.