[RFC 0/2] Excessive latency in GuC send action

[RFC 0/2] Excessive latency in GuC send action

[John.C.Harrison]

From: John Harrison <John.C.Harrison@Intel.com>

While working on a customer project, it was noticed that the time
taken to issue a pre-emption request to the GuC would vary quite
significantly. The correct case was low microseconds but the worst
case was tens of milliseconds. Two separate issues were identified as
causing this extra delay. The acquisition of the GuC send mutex lock
and the stall waiting for an ack from the GuC. Both of these are
necessary steps because the access to the send action mechanism must
be serialised. It is not designed for multiple concurrent operations.

Mutex Lock Delay:
The first issue seems to be with the way mutex_lock() itself is
implemented in the linux kernel. Even when the lock is available, it
seems that linux sometimes decides to do a task switch anyway and not
re-schedule the thread that requested the lock for some time. Hence
the time taken to acquire the mutex lock would generally be
essentially zero but in around 0.05% of cases it would be in the
6-10ms range. Note that there was never any actual contention of the
mutex observed. In all cases, the mutex was available.

The workaround implemented for the customer was to first use a
mutex_trylock(). If the try fails then it falls back to the regular
mutex_lock() call instead. As the try lock is not permitted to stall,
it never hits the random linux task switch issue. Running overnight,
3.2 million pre-emption events were logged with not a single mutex
delay over 10 microseconds (which was the granularity of the
measurement being used).

Ack Delay:
The second issue was with the wait for the GuC acknowledgment of the
send action command. In most cases, no delay is required - the
completion flag is set by the time of the first read. However, around
1% of the time the flag was not set and the wait_for() loop then took
in the region of 8-10ms to return. Analysis showed that this delay was
also entirely due to the linux kernel task switching away due to using
a sleeping wait in the polling loop. Using a non-sleeping wait brought
the latency down to the 10-20us range in the majority of 'slow' cases.
Certain tests had a noticeable spike of about 120us, presumably when
the delay was actually due to the GuC being busy. The worse extremes
measured were around 200us, with maybe one or two hits of 300us in an
overnight run.

The polling construct being used was a 'wait_for_us()' of 10
microseconds (spinning poll) followed by a 'wait_for()' of 10ms
(sleeping poll) with the final fall back being to give up and return
an error. As the command quite frequently takes just over 10us to
complete, this meant the code would regularly drop into the second
loop. Despite the sleep time being set for 1ms, it would actually
sleep for an average of 1.5ms and as noted would commonly hit closer
to 10ms.

The workaround was to extend the busy poll period to 100us in the case
of a pre-emption request. In the case of any other GuC send action
command, the original 10us was kept. The reasoning being that a
pre-emption request is a very high priority, urgent thing and is worth
burning the extra CPU cycles on a busy poll in order to guarantee a
suitably small latency. Whereas, the other send action commands are
not performance critical and a longer but more system friendly sleep
is not an issue.


Note that the two patches included here are based against the
customer's 4.11 tree. So they might not apply too well the current
upstream pre-emption implementation. It was noted that a recent update
to the gem_exec_latency IGT showed "additional latency in the mutex
for guc preemption". Which sounds like the same issue that was seen
here. Hence posting what I have to a wider audience.

John Harrison (2):
  drm/i915: Extend GuC action fast spin time
  drm/i915: Avoid stalling on GuC send mutex lock

 drivers/gpu/drm/i915/i915_guc_submission.c | 12 ++++++------
 drivers/gpu/drm/i915/intel_guc_log.c       |  6 +++---
 drivers/gpu/drm/i915/intel_huc.c           |  2 +-
 drivers/gpu/drm/i915/intel_uc.c            | 23 ++++++++++++++++++-----
 drivers/gpu/drm/i915/intel_uc.h            |  2 +-
 5 files changed, 29 insertions(+), 16 deletions(-)

-- 
2.13.0

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

[RFC 1/2] drm/i915: Extend GuC action fast spin time

[John.C.Harrison]

From: John Harrison <John.C.Harrison@Intel.com>

The 'request pre-emption' GuC command seems to be slower than other
commands. It typically takes 20-30us on a GP-MRB system (BXT). That
means that the super-fast busy-spin wait in the GuC send action code
hits the 10us time out. It then drops through to the more system
friendly sleeping wait with a 10ms timeout. Unfortunately, the
sleeping wait seems to average a 1.5ms delay. That is almost 100 times
slower than necessary! It also means that the super-high-priority
pre-emption request is getting a significant extra latency. Even
worse, the latency can be upwards of 8ms if the kernel decides not to
reschedule the i915 driver soon beause the system is busy doing other
things.

This patch extends the busy-spin wait timeout specifically for the
case of pre-emtion requests.

Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
---
 drivers/gpu/drm/i915/i915_guc_submission.c | 12 ++++++------
 drivers/gpu/drm/i915/intel_guc_log.c       |  6 +++---
 drivers/gpu/drm/i915/intel_huc.c           |  2 +-
 drivers/gpu/drm/i915/intel_uc.c            | 18 ++++++++++++++----
 drivers/gpu/drm/i915/intel_uc.h            |  2 +-
 5 files changed, 25 insertions(+), 15 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_guc_submission.c b/drivers/gpu/drm/i915/i915_guc_submission.c
index 918cedcef104..ff82f0561ec1 100644
--- a/drivers/gpu/drm/i915/i915_guc_submission.c
+++ b/drivers/gpu/drm/i915/i915_guc_submission.c
@@ -78,7 +78,7 @@ static int guc_allocate_doorbell(struct intel_guc *guc,
 		client->ctx_index
 	};
 
-	return intel_guc_send(guc, action, ARRAY_SIZE(action));
+	return intel_guc_send(guc, action, ARRAY_SIZE(action), false);
 }
 
 static int guc_release_doorbell(struct intel_guc *guc,
@@ -89,7 +89,7 @@ static int guc_release_doorbell(struct intel_guc *guc,
 		client->ctx_index
 	};
 
-	return intel_guc_send(guc, action, ARRAY_SIZE(action));
+	return intel_guc_send(guc, action, ARRAY_SIZE(action), false);
 }
 
 static struct guc_context_desc *__get_context_desc(struct i915_guc_client *client)
@@ -605,7 +605,7 @@ static int i915_guc_preempt(struct intel_engine_cs *engine)
 	data[5] = guc->execbuf_client->ctx_index;
 	data[6] = guc->shared_data_offset;
 
-	return intel_guc_send(guc, data, ARRAY_SIZE(data));
+	return intel_guc_send(guc, data, ARRAY_SIZE(data), true);
 }
 
 /**
@@ -1442,7 +1442,7 @@ int intel_guc_suspend(struct drm_i915_private *dev_priv)
 	/* first page of default ctx is shared data with GuC */
 	data[2] = guc->shared_data_offset;
 
-	return intel_guc_send(guc, data, ARRAY_SIZE(data));
+	return intel_guc_send(guc, data, ARRAY_SIZE(data), false);
 }
 
 
@@ -1466,7 +1466,7 @@ int intel_guc_resume(struct drm_i915_private *dev_priv)
 	/* first page of default ctx is shared data with GuC */
 	data[2] = guc->shared_data_offset;
 
-	return intel_guc_send(guc, data, ARRAY_SIZE(data));
+	return intel_guc_send(guc, data, ARRAY_SIZE(data), false);
 }
 
 int i915_guc_reset_engine(struct intel_engine_cs *engine)
@@ -1493,5 +1493,5 @@ int i915_guc_reset_engine(struct intel_engine_cs *engine)
 	/* first page is shared data with GuC */
 	data[6] = guc_ggtt_offset(ctx->engine[RCS].state);
 
-	return intel_guc_send(guc, data, ARRAY_SIZE(data));
+	return intel_guc_send(guc, data, ARRAY_SIZE(data), false);
 }
diff --git a/drivers/gpu/drm/i915/intel_guc_log.c b/drivers/gpu/drm/i915/intel_guc_log.c
index 0a4dd4454adf..95fd4e1ace41 100644
--- a/drivers/gpu/drm/i915/intel_guc_log.c
+++ b/drivers/gpu/drm/i915/intel_guc_log.c
@@ -43,7 +43,7 @@ static int guc_log_flush_complete(struct intel_guc *guc)
 		INTEL_GUC_ACTION_LOG_BUFFER_FILE_FLUSH_COMPLETE
 	};
 
-	return intel_guc_send(guc, action, ARRAY_SIZE(action));
+	return intel_guc_send(guc, action, ARRAY_SIZE(action), false);
 }
 
 static int guc_log_flush(struct intel_guc *guc)
@@ -53,7 +53,7 @@ static int guc_log_flush(struct intel_guc *guc)
 		0
 	};
 
-	return intel_guc_send(guc, action, ARRAY_SIZE(action));
+	return intel_guc_send(guc, action, ARRAY_SIZE(action), false);
 }
 
 static int guc_log_control(struct intel_guc *guc, u32 control_val)
@@ -63,7 +63,7 @@ static int guc_log_control(struct intel_guc *guc, u32 control_val)
 		control_val
 	};
 
-	return intel_guc_send(guc, action, ARRAY_SIZE(action));
+	return intel_guc_send(guc, action, ARRAY_SIZE(action), false);
 }
 
 
diff --git a/drivers/gpu/drm/i915/intel_huc.c b/drivers/gpu/drm/i915/intel_huc.c
index 80c262fd56ab..e78bca7fd074 100644
--- a/drivers/gpu/drm/i915/intel_huc.c
+++ b/drivers/gpu/drm/i915/intel_huc.c
@@ -314,7 +314,7 @@ void intel_guc_auth_huc(struct drm_i915_private *dev_priv)
 	data[0] = INTEL_GUC_ACTION_AUTHENTICATE_HUC;
 	data[1] = guc_ggtt_offset(vma) + huc->fw.rsa_offset;
 
-	ret = intel_guc_send(guc, data, ARRAY_SIZE(data));
+	ret = intel_guc_send(guc, data, ARRAY_SIZE(data), false);
 	if (ret) {
 		DRM_ERROR("HuC: GuC did not ack Auth request %d\n", ret);
 		goto out;
diff --git a/drivers/gpu/drm/i915/intel_uc.c b/drivers/gpu/drm/i915/intel_uc.c
index c46bc8594f22..680290ac36d6 100644
--- a/drivers/gpu/drm/i915/intel_uc.c
+++ b/drivers/gpu/drm/i915/intel_uc.c
@@ -43,12 +43,13 @@ static bool intel_guc_recv(struct intel_guc *guc, u32 *status)
 	return INTEL_GUC_RECV_IS_RESPONSE(val);
 }
 
-int intel_guc_send(struct intel_guc *guc, const u32 *action, u32 len)
+int intel_guc_send(struct intel_guc *guc, const u32 *action, u32 len, bool urgent)
 {
 	struct drm_i915_private *dev_priv = guc_to_i915(guc);
 	u32 status;
 	int i;
 	int ret;
+	int fast_retry = urgent ? 10 : 1;
 
 	if (WARN_ON(len < 1 || len > 15))
 		return -EINVAL;
@@ -69,9 +70,18 @@ int intel_guc_send(struct intel_guc *guc, const u32 *action, u32 len)
 	/*
 	 * Fast commands should complete in less than 10us, so sample quickly
 	 * up to that length of time, then switch to a slower sleep-wait loop.
-	 * No inte_guc_send command should ever take longer than 10ms.
+	 * No intel_guc_send command should ever take longer than 10ms.
+	 *
+	 * Updated: The 'request pre-emption' GuC command seems to average 120us
+	 * not <10us. Unfortunately, the second sleep option seems to have a
+	 * minimum stall time of around 8ms. That causes a huge increase in
+	 * pre-emption latency which is unacceptable for high priority workloads.
 	 */
-	ret = wait_for_us(intel_guc_recv(guc, &status), 10);
+	for (i = 0; i < fast_retry; i++) {
+		ret = wait_for_us(intel_guc_recv(guc, &status), 10);
+		if (ret == 0)
+			break;
+	}
 	if (ret)
 		ret = wait_for(intel_guc_recv(guc, &status), 10);
 	if (status != INTEL_GUC_STATUS_SUCCESS) {
@@ -111,6 +121,6 @@ int intel_guc_sample_forcewake(struct intel_guc *guc)
 		/* bit 0 and 1 are for Render and Media domain separately */
 		action[1] = GUC_FORCEWAKE_RENDER | GUC_FORCEWAKE_MEDIA;
 
-	return intel_guc_send(guc, action, ARRAY_SIZE(action));
+	return intel_guc_send(guc, action, ARRAY_SIZE(action), false);
 }
 
diff --git a/drivers/gpu/drm/i915/intel_uc.h b/drivers/gpu/drm/i915/intel_uc.h
index a47269223531..b76604dfb82d 100644
--- a/drivers/gpu/drm/i915/intel_uc.h
+++ b/drivers/gpu/drm/i915/intel_uc.h
@@ -191,7 +191,7 @@ struct intel_huc {
 
 /* intel_uc.c */
 void intel_uc_init_early(struct drm_i915_private *dev_priv);
-int intel_guc_send(struct intel_guc *guc, const u32 *action, u32 len);
+int intel_guc_send(struct intel_guc *guc, const u32 *action, u32 len, bool urgent);
 int intel_guc_sample_forcewake(struct intel_guc *guc);
 
 /* intel_guc_loader.c */
-- 
2.13.0

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

[RFC 2/2] drm/i915: Avoid stalling on GuC send mutex lock

[John.C.Harrison]

From: John Harrison <John.C.Harrison@Intel.com>

There is a mutex_lock in the GuC send action code path to ensure
serialised access to the host-to-GuC mechanism. Acquiring the lock
apparently sees random stalls of around 6ms. That is even when the
lock is definitely not acquired by any other thread. In the case of
sending pre-emption requests, a 6ms delay can really damage
performance of the high priority task requiring pre-emption.

It seems that using a mutex_trylock call first prevents this delay
from occurring.

Without the trylock, one particular test showed about one stall hit
for every 1,500 pre-emption requests. With the trylock, no stalls in
3,200,000 pre-emptions.

Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
---
 drivers/gpu/drm/i915/intel_uc.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/drivers/gpu/drm/i915/intel_uc.c b/drivers/gpu/drm/i915/intel_uc.c
index 680290ac36d6..e38eceb456c5 100644
--- a/drivers/gpu/drm/i915/intel_uc.c
+++ b/drivers/gpu/drm/i915/intel_uc.c
@@ -54,7 +54,10 @@ int intel_guc_send(struct intel_guc *guc, const u32 *action, u32 len, bool urgen
 	if (WARN_ON(len < 1 || len > 15))
 		return -EINVAL;
 
-	mutex_lock(&guc->send_mutex);
+	/* Use a trylock first to avoid a ~6ms random stall when
+	 * calling mutex_lock() directly!? */
+	if (!mutex_trylock(&guc->send_mutex))
+		mutex_lock(&guc->send_mutex);
 	intel_uncore_forcewake_get(dev_priv, FORCEWAKE_ALL);
 
 	dev_priv->guc.action_count += 1;
-- 
2.13.0

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

Re: [RFC 0/2] Excessive latency in GuC send action

[Daniel Vetter]

On Fri, Nov 17, 2017 at 04:39:32PM -0800, John.C.Harrison@Intel.com wrote:
> From: John Harrison <John.C.Harrison@Intel.com>
> 
> While working on a customer project, it was noticed that the time
> taken to issue a pre-emption request to the GuC would vary quite
> significantly. The correct case was low microseconds but the worst
> case was tens of milliseconds. Two separate issues were identified as
> causing this extra delay. The acquisition of the GuC send mutex lock
> and the stall waiting for an ack from the GuC. Both of these are
> necessary steps because the access to the send action mechanism must
> be serialised. It is not designed for multiple concurrent operations.
> 
> Mutex Lock Delay:
> The first issue seems to be with the way mutex_lock() itself is
> implemented in the linux kernel. Even when the lock is available, it
> seems that linux sometimes decides to do a task switch anyway and not
> re-schedule the thread that requested the lock for some time. Hence
> the time taken to acquire the mutex lock would generally be
> essentially zero but in around 0.05% of cases it would be in the
> 6-10ms range. Note that there was never any actual contention of the
> mutex observed. In all cases, the mutex was available.
> 
> The workaround implemented for the customer was to first use a
> mutex_trylock(). If the try fails then it falls back to the regular
> mutex_lock() call instead. As the try lock is not permitted to stall,
> it never hits the random linux task switch issue. Running overnight,
> 3.2 million pre-emption events were logged with not a single mutex
> delay over 10 microseconds (which was the granularity of the
> measurement being used).

This sounds like a core mutex implementation bug. Have you talked with
relevant maintainers (some work for Intel even)?
-Daniel

> Ack Delay:
> The second issue was with the wait for the GuC acknowledgment of the
> send action command. In most cases, no delay is required - the
> completion flag is set by the time of the first read. However, around
> 1% of the time the flag was not set and the wait_for() loop then took
> in the region of 8-10ms to return. Analysis showed that this delay was
> also entirely due to the linux kernel task switching away due to using
> a sleeping wait in the polling loop. Using a non-sleeping wait brought
> the latency down to the 10-20us range in the majority of 'slow' cases.
> Certain tests had a noticeable spike of about 120us, presumably when
> the delay was actually due to the GuC being busy. The worse extremes
> measured were around 200us, with maybe one or two hits of 300us in an
> overnight run.
> 
> The polling construct being used was a 'wait_for_us()' of 10
> microseconds (spinning poll) followed by a 'wait_for()' of 10ms
> (sleeping poll) with the final fall back being to give up and return
> an error. As the command quite frequently takes just over 10us to
> complete, this meant the code would regularly drop into the second
> loop. Despite the sleep time being set for 1ms, it would actually
> sleep for an average of 1.5ms and as noted would commonly hit closer
> to 10ms.
> 
> The workaround was to extend the busy poll period to 100us in the case
> of a pre-emption request. In the case of any other GuC send action
> command, the original 10us was kept. The reasoning being that a
> pre-emption request is a very high priority, urgent thing and is worth
> burning the extra CPU cycles on a busy poll in order to guarantee a
> suitably small latency. Whereas, the other send action commands are
> not performance critical and a longer but more system friendly sleep
> is not an issue.
> 
> 
> Note that the two patches included here are based against the
> customer's 4.11 tree. So they might not apply too well the current
> upstream pre-emption implementation. It was noted that a recent update
> to the gem_exec_latency IGT showed "additional latency in the mutex
> for guc preemption". Which sounds like the same issue that was seen
> here. Hence posting what I have to a wider audience.
> 
> John Harrison (2):
>   drm/i915: Extend GuC action fast spin time
>   drm/i915: Avoid stalling on GuC send mutex lock
> 
>  drivers/gpu/drm/i915/i915_guc_submission.c | 12 ++++++------
>  drivers/gpu/drm/i915/intel_guc_log.c       |  6 +++---
>  drivers/gpu/drm/i915/intel_huc.c           |  2 +-
>  drivers/gpu/drm/i915/intel_uc.c            | 23 ++++++++++++++++++-----
>  drivers/gpu/drm/i915/intel_uc.h            |  2 +-
>  5 files changed, 29 insertions(+), 16 deletions(-)
> 
> -- 
> 2.13.0
> 
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/intel-gfx

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx