[PATCH] drm/i915: Add special execution time measurements for pipe evasion section
Stanislav Lisovskiy
stanislav.lisovskiy at intel.com
Tue Apr 23 11:43:47 UTC 2024
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.
v2: - Just as expected, problem seems to be not in the actual plane updates, but
something related to vblank counter/scanline calculation. Added those functions
to trace their execution time as well(too bad didn't add those initially)
v3: - Add additional traces to __intel_get_crtc_scanline to figure out the precise
location, where delay takes place.
v4: - Add sanity check, in case if wrapped function table was malformed
(enum id doesn't match index in function table)
- Add possibility to initialize function table, also in runtime.
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 | 18 +++-
drivers/gpu/drm/i915/display/intel_display.c | 85 +++++++++++++++++--
drivers/gpu/drm/i915/display/intel_display.h | 64 ++++++++++++++
drivers/gpu/drm/i915/display/intel_vblank.c | 14 ++-
5 files changed, 180 insertions(+), 23 deletions(-)
diff --git a/drivers/gpu/drm/i915/display/intel_atomic_plane.c b/drivers/gpu/drm/i915/display/intel_atomic_plane.c
index 76d77d5a0409..ad88268026bb 100644
--- a/drivers/gpu/drm/i915/display/intel_atomic_plane.c
+++ b/drivers/gpu/drm/i915/display/intel_atomic_plane.c
@@ -844,19 +844,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 25593f6aae7d..96451d6ef9eb 100644
--- a/drivers/gpu/drm/i915/display/intel_crtc.c
+++ b/drivers/gpu/drm/i915/display/intel_crtc.c
@@ -524,7 +524,8 @@ void intel_pipe_update_start(struct intel_atomic_state *state,
crtc->debug.scanline_start = scanline;
crtc->debug.start_vbl_time = ktime_get();
- crtc->debug.start_vbl_count = intel_crtc_get_vblank_counter(crtc);
+ TIME_MEASURE_FUNC_WRAP(INTEL_CRTC_GET_VBLANK_COUNTER, pipe_evasion,
+ crtc->debug.start_vbl_count = intel_crtc_get_vblank_counter(crtc));
trace_intel_pipe_update_vblank_evaded(crtc);
return;
@@ -551,11 +552,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++;
}
}
@@ -578,8 +584,14 @@ void intel_pipe_update_end(struct intel_atomic_state *state,
struct intel_crtc_state *new_crtc_state =
intel_atomic_get_new_crtc_state(state, crtc);
enum pipe pipe = crtc->pipe;
- int scanline_end = intel_get_crtc_scanline(crtc);
- u32 end_vbl_count = intel_crtc_get_vblank_counter(crtc);
+ int scanline_end;
+ u32 end_vbl_count;
+
+ TIME_MEASURE_FUNC_WRAP(INTEL_GET_CRTC_SCANLINE, pipe_evasion,
+ scanline_end = intel_get_crtc_scanline(crtc));
+ TIME_MEASURE_FUNC_WRAP(INTEL_CRTC_GET_VBLANK_COUNTER, pipe_evasion,
+ end_vbl_count = intel_crtc_get_vblank_counter(crtc));
+
ktime_t end_vbl_time = ktime_get();
struct drm_i915_private *dev_priv = to_i915(crtc->base.dev);
diff --git a/drivers/gpu/drm/i915/display/intel_display.c b/drivers/gpu/drm/i915/display/intel_display.c
index 96ed1490fec7..17c5ce337c2b 100644
--- a/drivers/gpu/drm/i915/display/intel_display.c
+++ b/drivers/gpu/drm/i915/display/intel_display.c
@@ -6692,6 +6692,35 @@ static void intel_pipe_fastset(const struct intel_crtc_state *old_crtc_state,
intel_set_transcoder_timings_lrr(new_crtc_state);
}
+TIME_MEASURE_FUNC_TABLE_START(pipe_evasion)
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_COLOR_COMMIT_ARM, "intel_color_commit_arm"),
+ TIME_MEASURE_FUNC_INIT_STATIC(BDW_SET_PIPE_MISC, "bdw_set_pipe_misc"),
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_PIPE_FASTSET, "intel_pipe_fastset"),
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_PSR_PROGRAM_TRANS_MAN_TRK_CTL, "intel_psr_program_trans_maxn_trk_ctl"),
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_ATOMIC_UPDATE_WATERMARKS, "intel_atomic_update_watermarks"),
+ TIME_MEASURE_FUNC_INIT_STATIC(SKL_DETACH_SCALERS, "skl_detach_scalers"),
+ TIME_MEASURE_FUNC_INIT_STATIC(SKL_NEXT_PLANE_TO_COMMIT, "skl_next_plane_to_commit"),
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_UPDATE_PLANE, "intel_update_plane"),
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_DISABLE_PLANE, "intel_disable_plane"),
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_GET_CRTC_SCANLINE, "intel_get_crtc_scanline"),
+ TIME_MEASURE_FUNC_INIT_STATIC(INTEL_CRTC_GET_VBLANK_COUNTER, "intel_crtc_get_vblank_counter"),
+ TIME_MEASURE_FUNC_INIT_STATIC(GET_CRTC_SCANLINE_FROM_TIMESTAMP, "intel_get_crtc_scanline_from_timstamp"),
+ TIME_MEASURE_FUNC_INIT_STATIC(PIPE_DSL_READ, "pipe_dsl_read"),
+ TIME_MEASURE_FUNC_INIT_STATIC(GET_CRTC_SCANLINE_SPINLOCK, "get crtc scanline spinlock"),
+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)
{
@@ -6707,19 +6736,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,
@@ -6738,7 +6775,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));
if (vrr_enabling(old_crtc_state, new_crtc_state))
intel_vrr_enable(new_crtc_state);
@@ -8048,6 +8086,35 @@ static const struct intel_display_funcs i9xx_display_funcs = {
*/
void intel_init_display_hooks(struct drm_i915_private *dev_priv)
{
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_COLOR_COMMIT_ARM, "intel_color_commit_arm");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ BDW_SET_PIPE_MISC, "bdw_set_pipe_misc");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_PIPE_FASTSET, "intel_pipe_fastset");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_PSR_PROGRAM_TRANS_MAN_TRK_CTL, "intel_psr_program_trans_maxn_trk_ctl");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_ATOMIC_UPDATE_WATERMARKS, "intel_atomic_update_watermarks");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ SKL_DETACH_SCALERS, "skl_detach_scalers");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ SKL_NEXT_PLANE_TO_COMMIT, "skl_next_plane_to_commit");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_UPDATE_PLANE, "intel_update_plane");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_DISABLE_PLANE, "intel_disable_plane");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_GET_CRTC_SCANLINE, "intel_get_crtc_scanline");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ INTEL_CRTC_GET_VBLANK_COUNTER, "intel_crtc_get_vblank_counter");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ GET_CRTC_SCANLINE_FROM_TIMESTAMP, "intel_get_crtc_scanline_from_timstamp");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ PIPE_DSL_READ, "pipe_dsl_read");
+ TIME_MEASURE_FUNC_INIT_RUNTIME(pipe_evasion,
+ GET_CRTC_SCANLINE_SPINLOCK, "get crtc scanline spinlock");
+
if (DISPLAY_VER(dev_priv) >= 9) {
dev_priv->display.funcs.display = &skl_display_funcs;
} else if (HAS_DDI(dev_priv)) {
diff --git a/drivers/gpu/drm/i915/display/intel_display.h b/drivers/gpu/drm/i915/display/intel_display.h
index 56d1c0e3e62c..7765f7ec9364 100644
--- a/drivers/gpu/drm/i915/display/intel_display.h
+++ b/drivers/gpu/drm/i915/display/intel_display.h
@@ -553,8 +553,72 @@ 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_TABLE_DECLARE_WITH_SIZE(table_name, size) \
+ extern struct time_measure_func table_name[size];
+
+#define TIME_MEASURE_FUNC_INIT_STATIC(_id, _name) \
+ { .id = _id, .name = _name }
+
+#define TIME_MEASURE_FUNC_TABLE_END };
+
+#define TIME_MEASURE_FUNC_INIT_RUNTIME(table_name, _id, _name) \
+ { \
+ table_name[_id].id = _id; \
+ table_name[_id].name = _name; \
+ }
+
+#define TIME_MEASURE_FUNC_WRAP(_id, table_name, func_call) \
+ { \
+ WARN_ON(table_name[_id].id != _id); \
+ 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,
+ INTEL_GET_CRTC_SCANLINE,
+ INTEL_CRTC_GET_VBLANK_COUNTER,
+ GET_CRTC_SCANLINE_FROM_TIMESTAMP,
+ PIPE_DSL_READ,
+ GET_CRTC_SCANLINE_SPINLOCK,
+ 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);
diff --git a/drivers/gpu/drm/i915/display/intel_vblank.c b/drivers/gpu/drm/i915/display/intel_vblank.c
index baf7354cb6e2..627162abbc07 100644
--- a/drivers/gpu/drm/i915/display/intel_vblank.c
+++ b/drivers/gpu/drm/i915/display/intel_vblank.c
@@ -211,14 +211,19 @@ static int __intel_get_crtc_scanline(struct intel_crtc *crtc)
vblank = &crtc->base.dev->vblank[drm_crtc_index(&crtc->base)];
mode = &vblank->hwmode;
- if (crtc->mode_flags & I915_MODE_FLAG_GET_SCANLINE_FROM_TIMESTAMP)
- return __intel_get_crtc_scanline_from_timestamp(crtc);
+ if (crtc->mode_flags & I915_MODE_FLAG_GET_SCANLINE_FROM_TIMESTAMP) {
+ int ret;
+ TIME_MEASURE_FUNC_WRAP(GET_CRTC_SCANLINE_FROM_TIMESTAMP, pipe_evasion,
+ ret = __intel_get_crtc_scanline_from_timestamp(crtc));
+ return ret;
+ }
vtotal = mode->crtc_vtotal;
if (mode->flags & DRM_MODE_FLAG_INTERLACE)
vtotal /= 2;
- position = intel_de_read_fw(dev_priv, PIPEDSL(pipe)) & PIPEDSL_LINE_MASK;
+ TIME_MEASURE_FUNC_WRAP(PIPE_DSL_READ, pipe_evasion,
+ (position = intel_de_read_fw(dev_priv, PIPEDSL(pipe)) & PIPEDSL_LINE_MASK));
/*
* On HSW, the DSL reg (0x70000) appears to return 0 if we
@@ -441,7 +446,8 @@ int intel_get_crtc_scanline(struct intel_crtc *crtc)
unsigned long irqflags;
int position;
- local_irq_save(irqflags);
+ TIME_MEASURE_FUNC_WRAP(GET_CRTC_SCANLINE_SPINLOCK, pipe_evasion,
+ local_irq_save(irqflags));
intel_vblank_section_enter(dev_priv);
position = __intel_get_crtc_scanline(crtc);
--
2.37.3
More information about the Intel-gfx-trybot
mailing list