QTimer is very inaccurate

[Pavankumar S V]

@jsulm Ok, I will check which part of my application could be causing high cpu load.
If possible, can you please share any link with good description of how to profile Embedded QT applications?
Thanks a lot for the suggestions

@jsulm , @JonB can creating a separate thread for timerEvnt() with a msleep(20) will help me to get good accuracy?

[JonB]

@Pavankumar-S-V said in QTimer is very inaccurate:

@jsulm , @JonB can creating a separate thread for timerEvnt() with a msleep(20) will help me to get good accuracy?

No.

[jsulm]

@Pavankumar-S-V said in QTimer is very inaccurate:

can creating a separate thread for timerEvnt() with a msleep(20) will help me to get good accuracy?

I would say it depends whether the slot will be called in main thread or in the same thread where the timer is running. If in the same thread as timer then this could improve the situation (at least if the CPU has more than one core). But even then you should investigate the CPU load.

Profiling with GCC: https://www.thegeekstuff.com/2012/08/gprof-tutorial/

[JonB]

@jsulm
If you want a timer to tick at 20ms and do some processing I cannot see how msleep(20) can do any good anywhere. At best it would occupy the whole desired 20ms interval, leaving no time to do any further processing...? Though you know better than I.

[JonB]

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

Currently 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]

@JonB Oh, I should read more carefully :-) msleep() is of course not a good idea

[Pavankumar S V]

@jsulm ok, I will try to profile the application using gprof and see if I can figure out something.
Thank you

[Pavankumar S V]

@JonB : Let me check this and see if it is useful for my case
Thank you very much

[Pavankumar S V]

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

1. Please let me know if I'm missing something during profiling.
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 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

[jsulm]

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

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