docs/content/programming-guide/performance-profiling.md

   1 <!--
   2 /**-->
   3
   4 # Performance Profiling  {#performanceprofiling}
   5
   6
   7 DALi has many mechanisms for analyzing performance including kernel, system and network logging.
   8
   9
  10 ## Background
  11 The DALi rendering pipeline has 2 stages.
  12
  13 Each stage is typically run once per frame.
  14
  15 - Update
  16   - Run animations
  17   - Run constraints
  18   - Run physics
  19   - Update the scene-graph
  20 - Render
  21   - Upload 3D data using OpenGL ( textures, vertex buffers etc).
  22   - Draw the scene using OpenGL
  23
  24
  25 Update produces data - **Writes** final object positions to a buffer
  26
  27 Render consumes data - **Reads** object positions from a buffer and draws with OpenGL
  28
  29 ![ ](update-render.png)
  30
  31
  32 One reason for having 2 buffers is to allow both tasks to overlap and run in parallel in certain situations.
  33 E.g. if rendering is taking a long time (due to a texture upload), the Update thread can start work producing
  34 data for the next frame. The aim being to take advantage of multi-core CPU's.
  35
  36 To run at a solid 60 FPS (16 milliseconds per frame), it is recommended to stay below the following times:
  37
  38  - Update: 4 milliseconds
  39  - Render: 4 milliseconds
  40
  41 This will leave enough time for the output to be composited (if the system uses a compositor) and to avoid using
  42 too much CPU power.
  43
  44 The main DALi application thread which deals with event processing is independent of the update / render threads.
  45 This means animations won't stop if the main thread decides to do a long operation like downloading a file from the internet.
  46
  47
  48 ## Time Stamp Logging
  49
  50 This type of logging is used for recording individual time stamped events.
  51
  52 Setting DALI_PERFORMANCE_TIMESTAMP_OUTPUT environment variable will enable time stamps.
  53
  54 Tools such as Tizen dynamic analyzer and StageHand can be used to provide a GUI display of
  55 the output.
  56
  57
  58 The log options are:
  59
  60 |  Bit |  Function                | Example      |
  61 |------|--------------------------|--------------|
  62 |   0  |  log markers to DALi log (dlog on Tizen) | DALI_PERFORMANCE_TIMESTAMP_OUTPUT=1 dali-demo |
  63 |   1  |  log markers to kernel trace ( logs to ftrace )| DALI_PERFORMANCE_TIMESTAMP_OUTPUT=2 dali-demo |
  64 |   2  |  log markers to system trace ( ttrace on Tizen for Tizen analyzer) | DALI_PERFORMANCE_TIMESTAMP_OUTPUT=4 dali-demo |
  65 |   3  |  log markers to network client (tcp port 3001+) | DALI_PERFORMANCE_TIMESTAMP_OUTPUT=8 dali-demo |
  66
  67
  68
  69 ~~~
  70 DALI_PERFORMANCE_TIMESTAMP_OUTPUT=1 dali-demo
  71 INFO: DALI: 1134155.500142 (seconds), V_SYNC
  72 INFO: DALI: 1134155.500167 (seconds), UPDATE_START
  73 INFO: DALI: 1134155.500214 (seconds), PROCESS_EVENT_END
  74 INFO: DALI: 1134155.500659 (seconds), UPDATE_END
  75 INFO: DALI: 1134155.508039 (seconds), PROCESS_EVENT_START
  76 INFO: DALI: 1134155.508295 (seconds), PROCESS_EVENT_END
  77 INFO: DALI: 1134155.511109 (seconds), RENDER_START
  78 INFO: DALI: 1134155.511548 (seconds), RENDER_END
  79 INFO: DALI: 1134155.516899 (seconds), V_SYNC
  80 INFO: DALI: 1134155.516945 (seconds), UPDATE_START
  81 INFO: DALI: 1134155.517462 (seconds), UPDATE_END
  82 INFO: DALI: 1134155.527884 (seconds), RENDER_START
  83 INFO: DALI: 1134155.528108 (seconds), PROCESS_EVENT_START
  84 INFO: DALI: 1134155.528327 (seconds), RENDER_END
  85 INFO: DALI: 1134155.528358 (seconds), PROCESS_EVENT_END
  86 INFO: DALI: 1134155.528388 (seconds), PROCESS_EVENT_START
  87 INFO: DALI: 1134155.528749 (seconds), PROCESS_EVENT_END
  88 INFO: DALI: 1134155.533672 (seconds), V_SYNC
  89 ~~~
  90
  91 ### Markers that are logged
  92
  93 | Marker | Description
  94 |--------|-------------
  95 | 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 |
  96 | UPDATE_START | DALi update task has started |
  97 | UPDATE_START | DALi update task has finished |
  98 | RENDER_START | DALi render task has started |
  99 | RENDER_END | DALi render task has finished |
 100 | PROCESS_EVENT_START | DALi main thread processing events (e.g. in response to a touch event or a timer) |
 101 | PROCESS_EVENT_START | DALi main thread processing events finished |
 102 | SWAP_START | glSwapBuffers started (todo) |
 103 | SWAP_END | glSwapBuffers end  (todo) |
 104 | PAUSE  | Application paused |
 105 | RESUME | Application resumed |
 106
 107 ### Custom time stamps for application developers
 108
 109 A developer can output custom markers using the PerformanceLogger API (C++ only currently)
 110
 111 ~~~
 112 PerformanceLogger logger = PerformanceLogger::New("MyMarker");
 113 logger.AddMarker(PerformanceLogger::START_EVENT);
 114
 115 // do stuff
 116
 117 logger.AddMarker(PerformanceLogger::END_EVENT);
 118 ~~~
 119
 120 ## Statistics logging
 121
 122 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.
 123
 124 Setting DALI_LOG_PERFORMANCE_STATS environment variable will enable time stamps.
 125
 126 The log options are:
 127
 128 |  Bit |  Function                | Example      |
 129 |------|--------------------------|--------------|
 130 |   0  |  log all statistics to the DALi log | DALI_LOG_PERFORMANCE_STATS=1 dali-demo |
 131 |   1  |  log update and render statistics to the DALi log| DALI_LOG_PERFORMANCE_STATS=2 dali-demo |
 132 |   2  |  log event (main) task statistics to the DALi log| DALI_LOG_PERFORMANCE_STATS=4 dali-demo |
 133 |   3  |  log custom marker statistics to the DALi log | DALI_LOG_PERFORMANCE_STATS=8 dali-demo |
 134
 135 Example output
 136 ~~~
 137 $ export DALI_LOG_PERFORMANCE_STATS=1
 138 $ dali-demo
 139
 140  Event, min 0.04 ms, max 5.27 ms, total (0.1 secs), avg 0.28 ms, std dev 0.73 ms
 141  Update, min 0.29 ms, max 0.91 ms, total (0.5 secs), avg 0.68 ms, std dev 0.15 ms
 142  Render, min 0.33 ms, max 0.97 ms, total (0.6 secs), avg 0.73 ms, std dev 0.17 ms
 143  TableViewInit, min 76.55 ms, max 76.55 ms, total (0.1 secs), avg 76.55 ms, std dev 0.00 ms
 144 ~~~
 145
 146 If nothing is animating DALi will enter a paused state to save power. At this
 147 point nothing will be logged.
 148
 149 ### Custom statistics for application developers
 150
 151 This is identical to the custom timestamp example.
 152 ~~~
 153 PerformanceLogger logger = PerformanceLogger::New("MyMarker");
 154 logger.AddMarker(PerformanceLogger::START_EVENT);
 155
 156 // do stuff
 157
 158 logger.AddMarker(PerformanceLogger::END_EVENT);
 159 ~~~
 160
 161
 162 ## Application profiling
 163
 164  The main application thread in DALi is used to process and respond to events such as touch, key, mouse, gestures and timers.
 165
 166 Example:
 167 ~~~
 168 $ export DALI_LOG_PERFORMANCE_STATS=4
 169 $ dali-demo
 170 $
 171 $ ...
 172 $ INFO: DALI:  Event, min 0.04 ms, max 5.27 ms, total (0.1 secs), avg 0.28 ms, std dev 0.73 ms
 173 ~~~
 174
 175 Inside the event processing, the application may be listening for certain events.
 176 For example when an actor is touched, some application code may be run in an OnTouch callback.
 177 By checking the max times you can check for any spikes that occur when interacting with the application.
 178
 179 Example:
 180 ~~~
 181 $ INFO: DALI: Event , min 0.10 ms, max 500.01 ms, total (6.4 secs), avg 20.83 ms
 182
 183 - Something has taken 500 ms = 1/2 second during event processing.
 184 - Need to investigate what the application is doing for 1/2 a second.
 185 ~~~
 186
 187
 188 ## Using ftrace for timestamp logging
 189
 190 ~~~
 191 DALI_PERFORMANCE_TIMESTAMP_OUTPUT=2 dali-demo
 192 ~~~
 193
 194 Ftrace is a kernel tracer designed to help developers find out what is going on inside the kernel.
 195 It can be used for analyzing how long DALi takes to perform different tasks and
 196 what DALi is doing in relation to other system processes / interrupts.
 197
 198 On Tizen if the kernel has been built with ftrace enabled, then DALi can log out to ftrace.
 199 This gives exact time stamps of the main events in DALi.
 200 Current markers that are logged:
 201
 202
 203
 204 ### Checking ftrace is working on Linux
 205
 206 Documentation for ftrace:
 207 Follow these instructions to ensure the debugfs has been mounted, and the kernel you are using
 208 has been built with ftrace enabled.
 209
 210 https://www.kernel.org/doc/Documentation/trace/ftrace.txt
 211
 212 To check ftrace is working:
 213 ~~~
 214 $ cd /sys/kernel/debug/tracing
 215 $ echo 1 > tracing_enabled    (enabled tracing)
 216 $ echo "test" > trace_marker
 217 $ echo 0 > tracing_enabled    (disable tracing)
 218 $ cat trace
 219 #
 220 #          TASK-PID    CPU#    TIMESTAMP  FUNCTION
 221 #             | |       |          |         |
 222          <...>-2539  [001] 267964.345607: tracing_mark_write: test
 223
 224
 225 If the message did not get added to the trace, then check the write permissions on trace_marker file. E.g.
 226 $ chmod ugoa+w trace_marker
 227 ~~~
 228 To view DALi markers in trace file
 229
 230 ~~~
 231 $ export DALI_LOG_PERFORMANCE=2
 232 $ dali-demo
 233 $
 234 $ cat /sys/kernel/debug/tracing/trace
 235
 236   <...>-3330  [000] 785155.216611: tracing_mark_write: SPI_EV_DALI_V_SYNC
 237   <...>-3328  [003] 785155.216644: tracing_mark_write: SPI_EV_DALI_UPDATE_START
 238   <...>-3328  [003] 785155.217045: tracing_mark_write: SPI_EV_DALI_UPDATE_END
 239   <...>-3329  [001] 785155.227418: tracing_mark_write: SPI_EV_DALI_RENDER_START
 240   <...>-3329  [001] 785155.227807: tracing_mark_write: SPI_EV_DALI_RENDER_END
 241   <...>-3330  [000] 785155.233336: tracing_mark_write: SPI_EV_DALI_V_SYNC
 242   <...>-3328  [002] 785155.233374: tracing_mark_write: SPI_EV_DALI_UPDATE_START
 243   <...>-3328  [002] 785155.233672: tracing_mark_write: SPI_EV_DALI_UPDATE_END
 244   <...>-3329  [001] 785155.235161: tracing_mark_write: SPI_EV_DALI_RENDER_START
 245   <...>-3329  [001] 785155.235475: tracing_mark_write: SPI_EV_DALI_RENDER_END
 246   <...>-3330  [000] 785155.250029: tracing_mark_write: SPI_EV_DALI_V_SYNC
 247   <...>-3328  [003] 785155.250065: tracing_mark_write: SPI_EV_DALI_UPDATE_START
 248   <...>-3328  [003] 785155.250330: tracing_mark_write: SPI_EV_DALI_UPDATE_END
 249   <...>-3329  [001] 785155.252860: tracing_mark_write: SPI_EV_DALI_RENDER_START
 250   <...>-3329  [001] 785155.253178: tracing_mark_write: SPI_EV_DALI_RENDER_END
 251   <...>-3329  [001] 785155.264508: tracing_mark_write: SPI_EV_DALI_RENDER_START
 252   <...>-3329  [001] 785155.265006: tracing_mark_write: SPI_EV_DALI_RENDER_END
 253 ~~~
 254 */
 255
 256