PyTimechart practical
Pierre Tardy Software Engineer - UMG ELC, Feb 2012
About the author
Intel Employee since 2009 Working on Intels phone platforms
Meego Android Power Management Tools (pytimechart, buildbot) Open-Source expertise Formerly Freescale Employee
DVBH, LTE (gpe, oe, poky, cairo)
Agenda
I will not rephrase the documentation, you can access it following this link:
[Link]
Goal is to present the tool using real-world traces. See what you can get, what you wont get. 1. PyTimechart Overview 2. Audio Player usecase
Hunting the wakes
3. Bootcharting Ubuntu
4. Modem driver traces 3
Filtering with pytimechart
Hacking PyTimechart to decode your own traces
Questions?
PyTimechart Overview
PyTimechart Overview
Ftrace/perf are linux kernel tracing system.
Very low overhead
Already a lot of tracepoints available
Can trace all function calls without kernel compile Hard to dive into trace Most people need visual representation or get lost
PyTimechart aims to let you quickly find what you are looking for
Based on chaco, the browsing is very fast Based on python, parsing is very simple
PyTimechart Overview
One line per Process. Process in pytimechart can be: An IRQ callback
A workqueue
A tasklet A linux process, identified by pid, and comm A power state (cpuidle, runtime_pm) Zoom with mouse wheel Select a part of the chart
Show time range
Simple browsing
Processor share
Original trace as text
Audio Player usecase
hunting the wakes
LowPower MP3 usecase
Playing mp3 is easy. Playing your whole music library in one battery charge is much harder. Need to improve wake up count. Each time the cpu wakes up, energy is spent (cache, PLL, etc)
Audio HW is generating IRQ when a new buffer is needed. This goes all the way through user space, where the mp3 decode is done.
We are waiting for:
Audio IRQ
MP3Decode Sleep Audio IRQ
MP3Decode
Sleep Etc.
LowPower MP3 usecase
10
LowPower MP3 usecase. Overview
Here are the irqs
11
LowPower MP3 usecase. Overview
Here are the irqs
Here are mp3 decodes
12
4 IRQ for 1 MP3dec
First remark: mp3 decode happens every 4 audio irq: Can we increase the audio HW buffersize and get less wake because of IRQ?
13
LowPower MP3 usecase
A *lot* of stuff happens in between irqs. Very short processing, but each wake burns energy Need to kills the timers
14
LowPower MP3 usecase
If we zoom a bit, we see 3 wake-ups. All of them show timer softirq
15
LowPower MP3 usecase
If we zoom a bit, we see 3 wake-ups. All of them show timer softirq
This one is not a wake, because at this time AudioTrackThread is still running. This is just a normal scheduler interrupt
16
LowPower MP3 usecase
zoom on the first wake: We look for non kernel framework events
17
LowPower MP3 usecase
max3110_read. Grep this function in the kernel Findout why this driver is polling
18
LowPower MP3 usecase
Other wake Exercise: Who is the culprit?
19
LowPower MP3 usecase
Do_dbs_timer? Kondemand? This is the cpufreq on demand governor. This timer is deferrable
20
[Link]
LowPower MP3 usecase
Delayed_work_timer_fn !
1st learning: Use meaningful names for your functions. Even if it is static, better put the shortname of your driver in it. 2nd learning: Grep, rootcause, fix. -> remove the timer completely ->put it as deferrable so that it does not wake from idle
22
Quick Demo!
23
Bootcharting Ubuntu
filtering in pytimechart
24
Bootchart
Whats wrong here?
25
Bootchart
Too much process! Until systemd is integrated in ubuntu, there are a lot of short lived process during boot ;-) Need to filter them to have something viewable
26
Bootchart
Select-All Hide Filter-by-duration (100ms) Select-All Show We eventually hide all processes that live less that 100ms
27
Bootchart
Lots of process are spawn in parallel.
28
Bootchart
Lots of process are spawn in parallel.
When a process is needing cpu it is shown in light yellow.
29
Bootchart
Lots of process are spawn in parallel.
When a process is needing cpu it is shown in light yellow.
Here we have a lot of blkid process spawn by udev scripts.
30
Bootchart
Filtering more process
31
Bootchart
Filtering more process
There are some part were we sleep during boot
32
Hunting sleeps
Zoom to first sleep
We wake-up because of ahci
33
Hunting sleeps
Zoom to first sleep
We wake-up because of ahci Probably disk scan
34
Hunting sleeps
Zoom to first sleep
We wake-up because of ahci Probably disk scan Could we initialize more drivers in parallel?
35
[Link]
Although this is far to be new stuff, we dont see a lot of drivers using this, AFAIK.
Disgression on red irqs
What does those IRQs in red means?
37
Disgression on red irqs
IRQ handler that lasts more than 1ms Bad for RT latency!
38
Modem driver traces
Hacking PyTimechart to decode your own traces
39
Hacking PyTimechart to decode your own traces
Pytimechart is written in python
Easy to decode its own tracepoints
Even if you dont add tracepoints, you can take advantage of function tracing to make more sense of your traces
I want to see when the hsi driver is in receive mode
The trace I took for this is a simple receive SMS trace
First, I trace hsi* and ffl* which are the low level, and protocol driver of our modem interface
I can see 4 interesting functions in the trace:
hsi_start_rx() hsi_stop_rx() ffl_start_rx() ffl_stop_rx()
40
timechart/plugins/[Link]
Provided for convenience as a good starting point. See doc for more detailed info
41
timechart/plugins/[Link]
sed s/template/hsi/g [Link] > [Link]
42
timechart/plugins/[Link]
sed s/template/hsi/g [Link] > [Link]
I want that the start functions begins a process event
43
timechart/plugins/[Link]
sed s/template/hsi/g [Link] > [Link]
I want that the start functions begins a process event and the stop function ends it
44
timechart/plugins/[Link]
sed s/template/hsi/g [Link] > [Link]
I want that the start functions begins a process event and the stop function ends it
I also add a wake event to see where I come from
45
Results
46
Results Zoomed
47
Questions?
48
Thank You
49
