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

   1 /*! \page performance-profiling Performance Profiling
   2  *
   3  * <h2 class="pg">Enable Logging</h2>
   4  *
   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>
   8  * \code
   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)
  12  *
  13  * To log both update, render and event times, then combine bits 0 and 1.<br>
  14  * DALI_LOG_PERFORMANCE=3 dali-demo
  15  * \endcode
  16  *
  17  *
  18  * <h2 class="pg">Background</h2>
  19  * The Dali rendering pipeline has 2 stages.
  20  * Each stage is typically run once per frame.
  21  *
  22  * <ul>
  23  * <li> 1. Update
  24  * <ul>
  25  * <li> Run animations
  26  * <li> Run constraints
  27  * <li> Run physics
  28  * <li> Update the scene-graph
  29  * </ul>
  30  * <li> 2. Render
  31  * <ul>
  32  * <li> Upload 3D data using OpenGL ( textures, vertex buffers etc).
  33  * <li> Draw the scene using OpenGL
  34  * </ul>
  35  * </ul>
  36  *
  37  * To run at 60 FPS (16 milliseconds per frame), it is recommended to stay below the following times:
  38  * <ul>
  39  * <li> Update: 4 milliseconds
  40  * <li> Render: 4 milliseconds
  41  * </ul>
  42  *
  43  * This will leave enough time for the output to be composited (if the system uses a compositor) and to avoid using
  44  * too much CPU power.
  45  * The main Dali application thread which deals with event processing is independent of the update / render threads. <br>
  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  * 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>
  49  *
  50  * Example:
  51  * \code
  52  * $ export DALI_LOG_PERFORMANCE=1
  53  * $ dali-demo
  54  * $
  55  * $ ...
  56  * $ I/DALI ( 5692): slp-logging.cpp: LogMessage(40) > Update , min 0.59 ms, max 6.43 ms, total (3.4 secs), avg 1.26 ms
  57  * $ I/DALI ( 5692): slp-logging.cpp: LogMessage(40) > Render , min 1.67 ms, max 5.01 ms, total (4.5 secs), avg 3.71 ms
  58  * \endcode
  59  *
  60  * If nothing is animating Dali will enter a paused state to save power. At this
  61  * point nothing will be logged.
  62  *
  63  * <h2 class="pg">Performance advice </h2>
  64  *
  65  *
  66  * <h3> Tips to reduce update times: </h3>
  67  * <ul>
  68  * <li> Keep the actor count as small as possible.
  69  * <ul>
  70  * <li> Less actors == less processing
  71  * <li> Try to keep invisible or un-used actors off the stage. Don't have hidden views on the stage.
  72  * </ul>
  73  * <li> Ensure constraints are kept as simple as possible
  74  * </ul>
  75  *
  76  * <h3> Tips to reduce render times: </h3>
  77  *
  78  * <ul>
  79  * <li> Keep the visible actor count as small as possible == less draw calls
  80  * <li> If using a fixed set of images, try pre-generating a texture-atlas.
  81  * <ul>
  82  * <li> For each image within the Atlas, use ImageActor.SetPixelArea()  to use it.
  83  * <li> This reduces texture state changes when rendering.
  84  * </ul>
  85  * <li> Try to use 9-patch when you need to stretch an image while maintaining the border size.
  86  * <ul>
  87  * <li> See ImageActor::STYLE_NINE_PATCH
  88  * </ul>
  89  * <li> When using layers try to disable the depth test to avoid the depth buffer being cleared.
  90  * <li> If writing custom shaders, try to keep them as simple as possible.
  91  * <li> Try to keep texture sizes as small as possible.
  92  * </ul>
  93  *
  94  *  <h2 class="pg">Application profiling</h2>
  95  *
  96  *  The main application thread in Dali is used to process and respond to events such as touch, key, mouse, gestures and timers. <br>
  97  *  The time taken to process events can be measured by setting DALI_LOG_PERFORMANCE environment variable to 2 <br>
  98  *
  99  * Example:
 100  * \code
 101  * $ export DALI_LOG_PERFORMANCE=2
 102  * $ dali-demo
 103  * $
 104  * $ ...
 105  * $ INFO: DALI: Event , min 0.01 ms, max 14.99 ms, total (2.4 secs), avg 1.83 ms
 106  * \endcode
 107  *
 108  * Inside the event processing, the application may be listening for certain events. <br>
 109  * For example when an actor is touched, some application code may be run in an OnTouchEvent callback. <br>
 110  * By checking the max times you can check for any spikes that occur when interacting with the application.
 111  *
 112  * Example:
 113  * \code
 114  * $ INFO: DALI: Event , min 0.10 ms, max 500.01 ms, total (6.4 secs), avg 20.83 ms
 115  *
 116  * - Something has taken 500 ms = 1/2 second during event processing.
 117  * - Need to investigate what the application is doing for 1/2 a second.
 118  * \endcode
 119  *
 120  *
 121  * <h2 class="pg">Logging performance markers to Kernel trace file</h2>
 122  *
 123  * Ftrace is a kernel tracer designed to help developers find out what is going on inside the kernel.<br>
 124  * It can be used for analysing how long Dali takes to perform different tasks and <br>
 125  * what Dali is doing in relation to other system processes / interrupts.
 126  *
 127  * On Tizen if the kernel has been built with ftrace enabled, then Dali can log out to ftrace.<br>
 128  * This gives exact time stamps of the main events in Dali.
 129  * Current markers that are logged:
 130  * <ul>
 131  * <li> DALI_V_SYNC. The heart beat which represents Dali should start creating a new frame if anything has changed.<br>
 132  * Typically runs 60 Frames per second, depending on display refresh rate.
 133  * <li> DALI_UPDATE_START. Dali update task has started.
 134  * <li> DALI_UPDATE_START. Dali update task has finished
 135  * <li> DALI_RENDER_START. Dali render task has started
 136  * <li> DALI_RENDER_END. Dali render task has finished
 137  * </ul>
 138  *
 139  * <h3> Checking ftrace is working on Tizen</h3>
 140  *
 141  * Documentation for ftrace:
 142  * Follow these instructions to ensure the debugfs has been mounted, and the kernel you are using
 143  * has been built with ftrace enabled. <br>
 144  * https://www.kernel.org/doc/Documentation/trace/ftrace.txt
 145  *
 146  * To check ftrace is working:
 147  * \code
 148  * $ cd /sys/kernel/debug/tracing
 149  * $ echo 1 > tracing_enabled    (enabled tracing)
 150  * $ echo "test" > trace_marker
 151  * $ echo 0 > tracing_enabled    (disable tracing)
 152  * $ cat trace
 153  * #
 154  * #          TASK-PID    CPU#    TIMESTAMP  FUNCTION
 155  * #             | |       |          |         |
 156  *          <...>-2539  [001] 267964.345607: tracing_mark_write: test
 157  *
 158  *
 159  * If the message did not get added to the trace, then check the write permissions on trace_marker file. E.g.
 160  * $ chmod ugoa+w trace_marker
 161  * \endcode
 162  *
 163  * To view Dali markers in trace file<br>
 164  *
 165  * \code
 166  * $ export DALI_LOG_PERFORMANCE=4
 167  * $ dali-demo
 168  * $
 169  * $ cat /sys/kernel/debug/tracing/trace
 170  *
 171  *   <...>-3330  [000] 785155.216611: tracing_mark_write: SPI_EV_DALI_V_SYNC
 172  *   <...>-3328  [003] 785155.216644: tracing_mark_write: SPI_EV_DALI_UPDATE_START
 173  *   <...>-3328  [003] 785155.217045: tracing_mark_write: SPI_EV_DALI_UPDATE_END
 174  *   <...>-3329  [001] 785155.227418: tracing_mark_write: SPI_EV_DALI_RENDER_START
 175  *   <...>-3329  [001] 785155.227807: tracing_mark_write: SPI_EV_DALI_RENDER_END
 176  *   <...>-3330  [000] 785155.233336: tracing_mark_write: SPI_EV_DALI_V_SYNC
 177  *   <...>-3328  [002] 785155.233374: tracing_mark_write: SPI_EV_DALI_UPDATE_START
 178  *   <...>-3328  [002] 785155.233672: tracing_mark_write: SPI_EV_DALI_UPDATE_END
 179  *   <...>-3329  [001] 785155.235161: tracing_mark_write: SPI_EV_DALI_RENDER_START
 180  *   <...>-3329  [001] 785155.235475: tracing_mark_write: SPI_EV_DALI_RENDER_END
 181  *   <...>-3330  [000] 785155.250029: tracing_mark_write: SPI_EV_DALI_V_SYNC
 182  *   <...>-3328  [003] 785155.250065: tracing_mark_write: SPI_EV_DALI_UPDATE_START
 183  *   <...>-3328  [003] 785155.250330: tracing_mark_write: SPI_EV_DALI_UPDATE_END
 184  *   <...>-3329  [001] 785155.252860: tracing_mark_write: SPI_EV_DALI_RENDER_START
 185  *   <...>-3329  [001] 785155.253178: tracing_mark_write: SPI_EV_DALI_RENDER_END
 186  *   <...>-3329  [001] 785155.264508: tracing_mark_write: SPI_EV_DALI_RENDER_START
 187  *   <...>-3329  [001] 785155.265006: tracing_mark_write: SPI_EV_DALI_RENDER_END
 188  * \endcode
 189  */