Investigating startup delay in Qt app

vikramg

I see the following on my Pi-based embedded Linux platform that runs a Qt app at boot:

Very first launch at boot: takes 5 secs for UI to appear
Subsequent launches: 2.8 secs

This is very repeatable. For an embedded product it is desirable that the device be ready to use as soon as possible after power up, so every additional second matters, and I'm trying to trace the source of the additional 2.2 secs required to startup the very first time. The app is dynamically linked against Qt 5.12.8.

I think the only tasks involved in starting an application are:

Loading object files into memory
Dynamic linking
Qt app startup

Investigating these in order:

Certainly, the second time the app is run, all objects are in the filesystem cache. So it would seem reasonable that there would result some speedup in starting the app the second time around. To quantify how much, I used vmtouch to bring in all files (executable + shared objects) into memory the very first thing at bootup before starting the app. The first-startup delay went down slightly, from 5s to 4.5s (also very repeatable). So 0.5 secs can be attributed to loading the files from storage, and there's nothing I can do about that for the first launch.
Next up, dynamic linking. I haven't found any information that linking of shared objects gets cached anywhere in Linux for reuse, so I'm assuming that this overhead will be similar in all runs of the app. I checked the # of relocations using LD_DEBUG=statistics and that stays the same in the first run (5s startup) and subsequent runs (2.8s startup).
So this leaves the Qt app itself. From this page:
https://www.qt.io/blog/2019/01/11/qt-5-12-lts-road-faster-qml-application-startup
3a. I haven't precompiled QML, but the qmlcache is present in the run directory and presumably getting used.
3b. Distance fields: I set qt.scenegraph.time.glyph=true and see that the glyph preparation delay is very minor, about 200 ms, and the same in both the first run and subsequent runs.
3c. I did not look into the compressed textures yet; the UI is not very complex, and it seems unlikely it will be an issue.

So I'm at a loss. What could be the reason for the added delay at the first startup?

JonB

@vikramg
Some thoughts from me. I am a Linux programmer, I wouldn't know what an embedded device was if it slapped me in the face ;-) So if these are not appropriate only you will know.

Knowing nothing, my first thought would be that "startup" & "UI" things "take (imprecise) time to get going". But from my very limited understanding of embedded I think you would say the environment is supposed to be very predictable compared to non-embedded, it just doesn't spend "random" amounts of time doing unpredictable/sundry things!

Because it's a "UI" app, are there "UI-things" which have to be performed first time to "get going"? Or, where exactly in "start up" are you running this, has whatever "UI initialization" been done? Can you make your app run any later?
Can you write a non-UI Qt app and compare that for its first/second time run timings? That would indicate whether it's UI or not which leads to the delay.
What happens if you do the first/second runs of your app not at boot-time? Do you see the same time differences? Tells us whether boot-time is relevant to the situation.
Here is my actual concrete tip! Does your Pi-Linux have strace? Hope so! Use that (with output directed to file, obviously) on each invocation. See the -r & -t arguments (among others). I'm hoping this really does trace everything involved in running your program. Looking through the timestamps, and doing a kind of "diff" between first & second runs on what system calls are made (regardless of time) might be quite revealing.

SGaist

Hi,

You should take a look at this KDAB blog post and it's follow up. It will give you good pointers to inspect your system/application.

vikramg

@SGaist that’s a great blog post, thanks!

@JonB: thank you for your suggestions. There’s not very much different from a Qt-app point of view about Linux running on an embedded device vs on the Desktop so your experience is certainly relevant. You are correct, the environment is much more deterministic: startup is via sysvinit rather than full-fledged systemd, and the user space is stripped-down and does not use X (the Qt app runs fullscreen at boot using the EGLFS platform plugin). There are very few processes running on the system; idle mem usage (without my app running) is under 20 MB. This is why the inordinate startup delay was rather unexpected.

To answer your questions:

has whatever "UI initialization" been done?

There are no “UI-things” that need to be performed. System boots, kernel starts the init process (PID 1) that executes startup shell scripts in /etc/init.d which start logging daemons, network, sshd. The last thing to get started is my Qt app. If the app were left out, the system would just boot and do nothing, with only the framebuffer boot logo displayed on the screen.

Can you write a non-UI Qt app and compare that for its first/second time run timings?
What happens if you do the first/second runs of your app not at boot-time?

I did indeed write a Hello World Qt console app to test. It did reveal an interesting (but definitely-not-pertinent-to-Qt) detail that I left out in my initial message: there is an unknown interaction with app startup and the kernel random number generator device. The HelloW app runs in basically no time at all normally. But when launched via an init script, it takes 5 seconds to run! Turns out that is when the random number init is not yet complete. Once that is complete (the random-device driver prints “crng init done” in dmesg), all times are repeatable. It is these times that I have reported in my original message -- not exactly at boot, but after the rng init is complete (so that the as-yet undetermined effect of the rng is taken out of reckoning). In this case I launch the app from the console, not from the init script.

Does your Pi-Linux have strace? Hope so! Use that

This is useful, thanks. The link that @SGaist provided uses LTTng which appears to be strace-on-steroids. Unfortunately it doesn’t seem like it will be a quick resolution, so I will update this thread once I get to the bottom of it.

Thank you both for your time!