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

Bug #1479250 reported by Daniel van Vugt on 2015-07-29
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
The Ubuntu Power Consumption Project
Undecided
Unassigned
qtmir (Ubuntu)
High
Unassigned
unity8 (Ubuntu)
High
Unassigned

Bug Description

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.

Related branches

description: updated
tags: added: power-management
tags: added: phone
tags: added: phablet
removed: phone
Gerry Boland (gerboland) on 2015-09-02
Changed in qtmir:
status: New → Confirmed
Changed in qtmir (Ubuntu):
status: New → Confirmed
status: Confirmed → In Progress
Changed in qtmir:
status: Confirmed → In Progress
Changed in qtmir (Ubuntu):
importance: Undecided → High
Changed in qtmir:
importance: Undecided → Medium
Changed in qtmir (Ubuntu):
assignee: nobody → Daniel van Vugt (vanvugt)
Changed in qtmir:
assignee: nobody → Daniel van Vugt (vanvugt)
Daniel van Vugt (vanvugt) wrote :

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

Changed in qtmir:
status: In Progress → Triaged
Changed in qtmir (Ubuntu):
status: In Progress → Triaged
Changed in qtmir:
assignee: Daniel van Vugt (vanvugt) → nobody
Changed in qtmir (Ubuntu):
assignee: Daniel van Vugt (vanvugt) → nobody
Launchpad Janitor (janitor) wrote :

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

Changed in qtmir (Ubuntu):
status: Triaged → Fix Released
Changed in qtmir (Ubuntu):
status: Fix Released → Triaged
Daniel van Vugt (vanvugt) wrote :

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}])

tags: added: performance
Daniel van Vugt (vanvugt) wrote :
Download full text (7.8 KiB)

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

Read more...

summary: - unity8 process using CPU when the phone is idle
+ Unity8 wakes up the CPU continuously even when idle
Changed in unity8 (Ubuntu):
importance: Undecided → Medium
importance: Medium → High
tags: added: unity8-desktop

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) wrote :

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) wrote :

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

summary: - Unity8 wakes up the CPU continuously even when idle
+ Unity8 wakes up the CPU continuously at around 5Hz on a phone
Michał Sawicz (saviq) on 2017-03-13
no longer affects: qtmir
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers