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  * <h3> 1. Update </h3>
  22  * <ul>
  23  * <li> Run animations</li>
  24  * <li> Run constraints</li>
  25  * <li> Run physics</li>
  26  * <li> Update the scene-graph</li>
  27  * </ul>
  28  * <h3> 2. Render </h3>
  29  * <ul>
  30  * <li> Upload 3D data using OpenGL ( textures, vertex buffers etc).</li>
  31  * <li> Draw the scene using OpenGL</li>
  32  * </ul>
  33  *
  34  *
  35  * To run at 60 FPS (16 milliseconds per frame), it is recommended to stay below the following times:
  36  * <ul>
  37  * <li> Update: 4 milliseconds</li>
  38  * <li> Render: 4 milliseconds</li>
  39  * </ul>
  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  * 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.
  45  *
  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>
  47  *
  48  * Example:
  49  * \code
  50  * $ export DALI_LOG_PERFORMANCE=1
  51  * $ dali-demo
  52  * $
  53  * $ ...
  54  * $ 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
  55  * $ 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
  56  * \endcode
  57  *
  58  * If nothing is animating Dali will enter a paused state to save power. At this
  59  * point nothing will be logged.
  60  *
  61  *
  62  *  <h2 class="pg">Application profiling</h2>
  63  *
  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>
  66  *
  67  * Example:
  68  * \code
  69  * $ export DALI_LOG_PERFORMANCE=2
  70  * $ dali-demo
  71  * $
  72  * $ ...
  73  * $ INFO: DALI: Event , min 0.01 ms, max 14.99 ms, total (2.4 secs), avg 1.83 ms
  74  * \endcode
  75  *
  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.
  79  *
  80  * Example:
  81  * \code
  82  * $ INFO: DALI: Event , min 0.10 ms, max 500.01 ms, total (6.4 secs), avg 20.83 ms
  83  *
  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.
  86  * \endcode
  87  *
  88  *
  89  * <h2 class="pg">Logging performance markers to Kernel trace file</h2>
  90  *
  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.
  94  *
  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:
  98  * <ul>
  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
 105  * </ul>
 106  *
 107  * <h3> Checking ftrace is working on Linux</h3>
 108  *
 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
 113  *
 114  * To check ftrace is working:
 115  * \code
 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)
 120  * $ cat trace
 121  * #
 122  * #          TASK-PID    CPU#    TIMESTAMP  FUNCTION
 123  * #             | |       |          |         |
 124  *          <...>-2539  [001] 267964.345607: tracing_mark_write: test
 125  *
 126  *
 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
 129  * \endcode
 130  *
 131  * To view Dali markers in trace file<br>
 132  *
 133  * \code
 134  * $ export DALI_LOG_PERFORMANCE=4
 135  * $ dali-demo
 136  * $
 137  * $ cat /sys/kernel/debug/tracing/trace
 138  *
 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
 156  * \endcode
 157  */