Re: [Intel-gfx] [PATCH] drm/i915/pcode: Wait 10 seconds for pcode to settle

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi GG,

On Thu, Feb 02, 2023 at 10:22:30AM +0200, Gwan-gyeong Mun wrote:
> Hi Andi,
> 
> You gave a lot of explanations, and confirmed that this patch solves the
> problem, but the root cause of this problem still seems to be unclear.
> 
> In the logs where this problem was reported, the logs were output in the
> following order.
> 
> link
>  : https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_1294/bat-atsm-1/igt@i915_module_load@xxxxxxxxxxxxxxx#dmesg-warnings17324
> 
> [log]
> <7> [268.276586] i915 0000:4d:00.0: [drm:skl_pcode_request [i915]] PCODE
> timeout, retrying with preemption disabled
> ...
> <4> [268.276942] WARNING: CPU: 1 PID: 1678 at
> drivers/gpu/drm/i915/intel_pcode.c:196 skl_pcode_request+0x242/0x260 [i915]
> ...
> <3> [268.329058] i915 0000:4d:00.0: [drm] *ERROR* gt0: intel_pcode_init
> failed -11
> 
> 
> In other words, -EAGAIN was not returned when the first
> skl_pcode_try_request() was executed in the skl_pcode_request() function,
> but the logs confirmed that the _wait_for(COND ...) of the
> skl_pcode_request() function was executed.

I'm not following... how can you say that -EAGAIN was not
returned, it's written explecetly that pcode_init failed with
-11, i.e. -EAGAIN.

Besides if we get as far as to receive "PCODE timeout, retrying
with preemption disabled" isn't it because we failed twice? And
apparently with -EAGAIN?

How can you say from the logs above that this

	if (COND) {
		ret = 0;
		goto out;
	}

has not failed with -EAGAIN? The logs are not telling us how the
calls to __skl_pcode_try_request() failed. I am telling you after
I tested it.

I hope I understood what you are saying. Otherwise, let's have an
offline chat.

Andi

> And, I reviewed bpsec in more detail to see if I missed anything related to
> the status and restrictions of the initial GTDRIVER_MAILBOX_INTERFACE
> (PCODE).
> 
> I've reviewed bpsec in detail for the two below where
> GTDRIVER_MAILBOX_INTERFACE is mentioned, but I haven't identified any
> additional constraints other than those described below.
> 
> 
> Pcode Driver Mailbox Spec: 34151
> Driver Initialization Programming Sequence: 33149
> 
> RUN_BUSY: SW may write to the two mailbox registers only when RUN_BUSY is
> cleared (0b)
> 
> My suggestion is that the HW should explain and analyze the root cause of
> the situation where it takes more than 180s for the Busy bit of
> GTDRIVER_MAILBOX_INTERFACE to change to 0.
> 
> And the method of the proposed patch, the newly added line
> "__intel_wait_for_register_fw(uncore, GEN6_PCODE_MAILBOX, GEN6_PCODE_READY,
> 0, 500, 10000, NULL))" succeeded, but the existing method of trying 180s
> with checking intel_uncore_read_fw(uncore,
> GEN6_PCODE_MAILBOX)&GEN6_PCODE_READY) failed. Therefore please review it
> again.
> (Checking the code, it appears that both call usleep_range(wait__, wait__ *
> 2); in __wait_for().)
> 
> Br,
> 
> G.G.
> 
> 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)
> 
> 	/*
> 	 * Prime the PCODE by doing a request first. Normally it guarantees
> 	 * that a subsequent request, at most @timeout_base_ms later, succeeds.
> 	 * _wait_for() doesn't guarantee when its passed condition is evaluated
> 	 * first, so send the first request explicitly.
> 	 */
> 	if (COND) {
> 		ret = 0;
> 		goto out;
> 	}
> 	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
> }
> 
> 
> 
> 
> 
> 
> On 1/30/23 10:41 PM, Andi Shyti wrote:
> > Hi Rodrigo,
> > 
> > first of all, thanks for looking into this!
> > 
> > > > > > > > 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;
> > > > > > > 
> > > > > > > what if we fail here because the punit is still initializing and
> > > > > > > will be ready, say, in 10 seconds?
> > > > > > > 
> > > > > > > GG, without going any further, we fail here! The -EAGAIN we
> > > > > > > receive from the test comes from this point. We don't fail with
> > > > > > > -ETIMEDOUT, but with -EAGAIN and the reason is because the punit
> > > > > > > is not ready to perform the very fist communication and we fail
> > > > > > > the probing.
> > > > > > > 
> > > > > > > It doesn't mean, though, that there is anything wrong, we just
> > > > > > > need to wait a bit before "taking drastic decisions"!
> > > > > > > 
> > > > > > > This patch is suggesting to wait up to 10s for the punit to be
> > > > > > > ready and eventually try to probe again... and, indeed, it works!
> > > > > > 
> > > > > > As GG, what I still don't understand is how this extra 10 seconds
> > > > > > wait helps... have you tried to simple add the 10 to the 180 and
> > > > > > make the code 190 sec instead?
> > > > > 
> > > > > maybe I haven't been able to explain the issue properly.
> > > > > 
> > > > > I can even set that timer to 2hrs and a half and nothing changes
> > > > > because we fail before.
> > > > > 
> > > > > Here it's not a matter of how much do I wait but when do I check
> > > > > the pcode readiness (i.e. signalled by the GEN6_PCODE_READY bit
> > > > > in the GEN6_PCODE_MAILBOX register).
> > > > > 
> > > > > During a normal run we are always sure that communicating with
> > > > > the punit works, because we made it sure during the previous
> > > > > transaction.
> > > > > 
> > > > > During probe there is no previous transaction and we start
> > > > > communicating with the punit without making sure that it is
> > > > > ready. And indeed some times it is not, so that we suppress the
> > > > > probing on purpose instead of giving it another chance.
> > > > > 
> > > > > I admit that the commit message is not written properly and
> > > > > rather misleading, but here it's not at all a matter of how much
> > > > > do I wait.
> > > > 
> > > > The commit message was initially confused because it looks like
> > > > we are just adding a wait, without doing anything....
> > > > 
> > > > But looking to the code we can see that it will wait until
> > > > pcode is ready with a timeout of 10 seconds.
> > > > 
> > > > But if pcode is ready in 10 seconds, why pcode is not ready
> > > > in 190 seconds. We are doing absolutely nothing more that could
> > > > make pcode ready in 10 seconds that won't be in 190.
> > > > 
> > > > This is what we are missing here... The code as is doesn't make
> > > > a lot of sense to us and it looks like it is solving the issue
> > > > by the 10 extra seconds and not by some special status checking.
> > > 
> > > Okay, after an offline talk I am convinced now that we need some
> > > check like this in some place.
> > > 
> > > But the commit message needs be be fully re-written.
> > > 
> > > It needs to be clear that underneath, the pcode communication
> > > functions will do a check for ready without any wait, what will
> > > make desired timeout to never really wait for the pcode done
> > > and prematurely return.
> > > 
> > > at __snb_pcode_rw():
> > > 
> > >   if (intel_uncore_read_fw(uncore, GEN6_PCODE_MAILBOX) & GEN6_PCODE_READY)
> > >                  return -EAGAIN;
> > > 
> > > So, for this reason we need to ensure that pcode is really ready
> > > before we wait.
> > > 
> > > Other options are to handle the EAGAIN return and then wait.
> > > Or even change the __snb_pcode_rw to ensure that it is ready...
> > > 
> > > Something like:
> > > 
> > > -       if (intel_uncore_read_fw(uncore, GEN6_PCODE_MAILBOX) & GEN6_PCODE_READY)
> > > -               return -EAGAIN;
> > > +       if (__intel_wait_for_register_fw(uncore, GEN6_PCODE_MAILBOX,
> > > +                                        GEN6_PCODE_READY, GEN6_PCODE_READY,
> > > +                                        fast_timeout_us,
> > > +                                        slow_timeout_ms,
> > > +                                        NULL))
> > > +               return -ETIMEDOUT;
> > 
> > This works, but the difference is that you are putting it on any
> > call to the __snb_pcode_rw(), even when not necessary.
> > 
> > Putting it in the schema we used in our offline chat, the
> > original implementation was:
> > 
> >   +-----------------------+
> >   | r/w -> check if ready |-> r/w -> cir -> r/w -> cir -> r/w -> ...
> >   +-----------------------+
> >     probe time
> > 
> > (where cir stands for "check if ready"). Because in the first
> > r/w we didn't check the status of the punit we added:
> > 
> >   +-------------------+
> >   | cir -> r/w -> cir |-> r/w -> cir -> r/w -> cir -> r/w -> ...
> >   +-------------------+
> >      probe time
> > 
> > So that we are sure that the first r/w works. What you are
> > suggesting is:
> > 
> >   +-------------------+
> >   | cir -> r/w -> cir |-> cir -> r/w -> cir -> cir -> r/w -> cir ->
> >   --------------------+
> >      probe time
> > 
> > As you can se we have two "check if ready" in a raw, which might
> > be a bit of an overkill, it doesn't hurt much but it would look
> > like:
> > 
> >    if (__intel_wait_for_register_fw())
> >    	return -EAGAIN;
> > 
> >    intel_uncore_write_fw......
> > 
> >    if (__intel_wait_for_register_fw())
> >    	return -TIMEDOUT;
> > 
> > and this for every single snb_pcode_r/w.
> > 
> > Besides some functions might need the first wait, some might not.
> > Check, for example icl_tc_cold_exit() where the -EAGAIN is
> > handled. With your version the retries would be quite ponderous.
> > 
> > I'm sorry, but I can't take your suggestion as it can have major
> > consequences along i915, it requires more changes and and it
> > needs to be carefully tested.
> > 
> > On top of that I like Ashutosh refactoring that is quite an
> > elegant way to gain more flexibility at boot time without any
> > further impact.
> > 
> > > In the best regular case it will not change anything since the wait
> > > for will return 0 immediatelly... in the worst case we would double
> > > the timeout value, but this would be only in this insane case of
> > > 180 seconds anyway and if it goes really really nasty...
> > > 
> > > But anyway, now the motivation and the source of the issue is pretty
> > > clear, I can add my rv-b there, but I really want a better commit msg
> > > at least...
> > 
> > I definitely need to make a better commit message :)
> > 
> > Thanks a lot,
> > Andi
> > 
> > > > 
> > > > > 
> > > > > Thanks, Rodrigo!
> > > > > Andi
> > > > > 
> > > > > > > 
> > > > > > > Andi
> > > > > > > 
> > > > > > > > 
> > > > > > > >          /* 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.



[Index of Archives]     [Linux DRI Users]     [Linux Intel Graphics]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [XFree86]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Linux Kernel]     [Linux SCSI]     [XFree86]
  Powered by Linux