Dali 3D User Interface Engine
performance-profiling

Performance Profiling

DALi has many mechanisms for analysing performance including kernel, system and network logging.

Background

The DALi rendering pipeline has 2 stages.

Each stage is typically run once per frame.

Update produces data - Writes final object positions to a buffer

Render consumes data - Reads object positions from a buffer and draws with OpenGL

update-render.png

One reason for having 2 buffers is to allow both tasks to overlap and run in parallel in certain situations. E.g. if rendering is taking a long time (due to a texture upload), the Update thread can start work producing data for the next frame. The aim being to take advantage of multi-core CPU's.

To run at a solid 60 FPS (16 milliseconds per frame), it is recommended to stay below the following times:

This will leave enough time for the output to be composited (if the system uses a compositor) and to avoid using too much CPU power.

The main DALi application thread which deals with event processing is independent of the update / render threads. This means animations won't stop if the main thread decides to do a long operation like downloading a file from the internet.

Time Stamp Logging

This type of logging is used for recording individual time stamped events.

Setting DALI_PERFORMANCE_TIMESTAMP_OUTPUT environment variable will enable time stamps.

Tools such as Tizen dynamic analyser and StageHand can be used to provide a GUI display of the output.

The log options are:

Bit Function Example
0 log markers to DALi log (dlog on Tizen) DALI_PERFORMANCE_TIMESTAMP_OUTPUT=1 dali-demo
1 log markers to kernel trace ( logs to ftrace )DALI_PERFORMANCE_TIMESTAMP_OUTPUT=2 dali-demo
2 log markers to system trace ( ttrace on Tizen for Tizen analyser) DALI_PERFORMANCE_TIMESTAMP_OUTPUT=4 dali-demo
3 log markers to network client (tcp port 3001+) DALI_PERFORMANCE_TIMESTAMP_OUTPUT=8 dali-demo
DALI_PERFORMANCE_TIMESTAMP_OUTPUT=1 dali-demo
INFO: DALI: 1134155.500142 (seconds), V_SYNC
INFO: DALI: 1134155.500167 (seconds), UPDATE_START
INFO: DALI: 1134155.500214 (seconds), PROCESS_EVENT_END
INFO: DALI: 1134155.500659 (seconds), UPDATE_END
INFO: DALI: 1134155.508039 (seconds), PROCESS_EVENT_START
INFO: DALI: 1134155.508295 (seconds), PROCESS_EVENT_END
INFO: DALI: 1134155.511109 (seconds), RENDER_START
INFO: DALI: 1134155.511548 (seconds), RENDER_END
INFO: DALI: 1134155.516899 (seconds), V_SYNC
INFO: DALI: 1134155.516945 (seconds), UPDATE_START
INFO: DALI: 1134155.517462 (seconds), UPDATE_END
INFO: DALI: 1134155.527884 (seconds), RENDER_START
INFO: DALI: 1134155.528108 (seconds), PROCESS_EVENT_START
INFO: DALI: 1134155.528327 (seconds), RENDER_END
INFO: DALI: 1134155.528358 (seconds), PROCESS_EVENT_END
INFO: DALI: 1134155.528388 (seconds), PROCESS_EVENT_START
INFO: DALI: 1134155.528749 (seconds), PROCESS_EVENT_END
INFO: DALI: 1134155.533672 (seconds), V_SYNC

Markers that are logged

Marker Description
V_SYNC.The heart beat which represents DALi should start creating a new frame if anything has changed. Runs at display refresh rate, typically 60Hz
UPDATE_START DALi update task has started
UPDATE_START DALi update task has finished
RENDER_START DALi render task has started
RENDER_END DALi render task has finished
PROCESS_EVENT_START DALi main thread processing events (e.g. in response to a touch event or a timer)
PROCESS_EVENT_START DALi main thread processing events finished
SWAP_START glSwapBuffers started (todo)
SWAP_END glSwapBuffers end (todo)
PAUSE Application paused
RESUME Application resumed

Custom time stamps for application developers

A developer can output custom markers using the PerformanceLogger API (C++ only currently)

PerformanceLogger logger = PerformanceLogger::New("MyMarker");
logger.AddMarker(PerformanceLogger::START_EVENT);
// do stuff
logger.AddMarker(PerformanceLogger::END_EVENT);

Statistics logging

Statistics logging uses DALi log output which on Tizen is dlog, but this can also be used on desktop by redirecting stderr to a file.

Setting DALI_LOG_PERFORMANCE_STATS environment variable will enable time stamps.

The log options are:

Bit Function Example
0 log all statistics to the DALi log DALI_LOG_PERFORMANCE_STATS=1 dali-demo
1 log update and render statistics to the DALi logDALI_LOG_PERFORMANCE_STATS=2 dali-demo
2 log event (main) task statistics to the DALi logDALI_LOG_PERFORMANCE_STATS=4 dali-demo
3 log custom marker statistics to the DALi log DALI_LOG_PERFORMANCE_STATS=8 dali-demo

Example output

$ export DALI_LOG_PERFORMANCE_STATS=1
$ dali-demo
Event, min 0.04 ms, max 5.27 ms, total (0.1 secs), avg 0.28 ms, std dev 0.73 ms
Update, min 0.29 ms, max 0.91 ms, total (0.5 secs), avg 0.68 ms, std dev 0.15 ms
Render, min 0.33 ms, max 0.97 ms, total (0.6 secs), avg 0.73 ms, std dev 0.17 ms
TableViewInit, min 76.55 ms, max 76.55 ms, total (0.1 secs), avg 76.55 ms, std dev 0.00 ms

If nothing is animating DALi will enter a paused state to save power. At this point nothing will be logged.

Custom statistics for application developers

This is identical to the custom timestamp example.

PerformanceLogger logger = PerformanceLogger::New("MyMarker");
logger.AddMarker(PerformanceLogger::START_EVENT);
// do stuff
logger.AddMarker(PerformanceLogger::END_EVENT);

Application profiling

The main application thread in DALi is used to process and respond to events such as touch, key, mouse, gestures and timers.

Example:

$ export DALI_LOG_PERFORMANCE_STATS=4
$ dali-demo
$
$ ...
$ INFO: DALI: Event, min 0.04 ms, max 5.27 ms, total (0.1 secs), avg 0.28 ms, std dev 0.73 ms

Inside the event processing, the application may be listening for certain events. For example when an actor is touched, some application code may be run in an OnTouchEvent callback. By checking the max times you can check for any spikes that occur when interacting with the application.

Example:

$ INFO: DALI: Event , min 0.10 ms, max 500.01 ms, total (6.4 secs), avg 20.83 ms
- Something has taken 500 ms = 1/2 second during event processing.
- Need to investigate what the application is doing for 1/2 a second.

Using ftrace for timestamp logging

DALI_PERFORMANCE_TIMESTAMP_OUTPUT=2 dali-demo

Ftrace is a kernel tracer designed to help developers find out what is going on inside the kernel. It can be used for analysing how long DALi takes to perform different tasks and what DALi is doing in relation to other system processes / interrupts.

On Tizen if the kernel has been built with ftrace enabled, then DALi can log out to ftrace. This gives exact time stamps of the main events in Dali. Current markers that are logged:

Checking ftrace is working on Linux

Documentation for ftrace: Follow these instructions to ensure the debugfs has been mounted, and the kernel you are using has been built with ftrace enabled.

https://www.kernel.org/doc/Documentation/trace/ftrace.txt

To check ftrace is working:

$ cd /sys/kernel/debug/tracing
$ echo 1 > tracing_enabled (enabled tracing)
$ echo "test" > trace_marker
$ echo 0 > tracing_enabled (disable tracing)
$ cat trace
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<...>-2539 [001] 267964.345607: tracing_mark_write: test
If the message did not get added to the trace, then check the write permissions on trace_marker file. E.g.
$ chmod ugoa+w trace_marker

To view DALi markers in trace file

$ export DALI_LOG_PERFORMANCE=2
$ dali-demo
$
$ cat /sys/kernel/debug/tracing/trace
<...>-3330 [000] 785155.216611: tracing_mark_write: SPI_EV_DALI_V_SYNC
<...>-3328 [003] 785155.216644: tracing_mark_write: SPI_EV_DALI_UPDATE_START
<...>-3328 [003] 785155.217045: tracing_mark_write: SPI_EV_DALI_UPDATE_END
<...>-3329 [001] 785155.227418: tracing_mark_write: SPI_EV_DALI_RENDER_START
<...>-3329 [001] 785155.227807: tracing_mark_write: SPI_EV_DALI_RENDER_END
<...>-3330 [000] 785155.233336: tracing_mark_write: SPI_EV_DALI_V_SYNC
<...>-3328 [002] 785155.233374: tracing_mark_write: SPI_EV_DALI_UPDATE_START
<...>-3328 [002] 785155.233672: tracing_mark_write: SPI_EV_DALI_UPDATE_END
<...>-3329 [001] 785155.235161: tracing_mark_write: SPI_EV_DALI_RENDER_START
<...>-3329 [001] 785155.235475: tracing_mark_write: SPI_EV_DALI_RENDER_END
<...>-3330 [000] 785155.250029: tracing_mark_write: SPI_EV_DALI_V_SYNC
<...>-3328 [003] 785155.250065: tracing_mark_write: SPI_EV_DALI_UPDATE_START
<...>-3328 [003] 785155.250330: tracing_mark_write: SPI_EV_DALI_UPDATE_END
<...>-3329 [001] 785155.252860: tracing_mark_write: SPI_EV_DALI_RENDER_START
<...>-3329 [001] 785155.253178: tracing_mark_write: SPI_EV_DALI_RENDER_END
<...>-3329 [001] 785155.264508: tracing_mark_write: SPI_EV_DALI_RENDER_START
<...>-3329 [001] 785155.265006: tracing_mark_write: SPI_EV_DALI_RENDER_END
Dali Docs Home
Read more about Dali