linux-usb.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* How to proceed: usci_acpi: PPM init failed (-110)
@ 2021-08-23 18:06 Samuel Čavoj
  2021-08-24 10:24 ` Heikki Krogerus
  0 siblings, 1 reply; 10+ messages in thread
From: Samuel Čavoj @ 2021-08-23 18:06 UTC (permalink / raw)
  To: linux-usb; +Cc: heikki.krogerus

Hello,

The driver times out talking to the PPM (the message pops up 60 seconds
after loading the module, the timeout in ucsi_acpi_sync_write).
The command which times out is the first one after resetting the PPM in
ucsi_init, enabling basic notifications.

The laptop in question is an ASUS UM325U, with the AMD Ryzen 5700U SoC.

The ACPI description of the USBC000 device looks reasonable to my eyes,
but I am not an expert. The _DSM Method copies the UCSI OpRegion to (or
from) EC memory. I can provide a dump if needed.

I am looking for guidance on how to proceed, I am not too familiar with
the UCSI other than peeking at the spec for a short while.

Looking the error up online leads to various discussions usually ending
with installing an nvidia driver, however mine does not have any
dedicated GPU.

Regards,
Samuel

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2021-08-23 18:06 How to proceed: usci_acpi: PPM init failed (-110) Samuel Čavoj
@ 2021-08-24 10:24 ` Heikki Krogerus
       [not found]   ` <20210824164942.6pakfzf2crnxes7w@fastboi.localdomain>
  0 siblings, 1 reply; 10+ messages in thread
From: Heikki Krogerus @ 2021-08-24 10:24 UTC (permalink / raw)
  To: Samuel Čavoj; +Cc: linux-usb

On Mon, Aug 23, 2021 at 08:06:26PM +0200, Samuel Čavoj wrote:
> Hello,
> 
> The driver times out talking to the PPM (the message pops up 60 seconds
> after loading the module, the timeout in ucsi_acpi_sync_write).
> The command which times out is the first one after resetting the PPM in
> ucsi_init, enabling basic notifications.
> 
> The laptop in question is an ASUS UM325U, with the AMD Ryzen 5700U SoC.
> 
> The ACPI description of the USBC000 device looks reasonable to my eyes,
> but I am not an expert. The _DSM Method copies the UCSI OpRegion to (or
> from) EC memory. I can provide a dump if needed.
> 
> I am looking for guidance on how to proceed, I am not too familiar with
> the UCSI other than peeking at the spec for a short while.
> 
> Looking the error up online leads to various discussions usually ending
> with installing an nvidia driver, however mine does not have any
> dedicated GPU.

Can you send full dmesg output, and acpidump:

        % dmesg > dmesg.dump
        % acpidump -o acpi.dump

If enabling the notifications fails, then I'm not sure the EC firmware
on this board actually supports UCSI. That would not be unheard-of
situation.

thanks,

-- 
heikki

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
       [not found]   ` <20210824164942.6pakfzf2crnxes7w@fastboi.localdomain>
@ 2021-08-25  8:02     ` Heikki Krogerus
  2021-08-25  9:21       ` Samuel Čavoj
  0 siblings, 1 reply; 10+ messages in thread
From: Heikki Krogerus @ 2021-08-25  8:02 UTC (permalink / raw)
  To: Samuel Čavoj; +Cc: linux-usb

On Tue, Aug 24, 2021 at 06:49:42PM +0200, Samuel Čavoj wrote:
> On 24.08.2021 13:24, Heikki Krogerus wrote:
> > On Mon, Aug 23, 2021 at 08:06:26PM +0200, Samuel Čavoj wrote:
> > > Hello,
> > > 
> > > The driver times out talking to the PPM (the message pops up 60 seconds
> > > after loading the module, the timeout in ucsi_acpi_sync_write).
> > > The command which times out is the first one after resetting the PPM in
> > > ucsi_init, enabling basic notifications.
> > > 
> > > The laptop in question is an ASUS UM325U, with the AMD Ryzen 5700U SoC.
> > > 
> > > The ACPI description of the USBC000 device looks reasonable to my eyes,
> > > but I am not an expert. The _DSM Method copies the UCSI OpRegion to (or
> > > from) EC memory. I can provide a dump if needed.
> > > 
> > > I am looking for guidance on how to proceed, I am not too familiar with
> > > the UCSI other than peeking at the spec for a short while.
> > > 
> > > Looking the error up online leads to various discussions usually ending
> > > with installing an nvidia driver, however mine does not have any
> > > dedicated GPU.
> > 
> > Can you send full dmesg output, and acpidump:
> > 
> >         % dmesg > dmesg.dump
> >         % acpidump -o acpi.dump
> > 
> > If enabling the notifications fails, then I'm not sure the EC firmware
> > on this board actually supports UCSI. That would not be unheard-of
> > situation.
> > 
> > thanks,
> > 
> > -- 
> > heikki
> 
> Hello,
> 
> I've attached the respective dumps, I hope they arrive in one piece.
> 
> I've tried poking at the firmware in Windows, using UcsiControl.exe.
> 
> Running
> 
>     UcsiControl.exe Send 0 1
> 
> times out after a couple seconds, I assume this is related. The command
> is supposed to reset the controller, but maybe it then runs some commands
> as well. Running
> 
>     UcsiControl.exe Send 0 6
> 
> responds with a result instantly, supposedly this is the GetCapability
> command. I don't know how to interpret the results, but I can attach
> them if needed. The program is documented at [1].
> 
> This leads me to think that the firmware does actually support it, but
> has some kind of problem.

The reset command does not generate command completion event in UCSI
(that's why we poll the responce separately in the driver, just like
the spec tells us to do). So that command timing out may be expected.

You said that enabling the notifications with Set Notifications Enable
fails, so can you try this:

        UcsiControl.exe Send 0 00010005

thanks,

-- 
heikki

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2021-08-25  8:02     ` Heikki Krogerus
@ 2021-08-25  9:21       ` Samuel Čavoj
  2021-08-26  7:53         ` Heikki Krogerus
  0 siblings, 1 reply; 10+ messages in thread
From: Samuel Čavoj @ 2021-08-25  9:21 UTC (permalink / raw)
  To: Heikki Krogerus; +Cc: linux-usb

On 25.08.2021 11:02, Heikki Krogerus wrote:
> On Tue, Aug 24, 2021 at 06:49:42PM +0200, Samuel Čavoj wrote:
> > On 24.08.2021 13:24, Heikki Krogerus wrote:
> > > On Mon, Aug 23, 2021 at 08:06:26PM +0200, Samuel Čavoj wrote:
> > > > Hello,
> > > > 
> > > > The driver times out talking to the PPM (the message pops up 60 seconds
> > > > after loading the module, the timeout in ucsi_acpi_sync_write).
> > > > The command which times out is the first one after resetting the PPM in
> > > > ucsi_init, enabling basic notifications.
> > > > 
> > > > The laptop in question is an ASUS UM325U, with the AMD Ryzen 5700U SoC.
> > > > 
> > > > The ACPI description of the USBC000 device looks reasonable to my eyes,
> > > > but I am not an expert. The _DSM Method copies the UCSI OpRegion to (or
> > > > from) EC memory. I can provide a dump if needed.
> > > > 
> > > > I am looking for guidance on how to proceed, I am not too familiar with
> > > > the UCSI other than peeking at the spec for a short while.
> > > > 
> > > > Looking the error up online leads to various discussions usually ending
> > > > with installing an nvidia driver, however mine does not have any
> > > > dedicated GPU.
> > > 
> > > Can you send full dmesg output, and acpidump:
> > > 
> > >         % dmesg > dmesg.dump
> > >         % acpidump -o acpi.dump
> > > 
> > > If enabling the notifications fails, then I'm not sure the EC firmware
> > > on this board actually supports UCSI. That would not be unheard-of
> > > situation.
> > > 
> > > thanks,
> > > 
> > > -- 
> > > heikki
> > 
> > Hello,
> > 
> > I've attached the respective dumps, I hope they arrive in one piece.
> > 
> > I've tried poking at the firmware in Windows, using UcsiControl.exe.
> > 
> > Running
> > 
> >     UcsiControl.exe Send 0 1
> > 
> > times out after a couple seconds, I assume this is related. The command
> > is supposed to reset the controller, but maybe it then runs some commands
> > as well. Running
> > 
> >     UcsiControl.exe Send 0 6
> > 
> > responds with a result instantly, supposedly this is the GetCapability
> > command. I don't know how to interpret the results, but I can attach
> > them if needed. The program is documented at [1].
> > 
> > This leads me to think that the firmware does actually support it, but
> > has some kind of problem.
> 
> The reset command does not generate command completion event in UCSI
> (that's why we poll the responce separately in the driver, just like
> the spec tells us to do). So that command timing out may be expected.

That makes sense.

> You said that enabling the notifications with Set Notifications Enable
> fails, so can you try this:
> 
>         UcsiControl.exe Send 0 00010005

the command finishes instantly and does not seem to produce any error.

    PS C:\Program Files (x86)\USBTest\x64> .\UcsiControl.exe Send 0 00010005
    COMMAND:
    AsUInt64: 10005
    Command: 5
    DataLength: 0
    
    MESSAGE IN is empty.

Thank you,
Samuel

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2021-08-25  9:21       ` Samuel Čavoj
@ 2021-08-26  7:53         ` Heikki Krogerus
  2021-08-26 11:41           ` Samuel Čavoj
  0 siblings, 1 reply; 10+ messages in thread
From: Heikki Krogerus @ 2021-08-26  7:53 UTC (permalink / raw)
  To: Samuel Čavoj; +Cc: linux-usb

Hi Samuel,

On Wed, Aug 25, 2021 at 11:21:38AM +0200, Samuel Čavoj wrote:
> > You said that enabling the notifications with Set Notifications Enable
> > fails, so can you try this:
> > 
> >         UcsiControl.exe Send 0 00010005
> 
> the command finishes instantly and does not seem to produce any error.
> 
>     PS C:\Program Files (x86)\USBTest\x64> .\UcsiControl.exe Send 0 00010005
>     COMMAND:
>     AsUInt64: 10005
>     Command: 5
>     DataLength: 0
>     
>     MESSAGE IN is empty.

Thanks for testing that. So UCSI is definitely working on this
platform. I guess the ACPI notifications are simply not going through.

Can you check if there are any events coming from the EC with the
following commands:

        % modprobe -r ucsi_acpi
        % modprobe -r typec_ucsi
        % grep -i acpi /proc/interrupts
        ...
        % modprobe typec_ucsi
        % modprobe ucsi_acpi
        % grep -i acpi /proc/interrupts
        ...

See if the number of interrupts increases considerable, or at all. The
ucsi drivers need to be modules of course in order for that to work.

Maybe there is something special that the OS should do with the EC on
your board... There is a weird message in your dmesg.

        "ACPI: EC: interrupt blocked"

I don't know if it's relevant at all in this case, but I've just never
seen that. I'm not an EC or ACPI expert, but I think that you only see
that if the EC event interrupt is a GPIO. I would expect there to be
also a message:

        "ACPI: EC: interrupt unblocked"

But as said, I'm really not an EC expert. We probable need to ask the
ACPI guys about this, but let's first check the interrupts.

thanks,

-- 
heikki

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2021-08-26  7:53         ` Heikki Krogerus
@ 2021-08-26 11:41           ` Samuel Čavoj
  2022-01-22  0:21             ` Samuel Čavoj
  0 siblings, 1 reply; 10+ messages in thread
From: Samuel Čavoj @ 2021-08-26 11:41 UTC (permalink / raw)
  To: Heikki Krogerus; +Cc: linux-usb

Hello,

On 26.08.2021 10:53, Heikki Krogerus wrote:
> Hi Samuel,
> 
> > 
> > the command finishes instantly and does not seem to produce any error.
> > 
> >     PS C:\Program Files (x86)\USBTest\x64> .\UcsiControl.exe Send 0 00010005
> >     COMMAND:
> >     AsUInt64: 10005
> >     Command: 5
> >     DataLength: 0
> >     
> >     MESSAGE IN is empty.
> 
> Thanks for testing that. So UCSI is definitely working on this
> platform. I guess the ACPI notifications are simply not going through.
> 
> Can you check if there are any events coming from the EC with the
> following commands:
> 
>         % modprobe -r ucsi_acpi
>         % modprobe -r typec_ucsi
>         % grep -i acpi /proc/interrupts
>         ...
>         % modprobe typec_ucsi
>         % modprobe ucsi_acpi
>         % grep -i acpi /proc/interrupts
>         ...
> 
> See if the number of interrupts increases considerable, or at all. The
> ucsi drivers need to be modules of course in order for that to work.

I made four snapshots of the (filtered) /proc/interrupts file:

    1. with the modules loaded normally
    2. right after unloading them
    3. right after loading them again
    4. after the timeout expires and the init failed message is logged

Files 3 and 4 are identical. Between 1--2 and 2--3, IRQ 9 increases by
exactly 1 each time. The IRQ is described as "IR-IO-APIC 9-fasteoi acpi".
Here is the line in question from each of the files.

            CPU0       CPU1       CPU2       CPU3       CPU4       CPU5       CPU6       CPU7       CPU8       CPU9       CPU10      CPU11      CPU12      CPU13      CPU14      CPU15
   9:          0         52          0          0          0          0          0          0          0          0          0          0          0          0          0          0  IR-IO-APIC    9-fasteoi   acpi
   9:          0         53          0          0          0          0          0          0          0          0          0          0          0          0          0          0  IR-IO-APIC    9-fasteoi   acpi
   9:          0         54          0          0          0          0          0          0          0          0          0          0          0          0          0          0  IR-IO-APIC    9-fasteoi   acpi
   9:          0         54          0          0          0          0          0          0          0          0          0          0          0          0          0          0  IR-IO-APIC    9-fasteoi   acpi

To make it clear what I did in the first place, is to add a dev_err line
in the error branch right after "Enable basic notifications" in
ucsi_init. The line does get printed.

My understanding is that the PPM is completely quiet during the reset
procedure, and therefore the single notifications received should be the
completion notification for the "enable basic notifications" command.

I added a debug print to ucsi_acpi_notify, to see if the interrupt is
getting routed correctly at all (I suspected the ACPI might be
generating notifications for a different device). Another debug print
was added to ucsi_init right after the reset completes.

This is a snippet from ucsi_acpi_notify showing added printouts:

    dev_err(ua->dev, "checking ua->flags: %ld, cci: %d\n", ua->flags, cci);
	if (test_bit(COMMAND_PENDING, &ua->flags) &&
	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE)) {
        
        dev_err(ua->dev, "complete\n");
		complete(&ua->complete);
    }

Indeed, ucsi_acpi_notify gets called once when the module loads, after
the reset procedure is completed (as long as the ordering of the
messages in dmesg is good enough to tell, they are 20ms apart).
This is the output in dmesg: (i shortened the timeout to 5s).

    [ 1397.741701] ucsi_acpi USBC000:00: PPM reset succeeded
    [ 1397.761319] ucsi_acpi USBC000:00: checking ua->flags: 2, cci: 0
    [ 1402.941808] ucsi_acpi USBC000:00: failed to enable basic notifications
    [ 1402.989510] ucsi_acpi USBC000:00: PPM init failed (-110)

The completion condition is not satisfied and "complete" is not
printed. Possibly the firmware has some quirk, a cci of 0 seems wrong to
me.

> Maybe there is something special that the OS should do with the EC on

I suppose either that, or the PPM deviates from the spec. I don't know
how to go about tracing what Windows does, but that would be a way to
go.

> your board... There is a weird message in your dmesg.
> 
>         "ACPI: EC: interrupt blocked"
> 
> I don't know if it's relevant at all in this case, but I've just never
> seen that. I'm not an EC or ACPI expert, but I think that you only see
> that if the EC event interrupt is a GPIO. I would expect there to be
> also a message:
> 
>         "ACPI: EC: interrupt unblocked"

There is such a message in the log, on line 475. Also on every suspend,
the interrupt is blocked before going to sleep and unblocked when waking
up, which makes sense.

> But as said, I'm really not an EC expert. We probable need to ask the
> ACPI guys about this, but let's first check the interrupts.
> 
> thanks,
> 
> -- 
> heikki

Thank you very much for helping me with this.

Regards,
Samuel

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2021-08-26 11:41           ` Samuel Čavoj
@ 2022-01-22  0:21             ` Samuel Čavoj
  2022-01-24  9:23               ` Heikki Krogerus
  0 siblings, 1 reply; 10+ messages in thread
From: Samuel Čavoj @ 2022-01-22  0:21 UTC (permalink / raw)
  To: Heikki Krogerus; +Cc: linux-usb

Hi Heikki,

do you think we could get this back on track somehow? I'm not sure what 
to try next, do you have any ideas? Are there any tools to try and trace 
what the Windows driver does? Either from within Windows itself or 
intercept it somehow externally -- a hypervisor approach? Are there any 
tools developed for this purpose? I wasn't really able to find much.

Regards,
Samuel

On 2021-08-26 12:41, Samuel Čavoj wrote:
> Hello,
> 
> On 26.08.2021 10:53, Heikki Krogerus wrote:
>> Hi Samuel,
>> 
>> >
>> > the command finishes instantly and does not seem to produce any error.
>> >
>> >     PS C:\Program Files (x86)\USBTest\x64> .\UcsiControl.exe Send 0 00010005
>> >     COMMAND:
>> >     AsUInt64: 10005
>> >     Command: 5
>> >     DataLength: 0
>> >
>> >     MESSAGE IN is empty.
>> 
>> Thanks for testing that. So UCSI is definitely working on this
>> platform. I guess the ACPI notifications are simply not going through.
>> 
>> Can you check if there are any events coming from the EC with the
>> following commands:
>> 
>>         % modprobe -r ucsi_acpi
>>         % modprobe -r typec_ucsi
>>         % grep -i acpi /proc/interrupts
>>         ...
>>         % modprobe typec_ucsi
>>         % modprobe ucsi_acpi
>>         % grep -i acpi /proc/interrupts
>>         ...
>> 
>> See if the number of interrupts increases considerable, or at all. The
>> ucsi drivers need to be modules of course in order for that to work.
> 
> I made four snapshots of the (filtered) /proc/interrupts file:
> 
>     1. with the modules loaded normally
>     2. right after unloading them
>     3. right after loading them again
>     4. after the timeout expires and the init failed message is logged
> 
> Files 3 and 4 are identical. Between 1--2 and 2--3, IRQ 9 increases by
> exactly 1 each time. The IRQ is described as "IR-IO-APIC 9-fasteoi 
> acpi".
> Here is the line in question from each of the files.
> 
>             CPU0       CPU1       CPU2       CPU3       CPU4
> CPU5       CPU6       CPU7       CPU8       CPU9       CPU10
> CPU11      CPU12      CPU13      CPU14      CPU15
>    9:          0         52          0          0          0
> 0          0          0          0          0          0          0
>       0          0          0          0  IR-IO-APIC    9-fasteoi
> acpi
>    9:          0         53          0          0          0
> 0          0          0          0          0          0          0
>       0          0          0          0  IR-IO-APIC    9-fasteoi
> acpi
>    9:          0         54          0          0          0
> 0          0          0          0          0          0          0
>       0          0          0          0  IR-IO-APIC    9-fasteoi
> acpi
>    9:          0         54          0          0          0
> 0          0          0          0          0          0          0
>       0          0          0          0  IR-IO-APIC    9-fasteoi
> acpi
> 
> To make it clear what I did in the first place, is to add a dev_err 
> line
> in the error branch right after "Enable basic notifications" in
> ucsi_init. The line does get printed.
> 
> My understanding is that the PPM is completely quiet during the reset
> procedure, and therefore the single notifications received should be 
> the
> completion notification for the "enable basic notifications" command.
> 
> I added a debug print to ucsi_acpi_notify, to see if the interrupt is
> getting routed correctly at all (I suspected the ACPI might be
> generating notifications for a different device). Another debug print
> was added to ucsi_init right after the reset completes.
> 
> This is a snippet from ucsi_acpi_notify showing added printouts:
> 
>     dev_err(ua->dev, "checking ua->flags: %ld, cci: %d\n", ua->flags, 
> cci);
> 	if (test_bit(COMMAND_PENDING, &ua->flags) &&
> 	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE)) {
> 
>         dev_err(ua->dev, "complete\n");
> 		complete(&ua->complete);
>     }
> 
> Indeed, ucsi_acpi_notify gets called once when the module loads, after
> the reset procedure is completed (as long as the ordering of the
> messages in dmesg is good enough to tell, they are 20ms apart).
> This is the output in dmesg: (i shortened the timeout to 5s).
> 
>     [ 1397.741701] ucsi_acpi USBC000:00: PPM reset succeeded
>     [ 1397.761319] ucsi_acpi USBC000:00: checking ua->flags: 2, cci: 0
>     [ 1402.941808] ucsi_acpi USBC000:00: failed to enable basic 
> notifications
>     [ 1402.989510] ucsi_acpi USBC000:00: PPM init failed (-110)
> 
> The completion condition is not satisfied and "complete" is not
> printed. Possibly the firmware has some quirk, a cci of 0 seems wrong 
> to
> me.
> 
>> Maybe there is something special that the OS should do with the EC on
> 
> I suppose either that, or the PPM deviates from the spec. I don't know
> how to go about tracing what Windows does, but that would be a way to
> go.
> 
>> your board... There is a weird message in your dmesg.
>> 
>>         "ACPI: EC: interrupt blocked"
>> 
>> I don't know if it's relevant at all in this case, but I've just never
>> seen that. I'm not an EC or ACPI expert, but I think that you only see
>> that if the EC event interrupt is a GPIO. I would expect there to be
>> also a message:
>> 
>>         "ACPI: EC: interrupt unblocked"
> 
> There is such a message in the log, on line 475. Also on every suspend,
> the interrupt is blocked before going to sleep and unblocked when 
> waking
> up, which makes sense.
> 
>> But as said, I'm really not an EC expert. We probable need to ask the
>> ACPI guys about this, but let's first check the interrupts.
>> 
>> thanks,
>> 
>> --
>> heikki
> 
> Thank you very much for helping me with this.
> 
> Regards,
> Samuel

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2022-01-22  0:21             ` Samuel Čavoj
@ 2022-01-24  9:23               ` Heikki Krogerus
  2022-02-19  0:39                 ` Samuel Čavoj
  0 siblings, 1 reply; 10+ messages in thread
From: Heikki Krogerus @ 2022-01-24  9:23 UTC (permalink / raw)
  To: Samuel Čavoj; +Cc: linux-usb

On Sat, Jan 22, 2022 at 12:21:29AM +0000, Samuel Čavoj wrote:
> Hi Heikki,
> 
> do you think we could get this back on track somehow? I'm not sure what to
> try next, do you have any ideas? Are there any tools to try and trace what
> the Windows driver does? Either from within Windows itself or intercept it
> somehow externally -- a hypervisor approach? Are there any tools developed
> for this purpose? I wasn't really able to find much.

I don't have any ideas right now, but I'll try to think of something
that we could try. I'll also see if I can get my hands on one of those
Asus Zenbook laptops. It was a Zenbook 13, right?

Did you try to see what happens if you don't reset the "PPM"?

diff --git a/drivers/usb/typec/ucsi/ucsi.c b/drivers/usb/typec/ucsi/ucsi.c
index f0c2fa19f3e0f..6e93ef0cbe006 100644
--- a/drivers/usb/typec/ucsi/ucsi.c
+++ b/drivers/usb/typec/ucsi/ucsi.c
@@ -1199,13 +1199,6 @@ static int ucsi_init(struct ucsi *ucsi)
        int ret;
        int i;
 
-       /* Reset the PPM */
-       ret = ucsi_reset_ppm(ucsi);
-       if (ret) {
-               dev_err(ucsi->dev, "failed to reset PPM!\n");
-               goto err;
-       }
-
        /* Enable basic notifications */
        ucsi->ntfy = UCSI_ENABLE_NTFY_CMD_COMPLETE | UCSI_ENABLE_NTFY_ERROR;
        command = UCSI_SET_NOTIFICATION_ENABLE | ucsi->ntfy;

thanks,

> On 2021-08-26 12:41, Samuel Čavoj wrote:
> > Hello,
> > 
> > On 26.08.2021 10:53, Heikki Krogerus wrote:
> > > Hi Samuel,
> > > 
> > > >
> > > > the command finishes instantly and does not seem to produce any error.
> > > >
> > > >     PS C:\Program Files (x86)\USBTest\x64> .\UcsiControl.exe Send 0 00010005
> > > >     COMMAND:
> > > >     AsUInt64: 10005
> > > >     Command: 5
> > > >     DataLength: 0
> > > >
> > > >     MESSAGE IN is empty.
> > > 
> > > Thanks for testing that. So UCSI is definitely working on this
> > > platform. I guess the ACPI notifications are simply not going through.
> > > 
> > > Can you check if there are any events coming from the EC with the
> > > following commands:
> > > 
> > >         % modprobe -r ucsi_acpi
> > >         % modprobe -r typec_ucsi
> > >         % grep -i acpi /proc/interrupts
> > >         ...
> > >         % modprobe typec_ucsi
> > >         % modprobe ucsi_acpi
> > >         % grep -i acpi /proc/interrupts
> > >         ...
> > > 
> > > See if the number of interrupts increases considerable, or at all. The
> > > ucsi drivers need to be modules of course in order for that to work.
> > 
> > I made four snapshots of the (filtered) /proc/interrupts file:
> > 
> >     1. with the modules loaded normally
> >     2. right after unloading them
> >     3. right after loading them again
> >     4. after the timeout expires and the init failed message is logged
> > 
> > Files 3 and 4 are identical. Between 1--2 and 2--3, IRQ 9 increases by
> > exactly 1 each time. The IRQ is described as "IR-IO-APIC 9-fasteoi
> > acpi".
> > Here is the line in question from each of the files.
> > 
> >             CPU0       CPU1       CPU2       CPU3       CPU4
> > CPU5       CPU6       CPU7       CPU8       CPU9       CPU10
> > CPU11      CPU12      CPU13      CPU14      CPU15
> >    9:          0         52          0          0          0
> > 0          0          0          0          0          0          0
> >       0          0          0          0  IR-IO-APIC    9-fasteoi
> > acpi
> >    9:          0         53          0          0          0
> > 0          0          0          0          0          0          0
> >       0          0          0          0  IR-IO-APIC    9-fasteoi
> > acpi
> >    9:          0         54          0          0          0
> > 0          0          0          0          0          0          0
> >       0          0          0          0  IR-IO-APIC    9-fasteoi
> > acpi
> >    9:          0         54          0          0          0
> > 0          0          0          0          0          0          0
> >       0          0          0          0  IR-IO-APIC    9-fasteoi
> > acpi
> > 
> > To make it clear what I did in the first place, is to add a dev_err line
> > in the error branch right after "Enable basic notifications" in
> > ucsi_init. The line does get printed.
> > 
> > My understanding is that the PPM is completely quiet during the reset
> > procedure, and therefore the single notifications received should be the
> > completion notification for the "enable basic notifications" command.
> > 
> > I added a debug print to ucsi_acpi_notify, to see if the interrupt is
> > getting routed correctly at all (I suspected the ACPI might be
> > generating notifications for a different device). Another debug print
> > was added to ucsi_init right after the reset completes.
> > 
> > This is a snippet from ucsi_acpi_notify showing added printouts:
> > 
> >     dev_err(ua->dev, "checking ua->flags: %ld, cci: %d\n", ua->flags,
> > cci);
> > 	if (test_bit(COMMAND_PENDING, &ua->flags) &&
> > 	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE)) {
> > 
> >         dev_err(ua->dev, "complete\n");
> > 		complete(&ua->complete);
> >     }
> > 
> > Indeed, ucsi_acpi_notify gets called once when the module loads, after
> > the reset procedure is completed (as long as the ordering of the
> > messages in dmesg is good enough to tell, they are 20ms apart).
> > This is the output in dmesg: (i shortened the timeout to 5s).
> > 
> >     [ 1397.741701] ucsi_acpi USBC000:00: PPM reset succeeded
> >     [ 1397.761319] ucsi_acpi USBC000:00: checking ua->flags: 2, cci: 0
> >     [ 1402.941808] ucsi_acpi USBC000:00: failed to enable basic
> > notifications
> >     [ 1402.989510] ucsi_acpi USBC000:00: PPM init failed (-110)
> > 
> > The completion condition is not satisfied and "complete" is not
> > printed. Possibly the firmware has some quirk, a cci of 0 seems wrong to
> > me.
> > 
> > > Maybe there is something special that the OS should do with the EC on
> > 
> > I suppose either that, or the PPM deviates from the spec. I don't know
> > how to go about tracing what Windows does, but that would be a way to
> > go.
> > 
> > > your board... There is a weird message in your dmesg.
> > > 
> > >         "ACPI: EC: interrupt blocked"
> > > 
> > > I don't know if it's relevant at all in this case, but I've just never
> > > seen that. I'm not an EC or ACPI expert, but I think that you only see
> > > that if the EC event interrupt is a GPIO. I would expect there to be
> > > also a message:
> > > 
> > >         "ACPI: EC: interrupt unblocked"
> > 
> > There is such a message in the log, on line 475. Also on every suspend,
> > the interrupt is blocked before going to sleep and unblocked when waking
> > up, which makes sense.
> > 
> > > But as said, I'm really not an EC expert. We probable need to ask the
> > > ACPI guys about this, but let's first check the interrupts.
> > > 
> > > thanks,
> > > 
> > > --
> > > heikki
> > 
> > Thank you very much for helping me with this.
> > 
> > Regards,
> > Samuel

-- 
heikki

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2022-01-24  9:23               ` Heikki Krogerus
@ 2022-02-19  0:39                 ` Samuel Čavoj
  2022-03-24  9:45                   ` Heikki Krogerus
  0 siblings, 1 reply; 10+ messages in thread
From: Samuel Čavoj @ 2022-02-19  0:39 UTC (permalink / raw)
  To: Heikki Krogerus; +Cc: linux-usb

Hi

sorry about the delay.

On 2022-01-24 10:23, Heikki Krogerus wrote:
> On Sat, Jan 22, 2022 at 12:21:29AM +0000, Samuel Čavoj wrote:
>> Hi Heikki,
>> 
>> do you think we could get this back on track somehow? I'm not sure 
>> what to
>> try next, do you have any ideas? Are there any tools to try and trace 
>> what
>> the Windows driver does? Either from within Windows itself or 
>> intercept it
>> somehow externally -- a hypervisor approach? Are there any tools 
>> developed
>> for this purpose? I wasn't really able to find much.
> 
> I don't have any ideas right now, but I'll try to think of something
> that we could try. I'll also see if I can get my hands on one of those
> Asus Zenbook laptops. It was a Zenbook 13, right?

Yup, it's a Zenbook 13 OLED (UM325).

> 
> Did you try to see what happens if you don't reset the "PPM"?

No difference, as far as I can tell. I used the patch below to
get more output. This is right after boot, in the initramfs:

[    0.787887] ucsi_acpi USBC000:00: hi ucsi here
[    0.787893] ucsi_acpi USBC000:00: skipping reset
[    0.787894] ucsi_acpi USBC000:00: enable basic notifications
[    0.813169] ucsi_acpi USBC000:00: got notification:
[    0.814386] ucsi_acpi USBC000:00:     checking ua->flags: 2, cci: 0
[    1.859334] ucsi_acpi USBC000:00: PPM init failed (-110)

Same output after cold boot, reboot from linux and reboot from windows.

Thanks,
Samuel

diff --git a/drivers/usb/typec/ucsi/ucsi.c 
b/drivers/usb/typec/ucsi/ucsi.c
index 08561bf7c40c..f1880bdaa9f6 100644
--- a/drivers/usb/typec/ucsi/ucsi.c
+++ b/drivers/usb/typec/ucsi/ucsi.c
@@ -1185,25 +1185,34 @@ static int ucsi_init(struct ucsi *ucsi)
  	int ret;
  	int i;

+	dev_info(ucsi->dev, "hi ucsi here");
  	/* Reset the PPM */
+	dev_warn(ucsi->dev, "skipping reset");
+	/*
  	ret = ucsi_reset_ppm(ucsi);
  	if (ret) {
  		dev_err(ucsi->dev, "failed to reset PPM!\n");
  		goto err;
  	}
+	dev_info(ucsi->dev, "reset ok");
+	*/

  	/* Enable basic notifications */
  	ucsi->ntfy = UCSI_ENABLE_NTFY_CMD_COMPLETE | UCSI_ENABLE_NTFY_ERROR;
  	command = UCSI_SET_NOTIFICATION_ENABLE | ucsi->ntfy;
+	dev_info(ucsi->dev, "enable basic notifications");
  	ret = ucsi_send_command(ucsi, command, NULL, 0);
  	if (ret < 0)
  		goto err_reset;
+	dev_info(ucsi->dev, "done enable basic notifications");

  	/* Get PPM capabilities */
  	command = UCSI_GET_CAPABILITY;
+	dev_info(ucsi->dev, "get capabilities");
  	ret = ucsi_send_command(ucsi, command, &ucsi->cap, sizeof(ucsi->cap));
  	if (ret < 0)
  		goto err_reset;
+	dev_info(ucsi->dev, "done get capabilities");

  	if (!ucsi->cap.num_connectors) {
  		ret = -ENODEV;
@@ -1228,9 +1237,11 @@ static int ucsi_init(struct ucsi *ucsi)
  	/* Enable all notifications */
  	ucsi->ntfy = UCSI_ENABLE_NTFY_ALL;
  	command = UCSI_SET_NOTIFICATION_ENABLE | ucsi->ntfy;
+	dev_info(ucsi->dev, "enable all notifications");
  	ret = ucsi_send_command(ucsi, command, NULL, 0);
  	if (ret < 0)
  		goto err_unregister;
+	dev_info(ucsi->dev, "done enable all notifications");

  	return 0;

diff --git a/drivers/usb/typec/ucsi/ucsi_acpi.c 
b/drivers/usb/typec/ucsi/ucsi_acpi.c
index 6771f05e32c2..765c89594c41 100644
--- a/drivers/usb/typec/ucsi/ucsi_acpi.c
+++ b/drivers/usb/typec/ucsi/ucsi_acpi.c
@@ -98,6 +98,7 @@ static void ucsi_acpi_notify(acpi_handle handle, u32 
event, void *data)
  	struct ucsi_acpi *ua = data;
  	u32 cci;
  	int ret;
+	dev_info(ua->dev, "got notification:\n");

  	ret = ucsi_acpi_read(ua->ucsi, UCSI_CCI, &cci, sizeof(cci));
  	if (ret)
@@ -106,9 +107,13 @@ static void ucsi_acpi_notify(acpi_handle handle, 
u32 event, void *data)
  	if (UCSI_CCI_CONNECTOR(cci))
  		ucsi_connector_change(ua->ucsi, UCSI_CCI_CONNECTOR(cci));

+	dev_info(ua->dev, "    checking ua->flags: %ld, cci: %d\n", ua->flags, 
cci);
  	if (test_bit(COMMAND_PENDING, &ua->flags) &&
-	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE))
+	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE)) {
+
+		dev_warn(ua->dev, "    complete\n");
  		complete(&ua->complete);
+	}
  }

  static int ucsi_acpi_probe(struct platform_device *pdev)

> 
> diff --git a/drivers/usb/typec/ucsi/ucsi.c 
> b/drivers/usb/typec/ucsi/ucsi.c
> index f0c2fa19f3e0f..6e93ef0cbe006 100644
> --- a/drivers/usb/typec/ucsi/ucsi.c
> +++ b/drivers/usb/typec/ucsi/ucsi.c
> @@ -1199,13 +1199,6 @@ static int ucsi_init(struct ucsi *ucsi)
>         int ret;
>         int i;
> 
> -       /* Reset the PPM */
> -       ret = ucsi_reset_ppm(ucsi);
> -       if (ret) {
> -               dev_err(ucsi->dev, "failed to reset PPM!\n");
> -               goto err;
> -       }
> -
>         /* Enable basic notifications */
>         ucsi->ntfy = UCSI_ENABLE_NTFY_CMD_COMPLETE | 
> UCSI_ENABLE_NTFY_ERROR;
>         command = UCSI_SET_NOTIFICATION_ENABLE | ucsi->ntfy;
> 
> thanks,
> 
>> On 2021-08-26 12:41, Samuel Čavoj wrote:
>> > Hello,
>> >
>> > On 26.08.2021 10:53, Heikki Krogerus wrote:
>> > > Hi Samuel,
>> > >
>> > > >
>> > > > the command finishes instantly and does not seem to produce any error.
>> > > >
>> > > >     PS C:\Program Files (x86)\USBTest\x64> .\UcsiControl.exe Send 0 00010005
>> > > >     COMMAND:
>> > > >     AsUInt64: 10005
>> > > >     Command: 5
>> > > >     DataLength: 0
>> > > >
>> > > >     MESSAGE IN is empty.
>> > >
>> > > Thanks for testing that. So UCSI is definitely working on this
>> > > platform. I guess the ACPI notifications are simply not going through.
>> > >
>> > > Can you check if there are any events coming from the EC with the
>> > > following commands:
>> > >
>> > >         % modprobe -r ucsi_acpi
>> > >         % modprobe -r typec_ucsi
>> > >         % grep -i acpi /proc/interrupts
>> > >         ...
>> > >         % modprobe typec_ucsi
>> > >         % modprobe ucsi_acpi
>> > >         % grep -i acpi /proc/interrupts
>> > >         ...
>> > >
>> > > See if the number of interrupts increases considerable, or at all. The
>> > > ucsi drivers need to be modules of course in order for that to work.
>> >
>> > I made four snapshots of the (filtered) /proc/interrupts file:
>> >
>> >     1. with the modules loaded normally
>> >     2. right after unloading them
>> >     3. right after loading them again
>> >     4. after the timeout expires and the init failed message is logged
>> >
>> > Files 3 and 4 are identical. Between 1--2 and 2--3, IRQ 9 increases by
>> > exactly 1 each time. The IRQ is described as "IR-IO-APIC 9-fasteoi
>> > acpi".
>> > Here is the line in question from each of the files.
>> >
>> >             CPU0       CPU1       CPU2       CPU3       CPU4
>> > CPU5       CPU6       CPU7       CPU8       CPU9       CPU10
>> > CPU11      CPU12      CPU13      CPU14      CPU15
>> >    9:          0         52          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >    9:          0         53          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >    9:          0         54          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >    9:          0         54          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >
>> > To make it clear what I did in the first place, is to add a dev_err line
>> > in the error branch right after "Enable basic notifications" in
>> > ucsi_init. The line does get printed.
>> >
>> > My understanding is that the PPM is completely quiet during the reset
>> > procedure, and therefore the single notifications received should be the
>> > completion notification for the "enable basic notifications" command.
>> >
>> > I added a debug print to ucsi_acpi_notify, to see if the interrupt is
>> > getting routed correctly at all (I suspected the ACPI might be
>> > generating notifications for a different device). Another debug print
>> > was added to ucsi_init right after the reset completes.
>> >
>> > This is a snippet from ucsi_acpi_notify showing added printouts:
>> >
>> >     dev_err(ua->dev, "checking ua->flags: %ld, cci: %d\n", ua->flags,
>> > cci);
>> > 	if (test_bit(COMMAND_PENDING, &ua->flags) &&
>> > 	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE)) {
>> >
>> >         dev_err(ua->dev, "complete\n");
>> > 		complete(&ua->complete);
>> >     }
>> >
>> > Indeed, ucsi_acpi_notify gets called once when the module loads, after
>> > the reset procedure is completed (as long as the ordering of the
>> > messages in dmesg is good enough to tell, they are 20ms apart).
>> > This is the output in dmesg: (i shortened the timeout to 5s).
>> >
>> >     [ 1397.741701] ucsi_acpi USBC000:00: PPM reset succeeded
>> >     [ 1397.761319] ucsi_acpi USBC000:00: checking ua->flags: 2, cci: 0
>> >     [ 1402.941808] ucsi_acpi USBC000:00: failed to enable basic
>> > notifications
>> >     [ 1402.989510] ucsi_acpi USBC000:00: PPM init failed (-110)
>> >
>> > The completion condition is not satisfied and "complete" is not
>> > printed. Possibly the firmware has some quirk, a cci of 0 seems wrong to
>> > me.
>> >
>> > > Maybe there is something special that the OS should do with the EC on
>> >
>> > I suppose either that, or the PPM deviates from the spec. I don't know
>> > how to go about tracing what Windows does, but that would be a way to
>> > go.
>> >
>> > > your board... There is a weird message in your dmesg.
>> > >
>> > >         "ACPI: EC: interrupt blocked"
>> > >
>> > > I don't know if it's relevant at all in this case, but I've just never
>> > > seen that. I'm not an EC or ACPI expert, but I think that you only see
>> > > that if the EC event interrupt is a GPIO. I would expect there to be
>> > > also a message:
>> > >
>> > >         "ACPI: EC: interrupt unblocked"
>> >
>> > There is such a message in the log, on line 475. Also on every suspend,
>> > the interrupt is blocked before going to sleep and unblocked when waking
>> > up, which makes sense.
>> >
>> > > But as said, I'm really not an EC expert. We probable need to ask the
>> > > ACPI guys about this, but let's first check the interrupts.
>> > >
>> > > thanks,
>> > >
>> > > --
>> > > heikki
>> >
>> > Thank you very much for helping me with this.
>> >
>> > Regards,
>> > Samuel

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: How to proceed: usci_acpi: PPM init failed (-110)
  2022-02-19  0:39                 ` Samuel Čavoj
@ 2022-03-24  9:45                   ` Heikki Krogerus
  0 siblings, 0 replies; 10+ messages in thread
From: Heikki Krogerus @ 2022-03-24  9:45 UTC (permalink / raw)
  To: Samuel Čavoj; +Cc: linux-usb

Hi again,

I'm sorry for the super slow progress with this. Just a quick update.

On Sat, Feb 19, 2022 at 01:39:33AM +0100, Samuel Čavoj wrote:
> Hi
> 
> sorry about the delay.
> 
> On 2022-01-24 10:23, Heikki Krogerus wrote:
> > On Sat, Jan 22, 2022 at 12:21:29AM +0000, Samuel Čavoj wrote:
> > > Hi Heikki,
> > > 
> > > do you think we could get this back on track somehow? I'm not sure
> > > what to
> > > try next, do you have any ideas? Are there any tools to try and
> > > trace what
> > > the Windows driver does? Either from within Windows itself or
> > > intercept it
> > > somehow externally -- a hypervisor approach? Are there any tools
> > > developed
> > > for this purpose? I wasn't really able to find much.
> > 
> > I don't have any ideas right now, but I'll try to think of something
> > that we could try. I'll also see if I can get my hands on one of those
> > Asus Zenbook laptops. It was a Zenbook 13, right?
> 
> Yup, it's a Zenbook 13 OLED (UM325).

So, I'm not able to get one of those unfortunately.

> > Did you try to see what happens if you don't reset the "PPM"?
> 
> No difference, as far as I can tell. I used the patch below to
> get more output. This is right after boot, in the initramfs:
> 
> [    0.787887] ucsi_acpi USBC000:00: hi ucsi here
> [    0.787893] ucsi_acpi USBC000:00: skipping reset
> [    0.787894] ucsi_acpi USBC000:00: enable basic notifications
> [    0.813169] ucsi_acpi USBC000:00: got notification:
> [    0.814386] ucsi_acpi USBC000:00:     checking ua->flags: 2, cci: 0
> [    1.859334] ucsi_acpi USBC000:00: PPM init failed (-110)
> 
> Same output after cold boot, reboot from linux and reboot from windows.

Based on that output, there is a notification, and I'm assuming that
notification is for the command completion. But CCI is 0?

That could be because the mailbox in memory is not getting
synchronised for some reason, but it could also mean that the EC
firmware is really not writing anything to the CCI. Both cases
probable mean we are missing some extra step that Windows is doing,
but what... I have no idea.

thanks,

-- 
heikki

^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2022-03-24  9:45 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-08-23 18:06 How to proceed: usci_acpi: PPM init failed (-110) Samuel Čavoj
2021-08-24 10:24 ` Heikki Krogerus
     [not found]   ` <20210824164942.6pakfzf2crnxes7w@fastboi.localdomain>
2021-08-25  8:02     ` Heikki Krogerus
2021-08-25  9:21       ` Samuel Čavoj
2021-08-26  7:53         ` Heikki Krogerus
2021-08-26 11:41           ` Samuel Čavoj
2022-01-22  0:21             ` Samuel Čavoj
2022-01-24  9:23               ` Heikki Krogerus
2022-02-19  0:39                 ` Samuel Čavoj
2022-03-24  9:45                   ` Heikki Krogerus

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).