github-code/lvgl
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat(profiler): add built-in profiler (#4255)

Browse Source 
Signed-off-by: FASTSHIFT <vifextech@foxmail.com>
Co-authored-by: W-Mai <1341398182@qq.com>
This commit is contained in:
_VIFEXTech
2023-06-05 22:53:57 +08:00
committed by GitHub
parent 93f4b90393
commit 06b3b62475
13 changed files with 550 additions and 50 deletions
Download Patch File Download Diff File Expand all files Collapse all files

6
Kconfig
View File

@@ -1011,10 +1011,14 @@ menu "LVGL configuration"
config LV_USE_PROFILER
bool "Runtime performance profiler."
config LV_USE_PROFILER_BUILTIN
bool "Enable the built-in profiler"
depends on LV_USE_PROFILER
default y
config LV_PROFILER_INCLUDE
string "Header to include for the profiler"
depends on LV_USE_PROFILER
default "profiler.h"
default "lvgl/src/misc/lv_profiler_builtin.h"
config LV_USE_GRIDNAV
bool "Enable grid navigation"

BIN
docs/misc/perfetto_ui.png Executable file
View File

Binary file not shown.
Side by Side

After

Width:  |  Height:  |  Size: 130 KiB

1
docs/overview/index.rst
View File

@@ -24,5 +24,6 @@ Overview
anim
timer
draw
profiler
renderers/index
new_widget

202
docs/overview/profiler.rst Normal file
View File

@@ -0,0 +1,202 @@
.. _profiler:
========
Profiler
========
As the complexity of the application increases, performance issues such as low FPS and frequent cache misses
causing lag may arise. LVGL has internally set up some hooks for performance measurement to help developers
analyze and locate performance issues.
Introduction
************
LVGL has a built-in trace system to track and record the timestamps of important events that occur during runtime,
such as rendering events and user input events. These event timestamps serve as important metrics for performance analysis.
The trace system has a configurable record buffer that stores the names of event functions and their timestamps.
When the buffer is full, the trace system prints the log information through the provided user interface.
The output trace logs are formatted according to Android's `systrace <https://developer.android.com/topic/performance/tracing>`_
format and can be visualized using `Perfetto <https://ui.perfetto.dev>`_.
Usage
*****
Configure profiler
^^^^^^^^^^^^^^^^^^
To enable the profiler, set :c:macro:`LV_USE_PROFILER` in ``lv_conf.h`` and configure the following options:
1. Enable the built-in profiler functionality by setting :c:macro:`LV_USE_PROFILER_BUILTIN`.
2. Buffer configuration: Set the value of :c:macro:`LV_PROFILER_BUILTIN_BUF_SIZE` to configure the buffer size. A larger buffer can store more trace event information, reducing interference with rendering. However, it also results in higher memory consumption.
3. Timestamp configuration: LVGL uses the :cpp:func:`lv_tick_get` function with a precision of 1ms by default to obtain timestamps when events occur. Therefore, it cannot accurately measure intervals below 1ms. If your system environment can provide higher precision (e.g., 1us), you can configure the profiler as follows:
- Recommended configuration in **UNIX** environments:
.. code:: c
#include <time.h>
static uint32_t my_get_tick_us_cb(void)
{
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
return ts.tv_sec * 1000000 + ts.tv_nsec / 1000;
}
void my_profiler_init(void)
{
lv_profiler_builtin_config_t config;
lv_profiler_builtin_config_init(&config);
config.tick_per_sec = 1000000; /* One second is equal to 1000000 microseconds */
config.tick_get_cb = my_get_tick_us_cb;
lv_profiler_builtin_init(&config);
}
- Recommended configuration in **Arduino** environments:
.. code:: c
void my_profiler_init(void)
{
lv_profiler_builtin_config_t config;
lv_profiler_builtin_config_init(&config);
config.tick_per_sec = 1000000; /* One second is equal to 1000000 microseconds */
config.tick_get_cb = micros; /* Use the microsecond time stamp provided by Arduino */
lv_profiler_builtin_init(&config);
}
4. Log output configuration: LVGL uses the :cpp:func:`LV_LOG` interface by default to output trace information. If you want to use another interface to output log information (e.g., file stream), you can redirect the log output using the following code:
.. code:: c
static void my_log_print_cb(const char * buf)
{
printf("%s", buf);
}
void my_profiler_init(void)
{
lv_profiler_builtin_config_t config;
lv_profiler_builtin_config_init(&config);
... /* other configurations */
config.flush_cb = my_log_print_cb;
lv_profiler_builtin_init(&config);
}
Run the test scenario
^^^^^^^^^^^^^^^^^^^^^
Run the UI scenario that you want to measure, such as scrolling a scrollable page up and down or entering/exiting an application.
Process the logs
^^^^^^^^^^^^^^^^
Save the output log as `my_trace.txt`, use `trace_filter.py` for filtering and preprocessing:
.. code:: bash
./lvgl/scripts/trace_filter.py my_trace.txt
or
.. code:: bash
python3 ./lvgl/scripts/trace_filter.py my_trace.txt
You will obtain a processed text file named `trace.systrace`, which roughly contains the following content:
.. code:: text
# tracer: nop
#
LVGL-1 [0] 2892.002993: tracing_mark_write: B|1|lv_timer_handler
LVGL-1 [0] 2892.002993: tracing_mark_write: B|1|_lv_disp_refr_timer
LVGL-1 [0] 2892.003459: tracing_mark_write: B|1|refr_invalid_areas
LVGL-1 [0] 2892.003461: tracing_mark_write: B|1|lv_draw_rect
LVGL-1 [0] 2892.003550: tracing_mark_write: E|1|lv_draw_rect
LVGL-1 [0] 2892.003552: tracing_mark_write: B|1|lv_draw_rect
LVGL-1 [0] 2892.003556: tracing_mark_write: E|1|lv_draw_rect
LVGL-1 [0] 2892.003560: tracing_mark_write: B|1|lv_draw_rect
LVGL-1 [0] 2892.003573: tracing_mark_write: E|1|lv_draw_rect
...
Import the processed `trace.systrace` file into `Perfetto <https://ui.perfetto.dev>`_ and wait for it to be parsed.
Performance analysis
^^^^^^^^^^^^^^^^^^^^
If the log parsing is successful, you will see the following screen:
.. image:: /misc/perfetto_ui.png
In the Perfetto UI, use the :kbd:`A` or :kbd:`D` keys to pan the timeline horizontally
and the :kbd:`W` or :kbd:`S` keys to zoom in or out on the timeline.
Use the mouse to move the focus and click on functions on the timeline to observe their execution time.
Add Measurement Point
*********************
Users can add their own measured functions:
.. code:: c
void my_function(void)
{
LV_PROFILER_BEGIN;
do_something();
LV_PROFILER_END;
}
Custom profiler implementation
******************************
If you wish to use a profiler method provided by your operating system, you can modify the following configurations in ``lv_conf.h``:
- :c:macro:`LV_PROFILER_INCLUDE`: Provides a header file for the profiler function.
- :c:macro:`LV_PROFILER_BEGIN`: Profiler start point function.
- :c:macro:`LV_PROFILER_END`: Profiler end point function.
Taking `NuttX <https://github.com/apache/nuttx>`_ RTOS as an example:
.. code:: c
#define LV_PROFILER_INCLUDE "nuttx/sched_note.h"
#define LV_PROFILER_BEGIN sched_note_begin(NOTE_TAG_ALWAYS)
#define LV_PROFILER_END sched_note_end(NOTE_TAG_ALWAYS)
FAQ
***
Perfetto log parsing fails
^^^^^^^^^^^^^^^^^^^^^^^^^^
Please check the completeness of the logs. If the logs are incomplete, it may be due to the following reasons:
1. Serial port reception errors caused by a high baud rate. You need to reduce the baud rate.
2. Data corruption caused by other thread logs inserted during the printing of trace logs. You need to disable the log output of other threads or refer to the configuration above to use a separate log output interface.
3. Cross-thread calling of :c:macro:`LV_PROFILER_BEGIN/END`.The built-in LVGL profiler is designed for single-threaded use, so calling it from multiple threads can lead to thread safety issues. If you need to use it in a multi-threaded environment, you can use profiler interfaces provided by your operating system that ensure thread safety.
Function execution time displayed as 0s in Perfetto
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
If the function execution time is lower than the precision of the timestamps, this situation can occur. You can refer to the configuration instructions above to use a higher precision timestamp.
Significant stuttering occurs during profiling
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
When the buffer used to store trace events becomes full, the profiler will output all the data in the buffer, which can cause UI blocking and stuttering during the output. You can optimize this by taking the following measures:
1. Increase the value of :c:macro:`LV_PROFILER_BUILTIN_BUF_SIZE`. A larger buffer can reduce the frequency of log printing, but it also consumes more memory.
2. Optimize the execution time of log printing functions, such as increasing the serial port baud rate or improving file writing speed.
Trace logs are not being output
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
If the trace logs are not automatically printed when the buffer is not full, you can try the following methods to force the log output:
1. Reduce the value of :c:macro:`LV_PROFILER_BUILTIN_BUF_SIZE` to fill the buffer more quickly and trigger automatic printing.
2. Manually call or use a timer to call the :cpp:func:`lv_profiler_builtin_flush` function to force the log output.

1
docs/porting/index.rst
View File

@@ -16,5 +16,4 @@ Porting
sleep
os
log
profiler
draw

42
docs/porting/profiler.rst
View File

@@ -1,42 +0,0 @@
.. _profiler:
========
Profiler
========
As the complexity of the application increases, performance issues
such as low FPS and frequent cache misses causing lag may arise.
LVGL has internally set up some hooks for performance measurement
to help developers analyze and locate performance issues.
Porting
*******
To enable profiler, set :c:macro:`LV_USE_PROFILER` in ``lv_conf.h`` and configure the following options:
- :c:macro:`LV_PROFILER_INCLUDE`: Provides a header file for the profiler function.
- :c:macro:`LV_PROFILER_BEGIN`: Profiler start point function.
- :c:macro:`LV_PROFILER_END`: Profiler end point function.
Example
*******
The following is an example of output performance measurements using LVGL logging systems:
Configure ``lv_conf.h``:
.. code:: c
#define LV_USE_PROFILER 1
#define LV_PROFILER_INCLUDE "lvgl/src/hal/lv_hal_tick.h"
#define LV_PROFILER_BEGIN uint32_t profiler_start = lv_tick_get()
#define LV_PROFILER_END LV_LOG_USER("cost %dms", (int)lv_tick_elaps(profiler_start))
Users can add the measured functions themselves:
.. code:: c
LV_PROFILER_BEGIN;
my_func();
LV_PROFILER_END;

13
lv_conf_template.h
View File

@@ -703,14 +703,21 @@
/*1: Enable the runtime performance profiler*/
#define LV_USE_PROFILER 0
#if LV_USE_PROFILER
/*1: Enable the built-in profiler*/
#define LV_USE_PROFILER_BUILTIN 1
#if LV_USE_PROFILER_BUILTIN
/*Default profiler trace buffer size*/
#define LV_PROFILER_BUILTIN_BUF_SIZE (16 * 1024) /*[bytes]*/
#endif
/*Header to include for the profiler*/
#define LV_PROFILER_INCLUDE <stdint.h>
#define LV_PROFILER_INCLUDE "lvgl/src/misc/lv_profiler_builtin.h"
/*Profiler start point function*/
#define LV_PROFILER_BEGIN
#define LV_PROFILER_BEGIN LV_PROFILER_BUILTIN_BEGIN
/*Profiler end point function*/
#define LV_PROFILER_END
#define LV_PROFILER_END LV_PROFILER_BUILTIN_END
#endif
/*1: Enable Monkey test*/

1
lvgl.h
View File

@@ -28,6 +28,7 @@ extern "C" {
#include "src/misc/lv_async.h"
#include "src/misc/lv_anim_timeline.h"
#include "src/misc/lv_printf.h"
#include "src/misc/lv_profiler_builtin.h"
#include "src/hal/lv_hal.h"

41
scripts/trace_filter.py Executable file
View File

@@ -0,0 +1,41 @@
#!/usr/bin/env python3
import argparse
import re
MARK_LIST = ['tracing_mark_write']
def get_arg():
parser = argparse.ArgumentParser(description='Filter a log file to a trace file.')
parser.add_argument('log_file', metavar='log_file', type=str,
help='The input log file to process.')
parser.add_argument('trace_file', metavar='trace_file', type=str, nargs='?', default='trace.systrace',
help='The output trace file. If not provided, defaults to \'trace.systrace\'.')
args = parser.parse_args()
print('log_file: ' + args.log_file)
print('trace_file: ' + args.trace_file)
return args
if __name__ == '__main__':
args = get_arg()
with open(args.log_file, 'r') as f:
content = f.read()
# compile regex pattern
pattern = re.compile(r'(^.+-[0-9]+\s\[[0-9]]\s[0-9]+\.[0-9]+:\s('
+ "|".join(MARK_LIST)
+ r'):\s[B|E]\|[0-9]+\|.+$)', re.M)
matches = pattern.findall(content)
# write to args.trace_file
with open(args.trace_file, 'w') as f:
f.write('# tracer: nop\n#\n')
for match in matches:
f.write(match[0] + '\n')

7
src/core/lv_obj.c
View File

@@ -124,6 +124,13 @@ void lv_init(void)
#if LV_USE_BUILTIN_MALLOC
lv_mem_init_builtin();
#endif
#if LV_USE_PROFILER && LV_USE_PROFILER_BUILTIN
lv_profiler_builtin_config_t profiler_config;
lv_profiler_builtin_config_init(&profiler_config);
lv_profiler_builtin_init(&profiler_config);
#endif
_lv_timer_core_init();
_lv_fs_init();

29
src/lv_conf_internal.h
View File

@@ -2355,12 +2355,35 @@
#endif
#endif
#if LV_USE_PROFILER
/*1: Enable the built-in profiler*/
#ifndef LV_USE_PROFILER_BUILTIN
#ifdef _LV_KCONFIG_PRESENT
#ifdef CONFIG_LV_USE_PROFILER_BUILTIN
#define LV_USE_PROFILER_BUILTIN CONFIG_LV_USE_PROFILER_BUILTIN
#else
#define LV_USE_PROFILER_BUILTIN 0
#endif
#else
#define LV_USE_PROFILER_BUILTIN 1
#endif
#endif
#if LV_USE_PROFILER_BUILTIN
/*Default profiler trace buffer size*/
#ifndef LV_PROFILER_BUILTIN_BUF_SIZE
#ifdef CONFIG_LV_PROFILER_BUILTIN_BUF_SIZE
#define LV_PROFILER_BUILTIN_BUF_SIZE CONFIG_LV_PROFILER_BUILTIN_BUF_SIZE
#else
#define LV_PROFILER_BUILTIN_BUF_SIZE (16 * 1024) /*[bytes]*/
#endif
#endif
#endif
/*Header to include for the profiler*/
#ifndef LV_PROFILER_INCLUDE
#ifdef CONFIG_LV_PROFILER_INCLUDE
#define LV_PROFILER_INCLUDE CONFIG_LV_PROFILER_INCLUDE
#else
#define LV_PROFILER_INCLUDE <stdint.h>
#define LV_PROFILER_INCLUDE "lvgl/src/misc/lv_profiler_builtin.h"
#endif
#endif
@@ -2369,7 +2392,7 @@
#ifdef CONFIG_LV_PROFILER_BEGIN
#define LV_PROFILER_BEGIN CONFIG_LV_PROFILER_BEGIN
#else
#define LV_PROFILER_BEGIN
#define LV_PROFILER_BEGIN LV_PROFILER_BUILTIN_BEGIN
#endif
#endif
@@ -2378,7 +2401,7 @@
#ifdef CONFIG_LV_PROFILER_END
#define LV_PROFILER_END CONFIG_LV_PROFILER_END
#else
#define LV_PROFILER_END
#define LV_PROFILER_END LV_PROFILER_BUILTIN_END
#endif
#endif
#endif

168
src/misc/lv_profiler_builtin.c Normal file
View File

@@ -0,0 +1,168 @@
/**
* @file lv_profiler_builtin.c
*
*/
/*********************
* INCLUDES
*********************/
#include "lv_profiler_builtin.h"
#include "../lvgl.h"
/*********************
* DEFINES
*********************/
#if LV_USE_PROFILER && LV_USE_PROFILER_BUILTIN
#define LV_PROFILER_STR_MAX_LEN 128
#define LV_PROFILER_TICK_PER_SEC_MAX 1000000
/**********************
* TYPEDEFS
**********************/
/**
* @brief Structure representing a built-in profiler item in LVGL
*/
typedef struct {
char tag; /**< The tag of the profiler item */
uint32_t tick; /**< The tick value of the profiler item */
const char * func; /**< A pointer to the function associated with the profiler item */
} lv_profiler_builtin_item_t;
/**
* @brief Structure representing a context for the LVGL built-in profiler
*/
typedef struct {
lv_profiler_builtin_item_t * item_arr; /**< Pointer to an array of profiler items */
uint32_t item_num; /**< Number of profiler items in the array */
uint32_t cur_index; /**< Index of the current profiler item */
lv_profiler_builtin_config_t config; /**< Configuration for the built-in profiler */
} lv_profiler_builtin_ctx_t;
/**********************
* STATIC PROTOTYPES
**********************/
static void default_flush_cb(const char * buf);
/**********************
* STATIC VARIABLES
**********************/
static lv_profiler_builtin_ctx_t profiler_ctx = { 0 };
/**********************
* MACROS
**********************/
/**********************
* GLOBAL FUNCTIONS
**********************/
void lv_profiler_builtin_config_init(lv_profiler_builtin_config_t * config)
{
LV_ASSERT_NULL(config);
lv_memzero(config, sizeof(lv_profiler_builtin_config_t));
config->buf_size = LV_PROFILER_BUILTIN_BUF_SIZE;
config->tick_per_sec = 1000;
config->tick_get_cb = lv_tick_get;
config->flush_cb = default_flush_cb;
}
void lv_profiler_builtin_init(const lv_profiler_builtin_config_t * config)
{
LV_ASSERT_NULL(config);
LV_ASSERT_NULL(config->tick_get_cb);
uint32_t num = config->buf_size / sizeof(lv_profiler_builtin_item_t);
if(num == 0) {
LV_LOG_WARN("buf_size must > %d", (int)sizeof(lv_profiler_builtin_item_t));
return;
}
if(config->tick_per_sec == 0 || config->tick_per_sec > LV_PROFILER_TICK_PER_SEC_MAX) {
LV_LOG_WARN("tick_per_sec range must be between 1~%d", LV_PROFILER_TICK_PER_SEC_MAX);
return;
}
/*Free the old item_arr memory*/
if(profiler_ctx.item_arr != NULL) {
lv_profiler_builtin_uninit();
}
lv_memzero(&profiler_ctx, sizeof(profiler_ctx));
profiler_ctx.item_arr = lv_malloc(num * sizeof(lv_profiler_builtin_item_t));
LV_ASSERT_MALLOC(profiler_ctx.item_arr);
if(profiler_ctx.item_arr == NULL) {
LV_LOG_ERROR("malloc failed for item_arr");
return;
}
profiler_ctx.item_num = num;
profiler_ctx.config = *config;
LV_LOG_INFO("init OK, item_num = %d", (int)num);
}
void lv_profiler_builtin_uninit(void)
{
LV_ASSERT_NULL(profiler_ctx.item_arr);
lv_free(profiler_ctx.item_arr);
lv_memzero(&profiler_ctx, sizeof(profiler_ctx));
}
void lv_profiler_builtin_flush(void)
{
LV_ASSERT_NULL(profiler_ctx.item_arr);
if(!profiler_ctx.config.flush_cb) {
LV_LOG_WARN("flush_cb is not registered");
return;
}
uint32_t cur = 0;
char buf[LV_PROFILER_STR_MAX_LEN];
uint32_t tick_per_sec = profiler_ctx.config.tick_per_sec;
while(cur < profiler_ctx.cur_index) {
lv_profiler_builtin_item_t * item = &profiler_ctx.item_arr[cur++];
uint32_t sec = item->tick / tick_per_sec;
uint32_t usec = (item->tick % tick_per_sec) * (LV_PROFILER_TICK_PER_SEC_MAX / tick_per_sec);
lv_snprintf(buf, sizeof(buf),
"LVGL-1 [0] %" LV_PRIu32 ".%06" LV_PRIu32 ": tracing_mark_write: %c|1|%s\n",
sec,
usec,
item->tag,
item->func);
profiler_ctx.config.flush_cb(buf);
}
}
void lv_profiler_builtin_write(const char * func, char tag)
{
LV_ASSERT_NULL(profiler_ctx.item_arr);
LV_ASSERT_NULL(func);
if(profiler_ctx.cur_index >= profiler_ctx.item_num) {
lv_profiler_builtin_flush();
profiler_ctx.cur_index = 0;
}
lv_profiler_builtin_item_t * item = &profiler_ctx.item_arr[profiler_ctx.cur_index];
item->func = func;
item->tag = tag;
item->tick = profiler_ctx.config.tick_get_cb();
profiler_ctx.cur_index++;
}
/**********************
* STATIC FUNCTIONS
**********************/
static void default_flush_cb(const char * buf)
{
LV_LOG("%s", buf);
}
#endif /*LV_USE_PROFILER_BUILTIN*/

89
src/misc/lv_profiler_builtin.h Normal file
View File

@@ -0,0 +1,89 @@
/**
* @file lv_profiler_builtin.h.h
*
*/
#ifndef LV_PROFILER_BUILTIN_H
#define LV_PROFILER_BUILTIN_H
#ifdef __cplusplus
extern "C" {
#endif
/*********************
* INCLUDES
*********************/
#include "../lv_conf_internal.h"
#if LV_USE_PROFILER && LV_USE_PROFILER_BUILTIN
#include <stdbool.h>
#include <stddef.h>
#include <stdint.h>
/*********************
* DEFINES
*********************/
#define LV_PROFILER_BUILTIN_BEGIN lv_profiler_builtin_write(__func__, 'B')
#define LV_PROFILER_BUILTIN_END lv_profiler_builtin_write(__func__, 'E')
/**********************
* TYPEDEFS
**********************/
/**
* @brief LVGL profiler built-in configuration structure
*/
typedef struct {
size_t buf_size; /**< The size of the buffer used for profiling data */
uint32_t tick_per_sec; /**< The number of ticks per second */
uint32_t (*tick_get_cb)(void); /**< Callback function to get the current tick count */
void (*flush_cb)(const char * buf); /**< Callback function to flush the profiling data */
} lv_profiler_builtin_config_t;
/**********************
* GLOBAL PROTOTYPES
**********************/
/**
* @brief Initialize the configuration of the built-in profiler
* @param config Pointer to the configuration structure of the built-in profiler
*/
void lv_profiler_builtin_config_init(lv_profiler_builtin_config_t * config);
/**
* @brief Initialize the built-in profiler with the given configuration
* @param config Pointer to the configuration structure of the built-in profiler
*/
void lv_profiler_builtin_init(const lv_profiler_builtin_config_t * config);
/**
* @brief Uninitialize the built-in profiler
*/
void lv_profiler_builtin_uninit(void);
/**
* @brief Flush the profiling data to the console
*/
void lv_profiler_builtin_flush(void);
/**
* @brief Write the profiling data for a function with the given tag
* @param func Name of the function being profiled
* @param tag Tag to associate with the profiling data for the function
*/
void lv_profiler_builtin_write(const char * func, char tag);
/**********************
* MACROS
**********************/
#endif /*LV_USE_PROFILER_BUILTIN*/
#ifdef __cplusplus
} /*extern "C"*/
#endif
#endif /*LV_PROFILER_BUILTIN_H*/