On 1/27/23 11:00 AM, Andi Shyti wrote:
Hi Gwan-gyeong,
thanks for the review and the thorough explanation.
On Fri, Jan 27, 2023 at 08:50:26AM +0200, Gwan-gyeong Mun wrote:
On 1/11/23 5:36 PM, Andi Shyti wrote:
On Wed, Jan 11, 2023 at 03:18:38PM +0200, Jani Nikula wrote:
On Wed, 11 Jan 2023, Andi Shyti <andi.shyti@xxxxxxxxxxxxxxx> wrote:
From: Aravind Iddamsetty <aravind.iddamsetty@xxxxxxxxx>
During module load not all the punit transaction have completed
and we might end up timing out, as shown by the following
warning:
Root cause?
Hi Andi, looking at the log where this problem is reported,
https://gitlab.freedesktop.org/drm/intel/-/issues/7814
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1294/bat-atsm-1/igt@i915_module_load@xxxxxxxxxxxxxxx#dmesg-warnings17324
<4> [268.276908] i915 0000:4d:00.0: drm_WARN_ON_ONCE(timeout_base_ms > 3)
In the code above, the call stack is output, and the return value of
intel_pcode_init() returns -11 (-EAGAIN).
<3> [268.329058] i915 0000:4d:00.0: [drm] *ERROR* gt0: intel_pcode_init
failed -11
If you simplify the function call flow, you can see it as below. (The call
of _wait_for(COND, timeout_base_ms * 1000, 10, 10) in skl_pcode_request() is
omitted)
-------------------------------------------------------------------------
intel_pcode_init()
|
+-> skl_pcode_request(uncore, DG1_PCODE_STATUS,
DG1_UNCORE_GET_INIT_STATUS,
DG1_UNCORE_INIT_STATUS_COMPLETE,
DG1_UNCORE_INIT_STATUS_COMPLETE, 180000);
|
+-> skl_pcode_try_request()
|
+-> *status = __snb_pcode_rw(uncore, mbox, &request, NULL,
500, 0, true);
-------------------------------------------------------------------------
static int __snb_pcode_rw(struct intel_uncore *uncore, u32 mbox,
u32 *val, u32 *val1,
int fast_timeout_us, int slow_timeout_ms,
bool is_read)
{
...
if (intel_uncore_read_fw(uncore, GEN6_PCODE_MAILBOX) & GEN6_PCODE_READY)
return -EAGAIN;
intel_uncore_write_fw(uncore, GEN6_PCODE_DATA, *val);
intel_uncore_write_fw(uncore, GEN6_PCODE_DATA1, val1 ? *val1 : 0);
intel_uncore_write_fw(uncore,
GEN6_PCODE_MAILBOX, GEN6_PCODE_READY | mbox);
if (__intel_wait_for_register_fw(uncore,
GEN6_PCODE_MAILBOX,
GEN6_PCODE_READY, 0,
fast_timeout_us,
slow_timeout_ms,
&mbox))
return -ETIMEDOUT;
...
}
-------------------------------------------------------------------------
The case where skl_pcode_request() returns -EAGAIN can be considered as the
following scenario.
1. 1. When checking the GEN6_PCODE_MAILBOX register status before writing
the value to the GEN6_PCODE_DATA register in __snb_pcode_rw(), it is always
BUSY
correct! We fail with EAGAIN because we are not able to
communicate with the punit because the punit is busy.
Talking about this case we are in boot time and the gpu is
performing its boot routine, the punit as well. While the punit
is working we try communicate with it, but unfortunately, being
busy, we fail with -EAGAIN exactly where you pointed.
Adding an extra wait_for_register_fw, i.e. waiting until the
PCODE_READY register tells that the punit is ready, makes sure
that the read/write will succeed.
Thus Chris has added a 10 seconds wait before the very first read
and write. If the punit is not ready we don't fail with -EAGAIN
and give up the driver loading as it happens now. But we give it
another chance trying to probe it again later.
2. _wait_for(COND, timeout_base_ms * 1000, 10, 10) of skl_pcode_request()
returns -EAGAIN if the GEN6_PCODE_MAILBOX register indicates BUSY even after
waiting 500us after writing a value to the GEN6_PCODE_DATA register in
__snb_pcode_rw()
Isn't it the same as '1'?
(Even if skl_pcode_request() gives a timeout of 180 seconds, the time used
each time __snb_pcode_rw() is called is up to 500us. The rest of the time is
used for sleep.)
There is one big, massive, huge difference... the timeout in
skl_pcode_request() after the read/write, not before. So that at
the first communication we fail, return -EAGAIN and give up
probing without starting any timer.
Be aware of the fact that the timeout is not for the current
communication, but for the next one. De facto we start the
timeout after communicating, this makes sure that the next
communication will work.
But no one makes sure that the very first communication works
during probe. Thus the extra wait.
Hi Andi,
In the call flow invoked by intel_pcode_init(), I've added brief
comments where further clarification is needed in this scenario, and a
description of the suspicious scenario at the bottom.
-------------------------------------------------------------------------
intel_pcode_init()
|
+-> skl_pcode_request(uncore, DG1_PCODE_STATUS,
DG1_UNCORE_GET_INIT_STATUS,
DG1_UNCORE_INIT_STATUS_COMPLETE,
DG1_UNCORE_INIT_STATUS_COMPLETE, 180000);
|
+-> skl_pcode_try_request()
|
+-> *status = __snb_pcode_rw(uncore, mbox, &request, NULL,
500, 0, true);
-------------------------------------------------------------------------
static int __snb_pcode_rw(struct intel_uncore *uncore, u32 mbox,
u32 *val, u32 *val1,
int fast_timeout_us, int slow_timeout_ms,
bool is_read)
{
...
/* Before writing a value to the GEN6_PCODE_DATA register,
check if the bit in the GEN6_PCODE_MAILBOX register indicates
BUSY. */
if (intel_uncore_read_fw(uncore, GEN6_PCODE_MAILBOX) & GEN6_PCODE_READY)
return -EAGAIN;
/* write value to GEN6_PCODE_DATA register */
intel_uncore_write_fw(uncore, GEN6_PCODE_DATA, *val);
intel_uncore_write_fw(uncore, GEN6_PCODE_DATA1, val1 ? *val1 : 0);
/* In this scenario, the value
"DG1_PCODE_STATUS | GEN6_PCODE_READY"
is written to the GEN6_PCODE_MAILBOX register,
so that the Busy status of the GEN6_PCODE_MAILBOX register
can be checked later.
(When the value of the GEN6_PCODE_READY bit of the
GEN6_PCODE_MAILBOX register changes to 0, the operation can
be considered completed.) */
intel_uncore_write_fw(uncore,
GEN6_PCODE_MAILBOX, GEN6_PCODE_READY | mbox);
/* In this scenario, verify that the BUSY status bit in the
GEN6_PCODE_MAILBOX register turns off for up to 500us. */
if (__intel_wait_for_register_fw(uncore,
GEN6_PCODE_MAILBOX,
GEN6_PCODE_READY, 0,
fast_timeout_us,
slow_timeout_ms,
&mbox))
return -ETIMEDOUT;
/* If there is a failure here, it may be considered that the
"DG1_PCODE_STATUS | GEN6_PCODE_READY" operation was not
completed within 500us */
...
}
int skl_pcode_request(struct intel_uncore *uncore, u32 mbox, u32 request,
u32 reply_mask, u32 reply, int timeout_base_ms)
{
u32 status;
int ret;
mutex_lock(&uncore->i915->sb_lock);
#define COND \
skl_pcode_try_request(uncore, mbox, request, reply_mask, reply, &status)
/* the first trial for skl_pcode_try_request() can return
-EAGAIN or -ETIMEDOUT. And the code did not check the error
code here, so we don't know how far the __snb_pcode_rw()
function went. It is not known whether the pcode_mailbox
status was busy before writing the value to the
GEN6_PCODE_DATA register or after.*/
if (COND) {
ret = 0;
goto out;
}
/* In this scenario, skl_pcode_try_request() is invoked every
10us for 180 seconds. When skl_pcode_try_request() returns
-EAGAIN and -ETIMEDOUT by _wait_for(),
-ETIMEDOUT is returned to a variable ret. */
ret = _wait_for(COND, timeout_base_ms * 1000, 10, 10);
if (!ret)
goto out;
/*
* The above can time out if the number of requests was low (2 in the
* worst case) _and_ PCODE was busy for some reason even after a
* (queued) request and @timeout_base_ms delay. As a workaround retry
* the poll with preemption disabled to maximize the number of
* requests. Increase the timeout from @timeout_base_ms to 50ms to
* account for interrupts that could reduce the number of these
* requests, and for any quirks of the PCODE firmware that delays
* the request completion.
*/
drm_dbg_kms(&uncore->i915->drm,
"PCODE timeout, retrying with preemption disabled\n");
drm_WARN_ON_ONCE(&uncore->i915->drm, timeout_base_ms > 3);
preempt_disable();
ret = wait_for_atomic(COND, 50);
preempt_enable();
out:
mutex_unlock(&uncore->i915->sb_lock);
return status ? status : ret;
#undef COND
}
---------------------------------------------------------
If you try skl_pcode_try_request() for 180 seconds in
skl_pcode_request(), and the first "intel_uncore_read_fw(uncore,
GEN6_PCODE_MAILBOX) & GEN6_PCODE_READY)" call in __snb_pcode_rw() that
skl_pcode_try_request() invokes always fails. if then it does not make
sense to me why this patch fixes it by just waiting 10 seconds.This is
because if it was called with the flow described above, 180 seconds is
longer than 10 seconds, so the scenario you mentioned is also covered in
the existing code.
To describe in more detail the second scenario I previously commented on:
skl_pcode_request() tries skl_pcode_try_request() for 180 seconds
1) In skl_pcode_try_request(), the GEN6_PCODE_MAILBOX register bit is
not BUSY, so the value is written to the GEN6_PCODE_DATA1 register.
2) skl_pcode_try_request() returns -ETIMEDOUT value because the
operation of 1) does not complete within 500us.
3) Scenario in which the GEN6_PCODE_MAILBOX register bit is checked as
BUSY and returns -EAGAIN in the last call of skl_pcode_try_request()
invoked by skl_pcode_request()
If the reason why this problem occurred is because of this scenario,
shouldn't there be an attempt to increase fast_timeout_us used as an
argument of __snb_pcode_rw() to 500us or more when
skl_pcode_try_request() returns -ETIMEDOUT?
Br,
G.G.
In the situation where the problem is reported, it is not possible to
confirm exactly which scenario code causes the problem with the current log
information, and it seems that additional analysis is needed to confirm it.
If the hardware takes more than 500us to succeed after PCODE_MAILBOX write
under certain circumstances, it is thought that the root problem causing the
problem should be fixed.
Actually I have tested it and indeed the extra check on the
PCODE_READY is needed and makes the driver probe correctly.
Thanks,
Andi
