[PATCH] drm/i915: Print error state times relative to capture

[PATCH] drm/i915: Print error state times relative to capture

[Mika Kuoppala]

Using plain jiffies in error state output makes the output
time differences relative to the current system time. This
is wrong as it makes output time differences dependent
of when the error state is printed rather than when it is
captured.

Store capture jiffies into error state and use it
when outputting the state to fix time differences output.

Cc: Chris Wilson <chris@chris-wilson.co.uk>
Signed-off-by: Mika Kuoppala <mika.kuoppala@linux.intel.com>
---
 drivers/gpu/drm/i915/i915_gpu_error.c | 20 +++++++++++++-------
 drivers/gpu/drm/i915/i915_gpu_error.h |  1 +
 2 files changed, 14 insertions(+), 7 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_gpu_error.c b/drivers/gpu/drm/i915/i915_gpu_error.c
index effaf982b19b..fc7e76f21111 100644
--- a/drivers/gpu/drm/i915/i915_gpu_error.c
+++ b/drivers/gpu/drm/i915/i915_gpu_error.c
@@ -404,7 +404,8 @@ static const char *bannable(const struct drm_i915_error_context *ctx)
 
 static void error_print_request(struct drm_i915_error_state_buf *m,
 				const char *prefix,
-				const struct drm_i915_error_request *erq)
+				const struct drm_i915_error_request *erq,
+				const unsigned long timestamp)
 {
 	if (!erq->seqno)
 		return;
@@ -412,7 +413,7 @@ static void error_print_request(struct drm_i915_error_state_buf *m,
 	err_printf(m, "%s pid %d, ban score %d, seqno %8x:%08x, prio %d, emitted %dms ago, head %08x, tail %08x\n",
 		   prefix, erq->pid, erq->ban_score,
 		   erq->context, erq->seqno, erq->priority,
-		   jiffies_to_msecs(jiffies - erq->jiffies),
+		   jiffies_to_msecs(timestamp - erq->jiffies),
 		   erq->head, erq->tail);
 }
 
@@ -427,7 +428,8 @@ static void error_print_context(struct drm_i915_error_state_buf *m,
 }
 
 static void error_print_engine(struct drm_i915_error_state_buf *m,
-			       const struct drm_i915_error_engine *ee)
+			       const struct drm_i915_error_engine *ee,
+			       const unsigned long timestamp)
 {
 	int n;
 
@@ -499,12 +501,12 @@ static void error_print_engine(struct drm_i915_error_state_buf *m,
 		   hangcheck_action_to_str(ee->hangcheck_action));
 	err_printf(m, "  hangcheck action timestamp: %lu, %u ms ago\n",
 		   ee->hangcheck_timestamp,
-		   jiffies_to_msecs(jiffies - ee->hangcheck_timestamp));
+		   jiffies_to_msecs(timestamp - ee->hangcheck_timestamp));
 	err_printf(m, "  engine reset count: %u\n", ee->reset_count);
 
 	for (n = 0; n < ee->num_ports; n++) {
 		err_printf(m, "  ELSP[%d]:", n);
-		error_print_request(m, " ", &ee->execlist[n]);
+		error_print_request(m, " ", &ee->execlist[n], timestamp);
 	}
 
 	error_print_context(m, "  Active context: ", &ee->context);
@@ -650,6 +652,7 @@ int i915_error_state_to_str(struct drm_i915_error_state_buf *m,
 	ts = ktime_to_timespec64(error->uptime);
 	err_printf(m, "Uptime: %lld s %ld us\n",
 		   (s64)ts.tv_sec, ts.tv_nsec / NSEC_PER_USEC);
+	err_printf(m, "Jiffies: %lu (now %lu)\n", error->timestamp, jiffies);
 
 	for (i = 0; i < ARRAY_SIZE(error->engine); i++) {
 		if (error->engine[i].hangcheck_stalled &&
@@ -710,7 +713,8 @@ int i915_error_state_to_str(struct drm_i915_error_state_buf *m,
 
 	for (i = 0; i < ARRAY_SIZE(error->engine); i++) {
 		if (error->engine[i].engine_id != -1)
-			error_print_engine(m, &error->engine[i]);
+			error_print_engine(m, &error->engine[i],
+					   error->timestamp);
 	}
 
 	for (i = 0; i < ARRAY_SIZE(error->active_vm); i++) {
@@ -769,7 +773,8 @@ int i915_error_state_to_str(struct drm_i915_error_state_buf *m,
 				   dev_priv->engine[i]->name,
 				   ee->num_requests);
 			for (j = 0; j < ee->num_requests; j++)
-				error_print_request(m, " ", &ee->requests[j]);
+				error_print_request(m, " ", &ee->requests[j],
+						    error->timestamp);
 		}
 
 		if (IS_ERR(ee->waiters)) {
@@ -1743,6 +1748,7 @@ static int capture(void *data)
 	error->boottime = ktime_get_boottime();
 	error->uptime = ktime_sub(ktime_get(),
 				  error->i915->gt.last_init_time);
+	error->timestamp = jiffies;
 
 	capture_params(error);
 	capture_gen_state(error);
diff --git a/drivers/gpu/drm/i915/i915_gpu_error.h b/drivers/gpu/drm/i915/i915_gpu_error.h
index c05b6034d718..1f36ad526bc5 100644
--- a/drivers/gpu/drm/i915/i915_gpu_error.h
+++ b/drivers/gpu/drm/i915/i915_gpu_error.h
@@ -30,6 +30,7 @@ struct i915_gpu_state {
 	ktime_t time;
 	ktime_t boottime;
 	ktime_t uptime;
+	unsigned long timestamp; /* jiffies */
 
 	struct drm_i915_private *i915;
 
-- 
2.14.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH] drm/i915: Print error state times relative to capture

[Chris Wilson]

Quoting Mika Kuoppala (2018-04-16 14:40:52)
> Using plain jiffies in error state output makes the output
> time differences relative to the current system time. This
> is wrong as it makes output time differences dependent
> of when the error state is printed rather than when it is
> captured.
> 
> Store capture jiffies into error state and use it
> when outputting the state to fix time differences output.

Good point. It was always confusing to see "several hours ago", when what
we wanted to know was how long before the hanging request. Hmm, do we want
to use that as our reference point rather than the capture timestamp? Do 
we even need to see the jiffies? (Yes, we probably do want the raw value
to check, but I think it's secondary.)

> Cc: Chris Wilson <chris@chris-wilson.co.uk>
> Signed-off-by: Mika Kuoppala <mika.kuoppala@linux.intel.com>

Reviewed-by: Chris Wilson <chris@chris-wilson.co.uk>

Please do consider using the (earliest) guilty timestamp as time 0 and
print before/after. If no guilty then use capture?
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

[PATCH] drm/i915: Print error state times relative to capture

[Mika Kuoppala]

Using plain jiffies in error state output makes the output
time differences relative to the current system time. This
is wrong as it makes output time differences dependent
of when the error state is printed rather than when it is
captured.

Store capture jiffies into error state and use it
when outputting the state to fix time differences output.

v2: use engine timestamp as epoch, output formatting (Chris)

Cc: Chris Wilson <chris@chris-wilson.co.uk>
Signed-off-by: Mika Kuoppala <mika.kuoppala@linux.intel.com>
---
 drivers/gpu/drm/i915/i915_gpu_error.c | 48 +++++++++++++++++++++++++++++------
 drivers/gpu/drm/i915/i915_gpu_error.h |  2 ++
 2 files changed, 42 insertions(+), 8 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_gpu_error.c b/drivers/gpu/drm/i915/i915_gpu_error.c
index 671ffa37614e..fca550954be0 100644
--- a/drivers/gpu/drm/i915/i915_gpu_error.c
+++ b/drivers/gpu/drm/i915/i915_gpu_error.c
@@ -403,16 +403,17 @@ static const char *bannable(const struct drm_i915_error_context *ctx)
 }
 
 static void error_print_request(struct drm_i915_error_state_buf *m,
+				const struct i915_gpu_state *error,
 				const char *prefix,
 				const struct drm_i915_error_request *erq)
 {
 	if (!erq->seqno)
 		return;
 
-	err_printf(m, "%s pid %d, ban score %d, seqno %8x:%08x, prio %d, emitted %dms ago, head %08x, tail %08x\n",
+	err_printf(m, "%s pid %d, ban score %d, seqno %8x:%08x, prio %d, emitted %dms, head %08x, tail %08x\n",
 		   prefix, erq->pid, erq->ban_score,
 		   erq->context, erq->seqno, erq->sched_attr.priority,
-		   jiffies_to_msecs(jiffies - erq->jiffies),
+		   jiffies_to_msecs(erq->jiffies - error->epoch),
 		   erq->head, erq->tail);
 }
 
@@ -427,8 +428,10 @@ static void error_print_context(struct drm_i915_error_state_buf *m,
 }
 
 static void error_print_engine(struct drm_i915_error_state_buf *m,
-			       const struct drm_i915_error_engine *ee)
+			       const struct i915_gpu_state *error,
+			       const int engine_n)
 {
+	const struct drm_i915_error_engine *ee = &error->engine[engine_n];
 	int n;
 
 	err_printf(m, "%s command stream:\n",
@@ -497,14 +500,18 @@ static void error_print_engine(struct drm_i915_error_state_buf *m,
 	err_printf(m, "  hangcheck stall: %s\n", yesno(ee->hangcheck_stalled));
 	err_printf(m, "  hangcheck action: %s\n",
 		   hangcheck_action_to_str(ee->hangcheck_action));
-	err_printf(m, "  hangcheck action timestamp: %lu, %u ms ago\n",
+
+	err_printf(m, "  hangcheck action timestamp: %dms (%lu%s)\n",
+		   jiffies_to_msecs(ee->hangcheck_timestamp -
+				    error->epoch),
 		   ee->hangcheck_timestamp,
-		   jiffies_to_msecs(jiffies - ee->hangcheck_timestamp));
+		   ee->hangcheck_timestamp == error->epoch ? "; epoch" : "");
+
 	err_printf(m, "  engine reset count: %u\n", ee->reset_count);
 
 	for (n = 0; n < ee->num_ports; n++) {
 		err_printf(m, "  ELSP[%d]:", n);
-		error_print_request(m, " ", &ee->execlist[n]);
+		error_print_request(m, error, " ", &ee->execlist[n]);
 	}
 
 	error_print_context(m, "  Active context: ", &ee->context);
@@ -650,6 +657,11 @@ int i915_error_state_to_str(struct drm_i915_error_state_buf *m,
 	ts = ktime_to_timespec64(error->uptime);
 	err_printf(m, "Uptime: %lld s %ld us\n",
 		   (s64)ts.tv_sec, ts.tv_nsec / NSEC_PER_USEC);
+	err_printf(m, "Epoch: %lu jiffies (%u HZ)\n", error->epoch, HZ);
+	err_printf(m, "Capture: %lu jiffies; %d ms ago, %d ms after epoch\n",
+		   error->capture,
+		   jiffies_to_msecs(jiffies - error->capture),
+		   jiffies_to_msecs(error->capture - error->epoch));
 
 	for (i = 0; i < ARRAY_SIZE(error->engine); i++) {
 		if (error->engine[i].hangcheck_stalled &&
@@ -710,7 +722,7 @@ int i915_error_state_to_str(struct drm_i915_error_state_buf *m,
 
 	for (i = 0; i < ARRAY_SIZE(error->engine); i++) {
 		if (error->engine[i].engine_id != -1)
-			error_print_engine(m, &error->engine[i]);
+			error_print_engine(m, error, i);
 	}
 
 	for (i = 0; i < ARRAY_SIZE(error->active_vm); i++) {
@@ -769,7 +781,8 @@ int i915_error_state_to_str(struct drm_i915_error_state_buf *m,
 				   dev_priv->engine[i]->name,
 				   ee->num_requests);
 			for (j = 0; j < ee->num_requests; j++)
-				error_print_request(m, " ", &ee->requests[j]);
+				error_print_request(m, error, " ",
+						    &ee->requests[j]);
 		}
 
 		if (IS_ERR(ee->waiters)) {
@@ -1735,6 +1748,22 @@ static void capture_params(struct i915_gpu_state *error)
 #undef DUP
 }
 
+static unsigned long capture_find_epoch(const struct i915_gpu_state *error)
+{
+	unsigned long epoch = error->capture;
+	int i;
+
+	for (i = 0; i < ARRAY_SIZE(error->engine); i++) {
+		const struct drm_i915_error_engine *ee = &error->engine[i];
+
+		if (ee->hangcheck_stalled &&
+		    time_before(ee->hangcheck_timestamp, epoch))
+			epoch = ee->hangcheck_timestamp;
+	}
+
+	return epoch;
+}
+
 static int capture(void *data)
 {
 	struct i915_gpu_state *error = data;
@@ -1743,6 +1772,7 @@ static int capture(void *data)
 	error->boottime = ktime_get_boottime();
 	error->uptime = ktime_sub(ktime_get(),
 				  error->i915->gt.last_init_time);
+	error->capture = jiffies;
 
 	capture_params(error);
 	capture_gen_state(error);
@@ -1756,6 +1786,8 @@ static int capture(void *data)
 	error->overlay = intel_overlay_capture_error_state(error->i915);
 	error->display = intel_display_capture_error_state(error->i915);
 
+	error->epoch = capture_find_epoch(error);
+
 	return 0;
 }
 
diff --git a/drivers/gpu/drm/i915/i915_gpu_error.h b/drivers/gpu/drm/i915/i915_gpu_error.h
index 5d6fdcbc092c..0accd2ed72d9 100644
--- a/drivers/gpu/drm/i915/i915_gpu_error.h
+++ b/drivers/gpu/drm/i915/i915_gpu_error.h
@@ -31,6 +31,8 @@ struct i915_gpu_state {
 	ktime_t time;
 	ktime_t boottime;
 	ktime_t uptime;
+	unsigned long capture;
+	unsigned long epoch;
 
 	struct drm_i915_private *i915;
 
-- 
2.14.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH] drm/i915: Print error state times relative to capture

[Chris Wilson]

Quoting Mika Kuoppala (2018-04-27 16:12:48)
> @@ -427,8 +428,10 @@ static void error_print_context(struct drm_i915_error_state_buf *m,
>  }
>  
>  static void error_print_engine(struct drm_i915_error_state_buf *m,
> -                              const struct drm_i915_error_engine *ee)
> +                              const struct i915_gpu_state *error,
> +                              const int engine_n)

Make it pass in the error_engine again, and
Reviewed-by: Chris Wilson <chris@chris-wilson.co.uk>
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

✓ Fi.CI.BAT: success for drm/i915: Print error state times relative to capture (rev2)

[Patchwork]

== Series Details ==

Series: drm/i915: Print error state times relative to capture (rev2)
URL   : https://patchwork.freedesktop.org/series/41749/
State : success

== Summary ==

= CI Bug Log - changes from CI_DRM_4108 -> Patchwork_8827 =

== Summary - WARNING ==

  Minor unknown changes coming with Patchwork_8827 need to be verified
  manually.
  
  If you think the reported changes have nothing to do with the changes
  introduced in Patchwork_8827, please notify your bug team to allow them
  to document this new failure mode, which will reduce false positives in CI.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/41749/revisions/2/mbox/

== Possible new issues ==

  Here are the unknown changes that may have been introduced in Patchwork_8827:

  === IGT changes ===

    ==== Warnings ====

    igt@gem_exec_gttfill@basic:
      fi-pnv-d510:        SKIP -> PASS

    igt@kms_frontbuffer_tracking@basic:
      fi-bsw-n3050:       SKIP -> PASS +12

    
== Known issues ==

  Here are the changes found in Patchwork_8827 that come from known issues:

  === IGT changes ===

    ==== Issues hit ====

    igt@kms_pipe_crc_basic@suspend-read-crc-pipe-c:
      fi-cnl-y3:          PASS -> DMESG-WARN (fdo#104951)

    
    ==== Possible fixes ====

    igt@gem_sync@basic-each:
      fi-bsw-n3050:       DMESG-FAIL -> PASS

    igt@kms_pipe_crc_basic@hang-read-crc-pipe-c:
      fi-bsw-n3050:       FAIL -> PASS

    igt@kms_pipe_crc_basic@suspend-read-crc-pipe-c:
      fi-bsw-n3050:       DMESG-WARN -> PASS

    
  fdo#104951 https://bugs.freedesktop.org/show_bug.cgi?id=104951


== Participating hosts (39 -> 36) ==

  Missing    (3): fi-ctg-p8600 fi-ilk-m540 fi-skl-6700hq 


== Build changes ==

    * Linux: CI_DRM_4108 -> Patchwork_8827

  CI_DRM_4108: 6270f64d10649baff02ae464542f185476a6f652 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGT_4450: 0350f0e7f6a0e07281445fc3082aa70419f4aac7 @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
  Patchwork_8827: 838bd2331dc3bcd184f98d9b13b02d2cca5d13bf @ git://anongit.freedesktop.org/gfx-ci/linux
  piglit_4450: b57600ba58ae0cdbad86826fd653aa0191212f27 @ git://anongit.freedesktop.org/piglit


== Linux commits ==

838bd2331dc3 drm/i915: Print error state times relative to capture

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_8827/issues.html
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

✓ Fi.CI.IGT: success for drm/i915: Print error state times relative to capture (rev2)

[Patchwork]

== Series Details ==

Series: drm/i915: Print error state times relative to capture (rev2)
URL   : https://patchwork.freedesktop.org/series/41749/
State : success

== Summary ==

= CI Bug Log - changes from CI_DRM_4108_full -> Patchwork_8827_full =

== Summary - WARNING ==

  Minor unknown changes coming with Patchwork_8827_full need to be verified
  manually.
  
  If you think the reported changes have nothing to do with the changes
  introduced in Patchwork_8827_full, please notify your bug team to allow them
  to document this new failure mode, which will reduce false positives in CI.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/41749/revisions/2/mbox/

== Possible new issues ==

  Here are the unknown changes that may have been introduced in Patchwork_8827_full:

  === IGT changes ===

    ==== Warnings ====

    igt@gem_exec_schedule@deep-render:
      shard-kbl:          PASS -> SKIP

    igt@gem_mocs_settings@mocs-rc6-bsd2:
      shard-kbl:          SKIP -> PASS

    
== Known issues ==

  Here are the changes found in Patchwork_8827_full that come from known issues:

  === IGT changes ===

    ==== Issues hit ====

    igt@kms_flip@flip-vs-absolute-wf_vblank-interruptible:
      shard-glk:          PASS -> FAIL (fdo#100368)

    igt@kms_flip@flip-vs-expired-vblank:
      shard-glk:          PASS -> FAIL (fdo#102887, fdo#105363)

    igt@kms_flip@plain-flip-ts-check-interruptible:
      shard-hsw:          PASS -> FAIL (fdo#100368) +1

    igt@kms_plane_lowres@pipe-c-tiling-x:
      shard-apl:          PASS -> FAIL (fdo#103166)

    igt@kms_sysfs_edid_timing:
      shard-apl:          PASS -> WARN (fdo#100047)

    igt@kms_vblank@pipe-a-accuracy-idle:
      shard-hsw:          PASS -> FAIL (fdo#102583)

    
    ==== Possible fixes ====

    igt@kms_flip@2x-flip-vs-absolute-wf_vblank:
      shard-hsw:          FAIL (fdo#103928) -> PASS

    igt@kms_flip@absolute-wf_vblank-interruptible:
      shard-glk:          FAIL (fdo#106087) -> PASS

    igt@kms_flip@dpms-vs-vblank-race-interruptible:
      shard-glk:          FAIL (fdo#103060) -> PASS

    igt@kms_flip@plain-flip-ts-check:
      shard-hsw:          FAIL (fdo#100368) -> PASS

    igt@kms_flip@plain-flip-ts-check-interruptible:
      shard-glk:          FAIL (fdo#100368) -> PASS

    igt@kms_frontbuffer_tracking@fbc-rgb565-draw-pwrite:
      shard-kbl:          DMESG-WARN (fdo#106247) -> PASS

    igt@kms_setmode@basic:
      shard-kbl:          FAIL (fdo#99912) -> PASS

    
  fdo#100047 https://bugs.freedesktop.org/show_bug.cgi?id=100047
  fdo#100368 https://bugs.freedesktop.org/show_bug.cgi?id=100368
  fdo#102583 https://bugs.freedesktop.org/show_bug.cgi?id=102583
  fdo#102887 https://bugs.freedesktop.org/show_bug.cgi?id=102887
  fdo#103060 https://bugs.freedesktop.org/show_bug.cgi?id=103060
  fdo#103166 https://bugs.freedesktop.org/show_bug.cgi?id=103166
  fdo#103928 https://bugs.freedesktop.org/show_bug.cgi?id=103928
  fdo#105363 https://bugs.freedesktop.org/show_bug.cgi?id=105363
  fdo#106087 https://bugs.freedesktop.org/show_bug.cgi?id=106087
  fdo#106247 https://bugs.freedesktop.org/show_bug.cgi?id=106247
  fdo#99912 https://bugs.freedesktop.org/show_bug.cgi?id=99912


== Participating hosts (9 -> 8) ==

  Missing    (1): shard-glkb 


== Build changes ==

    * Linux: CI_DRM_4108 -> Patchwork_8827

  CI_DRM_4108: 6270f64d10649baff02ae464542f185476a6f652 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGT_4450: 0350f0e7f6a0e07281445fc3082aa70419f4aac7 @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
  Patchwork_8827: 838bd2331dc3bcd184f98d9b13b02d2cca5d13bf @ git://anongit.freedesktop.org/gfx-ci/linux
  piglit_4450: b57600ba58ae0cdbad86826fd653aa0191212f27 @ git://anongit.freedesktop.org/piglit

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_8827/shards.html
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH] drm/i915: Print error state times relative to capture

[Mika Kuoppala]

Chris Wilson <chris@chris-wilson.co.uk> writes:

> Quoting Mika Kuoppala (2018-04-27 16:12:48)
>> @@ -427,8 +428,10 @@ static void error_print_context(struct drm_i915_error_state_buf *m,
>>  }
>>  
>>  static void error_print_engine(struct drm_i915_error_state_buf *m,
>> -                              const struct drm_i915_error_engine *ee)
>> +                              const struct i915_gpu_state *error,
>> +                              const int engine_n)
>
> Make it pass in the error_engine again, and

Done.

> Reviewed-by: Chris Wilson <chris@chris-wilson.co.uk>

Thanks for review. Pushed.
-Mika

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx