1 /*! \page performance-profiling Performance Profiling
3 * <h2 class="pg">Enable Logging</h2>
5 * Setting DALI_LOG_PERFORMANCE environment variable will enable performance profiling <br>
6 * It uses a bit mask to decide what to log. <br>
7 * The log options are:<br>
9 * Bit 0 = Log update and render threads (e.g. DALI_LOG_PERFORMANCE=1 dali-demo)
10 * Bit 1 = Log event process time (e.g. DALI_LOG_PERFORMANCE=2 dali-demo)
11 * Bit 2 = Log Dali markers to trace file (e.g. DALI_LOG_PERFORMANCE=4 dali-demo)
13 * To log both update, render and event times, then combine bits 0 and 1.<br>
14 * DALI_LOG_PERFORMANCE=3 dali-demo
18 * <h2 class="pg">Background</h2>
19 * The Dali rendering pipeline has 2 stages.
20 * Each stage is typically run once per frame.
21 * <h3> 1. Update </h3>
23 * <li> Run animations</li>
24 * <li> Run constraints</li>
25 * <li> Run physics</li>
26 * <li> Update the scene-graph</li>
28 * <h3> 2. Render </h3>
30 * <li> Upload 3D data using OpenGL ( textures, vertex buffers etc).</li>
31 * <li> Draw the scene using OpenGL</li>
35 * To run at 60 FPS (16 milliseconds per frame), it is recommended to stay below the following times:
37 * <li> Update: 4 milliseconds</li>
38 * <li> Render: 4 milliseconds</li>
41 * This will leave enough time for the output to be composited (if the system uses a compositor) and to avoid using
43 * The main Dali application thread which deals with event processing is independent of the update / render threads. <br>
44 * This means animations won't stop if the main thread decides to do a long operation like downloading a file from the internet.
46 * Performance logging uses Dali log output which on Tizen is dlog, but this can also be used on desktop by redirecting stderr to a file.<br>
50 * $ export DALI_LOG_PERFORMANCE=1
54 * $ I/DALI ( 5692): tizen-logging.cpp: LogMessage(40) > Update , min 0.59 ms, max 6.43 ms, total (3.4 secs), avg 1.26 ms
55 * $ I/DALI ( 5692): tizen-logging.cpp: LogMessage(40) > Render , min 1.67 ms, max 5.01 ms, total (4.5 secs), avg 3.71 ms
58 * If nothing is animating Dali will enter a paused state to save power. At this
59 * point nothing will be logged.
62 * <h2 class="pg">Application profiling</h2>
64 * The main application thread in Dali is used to process and respond to events such as touch, key, mouse, gestures and timers. <br>
65 * The time taken to process events can be measured by setting DALI_LOG_PERFORMANCE environment variable to 2 <br>
69 * $ export DALI_LOG_PERFORMANCE=2
73 * $ INFO: DALI: Event , min 0.01 ms, max 14.99 ms, total (2.4 secs), avg 1.83 ms
76 * Inside the event processing, the application may be listening for certain events. <br>
77 * For example when an actor is touched, some application code may be run in an OnTouchEvent callback. <br>
78 * By checking the max times you can check for any spikes that occur when interacting with the application.
82 * $ INFO: DALI: Event , min 0.10 ms, max 500.01 ms, total (6.4 secs), avg 20.83 ms
84 * - Something has taken 500 ms = 1/2 second during event processing.
85 * - Need to investigate what the application is doing for 1/2 a second.
89 * <h2 class="pg">Logging performance markers to Kernel trace file</h2>
91 * Ftrace is a kernel tracer designed to help developers find out what is going on inside the kernel.<br>
92 * It can be used for analysing how long Dali takes to perform different tasks and <br>
93 * what Dali is doing in relation to other system processes / interrupts.
95 * On Tizen if the kernel has been built with ftrace enabled, then Dali can log out to ftrace.<br>
96 * This gives exact time stamps of the main events in Dali.
97 * Current markers that are logged:
99 * <li> DALI_V_SYNC. The heart beat which represents Dali should start creating a new frame if anything has changed.<br>
100 * Typically runs 60 Frames per second, depending on display refresh rate.
101 * <li> DALI_UPDATE_START. Dali update task has started.
102 * <li> DALI_UPDATE_START. Dali update task has finished
103 * <li> DALI_RENDER_START. Dali render task has started
104 * <li> DALI_RENDER_END. Dali render task has finished
107 * <h3> Checking ftrace is working on Linux</h3>
109 * Documentation for ftrace:
110 * Follow these instructions to ensure the debugfs has been mounted, and the kernel you are using
111 * has been built with ftrace enabled. <br>
112 * https://www.kernel.org/doc/Documentation/trace/ftrace.txt
114 * To check ftrace is working:
116 * $ cd /sys/kernel/debug/tracing
117 * $ echo 1 > tracing_enabled (enabled tracing)
118 * $ echo "test" > trace_marker
119 * $ echo 0 > tracing_enabled (disable tracing)
122 * # TASK-PID CPU# TIMESTAMP FUNCTION
124 * <...>-2539 [001] 267964.345607: tracing_mark_write: test
127 * If the message did not get added to the trace, then check the write permissions on trace_marker file. E.g.
128 * $ chmod ugoa+w trace_marker
131 * To view Dali markers in trace file<br>
134 * $ export DALI_LOG_PERFORMANCE=4
137 * $ cat /sys/kernel/debug/tracing/trace
139 * <...>-3330 [000] 785155.216611: tracing_mark_write: SPI_EV_DALI_V_SYNC
140 * <...>-3328 [003] 785155.216644: tracing_mark_write: SPI_EV_DALI_UPDATE_START
141 * <...>-3328 [003] 785155.217045: tracing_mark_write: SPI_EV_DALI_UPDATE_END
142 * <...>-3329 [001] 785155.227418: tracing_mark_write: SPI_EV_DALI_RENDER_START
143 * <...>-3329 [001] 785155.227807: tracing_mark_write: SPI_EV_DALI_RENDER_END
144 * <...>-3330 [000] 785155.233336: tracing_mark_write: SPI_EV_DALI_V_SYNC
145 * <...>-3328 [002] 785155.233374: tracing_mark_write: SPI_EV_DALI_UPDATE_START
146 * <...>-3328 [002] 785155.233672: tracing_mark_write: SPI_EV_DALI_UPDATE_END
147 * <...>-3329 [001] 785155.235161: tracing_mark_write: SPI_EV_DALI_RENDER_START
148 * <...>-3329 [001] 785155.235475: tracing_mark_write: SPI_EV_DALI_RENDER_END
149 * <...>-3330 [000] 785155.250029: tracing_mark_write: SPI_EV_DALI_V_SYNC
150 * <...>-3328 [003] 785155.250065: tracing_mark_write: SPI_EV_DALI_UPDATE_START
151 * <...>-3328 [003] 785155.250330: tracing_mark_write: SPI_EV_DALI_UPDATE_END
152 * <...>-3329 [001] 785155.252860: tracing_mark_write: SPI_EV_DALI_RENDER_START
153 * <...>-3329 [001] 785155.253178: tracing_mark_write: SPI_EV_DALI_RENDER_END
154 * <...>-3329 [001] 785155.264508: tracing_mark_write: SPI_EV_DALI_RENDER_START
155 * <...>-3329 [001] 785155.265006: tracing_mark_write: SPI_EV_DALI_RENDER_END