[PATCH] drm/i915/pcode: Wait 10 seconds for pcode to settle

[Andi Shyti]

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 at linux.intel.com> wrote:
> > > > From: Aravind Iddamsetty <aravind.iddamsetty at intel.com>
> > > > 
> > > > 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@resize-bar.html#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.

> 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