Unity8 wakes up the CPU continuously at around 5Hz on a phone

[Daniel van Vugt]

top reports the unity8 process is consuming about 1% CPU even when the phone is idle (screen on):

11688 phablet 20 0 482184 101352 44872 S 1.0 5.4 0:37.10 unity8

This makes unity8 the top consumer of CPU. 1% on modern CPUs like you find in phones is actually a very large amount of work going on (~10 million clock ticks spent executing instructions per second on a 1GHz core).

$ system-image-cli -i
current build number: 272
device name: mako
channel: ubuntu-touch/devel-proposed/ubuntu
last update: 2015-07-29 05:53:01
version version: 272
version ubuntu: 20150729
version device: 20150708
version custom: 20150729

Running eventstat shows this CPU time is being used in 5 events per second:

 Event/s PID Task Init Function Callback
   36.36 0 [swapper/0] hrtimer_start_range_ns tick_sched_timer
    5.05 11688 unity8 hrtimer_start_range_ns hrtimer_wakeup

So it sounds like QtMir's frame dropper is the culprit.

[Daniel van Vugt (vanvugt)]

My attached branch only solves half the problem, so this bug needs to stay open till the other half is investigated.

[Launchpad Janitor (janitor)]

This bug was fixed in the package qtmir - 0.4.6+15.10.20150914-0ubuntu1

---------------
qtmir (0.4.6+15.10.20150914-0ubuntu1) wily; urgency=medium

  [ Daniel d'Andrada ]
  * MirSurfaceItem gets dirty when it's set to draw a different (or no)
    surface (LP: #1492185)
  * QtEventFeeder: log the pointer events it gets from Mir

  [ Daniel van Vugt ]
  * Stop waking up every 200ms if there's nothing to wake up for. It's
    just wasting battery. (LP: #1479250)

 -- Gerry Boland <email address hidden> Mon, 14 Sep 2015 13:11:56 +0000

[Daniel van Vugt (vanvugt)]

Even with the fix unity8 is the busiest process while the phone is idle. strace shows it is constantly:

clock_gettime(CLOCK_MONOTONIC, {72187, 518292300}) = 0
clock_gettime(CLOCK_MONOTONIC, {72187, 520417454}) = 0
poll([{fd=5, events=POLLIN}, {fd=49, events=POLLIN}, {fd=50, events=POLLIN}, {fd=54, events=POLLIN}, {fd=61, events=POLLIN}, {fd=71, events=POLLIN}, {fd=74, events=POLLIN}, {fd=78, events=POLLIN}, {fd=94, events=POLLIN}, {fd=102, events=POLLIN}, {fd=112, events=POLLIN}], 11, 2480) = 1 ([{fd=5, revents=POLLIN}])
read(5, "\1\0\0\0\0\0\0\0", 16) = 8
clock_gettime(CLOCK_MONOTONIC, {72187, 585895531}) = 0
clock_gettime(CLOCK_MONOTONIC, {72187, 588166993}) = 0
poll([{fd=5, events=POLLIN}, {fd=49, events=POLLIN}, {fd=50, events=POLLIN}, {fd=54, events=POLLIN}, {fd=61, events=POLLIN}, {fd=71, events=POLLIN}, {fd=74, events=POLLIN}, {fd=78, events=POLLIN}, {fd=94, events=POLLIN}, {fd=102, events=POLLIN}, {fd=112, events=POLLIN}], 11, 2412) = 1 ([{fd=5, revents=POLLIN}])
read(5, "\1\0\0\0\0\0\0\0", 16) = 8
clock_gettime(CLOCK_MONOTONIC, {72187, 653935377}) = 0
clock_gettime(CLOCK_MONOTONIC, {72187, 656290762}) = 0
poll([{fd=5, events=POLLIN}, {fd=49, events=POLLIN}, {fd=50, events=POLLIN}, {fd=54, events=POLLIN}, {fd=61, events=POLLIN}, {fd=71, events=POLLIN}, {fd=74, events=POLLIN}, {fd=78, events=POLLIN}, {fd=94, events=POLLIN}, {fd=102, events=POLLIN}, {fd=112, events=POLLIN}], 11, 2344) = 1 ([{fd=5, revents=POLLIN}])
read(5, "\1\0\0\0\0\0\0\0", 16) = 8
clock_gettime(CLOCK_MONOTONIC, {72187, 719686685}) = 0
clock_gettime(CLOCK_MONOTONIC, {72187, 721147762}) = 0
poll([{fd=5, events=POLLIN}, {fd=49, events=POLLIN}, {fd=50, events=POLLIN}, {fd=54, events=POLLIN}, {fd=61, events=POLLIN}, {fd=71, events=POLLIN}, {fd=74, events=POLLIN}, {fd=78, events=POLLIN}, {fd=94, events=POLLIN}, {fd=102, events=POLLIN}, {fd=112, events=POLLIN}], 11, 2279) = 1 ([{fd=5, revents=POLLIN}])

[Daniel van Vugt (vanvugt)]

Still a problem, now on Unity8 in zesty desktop. An idle desktop spins the CPU constantly:

$ sudo strace -p `pidof unity8`
...
futex(0x55a7fefd1e8c, FUTEX_WAIT_PRIVATE, 25901, NULL) = 0
futex(0x55a7fefd1e60, FUTEX_WAKE_PRIVATE, 1) = 0
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 5) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\6\0\0\0\0\0\0\0", 16) = 8
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 4) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\6\0\0\0\0\0\0\0", 16) = 8
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 1) = 0 (Timeout)
futex(0x55a7fefd1e8c, FUTEX_WAIT_PRIVATE, 25903, NULL) = 0
futex(0x55a7fefd1e60, FUTEX_WAKE_PRIVATE, 1) = 0
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 5) = 0 (Timeout)
futex(0x55a7fefd1e8c, FUTEX_WAIT_PRIVATE, 25905, NULL) = 0
futex(0x55a7fefd1e60, FUTEX_WAKE_PRIVATE, 1) = 0
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 5) = 0 (Timeout)
futex(0x55a7fefd1e8c, FUTEX_WAIT_PRIVATE, 25907, NULL) = 0
futex(0x55a7fefd1e60, FUTEX_WAKE_PRIVATE, 1) = 0
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 5) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\6\0\0\0\0\0\0\0", 16) = 8
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 2) = 0 (Timeout)
futex(0x55a7fefd1e8c, FUTEX_WAIT_PRIVATE, 25909, NULL) = 0
futex(0x55a7fefd1e60, FUTEX_WAKE_PRIVATE, 1) = 0
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd=82, events=POLLIN}, {fd=84, events=POLLIN}, {fd=86, events=POLLIN}, {fd=88, events=POLLIN}], 10, 0) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\6\0\0\0\0\0\0\0", 16) = 8
poll([{fd=4, events=POLLIN}, {fd=42, events=POLLIN}, {fd=44, events=POLLIN}, {fd=60, events=POLLIN}, {fd=68, events=POLLIN}, {fd=80, events=POLLIN}, {fd...

[Daniel van Vugt (vanvugt)]

Looks like a common theme all along is:

   read(fd, buf, 16) = 8

So what polls for and reads into a max buffer size of 16?

[Daniel van Vugt (vanvugt)]

eventstat reports the wakeup frequency is suspiciously familiar:

 Event/s PID Task Init Function Callback
   62.00 12359 QSGRenderThread do_nanosleep hrtimer_wakeup
   62.00 11858 unity8 schedule_hrtimeout_range_ hrtimer_wakeup

[Daniel van Vugt (vanvugt)]

I'm moving this new desktop issue into a new bug 1664828