From: Simon Glass <sjg@chromium.org> Provide more timing information for expo operation, including the time taken to: - render the scene - sync the framebuffer to the display - poll for keyboard / mouse input These are averages calculated over the past second. Update the documentation to mention these features. Signed-off-by: Simon Glass <sjg@chromium.org> --- boot/expo.c | 11 ++++++- boot/expo_test.c | 74 +++++++++++++++++++++++++++++++++++++++++++- doc/develop/expo.rst | 28 ++++++++++++++--- include/expo_test.h | 62 +++++++++++++++++++++++++++++++++++++ 4 files changed, 169 insertions(+), 6 deletions(-) diff --git a/boot/expo.c b/boot/expo.c index 2a75eed2c39..4f2c6d928a3 100644 --- a/boot/expo.c +++ b/boot/expo.c @@ -323,6 +323,7 @@ static int expo_render_(struct expo *exp, bool dirty_only) u32 colour; int ret; + expo_test_mark(exp); expo_test_update(exp); back = vid_priv->white_on_black ? VID_BLACK : VID_WHITE; @@ -352,6 +353,7 @@ static int expo_render_(struct expo *exp, bool dirty_only) return log_msg_ret("tst", ret); video_sync(dev, true); + expo_test_sync(exp); return scn ? 0 : -ECHILD; } @@ -528,6 +530,8 @@ int expo_poll(struct expo *exp, struct expo_action *act) { int key, ret = -EAGAIN; + expo_test_mark(exp); + /* update mouse position if mouse is enabled */ update_mouse_position(exp); @@ -541,11 +545,16 @@ int expo_poll(struct expo *exp, struct expo_action *act) if (!ret) ret = expo_send_click(exp, pos.x, pos.y); } - if (ret) + if (ret) { + expo_test_poll(exp); return log_msg_ret("epk", ret); + } /* get the action (either a key or a click) */ ret = expo_action_get(exp, act); + + expo_test_poll(exp); + if (ret) return log_msg_ret("eag", ret); diff --git a/boot/expo_test.c b/boot/expo_test.c index 726027aabb6..3ddeb86fb2c 100644 --- a/boot/expo_test.c +++ b/boot/expo_test.c @@ -49,6 +49,13 @@ void expo_test_checkenv(struct expo *exp) test->last_update = get_timer(0); } +void expo_test_mark(struct expo *exp) +{ + struct expo_test_mode *test = exp->test; + + test->base_time_us = timer_get_us(); +} + void expo_test_update(struct expo *exp) { struct expo_test_mode *test = exp->test; @@ -56,6 +63,20 @@ void expo_test_update(struct expo *exp) test->render_count++; } +void expo_test_sync(struct expo *exp) +{ + struct expo_test_mode *test = exp->test; + + test->sync_delta_us = get_timer_us(test->base_time_us); +} + +void expo_test_poll(struct expo *exp) +{ + struct expo_test_mode *test = exp->test; + + test->poll_delta_us = get_timer_us(test->base_time_us); +} + int expo_calc_fps(struct expo_test_mode *test) { ulong oldest_time, newest_time; @@ -108,6 +129,10 @@ int expo_test_render(struct expo *exp) if (!test->enabled) return 0; + /* Calculate time between update and render */ + if (test->base_time_us) + test->render_delta_us = get_timer_us(test->base_time_us); + /* Select 8x16 font for test display */ ret = vidconsole_select_font(exp->cons, "8x16", 0); if (ret && ret != -ENOSYS) @@ -116,13 +141,36 @@ int expo_test_render(struct expo *exp) vid_priv = dev_get_uclass_priv(dev); cons_priv = dev_get_uclass_priv(exp->cons); - /* Update FPS if at least 1 second has elapsed */ + /* Accumulate delta times for averaging */ + test->render_total_us += test->render_delta_us; + test->sync_total_us += test->sync_delta_us; + test->poll_total_us += test->poll_delta_us; + test->frame_count_last_sec++; + + /* Update FPS and averages if at least 1 second has elapsed */ if (get_timer(test->last_update) >= 1000) { now = get_timer(test->start_time_ms); test->fps_index = (test->fps_index + 1) % EXPO_FPS_AVG_SECONDS; test->fps_timestamps_ms[test->fps_index] = now; test->fps_frame_counts[test->fps_index] = test->render_count; test->fps_last = expo_calc_fps(test); + + /* Calculate averages over the last second */ + if (test->frame_count_last_sec > 0) { + test->render_avg_us = test->render_total_us / + test->frame_count_last_sec; + test->sync_avg_us = test->sync_total_us / + test->frame_count_last_sec; + test->poll_avg_us = test->poll_total_us / + test->frame_count_last_sec; + } + + /* Reset accumulation counters */ + test->render_total_us = 0; + test->sync_total_us = 0; + test->poll_total_us = 0; + test->frame_count_last_sec = 0; + test->last_update = get_timer(0); } @@ -141,5 +189,29 @@ int expo_test_render(struct expo *exp) vidconsole_put_string(exp->cons, buf); } + /* Display average render time in milliseconds on next line */ + snprintf(buf, sizeof(buf), "render %6lu.%01lums", + test->render_avg_us / 1000, + (test->render_avg_us % 1000) / 100); + y += cons_priv->y_charsize; + vidconsole_set_cursor_pos(exp->cons, x, y); + vidconsole_put_string(exp->cons, buf); + + /* Display average sync time in milliseconds on next line */ + snprintf(buf, sizeof(buf), "sync %6lu.%01lums", + test->sync_avg_us / 1000, + (test->sync_avg_us % 1000) / 100); + y += cons_priv->y_charsize; + vidconsole_set_cursor_pos(exp->cons, x, y); + vidconsole_put_string(exp->cons, buf); + + /* Display average poll time in milliseconds on next line */ + snprintf(buf, sizeof(buf), "poll %6lu.%01lums", + test->poll_avg_us / 1000, + (test->poll_avg_us % 1000) / 100); + y += cons_priv->y_charsize; + vidconsole_set_cursor_pos(exp->cons, x, y); + vidconsole_put_string(exp->cons, buf); + return 0; } diff --git a/doc/develop/expo.rst b/doc/develop/expo.rst index 85ccbe7fd63..9ce00e621e5 100644 --- a/doc/develop/expo.rst +++ b/doc/develop/expo.rst @@ -578,10 +578,10 @@ Future ideas ------------ Test Mode ---------- +~~~~~~~~~ Expo supports a test mode that can be enabled by setting the environment -variable `expotest` to 1. When enabled, expo displays the frame count in the +variable `expotest` to 1. When enabled, expo displays performance metrics in the top-right corner of the display. This is useful for debugging and performance analysis. @@ -590,8 +590,28 @@ To enable test mode:: => setenv expotest 1 => bootflow menu -The frame count shows the number of times `expo_render()` has been called since -`expo_enter_mode()` was invoked. The counter resets each time expo mode is entered. +Test mode displays the following metrics: + +Frame count + Shows the total number of frames rendered. This is the number of times + `expo_render()` has been called since `expo_enter_mode()` was invoked. + The counter resets each time expo mode is entered. + +FPS (frames per second) + Shows the rendering rate averaged over the past 5 seconds. This provides + a stable indication of rendering performance. + +Timing information + Shows average timings (in millisecond) for the following operations, + measured over the past second: + + - Render: Time taken to render the scene + - Sync: Time taken to sync the framebuffer to the display + - Poll: Time taken to poll for keyboard/mouse input + +These metrics help identify performance bottlenecks and verify that expo is +operating efficiently. The timing information is particularly useful when +optimizing display drivers or debugging slow rendering issues. Some ideas for future work: diff --git a/include/expo_test.h b/include/expo_test.h index 9d557e29c87..6363e70a3e5 100644 --- a/include/expo_test.h +++ b/include/expo_test.h @@ -23,6 +23,17 @@ struct expo; * @fps_index: Current index in the FPS tracking arrays * @fps_last: Last calculated FPS value * @last_update: Time of last FPS update (milliseconds) + * @base_time_us: Base time in microseconds for delta calculations + * @render_delta_us: Time between update and render in microseconds + * @sync_delta_us: Time taken by video_manual_sync() in microseconds + * @poll_delta_us: Time taken by expo_poll() in microseconds + * @render_total_us: Cumulative render time in current second (us) + * @sync_total_us: Cumulative sync time in current second (us) + * @poll_total_us: Cumulative poll time in current second (us) + * @frame_count_last_sec: Number of frames in current measurement second + * @render_avg_us: Average render time over last second (microseconds) + * @sync_avg_us: Average sync time over last second (microseconds) + * @poll_avg_us: Average poll time over last second (microseconds) */ struct expo_test_mode { bool enabled; @@ -33,6 +44,17 @@ struct expo_test_mode { int fps_index; int fps_last; ulong last_update; + ulong base_time_us; + ulong render_delta_us; + ulong sync_delta_us; + ulong poll_delta_us; + ulong render_total_us; + ulong sync_total_us; + ulong poll_total_us; + int frame_count_last_sec; + ulong render_avg_us; + ulong sync_avg_us; + ulong poll_avg_us; }; #if CONFIG_IS_ENABLED(EXPO_TEST) @@ -62,6 +84,16 @@ void expo_test_uninit(struct expo *exp); */ void expo_test_checkenv(struct expo *exp); +/** + * expo_test_mark() - Mark the current time for delta calculations + * + * @exp: Expo to update test mode for + * + * Records the current time in microseconds as the base time for subsequent + * delta calculations + */ +void expo_test_mark(struct expo *exp); + /** * expo_test_update() - Update test mode counters * @@ -69,6 +101,24 @@ void expo_test_checkenv(struct expo *exp); */ void expo_test_update(struct expo *exp); +/** + * expo_test_poll() - Calculate poll delta time + * + * @exp: Expo to update test mode for + * + * Calculates the time taken by expo_poll() based on the base time + */ +void expo_test_poll(struct expo *exp); + +/** + * expo_test_sync() - Calculate sync delta time + * + * @exp: Expo to update test mode for + * + * Calculates the time taken by video_manual_sync() based on the base time + */ +void expo_test_sync(struct expo *exp); + /** * expo_test_render() - Render test mode information * @@ -100,10 +150,22 @@ static inline void expo_test_checkenv(struct expo *exp) { } +static inline void expo_test_mark(struct expo *exp) +{ +} + static inline void expo_test_update(struct expo *exp) { } +static inline void expo_test_poll(struct expo *exp) +{ +} + +static inline void expo_test_sync(struct expo *exp) +{ +} + static inline int expo_test_render(struct expo *exp) { return 0; -- 2.43.0