QTimer is very inaccurate

[Pavankumar S V]

@jsulm : In the .pro file of qt project, I added these flags like below:

QMAKE_CFLAGS += -Werror -O0 -pg
QMAKE_CXXFLAGS += -Werror -O0 -pg

QMAKE_LFLAGS += -pg

[jsulm]

@Pavankumar-S-V Did you do a complete rebuild?

• Delete build folder
• Run qmake
• Build

[Pavankumar S V]

@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.

[JonB]

@Pavankumar-S-V
Run your executable under strace. Do you see any mention of gmon.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?

[JoeCFD]

@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.

[Pavankumar S V]

@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 total

As per the above report, i don't see anything related to gprof.

1. Do you think any specific system call should have been called that indicates the generation of gmon.out?
2. 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.
3. Please let me know how to proceed furthur.

[Pavankumar S V]

@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.

[JonB]

@Pavankumar-S-V
I do not recognise this output from strace --- looks more like output from gprof if anything to me.

Output from strace should show each individual system call as its own line, together with extra information where available. For example, there should be a line for every file open() system call, showing the filename. You should redirect its output to some file and grep that for mention of the gmon.out file you say is not being produced anywhere when it should be.

P.S.
To be 100% clear: I am suggesting you run your executable under strace, not any gprof you might try after the executable has been run. You are saying that your executable compiled and linked with -pg is failing to produce a gmon.out file, and I am trying to trace that down.

[Pavankumar S V]

@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-GKskYjTgC9

Please check the report once. Please let me know if you cannot access the link.

Thanks

[JonB]

@Pavankumar-S-V
I don't know why you introduced some taskset command about which I know nothing, but will ignore that.

Since it does no mention writing to gmon.out I 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 wrt gmon.out.

[Pavankumar S V]

@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.

[JonB]

@Pavankumar-S-V
I can only say that I have successfully used -pg/gmon.out/gprof from Qt Creator with Qt 5.15 under Ubuntu.

[Pavankumar S V]

@jsulm, @JonB
Hello Both,

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:

1. Any idea why "AnimatedImage" is causing such a high cpu load. Any CPU intensive operations are done by QT which are specific to AnimatedImages?
2. 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.