QTimer is very inaccurate
-
@Pavankumar-S-V
You might like to look at the topic Small example showing QTimer slowing to a halt. The important take away is the OP's last post there, https://forum.qt.io/topic/94657/small-example-showing-qtimer-slowing-to-a-halt/16, where the gist isCurrently I have moved the logging functionality on a separate thread and this seems to work fine.
Something in your application might benefit from being moved to a thread if the main thread is too busy to keep up.
But to me this still does not resolve your CPU usage issue. If anything takes near 100% CPU time you have a potential problem keeping up....
-
@jsulm : I tried to profile the application using "gprof" as per your suggestion.
I followed the same procedure that is mentioned in the link shared by you. But the file that holds the profiled data(gmon.out) is not getting generated after running and exiting from the application.
Just to confirm, I followed the following steps:
1) Enabled -pg, -O0 in the compiler, linker and built the qt project.
2) I made the following modification to the main() so that the application returns from main() gracefully(This is one of the condition for gprof):int main(int argc, char *argv[]) { QApplication *app; app = new QApplication(argc, argv); MainClass maincls; maincls.view = new QQuickView; maincls.view->setSource(QUrl::fromLocalFile("Path of Loader.qml")); maincls.view->show(); //starting all the user threads maincls.view->installEventFilter(&maincls); exitTimer = new QTimer(); exitTimer->setSingleShot(true); QObject::connect(exitTimer, &QTimer::timeout, app, &QApplication::quit, Qt::QueuedConnection); exitTimer->start(85000); //main event loop should run for 85 sec and return to the main function after that. app->exec(); qDebug()<<"Exiting qt;"; //This message is printed successfully return 0; }The above procedure should have generated "gmon.out" file but it has not. I have used gprof before for C based application and successfully profiled it. But I'm facing this issue when profiling qt application using grpof.
- Please let me know if I'm missing something during profiling.
- Please let me know if gprof is a right profiling tool to profile the qt application. As per my experience with gprof before, it is not very suitable for multi threaded applications and also provides info related to only user space.
- Please guide me to the right way for profiling embedded qt applications as there is very limited information available online related to qt profiling. As I'm working on improving the performance of the qt based device, it would be very useful for me to profile the app.
Thank you
-
@Pavankumar-S-V said in QTimer is very inaccurate:
Enabled -pg, -O0 in the compiler, linker and built the qt project.
Can you show how?
-
@jsulm : In the .pro file of qt project, I added these flags like below:
QMAKE_CFLAGS += -Werror -O0 -pg
QMAKE_CXXFLAGS += -Werror -O0 -pgQMAKE_LFLAGS += -pg
-
@Pavankumar-S-V Did you do a complete rebuild?
- Delete build folder
- Run qmake
- Build
-
@jsulm : Yes I did a complete re-build.
We have a Makefile that calls qmake to generate a .mk for the build.
I have checked in that generated .mk file and made sure that these flags are reflected in CFLAGS, CXXFLAGS. So, these flags are indeed considered for the build as per my understanding. -
@Pavankumar-S-V
Run your executable understrace. Do you see any mention ofgmon.out?So, these flags are indeed considered for the build as per my understanding.
Probably. But I would inspect the actual commands issued, why not do so?
-
@Pavankumar-S-V can you try Qt::DirectConnection in signal and slot connection of your timer ?
Note that this may make your CPU very busy.
-
@JonB Thanks for your suggestion. I execution my qt app with strace((strace -c)) and following is the summary report:
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 60.56 2.065174 185 11146 2 futex 9.86 0.336357 9 33782 semop 6.68 0.227773 21 10454 9734 openat 4.65 0.158571 26 5944 11 write 4.64 0.158276 29 5451 read 2.37 0.080926 19 4138 mprotect 1.96 0.066935 185 360 munmap 1.43 0.048862 26 1812 1 mmap2 1.28 0.043518 14 2966 4 statx 1.18 0.040082 6 5979 259 rt_sigreturn 1.01 0.034415 12 2783 2677 recvmsg 0.53 0.017979 9 1961 cacheflush 0.52 0.017783 12 1395 1 poll 0.37 0.012461 10 1174 close 0.35 0.011980 11 1002 getcwd 0.35 0.011798 25 457 memfd_create 0.28 0.009419 672 14 clone 0.25 0.008616 21 397 395 readlink 0.24 0.008117 2029 4 uname 0.23 0.007893 9 813 _llseek 0.21 0.007148 26 273 78 stat64 0.21 0.007088 15 466 ftruncate 0.18 0.006122 19 318 130 access 0.16 0.005416 51 105 1 ioctl 0.15 0.005156 15 326 brk 0.09 0.003161 16 186 fstat64 0.07 0.002225 11 192 lstat64 0.06 0.001929 48 40 getdents64 0.05 0.001867 15 118 madvise 0.03 0.000971 57 17 sendmsg 0.02 0.000535 13 40 fcntl64 0.01 0.000254 127 2 socketpair 0.00 0.000165 23 7 semget 0.00 0.000127 6 20 rt_sigaction 0.00 0.000120 40 3 fallocate 0.00 0.000114 57 2 unlink 0.00 0.000095 47 2 sendfile 0.00 0.000078 5 15 getpid 0.00 0.000061 61 1 linkat 0.00 0.000046 46 1 statfs 0.00 0.000035 2 14 sched_get_priority_min 0.00 0.000034 34 1 sched_setaffinity 0.00 0.000033 2 14 sched_get_priority_max 0.00 0.000028 14 2 execve 0.00 0.000028 28 1 mremap 0.00 0.000027 3 7 sched_setscheduler 0.00 0.000024 24 1 semctl 0.00 0.000022 11 2 socket 0.00 0.000022 11 2 set_tls 0.00 0.000020 20 1 sched_getaffinity 0.00 0.000016 16 1 chmod 0.00 0.000016 4 4 gettid 0.00 0.000014 4 3 geteuid32 0.00 0.000013 13 1 setitimer 0.00 0.000012 2 6 rt_sigprocmask 0.00 0.000010 5 2 getuid32 0.00 0.000005 2 2 tgkill 0.00 0.000004 4 1 getgid32 0.00 0.000004 4 1 getegid32 0.00 0.000000 0 1 1 mkdir 0.00 0.000000 0 1 sigreturn 0.00 0.000000 0 10 writev 0.00 0.000000 0 1 fdatasync 0.00 0.000000 0 1 ugetrlimit 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 connect 0.00 0.000000 0 1 set_robust_list 0.00 0.000000 0 1 eventfd2 ------ ----------- ----------- --------- --------- ---------------- 100.00 3.409980 94250 13294 totalAs per the above report, i don't see anything related to gprof.
- Do you think any specific system call should have been called that indicates the generation of gmon.out?
- Please let me know if gprof is a right profiling tool to profile the qt application. As per my experience with gprof before, it is not very suitable for multi threaded applications and also provides info related to only user space.
- Please let me know how to proceed furthur.
-
@JoeCFD : I tried to use"Qt::DirectConnection" in signal slot connection as per your suggestion. But somehow the whole application is crashing.
Also, QT documentation recommends to use QueuedConnection for quit() slot(as per below explaination):
It's good practice to always connect signals to this slot using a QueuedConnection. If a signal connected (non-queued) to this slot is emitted before control enters the main event loop (such as before "int main" calls exec()), the slot has no effect and the application never exits. Using a queued connection ensures that the slot will not be invoked until after control enters the main event loop. -
@Pavankumar-S-V
I do not recognise this output fromstrace--- looks more like output fromgprofif anything to me.Output from
straceshould show each individual system call as its own line, together with extra information where available. For example, there should be a line for every fileopen()system call, showing the filename. You should redirect its output to some file andgrepthat for mention of thegmon.outfile you say is not being produced anywhere when it should be.P.S.
To be 100% clear: I am suggesting you run your executable understrace, not anygprofyou might try after the executable has been run. You are saying that your executable compiled and linked with-pgis failing to produce agmon.outfile, and I am trying to trace that down. -
@JonB : ok understood.
I tried running the qt app under strace to produce detailed system call report and I don't find any references to gmon.out.
I ran the app using the following command:
taskset 0x3 strace -T -o /tmp/strace_output.txt taskset 0x2 ../QTapp_name &Here is the link where the generated report is placed:
https://go.wetransfer.com/t-GKskYjTgC9Please check the report once. Please let me know if you cannot access the link.
Thanks
-
@Pavankumar-S-V
I don't know why you introduced sometasksetcommand about which I know nothing, but will ignore that.Since it does no mention writing to
gmon.outI can only include it was not compiled & linked properly with-pg. If you want to understand/verify that I suggest you start with a small, standalone program, verify your compiler/linker flags, and verify final behavior wrtgmon.out. -
@JonB
taskset is used to limit a process to a particular cpu core. We have a device with dual cpu core where the qt app has to run on second core. With "taskset 0x3 strace", I'm trying to run strace on both cpu core as it is heavy. With "taskset 0x2 qt_app", I'm limiting the qt app to use only second core.ok, I'll try with small program and try to make sure -pg flag is considered during the build.
As I'm investing lot of time in getting gprof working, I hope it produces complete profiling data of qt app and helps me to find the exact reason for high cpu usage.
Thank you for your time. I'll get back after trying your suggestions.
-
@Pavankumar-S-V
I can only say that I have successfully used-pg/gmon.out/gproffrom Qt Creator with Qt 5.15 under Ubuntu. -
I found the reason for high CPU load.
Background:
We have our own devices and I'm working on creating user Interfaces on the display of our device. We have many qml files to create some objects which needs to displayed on the device.We have a Software Tool which draws the objects on the PC using qml Files as per the user settings(like the size, position of the object on the display etc..). Then the objects are downloaded into our device.
Root cause for High Cpu Load, Inaccuracy of QTimer:
As a part of the objects that are created and downloaded from PC to the device, there is a ".gif(AnimatedImage)" object also.
We are setting the "playing" property of this qml object to "true". So, this object is causing high CPU load even though the page in which this object is present is made invisible(i.e "visible" property is changed to false). This is the reason also for the inaccuracy of the QTimer as AnimatedImage is consuming lot of CPU time and Qtimer is not triggered at the right time.When I binded the "playing" property of "AnimatedImage" object with its "visible" property, the cpu load is very much reduced(from around 100% to around 15%). Only when I open the page which has "AnimatedImage" object, the cpu load is increasing back to around 100%.
Questions:
- Any idea why "AnimatedImage" is causing such a high cpu load. Any CPU intensive operations are done by QT which are specific to AnimatedImages?
- The "cache" property of the "AnimatedImage" is false in high CPU load scenario. But if I change "cache" to true and open the page with "AnimatedImage", cpu usage is around 35%( but it was more than 100% when "cache" is false). How "cache" property is affecting the cpu usage of "AnimatedImage"?
Thanks in Advance.
