sudoku app when idle is actually quite busy

[Colin Ian King]

I ran some analyis on the Sudoku app when it was "idle". I just gathered 60 seconds worth of samples to see what was going on in the "idle" state:

CPU usage:
  PID Process USR% SYS% TOTAL%
  1274 qmlscene 0.20 0.72 0.92

Wakeups:
  PID Process Wake/Sec Kernel Functions
  1278 qmlscene 1.00 (hrtimer_start_range_ns, hrtimer_wakeup)
  1274 qmlscene 0.97 (hrtimer_start_range_ns, hrtimer_wakeup)
  1283 qmlscene 0.20 (hrtimer_start_range_ns, hrtimer_wakeup)

File I/O Operations:
  No file I/O operations detected

System Calls Traced:
  PID Process Syscall Count Rate/Sec
  1274 qmlscene clock_gettime 2111 35.1820
  1274 qmlscene poll 996 16.5994
  1274 qmlscene read 938 15.6327
  1274 qmlscene futex 114 1.8999
  1274 qmlscene SYS_NR_0 1 0.0167

Top Polling System Calls:
  PID Process Syscall Rate/Sec Infinite Zero Minimum Maximum Average
                                                           Timeouts Timeouts Timeout Timeout Timeout
  1274 qmlscene poll 16.5994 0 1 0.0 sec 999.0 msec 555.6 msec

Distribution of poll timeout times:
                                                            10.0 100.0 1.0 10.0 100.0 1.0 10.0 100.0
                                                    up to to to to to to to to or more
                                              Zero 9.9 99.9 999.9 9.9 99.9 999.9 9.9 99.9 Infinite
  PID Process Syscall sec usec usec usec msec msec msec sec sec sec Wait
  1274 qmlscene poll 1 - - - 8 80 907 - - - 0

[ one needs a proportional font to see this data nicely tabulated :-( ]

Is it expected to see 35 clock_gettime() calls a second when idle? Or ~16 poll()/reads() a second? In idle, it is consuming nearly 1% of the CPU. I'd expect idle to really to suck less power.

[Dinko Osmankovic (dinko-metalac)]

Hmm, there is a Timer component that triggers an event every second. It's used for calculating score. Do you have a suggestion? Maybe to increase interval of the Timer component?

[Colin Ian King (colin-king)]

I'm not sure, but it is strange that qmlscene is polling at 35Hz on clock_gettime and ~16Hz on poll()/read.

[Dinko Osmankovic (dinko-metalac)]

Btw, what do you use for this output? Powertop? And how do you use it?

[Colin Ian King (colin-king)]

health-check, it's a tool I wrote to track down problematic apps, it can be found in my PPA:

ppa:colin-king/white

see: http://kernel.ubuntu.com/~cking/health-check/

[Dinko Osmankovic (dinko-metalac)]

Thanks a lot :)

Btw, using "sudo health-check -p qmlscene -c -d 60" I get these results:

CPU usage:
   PID Process USR% SYS%
   7342 qmlscene 0.02 0.00

Wakeups:
   PID Process Wake/Sec Kernel Functions
   7342 qmlscene 1.00 (hrtimer_start_range_ns, hrtimer_wakeup)

File I/O Operations:
  No file I/O operations detected

This is kind of ok in my mind. Do I get something wrong? Maybe wrong arguments for health check?

[Dinko Osmankovic (dinko-metalac)]

Btw, this is amd64.

[Colin Ian King (colin-king)]

I see the activity on ARM based platforms such as the Samsung Galaxy Nexus or Nexus 4. I didn't test specifically on amd64. So your amd64 results aren't representative of the final target device I guess.

[Dinko Osmankovic (dinko-metalac)]

I see. Can you provide me some insight into you results? I mean, when these processes occur:

1274 qmlscene clock_gettime 2111 35.1820
  1274 qmlscene poll 996 16.5994
  1274 qmlscene read 938 15.6327

[Dinko Osmankovic (dinko-metalac)]

I tested it on my GNex and I can confirm this issue. But, it seems it has to do with QML Timer component which is actually Qt's QTimer wrapped in QML.

Why it happens on ARM only I have no idea. Kernel issue perhaps?

[Colin Ian King (colin-king)]

when it comes down to the clock_gettime(), poll() and read() system calls one needs to identify the thread PID and then probably attach gdb to find out where in the code it is calling these particular system calls. I'm not really able to explain why it's only happening on ARM, but since one can trap all this activity in userspace I doubt the underlying cause is a kernel issue.

[Dinko Osmankovic (dinko-metalac)]

Poll() and read() are file based system calls? Am I correct? When it comes to clock_gettime() the only thing that can call it from sudoku app i QTimer, though I have no Idead why. I'll try to find out.

[Colin Ian King (colin-king)]

strace or gdb will give you more clues to what poll and read are doing. poll with NULL fd's can be used to do blocking sleeps or be using file descriptors on socket or pipe file descriptors, so it's not necessarily "file" based per se. read() may again be reading on a socket or pipe, so it's not necessarily reading a file.

[Colin Ian King (colin-king)]

Looks like recent changes in the software stack have led to some improvements:

sudo health-check -p 1728 -d 30
CPU usage:
  PID Process USR% SYS% TOTAL%
  1728 qmlscene 0.07 0.00 0.07 (very light load)

Wakeups:
  PID Process Wake/Sec Kernel Functions
  1728 qmlscene 1.00 (hrtimer_start_range_ns, hrtimer_wakeup) (low)

Context Switches:
  PID Process Voluntary Involuntary Total
                             Ctxt Sw/Sec Ctxt Sw/Sec Ctxt Sw/Sec
  1728 qmlscene 13.00 0.00 13.00 (moderate)

File I/O operations:
 No file I/O operations detected.

System calls traced:
  PID Process Syscall Count Rate/Sec
  1728 qmlscene poll 31 1.0333

Top polling system calls:
  PID Process Syscall Rate/Sec Infinite Zero Minimum Maximum Average
                                                           Timeouts Timeouts Timeout Timeout Timeout
  1728 qmlscene poll 1.0333 0 0 788.0 msec 998.0 msec 990.5 msec

So we're now just seeing a 1 Hz poll in qmlscene now.

[Dinko Osmankovic (dinko-metalac)]

Great Colin, this is what the app is supposed to behave. I have a timer that triggers every second. Is this ok by your standard? I think it is possible to increase is to maybe 5 s without using to much in scores calculation department.

[Colin Ian King (colin-king)]

Dinko, I guess the fundamental question is why does there have to be a 1Hz polling thread when idle?

[Dinko Osmankovic (dinko-metalac)]

Well, I am counting seconds since the start of the new game. I use it to calculate scores...