Re: [Intel-gfx] [PATCH v2] drm/i915/display: Record the plane update times for debugging
Quoting Ville Syrjälä (2020-12-02 19:24:33)
> On Fri, Nov 27, 2020 at 04:18:41PM +, Chris Wilson wrote:
> > +#if IS_ENABLED(CONFIG_DRM_I915_DEBUG_VBLANK_EVADE)
> > +static void crtc_updates_info(struct seq_file *m,
> > + struct intel_crtc *crtc,
> > + const char *hdr)
> > +{
> > + char buf[ARRAY_SIZE(crtc->debug.vbl.times) + 1] = {};
> > + int h, row, max;
> > + u64 count;
> > +
> > + max = 0;
> > + count = 0;
> > + for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl.times); h++) {
> > + if (crtc->debug.vbl.times[h] > max)
> > + max = crtc->debug.vbl.times[h];
> > + count += crtc->debug.vbl.times[h];
> > + }
> > + seq_printf(m, "%sUpdates: %llu\n", hdr, count);
> > + if (!count)
> > + return;
> > +
> > + memset(buf, '-', sizeof(buf) - 1);
> > + seq_printf(m, "%s |%s|\n", hdr, buf);
> > +
> > + for (row = ilog2(max) - 1; row; row--) {
>
> row >= 0?
I skipped the last row, as the ilog2() would also catch all the empty
bins. The alternative is s/>=/>/, but my gut feeling was because of the
rounding down from ilog2, >= would be better.
> > + memset(buf, ' ', sizeof(buf) - 1);
> > + for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl.times); h++) {
> > + if (ilog2(crtc->debug.vbl.times[h]) >= row)
> > + buf[h] = '*';
> > + }
> > + seq_printf(m, "%s |%s|\n", hdr, buf);
> > + }
>
> I have a feeling that putting the graph on its side would make it more
> readable since then we could easily label more (all even?) of the bins.
> Right now I'm having a hard time seeing what's what exactly.
Ok, labelling the axis (axes if you are lucky) is a definite advantage.
> > diff --git a/drivers/gpu/drm/i915/display/intel_display_types.h
> > b/drivers/gpu/drm/i915/display/intel_display_types.h
> > index ce82d654d0f2..30c82bc5ca98 100644
> > --- a/drivers/gpu/drm/i915/display/intel_display_types.h
> > +++ b/drivers/gpu/drm/i915/display/intel_display_types.h
> > @@ -1186,6 +1186,15 @@ struct intel_crtc {
> > ktime_t start_vbl_time;
> > int min_vbl, max_vbl;
> > int scanline_start;
> > +#ifdef CONFIG_DRM_I915_DEBUG_VBLANK_EVADE
> > + struct {
> > + u64 min;
> > + u64 max;
> > + u64 sum;
> > + unsigned long over;
>
> Was there a particular reason for the long? The bins are
> ints so can't really see why this couldn't be an in too.
A touch of pessimism.
-Chris
___
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
Re: [Intel-gfx] [PATCH v2] drm/i915/display: Record the plane update times for debugging
On Fri, Nov 27, 2020 at 04:18:41PM +, Chris Wilson wrote:
> Since we try and estimate how long we require to update the registers to
> perform a plane update, it is of vital importance that we measure the
> distribution of plane updates to better guide our estimate. If we
> underestimate how long it takes to perform the plane update, we may
> slip into the next scanout frame causing a tear. If we overestimate, we
> may unnecessarily delay the update to the next frame, causing visible
> jitter.
>
> Replace the warning that we exceed some arbitrary threshold for the
> vblank update with a histogram for debugfs.
>
> v2: Add a per-crtc debugfs entry so that the information is easier to
> extract when testing individual CRTC, and so that it can be reset before
> a test.
>
> Closes: https://gitlab.freedesktop.org/drm/intel/-/issues/1982
> Signed-off-by: Chris Wilson
> Cc: Jani Nikula
> Cc: Ville Syrjälä
> ---
> drivers/gpu/drm/i915/display/intel_display.c | 10 +-
> .../drm/i915/display/intel_display_debugfs.c | 117 ++
> .../drm/i915/display/intel_display_debugfs.h | 3 +
> .../drm/i915/display/intel_display_types.h| 9 ++
> drivers/gpu/drm/i915/display/intel_sprite.c | 49 +---
> drivers/gpu/drm/i915/display/intel_sprite.h | 10 ++
> 6 files changed, 180 insertions(+), 18 deletions(-)
>
> diff --git a/drivers/gpu/drm/i915/display/intel_display.c
> b/drivers/gpu/drm/i915/display/intel_display.c
> index ba26545392bc..9187a20a8aca 100644
> --- a/drivers/gpu/drm/i915/display/intel_display.c
> +++ b/drivers/gpu/drm/i915/display/intel_display.c
> @@ -45,6 +45,7 @@
>
> #include "display/intel_crt.h"
> #include "display/intel_ddi.h"
> +#include "display/intel_display_debugfs.h"
> #include "display/intel_dp.h"
> #include "display/intel_dp_mst.h"
> #include "display/intel_dpll_mgr.h"
> @@ -17266,6 +17267,12 @@ intel_cursor_plane_create(struct drm_i915_private
> *dev_priv,
> return ERR_PTR(ret);
> }
>
> +static int intel_crtc_late_register(struct drm_crtc *crtc)
> +{
> + intel_crtc_debugfs_add(crtc);
> + return 0;
> +}
> +
> #define INTEL_CRTC_FUNCS \
> .gamma_set = drm_atomic_helper_legacy_gamma_set, \
> .set_config = drm_atomic_helper_set_config, \
> @@ -17275,7 +17282,8 @@ intel_cursor_plane_create(struct drm_i915_private
> *dev_priv,
> .atomic_destroy_state = intel_crtc_destroy_state, \
> .set_crc_source = intel_crtc_set_crc_source, \
> .verify_crc_source = intel_crtc_verify_crc_source, \
> - .get_crc_sources = intel_crtc_get_crc_sources
> + .get_crc_sources = intel_crtc_get_crc_sources, \
> + .late_register = intel_crtc_late_register
>
> static const struct drm_crtc_funcs bdw_crtc_funcs = {
> INTEL_CRTC_FUNCS,
> diff --git a/drivers/gpu/drm/i915/display/intel_display_debugfs.c
> b/drivers/gpu/drm/i915/display/intel_display_debugfs.c
> index ca41e8c00ad7..08db0ff022e0 100644
> --- a/drivers/gpu/drm/i915/display/intel_display_debugfs.c
> +++ b/drivers/gpu/drm/i915/display/intel_display_debugfs.c
> @@ -18,6 +18,7 @@
> #include "intel_pm.h"
> #include "intel_psr.h"
> #include "intel_sideband.h"
> +#include "intel_sprite.h"
>
> static inline struct drm_i915_private *node_to_i915(struct drm_info_node
> *node)
> {
> @@ -865,6 +866,103 @@ static void intel_scaler_info(struct seq_file *m,
> struct intel_crtc *crtc)
> }
> }
>
> +#if IS_ENABLED(CONFIG_DRM_I915_DEBUG_VBLANK_EVADE)
> +static void crtc_updates_info(struct seq_file *m,
> + struct intel_crtc *crtc,
> + const char *hdr)
> +{
> + char buf[ARRAY_SIZE(crtc->debug.vbl.times) + 1] = {};
> + int h, row, max;
> + u64 count;
> +
> + max = 0;
> + count = 0;
> + for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl.times); h++) {
> + if (crtc->debug.vbl.times[h] > max)
> + max = crtc->debug.vbl.times[h];
> + count += crtc->debug.vbl.times[h];
> + }
> + seq_printf(m, "%sUpdates: %llu\n", hdr, count);
> + if (!count)
> + return;
> +
> + memset(buf, '-', sizeof(buf) - 1);
> + seq_printf(m, "%s |%s|\n", hdr, buf);
> +
> + for (row = ilog2(max) - 1; row; row--) {
row >= 0?
> + memset(buf, ' ', sizeof(buf) - 1);
> + for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl.times); h++) {
> + if (ilog2(crtc->debug.vbl.times[h]) >= row)
> + buf[h] = '*';
> + }
> + seq_printf(m, "%s |%s|\n", hdr, buf);
> + }
I have a feeling that putting the graph on its side would make it more
readable since then we could easily label more (all even?) of the bins.
Right now I'm having a hard time seeing what's what exactly.
> + memset(buf, '-', sizeof(buf) - 1);
> + seq_printf(m, "%s |%s|\n", hdr, buf);
> + seq_printf(m, "%s1us (log) 1ms\n", hdr);
> +
> + seq_printf(m, "%sMin update: %lluns\n",
Re: [Intel-gfx] [PATCH v2] drm/i915/display: Record the plane update times for debugging
Quoting Chris Wilson (2020-11-27 16:18:41) > Since we try and estimate how long we require to update the registers to > perform a plane update, it is of vital importance that we measure the > distribution of plane updates to better guide our estimate. If we > underestimate how long it takes to perform the plane update, we may > slip into the next scanout frame causing a tear. If we overestimate, we > may unnecessarily delay the update to the next frame, causing visible > jitter. > > Replace the warning that we exceed some arbitrary threshold for the > vblank update with a histogram for debugfs. > > v2: Add a per-crtc debugfs entry so that the information is easier to > extract when testing individual CRTC, and so that it can be reset before > a test. With the per-crtc reset functionality, we can more easily detect errors under testing, e.g. https://patchwork.freedesktop.org/series/84359/ and suppress the warnings when no one is watching (but are flooding the CI results at present). Any one in favour? -Chris ___ Intel-gfx mailing list Intel-gfx@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/intel-gfx
[Intel-gfx] [PATCH v2] drm/i915/display: Record the plane update times for debugging
Since we try and estimate how long we require to update the registers to
perform a plane update, it is of vital importance that we measure the
distribution of plane updates to better guide our estimate. If we
underestimate how long it takes to perform the plane update, we may
slip into the next scanout frame causing a tear. If we overestimate, we
may unnecessarily delay the update to the next frame, causing visible
jitter.
Replace the warning that we exceed some arbitrary threshold for the
vblank update with a histogram for debugfs.
v2: Add a per-crtc debugfs entry so that the information is easier to
extract when testing individual CRTC, and so that it can be reset before
a test.
Closes: https://gitlab.freedesktop.org/drm/intel/-/issues/1982
Signed-off-by: Chris Wilson
Cc: Jani Nikula
Cc: Ville Syrjälä
---
drivers/gpu/drm/i915/display/intel_display.c | 10 +-
.../drm/i915/display/intel_display_debugfs.c | 117 ++
.../drm/i915/display/intel_display_debugfs.h | 3 +
.../drm/i915/display/intel_display_types.h| 9 ++
drivers/gpu/drm/i915/display/intel_sprite.c | 49 +---
drivers/gpu/drm/i915/display/intel_sprite.h | 10 ++
6 files changed, 180 insertions(+), 18 deletions(-)
diff --git a/drivers/gpu/drm/i915/display/intel_display.c
b/drivers/gpu/drm/i915/display/intel_display.c
index ba26545392bc..9187a20a8aca 100644
--- a/drivers/gpu/drm/i915/display/intel_display.c
+++ b/drivers/gpu/drm/i915/display/intel_display.c
@@ -45,6 +45,7 @@
#include "display/intel_crt.h"
#include "display/intel_ddi.h"
+#include "display/intel_display_debugfs.h"
#include "display/intel_dp.h"
#include "display/intel_dp_mst.h"
#include "display/intel_dpll_mgr.h"
@@ -17266,6 +17267,12 @@ intel_cursor_plane_create(struct drm_i915_private
*dev_priv,
return ERR_PTR(ret);
}
+static int intel_crtc_late_register(struct drm_crtc *crtc)
+{
+ intel_crtc_debugfs_add(crtc);
+ return 0;
+}
+
#define INTEL_CRTC_FUNCS \
.gamma_set = drm_atomic_helper_legacy_gamma_set, \
.set_config = drm_atomic_helper_set_config, \
@@ -17275,7 +17282,8 @@ intel_cursor_plane_create(struct drm_i915_private
*dev_priv,
.atomic_destroy_state = intel_crtc_destroy_state, \
.set_crc_source = intel_crtc_set_crc_source, \
.verify_crc_source = intel_crtc_verify_crc_source, \
- .get_crc_sources = intel_crtc_get_crc_sources
+ .get_crc_sources = intel_crtc_get_crc_sources, \
+ .late_register = intel_crtc_late_register
static const struct drm_crtc_funcs bdw_crtc_funcs = {
INTEL_CRTC_FUNCS,
diff --git a/drivers/gpu/drm/i915/display/intel_display_debugfs.c
b/drivers/gpu/drm/i915/display/intel_display_debugfs.c
index ca41e8c00ad7..08db0ff022e0 100644
--- a/drivers/gpu/drm/i915/display/intel_display_debugfs.c
+++ b/drivers/gpu/drm/i915/display/intel_display_debugfs.c
@@ -18,6 +18,7 @@
#include "intel_pm.h"
#include "intel_psr.h"
#include "intel_sideband.h"
+#include "intel_sprite.h"
static inline struct drm_i915_private *node_to_i915(struct drm_info_node *node)
{
@@ -865,6 +866,103 @@ static void intel_scaler_info(struct seq_file *m, struct
intel_crtc *crtc)
}
}
+#if IS_ENABLED(CONFIG_DRM_I915_DEBUG_VBLANK_EVADE)
+static void crtc_updates_info(struct seq_file *m,
+ struct intel_crtc *crtc,
+ const char *hdr)
+{
+ char buf[ARRAY_SIZE(crtc->debug.vbl.times) + 1] = {};
+ int h, row, max;
+ u64 count;
+
+ max = 0;
+ count = 0;
+ for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl.times); h++) {
+ if (crtc->debug.vbl.times[h] > max)
+ max = crtc->debug.vbl.times[h];
+ count += crtc->debug.vbl.times[h];
+ }
+ seq_printf(m, "%sUpdates: %llu\n", hdr, count);
+ if (!count)
+ return;
+
+ memset(buf, '-', sizeof(buf) - 1);
+ seq_printf(m, "%s |%s|\n", hdr, buf);
+
+ for (row = ilog2(max) - 1; row; row--) {
+ memset(buf, ' ', sizeof(buf) - 1);
+ for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl.times); h++) {
+ if (ilog2(crtc->debug.vbl.times[h]) >= row)
+ buf[h] = '*';
+ }
+ seq_printf(m, "%s |%s|\n", hdr, buf);
+ }
+
+ memset(buf, '-', sizeof(buf) - 1);
+ seq_printf(m, "%s |%s|\n", hdr, buf);
+ seq_printf(m, "%s1us (log) 1ms\n", hdr);
+
+ seq_printf(m, "%sMin update: %lluns\n",
+ hdr, crtc->debug.vbl.min);
+ seq_printf(m, "%sMax update: %lluns\n",
+ hdr, crtc->debug.vbl.max);
+ seq_printf(m, "%sAverage update: %lluns\n",
+ hdr, div64_u64(crtc->debug.vbl.sum, count));
+ seq_printf(m, "%sOverruns > %uus: %lu\n",
+ hdr, VBLANK_EVASION_TIME_US, crtc->debug.vbl.over);
+}
+
+static int crtc_updates_show(struct seq_file *m, voi
[Intel-gfx] [PATCH v2] drm/i915/display: Record the plane update times for debugging
Since we try and estimate how long we require to update the registers to
perform a plane update, it is of vital importance that we measure the
distribution of plane updates to better guide our estimate. If we
underestimate how long it takes to perform the plane update, we may
slip into the next scanout frame causing a tear. If we overestimate, we
may unnecessarily delay the update to the next frame, causing visible
jitter.
Replace the warning that we exceed some arbitrary threshold for the
vblank update with a histogram for debugfs.
Signed-off-by: Chris Wilson
Cc: Jani Nikula
Cc: Ville Syrjälä
---
.../drm/i915/display/intel_display_debugfs.c | 46 +++
.../drm/i915/display/intel_display_types.h| 7 +++
drivers/gpu/drm/i915/display/intel_sprite.c | 29 +---
3 files changed, 75 insertions(+), 7 deletions(-)
diff --git a/drivers/gpu/drm/i915/display/intel_display_debugfs.c
b/drivers/gpu/drm/i915/display/intel_display_debugfs.c
index ca41e8c00ad7..d4bcf4971558 100644
--- a/drivers/gpu/drm/i915/display/intel_display_debugfs.c
+++ b/drivers/gpu/drm/i915/display/intel_display_debugfs.c
@@ -865,6 +865,50 @@ static void intel_scaler_info(struct seq_file *m, struct
intel_crtc *crtc)
}
}
+#ifdef CONFIG_DRM_I915_DEBUG_VBLANK_EVADE
+static void crtc_vblank_info(struct seq_file *m, struct intel_crtc *crtc)
+{
+ char buf[ARRAY_SIZE(crtc->debug.vbl_times) + 1] = {};
+ int h, row, max;
+ u64 count;
+
+ max = 0;
+ count = 0;
+ for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl_times); h++) {
+ if (crtc->debug.vbl_times[h] > max)
+ max = crtc->debug.vbl_times[h];
+ count += crtc->debug.vbl_times[h];
+ }
+ seq_printf(m, "\tUpdates: %llu\n", count);
+ if (!count)
+ return;
+
+ memset(buf, '-', sizeof(buf) - 1);
+ seq_printf(m, "\t |%s|\n", buf);
+
+ for (row = ilog2(max) - 1; row; row--) {
+ memset(buf, ' ', sizeof(buf) - 1);
+ for (h = 0; h < ARRAY_SIZE(crtc->debug.vbl_times); h++) {
+ if (ilog2(crtc->debug.vbl_times[h]) >= row)
+ buf[h] = '*';
+ }
+ seq_printf(m, "\t |%s|\n", buf);
+ }
+
+ memset(buf, '-', sizeof(buf) - 1);
+ seq_printf(m, "\t |%s|\n", buf);
+ seq_printf(m, "\t1us (log) 1ms\n");
+
+ seq_printf(m, "\tMin update: %lluns\n", crtc->debug.min_vbl_time);
+ seq_printf(m, "\tMax update: %lluns\n", crtc->debug.max_vbl_time);
+ seq_printf(m, "\tAverage update: %lluns\n",
+ div64_u64(crtc->debug.sum_vbl_time, count));
+ seq_printf(m, "\tOverflows: %lu\n", crtc->debug.over_vbl_time);
+}
+#else
+static void crtc_vblank_info(struct seq_file *m, struct intel_crtc *crtc) {}
+#endif
+
static void intel_crtc_info(struct seq_file *m, struct intel_crtc *crtc)
{
struct drm_i915_private *dev_priv = node_to_i915(m->private);
@@ -907,6 +951,8 @@ static void intel_crtc_info(struct seq_file *m, struct
intel_crtc *crtc)
seq_printf(m, "\tunderrun reporting: cpu=%s pch=%s\n",
yesno(!crtc->cpu_fifo_underrun_disabled),
yesno(!crtc->pch_fifo_underrun_disabled));
+
+ crtc_vblank_info(m, crtc);
}
static int i915_display_info(struct seq_file *m, void *unused)
diff --git a/drivers/gpu/drm/i915/display/intel_display_types.h
b/drivers/gpu/drm/i915/display/intel_display_types.h
index ce82d654d0f2..efbb7c61e6fb 100644
--- a/drivers/gpu/drm/i915/display/intel_display_types.h
+++ b/drivers/gpu/drm/i915/display/intel_display_types.h
@@ -1186,6 +1186,13 @@ struct intel_crtc {
ktime_t start_vbl_time;
int min_vbl, max_vbl;
int scanline_start;
+#ifdef CONFIG_DRM_I915_DEBUG_VBLANK_EVADE
+ u64 min_vbl_time;
+ u64 max_vbl_time;
+ u64 sum_vbl_time;
+ unsigned int vbl_times[21]; /* [1us, 1ms] */
+ unsigned long over_vbl_time;
+#endif
} debug;
/* scalers available on this crtc */
diff --git a/drivers/gpu/drm/i915/display/intel_sprite.c
b/drivers/gpu/drm/i915/display/intel_sprite.c
index 019a2d6d807a..661cbaf4cc38 100644
--- a/drivers/gpu/drm/i915/display/intel_sprite.c
+++ b/drivers/gpu/drm/i915/display/intel_sprite.c
@@ -250,13 +250,28 @@ void intel_pipe_update_end(struct intel_crtc_state
*new_crtc_state)
crtc->debug.scanline_start, scanline_end);
}
#ifdef CONFIG_DRM_I915_DEBUG_VBLANK_EVADE
- else if (ktime_us_delta(end_vbl_time, crtc->debug.start_vbl_time) >
-VBLANK_EVASION_TIME_US)
- drm_warn(&dev_priv->drm,
-"Atomic update on pipe (%c) took %lld us, max time
under evasion is %u us\n",
-pipe_name(pipe),
-ktime_us_delta(end_vbl_time,
crtc->debug.start_vb
