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