[PATCH] drm/i915: Add special execution time measurements for pipe evasion section
Jani Nikula
jani.nikula at intel.com
Mon Aug 7 10:30:06 UTC 2023
On Mon, 07 Aug 2023, Stanislav Lisovskiy <stanislav.lisovskiy at intel.com> wrote:
> We are getting "pipe evasion exceeded 250 us" on constant basis for different
> platforms for many years. Current tracing instrumentation, shows us only
> aggregate execution times for the functions in evasion section, however we are
> only and particularly interested in those _only_ once this timing is exceeded,
> average timing measurements or those which happen when we don't exceed that
> 250 us threshold are not informative at all.
> This patch attemmpts to add a special debug print instrumentation, that prints
> all the execution time measurements of functions participating in vblank evasion
> only once it is exceeded and remain silent otherwise.
> It shouldn't also add much overhead because all it does is just calling ktime_get
> before and after function call.
I see that this has been sent for trybot, but just so there's no
confusion: This is fine for debugging, but not for merging upstream.
BR,
Jani.
>
> Signed-off-by: Stanislav Lisovskiy <stanislav.lisovskiy at intel.com>
> ---
> .../gpu/drm/i915/display/intel_atomic_plane.c | 22 +++++---
> drivers/gpu/drm/i915/display/intel_crtc.c | 5 ++
> drivers/gpu/drm/i915/display/intel_display.c | 51 +++++++++++++++----
> drivers/gpu/drm/i915/display/intel_display.h | 49 ++++++++++++++++++
> 4 files changed, 111 insertions(+), 16 deletions(-)
>
> diff --git a/drivers/gpu/drm/i915/display/intel_atomic_plane.c b/drivers/gpu/drm/i915/display/intel_atomic_plane.c
> index 60a492e186ab8..72abca8321a62 100644
> --- a/drivers/gpu/drm/i915/display/intel_atomic_plane.c
> +++ b/drivers/gpu/drm/i915/display/intel_atomic_plane.c
> @@ -841,19 +841,27 @@ static void skl_crtc_planes_update_arm(struct intel_atomic_state *state,
> memcpy(ddb_y, old_crtc_state->wm.skl.plane_ddb_y,
> sizeof(old_crtc_state->wm.skl.plane_ddb_y));
>
> - while ((plane = skl_next_plane_to_commit(state, crtc, ddb, ddb_y, &update_mask))) {
> - struct intel_plane_state *new_plane_state =
> - intel_atomic_get_new_plane_state(state, plane);
> + while (1) {
> + struct intel_plane_state *new_plane_state;
> +
> + TIME_MEASURE_FUNC_WRAP(SKL_NEXT_PLANE_TO_COMMIT, pipe_evasion,
> + plane = skl_next_plane_to_commit(state, crtc, ddb, ddb_y, &update_mask));
> +
> + if (!plane)
> + break;
> +
> + new_plane_state = intel_atomic_get_new_plane_state(state, plane);
>
> /*
> * TODO: for mailbox updates intel_plane_update_noarm()
> * would have to be called here as well.
> */
> if (new_plane_state->uapi.visible ||
> - new_plane_state->planar_slave)
> - intel_plane_update_arm(plane, new_crtc_state, new_plane_state);
> - else
> - intel_plane_disable_arm(plane, new_crtc_state);
> + new_plane_state->planar_slave) {
> + TIME_MEASURE_FUNC_WRAP(INTEL_UPDATE_PLANE, pipe_evasion, intel_plane_update_arm(plane, new_crtc_state, new_plane_state));
> + } else {
> + TIME_MEASURE_FUNC_WRAP(INTEL_DISABLE_PLANE, pipe_evasion, intel_plane_disable_arm(plane, new_crtc_state));
> + }
> }
> }
>
> diff --git a/drivers/gpu/drm/i915/display/intel_crtc.c b/drivers/gpu/drm/i915/display/intel_crtc.c
> index 182c6dd64f47c..7bad7c8544b7e 100644
> --- a/drivers/gpu/drm/i915/display/intel_crtc.c
> +++ b/drivers/gpu/drm/i915/display/intel_crtc.c
> @@ -617,11 +617,16 @@ static void dbg_vblank_evade(struct intel_crtc *crtc, ktime_t end)
> crtc->debug.vbl.max = delta;
>
> if (delta > 1000 * VBLANK_EVASION_TIME_US) {
> + struct drm_i915_private *dev_priv = to_i915(crtc->base.dev);
> +
> drm_dbg_kms(crtc->base.dev,
> "Atomic update on pipe (%c) took %lld us, max time under evasion is %u us\n",
> pipe_name(crtc->pipe),
> div_u64(delta, 1000),
> VBLANK_EVASION_TIME_US);
> +
> + print_time_measure_table(dev_priv, pipe_evasion, PIPE_EVASION_ENUM_MAX);
> +
> crtc->debug.vbl.over++;
> }
> }
> diff --git a/drivers/gpu/drm/i915/display/intel_display.c b/drivers/gpu/drm/i915/display/intel_display.c
> index 43cba98f77531..b35dc3704725d 100644
> --- a/drivers/gpu/drm/i915/display/intel_display.c
> +++ b/drivers/gpu/drm/i915/display/intel_display.c
> @@ -6486,6 +6486,30 @@ static void intel_pipe_fastset(const struct intel_crtc_state *old_crtc_state,
> &new_crtc_state->dp_m_n);
> }
>
> +TIME_MEASURE_FUNC_TABLE_START(pipe_evasion)
> + TIME_MEASURE_FUNC(INTEL_COLOR_COMMIT_ARM, "intel_color_commit_arm"),
> + TIME_MEASURE_FUNC(BDW_SET_PIPE_MISC, "bdw_set_pipe_misc"),
> + TIME_MEASURE_FUNC(INTEL_PIPE_FASTSET, "intel_pipe_fastset"),
> + TIME_MEASURE_FUNC(INTEL_PSR_PROGRAM_TRANS_MAN_TRK_CTL, "intel_psr_program_trans_maxn_trk_ctl"),
> + TIME_MEASURE_FUNC(INTEL_ATOMIC_UPDATE_WATERMARKS, "intel_atomic_update_watermarks"),
> + TIME_MEASURE_FUNC(SKL_DETACH_SCALERS, "skl_detach_scalers"),
> + TIME_MEASURE_FUNC(SKL_NEXT_PLANE_TO_COMMIT, "skl_next_plane_to_commit"),
> + TIME_MEASURE_FUNC(INTEL_UPDATE_PLANE, "intel_update_plane"),
> + TIME_MEASURE_FUNC(INTEL_DISABLE_PLANE, "intel_disable_plane"),
> +TIME_MEASURE_FUNC_TABLE_END
> +
> +void print_time_measure_table(struct drm_i915_private *dev_priv,
> + struct time_measure_func *table, int num_entries)
> +{
> + int i;
> + for (i = 0; i < num_entries; i++)
> + {
> + drm_dbg_kms(&dev_priv->drm,
> + "Function %s took %lld us\n",
> + table[i].name, ktime_us_delta(table[i].end, table[i].start));
> + }
> +}
> +
> static void commit_pipe_pre_planes(struct intel_atomic_state *state,
> struct intel_crtc *crtc)
> {
> @@ -6501,19 +6525,27 @@ static void commit_pipe_pre_planes(struct intel_atomic_state *state,
> * CRTC was enabled.
> */
> if (!modeset) {
> - if (intel_crtc_needs_color_update(new_crtc_state))
> - intel_color_commit_arm(new_crtc_state);
> + if (intel_crtc_needs_color_update(new_crtc_state)) {
> + TIME_MEASURE_FUNC_WRAP(INTEL_COLOR_COMMIT_ARM,
> + pipe_evasion, intel_color_commit_arm(new_crtc_state));
> + }
>
> - if (DISPLAY_VER(dev_priv) >= 9 || IS_BROADWELL(dev_priv))
> - bdw_set_pipe_misc(new_crtc_state);
> + if (DISPLAY_VER(dev_priv) >= 9 || IS_BROADWELL(dev_priv)) {
> + TIME_MEASURE_FUNC_WRAP(BDW_SET_PIPE_MISC,
> + pipe_evasion, bdw_set_pipe_misc(new_crtc_state));
> + }
>
> - if (intel_crtc_needs_fastset(new_crtc_state))
> - intel_pipe_fastset(old_crtc_state, new_crtc_state);
> + if (intel_crtc_needs_fastset(new_crtc_state)) {
> + TIME_MEASURE_FUNC_WRAP(INTEL_PIPE_FASTSET,
> + pipe_evasion, intel_pipe_fastset(old_crtc_state, new_crtc_state));
> + }
> }
>
> - intel_psr2_program_trans_man_trk_ctl(new_crtc_state);
> + TIME_MEASURE_FUNC_WRAP(INTEL_PSR_PROGRAM_TRANS_MAN_TRK_CTL,
> + pipe_evasion, intel_psr2_program_trans_man_trk_ctl(new_crtc_state));
>
> - intel_atomic_update_watermarks(state, crtc);
> + TIME_MEASURE_FUNC_WRAP(INTEL_ATOMIC_UPDATE_WATERMARKS,
> + pipe_evasion, intel_atomic_update_watermarks(state, crtc));
> }
>
> static void commit_pipe_post_planes(struct intel_atomic_state *state,
> @@ -6530,7 +6562,8 @@ static void commit_pipe_post_planes(struct intel_atomic_state *state,
> */
> if (DISPLAY_VER(dev_priv) >= 9 &&
> !intel_crtc_needs_modeset(new_crtc_state))
> - skl_detach_scalers(new_crtc_state);
> + TIME_MEASURE_FUNC_WRAP(SKL_DETACH_SCALERS,
> + pipe_evasion, skl_detach_scalers(new_crtc_state));
> }
>
> static void intel_enable_crtc(struct intel_atomic_state *state,
> diff --git a/drivers/gpu/drm/i915/display/intel_display.h b/drivers/gpu/drm/i915/display/intel_display.h
> index 49ac8473b988b..31bd34e2f253c 100644
> --- a/drivers/gpu/drm/i915/display/intel_display.h
> +++ b/drivers/gpu/drm/i915/display/intel_display.h
> @@ -531,8 +531,57 @@ enum drm_mode_status intel_mode_valid(struct drm_device *dev,
> int intel_atomic_commit(struct drm_device *dev, struct drm_atomic_state *_state,
> bool nonblock);
>
> +
> +struct time_measure_func
> +{
> + int id;
> + const char *name;
> + ktime_t start;
> + ktime_t end;
> +};
> +
> +#define TIME_MEASURE_ENUM_START(enum_name) \
> + enum enum_name {
> +#define TIME_MEASURE_ENUM_END };
> +
> +#define TIME_MEASURE_FUNC_TABLE_START(table_name) \
> + struct time_measure_func table_name[] = {
> +
> +#define TIME_MEASURE_FUNC_TABLE_DECLARE(table_name) \
> + extern struct time_measure_func table_name[];
> +
> +#define TIME_MEASURE_FUNC(_id, _name) \
> + { .id = _id, .name = _name }
> +
> +#define TIME_MEASURE_FUNC_TABLE_END };
> +
> +#define TIME_MEASURE_FUNC_WRAP(id, table_name, func_call) \
> + { \
> + table_name[id].start = ktime_get(); \
> + func_call; \
> + table_name[id].end = ktime_get(); \
> + }
> +
> +TIME_MEASURE_ENUM_START(pipe_evasion_enum)
> + INTEL_COLOR_COMMIT_ARM,
> + BDW_SET_PIPE_MISC,
> + INTEL_PIPE_FASTSET,
> + INTEL_PSR_PROGRAM_TRANS_MAN_TRK_CTL,
> + INTEL_ATOMIC_UPDATE_WATERMARKS,
> + SKL_DETACH_SCALERS,
> + SKL_NEXT_PLANE_TO_COMMIT,
> + INTEL_UPDATE_PLANE,
> + INTEL_DISABLE_PLANE,
> + PIPE_EVASION_ENUM_MAX
> +TIME_MEASURE_ENUM_END
> +
> +TIME_MEASURE_FUNC_TABLE_DECLARE(pipe_evasion);
> +
> void intel_hpd_poll_fini(struct drm_i915_private *i915);
>
> +void print_time_measure_table(struct drm_i915_private *i915,
> + struct time_measure_func *table, int num_entries);
> +
> /* modesetting asserts */
> void assert_transcoder(struct drm_i915_private *dev_priv,
> enum transcoder cpu_transcoder, bool state);
--
Jani Nikula, Intel Open Source Graphics Center
More information about the Intel-gfx-trybot
mailing list