How to proceed: usci_acpi: PPM init failed (-110)

How to proceed: usci_acpi: PPM init failed (-110)

[Samuel Čavoj]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Heikki Krogerus]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Heikki Krogerus]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Samuel Čavoj]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Heikki Krogerus]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Samuel Čavoj]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Samuel Čavoj]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Heikki Krogerus]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Samuel Čavoj]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Heikki Krogerus]

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

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Samuel Čavoj]

Hi Heikki,

I gave this a hard look and figured out the issue. Long story short, the
firmware is clearing the CCI on EC RAM after copying from EC RAM to
system memory. This happens both when notifications are delivered and
when a read operation is explicitly performed via _DSM(read). What the
driver currently does after receiving a notification is performing an
explicit read. However by this time the CCI in EC RAM has been cleared
by the AML and the information is lost.

Details:

1. _DSM(read) of the UCSI device:

Copies all relevant fields of the mailbox data structure from EC RAM
to a SystemMemory OperationRegion. The last field to be copied is the
CCI:

     [...]
     CCI0 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI0))
     CCI1 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI1))
     CCI2 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI2))
     CCI3 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI3))
     [...]

However, for some reason, this is followed by another two operations,
which zero-out half of the CCI:

     [...]
     \_SB.PCI0.SBRG.EC0.ECWT (Zero, RefOf (\_SB.PCI0.SBRG.EC0.CCI0))
     \_SB.PCI0.SBRG.EC0.ECWT (Zero, RefOf (\_SB.PCI0.SBRG.EC0.CCI3))

I don't know why this is present. This does not cause the problem,
however, only leads to issues if two explicit reads are performed
consecutively. What does cause problems with the current driver
implementation is:

2. The event handler (_Q79)

The _Q79 event handler on my machine is responsible for the UCSI
notifications. It performs a copy from EC RAM to system memory and
triggers the 0x80 notification on the UCSI device (called UBTC).
The final instructions of this handler are:

     [...]
     ^^^^UBTC.CCI0 = CCI0 /* \_SB_.PCI0.SBRG.EC0_.CCI0 */
     ^^^^UBTC.CCI1 = CCI1 /* \_SB_.PCI0.SBRG.EC0_.CCI1 */
     ^^^^UBTC.CCI2 = CCI2 /* \_SB_.PCI0.SBRG.EC0_.CCI2 */
     ^^^^UBTC.CCI3 = CCI3 /* \_SB_.PCI0.SBRG.EC0_.CCI3 */
     USGC = 0xF1
     CCI0 = Zero // These two lines are the culprit
     CCI3 = Zero
     Local1 = ((Timer - Local0) / 0x2710)
     Notify (UBTC, 0x80) // Status Change
     Release (ECMT)


A side note:
I figured this out by booting up a Windows installation and convincing
the local kernel debugger to dump ACPI trace information to a file. The 
file
contained an outrageous amount of information with inconsistent 
formatting
(missing commas and stuff) for which I wrote an extremely janky parser 
in
Python. This let me examine the exact steps performed by the Windows 
driver.
And the difference I noticed is that the Linux driver was issuing a 
_DSM(read)
after every notification, reading the already-zeroed-out CCI.

Patching the AML to remove the zeroing-out instructions seemed to work 
as
well, but I suppose this is not a good general solution.

Following is a prototype-grade patch, in essence performing soft-reads 
most of
the time (i.e. just reading from the OpRegion and not calling _DSM) and 
explicit
reads when necessary. I am unfortunately not familiar with the spec and 
the
hardware in the wild and I understand that it is possible that some 
devices on
the other hand do not synchronize the mailbox when notifying and it 
needs to be
done explicitly. I suppose we'd need a parameter to configure this 
behaviour in
that case with a quirk system. The patch works on my system. Some other 
issues
surface later, but I think they are related to a particular cheap dongle 
I have
because they don't seem to occur without it.

What do you think about this situation? Is the patch reasonable, or does 
it need
a significant re-think?

thanks,
     Sam

 From 45a29c149a29da989fbdd843c7f040a4454c3a33 Mon Sep 17 00:00:00 2001
 From: =?UTF-8?q?Samuel=20=C4=8Cavoj?= <samuel@cavoj.net>
Date: Fri, 11 Nov 2022 00:06:24 +0100
Subject: [PATCH] TODO: ucsi: introduce read_explicit
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Signed-off-by: Samuel Čavoj <samuel@cavoj.net>
---
  drivers/usb/typec/ucsi/ucsi.c         |  9 +++++----
  drivers/usb/typec/ucsi/ucsi.h         |  3 +++
  drivers/usb/typec/ucsi/ucsi_acpi.c    | 11 +++++++++++
  drivers/usb/typec/ucsi/ucsi_ccg.c     |  1 +
  drivers/usb/typec/ucsi/ucsi_stm32g0.c |  1 +
  5 files changed, 21 insertions(+), 4 deletions(-)

diff --git a/drivers/usb/typec/ucsi/ucsi.c 
b/drivers/usb/typec/ucsi/ucsi.c
index e690fa50ffce..c2fce8b27821 100644
--- a/drivers/usb/typec/ucsi/ucsi.c
+++ b/drivers/usb/typec/ucsi/ucsi.c
@@ -884,7 +884,7 @@ static int ucsi_reset_ppm(struct ucsi *ucsi)
  			goto out;
  		}

-		ret = ucsi->ops->read(ucsi, UCSI_CCI, &cci, sizeof(cci));
+		ret = ucsi->ops->read_explicit(ucsi, UCSI_CCI, &cci, sizeof(cci));
  		if (ret)
  			goto out;

@@ -1351,7 +1351,8 @@ struct ucsi *ucsi_create(struct device *dev, const 
struct ucsi_operations *ops)
  {
  	struct ucsi *ucsi;

-	if (!ops || !ops->read || !ops->sync_write || !ops->async_write)
+	if (!ops || !ops->read || !ops->read_explicit || !ops->sync_write ||
+	    !ops->async_write)
  		return ERR_PTR(-EINVAL);

  	ucsi = kzalloc(sizeof(*ucsi), GFP_KERNEL);
@@ -1385,8 +1386,8 @@ int ucsi_register(struct ucsi *ucsi)
  {
  	int ret;

-	ret = ucsi->ops->read(ucsi, UCSI_VERSION, &ucsi->version,
-			      sizeof(ucsi->version));
+	ret = ucsi->ops->read_explicit(ucsi, UCSI_VERSION, &ucsi->version,
+				       sizeof(ucsi->version));
  	if (ret)
  		return ret;

diff --git a/drivers/usb/typec/ucsi/ucsi.h 
b/drivers/usb/typec/ucsi/ucsi.h
index 8eb391e3e592..e961ec1f92a0 100644
--- a/drivers/usb/typec/ucsi/ucsi.h
+++ b/drivers/usb/typec/ucsi/ucsi.h
@@ -37,6 +37,7 @@ struct ucsi_altmode;
  /**
   * struct ucsi_operations - UCSI I/O operations
   * @read: Read operation
+ * @read_explicit: Read operation with explicit poll if applicable
   * @sync_write: Blocking write operation
   * @async_write: Non-blocking write operation
   * @update_altmodes: Squashes duplicate DP altmodes
@@ -48,6 +49,8 @@ struct ucsi_altmode;
  struct ucsi_operations {
  	int (*read)(struct ucsi *ucsi, unsigned int offset,
  		    void *val, size_t val_len);
+	int (*read_explicit)(struct ucsi *ucsi, unsigned int offset,
+			     void *val, size_t val_len);
  	int (*sync_write)(struct ucsi *ucsi, unsigned int offset,
  			  const void *val, size_t val_len);
  	int (*async_write)(struct ucsi *ucsi, unsigned int offset,
diff --git a/drivers/usb/typec/ucsi/ucsi_acpi.c 
b/drivers/usb/typec/ucsi/ucsi_acpi.c
index a0cd8c4ebe31..20432f4313c9 100644
--- a/drivers/usb/typec/ucsi/ucsi_acpi.c
+++ b/drivers/usb/typec/ucsi/ucsi_acpi.c
@@ -52,6 +52,16 @@ static int ucsi_acpi_read(struct ucsi *ucsi, unsigned 
int offset,
  			  void *val, size_t val_len)
  {
  	struct ucsi_acpi *ua = ucsi_get_drvdata(ucsi);
+
+	memcpy(val, ua->base + offset, val_len);
+
+	return 0;
+}
+
+static int ucsi_acpi_read_explicit(struct ucsi *ucsi, unsigned int 
offset,
+				   void *val, size_t val_len)
+{
+	struct ucsi_acpi *ua = ucsi_get_drvdata(ucsi);
  	int ret;

  	ret = ucsi_acpi_dsm(ua, UCSI_DSM_FUNC_READ);
@@ -101,6 +111,7 @@ static int ucsi_acpi_sync_write(struct ucsi *ucsi, 
unsigned int offset,

  static const struct ucsi_operations ucsi_acpi_ops = {
  	.read = ucsi_acpi_read,
+	.read_explicit = ucsi_acpi_read_explicit,
  	.sync_write = ucsi_acpi_sync_write,
  	.async_write = ucsi_acpi_async_write
  };
diff --git a/drivers/usb/typec/ucsi/ucsi_ccg.c 
b/drivers/usb/typec/ucsi/ucsi_ccg.c
index 5c0bf48be766..c1d2db3a7363 100644
--- a/drivers/usb/typec/ucsi/ucsi_ccg.c
+++ b/drivers/usb/typec/ucsi/ucsi_ccg.c
@@ -593,6 +593,7 @@ static int ucsi_ccg_sync_write(struct ucsi *ucsi, 
unsigned int offset,

  static const struct ucsi_operations ucsi_ccg_ops = {
  	.read = ucsi_ccg_read,
+	.read_explicit = ucsi_ccg_read,
  	.sync_write = ucsi_ccg_sync_write,
  	.async_write = ucsi_ccg_async_write,
  	.update_altmodes = ucsi_ccg_update_altmodes
diff --git a/drivers/usb/typec/ucsi/ucsi_stm32g0.c 
b/drivers/usb/typec/ucsi/ucsi_stm32g0.c
index 061551d464f1..274b5f016dfb 100644
--- a/drivers/usb/typec/ucsi/ucsi_stm32g0.c
+++ b/drivers/usb/typec/ucsi/ucsi_stm32g0.c
@@ -437,6 +437,7 @@ static irqreturn_t ucsi_stm32g0_irq_handler(int irq, 
void *data)

  static const struct ucsi_operations ucsi_stm32g0_ops = {
  	.read = ucsi_stm32g0_read,
+	.read_explicit = ucsi_stm32g0_read,
  	.sync_write = ucsi_stm32g0_sync_write,
  	.async_write = ucsi_stm32g0_async_write,
  };
-- 
2.38.1



On 2022-03-24 10:45, Heikki Krogerus wrote:
> 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,

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Heikki Krogerus]

Hi Sam,

Sorry to keep you waiting.

On Thu, Dec 22, 2022 at 09:18:27PM +0100, Samuel Čavoj wrote:
> Hi Heikki,
> 
> I gave this a hard look and figured out the issue. Long story short, the
> firmware is clearing the CCI on EC RAM after copying from EC RAM to
> system memory. This happens both when notifications are delivered and
> when a read operation is explicitly performed via _DSM(read). What the
> driver currently does after receiving a notification is performing an
> explicit read. However by this time the CCI in EC RAM has been cleared
> by the AML and the information is lost.
> 
> Details:
> 
> 1. _DSM(read) of the UCSI device:
> 
> Copies all relevant fields of the mailbox data structure from EC RAM
> to a SystemMemory OperationRegion. The last field to be copied is the
> CCI:
> 
>     [...]
>     CCI0 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI0))
>     CCI1 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI1))
>     CCI2 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI2))
>     CCI3 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI3))
>     [...]
> 
> However, for some reason, this is followed by another two operations,
> which zero-out half of the CCI:
> 
>     [...]
>     \_SB.PCI0.SBRG.EC0.ECWT (Zero, RefOf (\_SB.PCI0.SBRG.EC0.CCI0))
>     \_SB.PCI0.SBRG.EC0.ECWT (Zero, RefOf (\_SB.PCI0.SBRG.EC0.CCI3))
> 
> I don't know why this is present. This does not cause the problem,
> however, only leads to issues if two explicit reads are performed
> consecutively. What does cause problems with the current driver
> implementation is:
> 
> 2. The event handler (_Q79)
> 
> The _Q79 event handler on my machine is responsible for the UCSI
> notifications. It performs a copy from EC RAM to system memory and
> triggers the 0x80 notification on the UCSI device (called UBTC).
> The final instructions of this handler are:
> 
>     [...]
>     ^^^^UBTC.CCI0 = CCI0 /* \_SB_.PCI0.SBRG.EC0_.CCI0 */
>     ^^^^UBTC.CCI1 = CCI1 /* \_SB_.PCI0.SBRG.EC0_.CCI1 */
>     ^^^^UBTC.CCI2 = CCI2 /* \_SB_.PCI0.SBRG.EC0_.CCI2 */
>     ^^^^UBTC.CCI3 = CCI3 /* \_SB_.PCI0.SBRG.EC0_.CCI3 */
>     USGC = 0xF1
>     CCI0 = Zero // These two lines are the culprit
>     CCI3 = Zero
>     Local1 = ((Timer - Local0) / 0x2710)
>     Notify (UBTC, 0x80) // Status Change
>     Release (ECMT)
> 
> 
> A side note:
> I figured this out by booting up a Windows installation and convincing
> the local kernel debugger to dump ACPI trace information to a file. The file
> contained an outrageous amount of information with inconsistent formatting
> (missing commas and stuff) for which I wrote an extremely janky parser in
> Python. This let me examine the exact steps performed by the Windows driver.
> And the difference I noticed is that the Linux driver was issuing a
> _DSM(read)
> after every notification, reading the already-zeroed-out CCI.
> 
> Patching the AML to remove the zeroing-out instructions seemed to work as
> well, but I suppose this is not a good general solution.
> 
> Following is a prototype-grade patch, in essence performing soft-reads most
> of
> the time (i.e. just reading from the OpRegion and not calling _DSM) and
> explicit
> reads when necessary. I am unfortunately not familiar with the spec and the
> hardware in the wild and I understand that it is possible that some devices
> on
> the other hand do not synchronize the mailbox when notifying and it needs to
> be
> done explicitly. I suppose we'd need a parameter to configure this behaviour
> in
> that case with a quirk system. The patch works on my system. Some other
> issues
> surface later, but I think they are related to a particular cheap dongle I
> have
> because they don't seem to occur without it.
> 
> What do you think about this situation? Is the patch reasonable, or does it
> need
> a significant re-think?

This is great! Thank you so much for figuring this one out!

I think your patch looks totally reasonable, but let me test it with
a couple of different systems that I have. I'll check the event
handlers from the ACPI tables. If that is how Windows works in
general, then this is what has to be done.

Thanks!

> From 45a29c149a29da989fbdd843c7f040a4454c3a33 Mon Sep 17 00:00:00 2001
> From: =?UTF-8?q?Samuel=20=C4=8Cavoj?= <samuel@cavoj.net>
> Date: Fri, 11 Nov 2022 00:06:24 +0100
> Subject: [PATCH] TODO: ucsi: introduce read_explicit
> MIME-Version: 1.0
> Content-Type: text/plain; charset=UTF-8
> Content-Transfer-Encoding: 8bit
> 
> Signed-off-by: Samuel Čavoj <samuel@cavoj.net>
> ---
>  drivers/usb/typec/ucsi/ucsi.c         |  9 +++++----
>  drivers/usb/typec/ucsi/ucsi.h         |  3 +++
>  drivers/usb/typec/ucsi/ucsi_acpi.c    | 11 +++++++++++
>  drivers/usb/typec/ucsi/ucsi_ccg.c     |  1 +
>  drivers/usb/typec/ucsi/ucsi_stm32g0.c |  1 +
>  5 files changed, 21 insertions(+), 4 deletions(-)
> 
> diff --git a/drivers/usb/typec/ucsi/ucsi.c b/drivers/usb/typec/ucsi/ucsi.c
> index e690fa50ffce..c2fce8b27821 100644
> --- a/drivers/usb/typec/ucsi/ucsi.c
> +++ b/drivers/usb/typec/ucsi/ucsi.c
> @@ -884,7 +884,7 @@ static int ucsi_reset_ppm(struct ucsi *ucsi)
>  			goto out;
>  		}
> 
> -		ret = ucsi->ops->read(ucsi, UCSI_CCI, &cci, sizeof(cci));
> +		ret = ucsi->ops->read_explicit(ucsi, UCSI_CCI, &cci, sizeof(cci));
>  		if (ret)
>  			goto out;
> 
> @@ -1351,7 +1351,8 @@ struct ucsi *ucsi_create(struct device *dev, const
> struct ucsi_operations *ops)
>  {
>  	struct ucsi *ucsi;
> 
> -	if (!ops || !ops->read || !ops->sync_write || !ops->async_write)
> +	if (!ops || !ops->read || !ops->read_explicit || !ops->sync_write ||
> +	    !ops->async_write)
>  		return ERR_PTR(-EINVAL);
> 
>  	ucsi = kzalloc(sizeof(*ucsi), GFP_KERNEL);
> @@ -1385,8 +1386,8 @@ int ucsi_register(struct ucsi *ucsi)
>  {
>  	int ret;
> 
> -	ret = ucsi->ops->read(ucsi, UCSI_VERSION, &ucsi->version,
> -			      sizeof(ucsi->version));
> +	ret = ucsi->ops->read_explicit(ucsi, UCSI_VERSION, &ucsi->version,
> +				       sizeof(ucsi->version));
>  	if (ret)
>  		return ret;
> 
> diff --git a/drivers/usb/typec/ucsi/ucsi.h b/drivers/usb/typec/ucsi/ucsi.h
> index 8eb391e3e592..e961ec1f92a0 100644
> --- a/drivers/usb/typec/ucsi/ucsi.h
> +++ b/drivers/usb/typec/ucsi/ucsi.h
> @@ -37,6 +37,7 @@ struct ucsi_altmode;
>  /**
>   * struct ucsi_operations - UCSI I/O operations
>   * @read: Read operation
> + * @read_explicit: Read operation with explicit poll if applicable
>   * @sync_write: Blocking write operation
>   * @async_write: Non-blocking write operation
>   * @update_altmodes: Squashes duplicate DP altmodes
> @@ -48,6 +49,8 @@ struct ucsi_altmode;
>  struct ucsi_operations {
>  	int (*read)(struct ucsi *ucsi, unsigned int offset,
>  		    void *val, size_t val_len);
> +	int (*read_explicit)(struct ucsi *ucsi, unsigned int offset,
> +			     void *val, size_t val_len);
>  	int (*sync_write)(struct ucsi *ucsi, unsigned int offset,
>  			  const void *val, size_t val_len);
>  	int (*async_write)(struct ucsi *ucsi, unsigned int offset,
> diff --git a/drivers/usb/typec/ucsi/ucsi_acpi.c
> b/drivers/usb/typec/ucsi/ucsi_acpi.c
> index a0cd8c4ebe31..20432f4313c9 100644
> --- a/drivers/usb/typec/ucsi/ucsi_acpi.c
> +++ b/drivers/usb/typec/ucsi/ucsi_acpi.c
> @@ -52,6 +52,16 @@ static int ucsi_acpi_read(struct ucsi *ucsi, unsigned int
> offset,
>  			  void *val, size_t val_len)
>  {
>  	struct ucsi_acpi *ua = ucsi_get_drvdata(ucsi);
> +
> +	memcpy(val, ua->base + offset, val_len);
> +
> +	return 0;
> +}
> +
> +static int ucsi_acpi_read_explicit(struct ucsi *ucsi, unsigned int offset,
> +				   void *val, size_t val_len)
> +{
> +	struct ucsi_acpi *ua = ucsi_get_drvdata(ucsi);
>  	int ret;
> 
>  	ret = ucsi_acpi_dsm(ua, UCSI_DSM_FUNC_READ);
> @@ -101,6 +111,7 @@ static int ucsi_acpi_sync_write(struct ucsi *ucsi,
> unsigned int offset,
> 
>  static const struct ucsi_operations ucsi_acpi_ops = {
>  	.read = ucsi_acpi_read,
> +	.read_explicit = ucsi_acpi_read_explicit,
>  	.sync_write = ucsi_acpi_sync_write,
>  	.async_write = ucsi_acpi_async_write
>  };
> diff --git a/drivers/usb/typec/ucsi/ucsi_ccg.c
> b/drivers/usb/typec/ucsi/ucsi_ccg.c
> index 5c0bf48be766..c1d2db3a7363 100644
> --- a/drivers/usb/typec/ucsi/ucsi_ccg.c
> +++ b/drivers/usb/typec/ucsi/ucsi_ccg.c
> @@ -593,6 +593,7 @@ static int ucsi_ccg_sync_write(struct ucsi *ucsi,
> unsigned int offset,
> 
>  static const struct ucsi_operations ucsi_ccg_ops = {
>  	.read = ucsi_ccg_read,
> +	.read_explicit = ucsi_ccg_read,
>  	.sync_write = ucsi_ccg_sync_write,
>  	.async_write = ucsi_ccg_async_write,
>  	.update_altmodes = ucsi_ccg_update_altmodes
> diff --git a/drivers/usb/typec/ucsi/ucsi_stm32g0.c
> b/drivers/usb/typec/ucsi/ucsi_stm32g0.c
> index 061551d464f1..274b5f016dfb 100644
> --- a/drivers/usb/typec/ucsi/ucsi_stm32g0.c
> +++ b/drivers/usb/typec/ucsi/ucsi_stm32g0.c
> @@ -437,6 +437,7 @@ static irqreturn_t ucsi_stm32g0_irq_handler(int irq,
> void *data)
> 
>  static const struct ucsi_operations ucsi_stm32g0_ops = {
>  	.read = ucsi_stm32g0_read,
> +	.read_explicit = ucsi_stm32g0_read,
>  	.sync_write = ucsi_stm32g0_sync_write,
>  	.async_write = ucsi_stm32g0_async_write,
>  };

Br,

-- 
heikki

Re: How to proceed: usci_acpi: PPM init failed (-110)

[Heikki Krogerus]

On Mon, Jan 02, 2023 at 12:09:19PM +0200, Heikki Krogerus wrote:
> Hi Sam,
> 
> Sorry to keep you waiting.
> 
> On Thu, Dec 22, 2022 at 09:18:27PM +0100, Samuel Čavoj wrote:
> > Hi Heikki,
> > 
> > I gave this a hard look and figured out the issue. Long story short, the
> > firmware is clearing the CCI on EC RAM after copying from EC RAM to
> > system memory. This happens both when notifications are delivered and
> > when a read operation is explicitly performed via _DSM(read). What the
> > driver currently does after receiving a notification is performing an
> > explicit read. However by this time the CCI in EC RAM has been cleared
> > by the AML and the information is lost.
> > 
> > Details:
> > 
> > 1. _DSM(read) of the UCSI device:
> > 
> > Copies all relevant fields of the mailbox data structure from EC RAM
> > to a SystemMemory OperationRegion. The last field to be copied is the
> > CCI:
> > 
> >     [...]
> >     CCI0 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI0))
> >     CCI1 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI1))
> >     CCI2 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI2))
> >     CCI3 = \_SB.PCI0.SBRG.EC0.ECRD (RefOf (\_SB.PCI0.SBRG.EC0.CCI3))
> >     [...]
> > 
> > However, for some reason, this is followed by another two operations,
> > which zero-out half of the CCI:
> > 
> >     [...]
> >     \_SB.PCI0.SBRG.EC0.ECWT (Zero, RefOf (\_SB.PCI0.SBRG.EC0.CCI0))
> >     \_SB.PCI0.SBRG.EC0.ECWT (Zero, RefOf (\_SB.PCI0.SBRG.EC0.CCI3))
> > 
> > I don't know why this is present. This does not cause the problem,
> > however, only leads to issues if two explicit reads are performed
> > consecutively. What does cause problems with the current driver
> > implementation is:
> > 
> > 2. The event handler (_Q79)
> > 
> > The _Q79 event handler on my machine is responsible for the UCSI
> > notifications. It performs a copy from EC RAM to system memory and
> > triggers the 0x80 notification on the UCSI device (called UBTC).
> > The final instructions of this handler are:
> > 
> >     [...]
> >     ^^^^UBTC.CCI0 = CCI0 /* \_SB_.PCI0.SBRG.EC0_.CCI0 */
> >     ^^^^UBTC.CCI1 = CCI1 /* \_SB_.PCI0.SBRG.EC0_.CCI1 */
> >     ^^^^UBTC.CCI2 = CCI2 /* \_SB_.PCI0.SBRG.EC0_.CCI2 */
> >     ^^^^UBTC.CCI3 = CCI3 /* \_SB_.PCI0.SBRG.EC0_.CCI3 */
> >     USGC = 0xF1
> >     CCI0 = Zero // These two lines are the culprit
> >     CCI3 = Zero
> >     Local1 = ((Timer - Local0) / 0x2710)
> >     Notify (UBTC, 0x80) // Status Change
> >     Release (ECMT)
> > 
> > 
> > A side note:
> > I figured this out by booting up a Windows installation and convincing
> > the local kernel debugger to dump ACPI trace information to a file. The file
> > contained an outrageous amount of information with inconsistent formatting
> > (missing commas and stuff) for which I wrote an extremely janky parser in
> > Python. This let me examine the exact steps performed by the Windows driver.
> > And the difference I noticed is that the Linux driver was issuing a
> > _DSM(read)
> > after every notification, reading the already-zeroed-out CCI.
> > 
> > Patching the AML to remove the zeroing-out instructions seemed to work as
> > well, but I suppose this is not a good general solution.
> > 
> > Following is a prototype-grade patch, in essence performing soft-reads most
> > of
> > the time (i.e. just reading from the OpRegion and not calling _DSM) and
> > explicit
> > reads when necessary. I am unfortunately not familiar with the spec and the
> > hardware in the wild and I understand that it is possible that some devices
> > on
> > the other hand do not synchronize the mailbox when notifying and it needs to
> > be
> > done explicitly. I suppose we'd need a parameter to configure this behaviour
> > in
> > that case with a quirk system. The patch works on my system. Some other
> > issues
> > surface later, but I think they are related to a particular cheap dongle I
> > have
> > because they don't seem to occur without it.
> > 
> > What do you think about this situation? Is the patch reasonable, or does it
> > need
> > a significant re-think?
> 
> This is great! Thank you so much for figuring this one out!
> 
> I think your patch looks totally reasonable, but let me test it with
> a couple of different systems that I have. I'll check the event
> handlers from the ACPI tables. If that is how Windows works in
> general, then this is what has to be done.

I did not manage to test all the boards that I was hoping to test, but
I think we could move forward with this. Can you format the patch
properly and send it to this mailing list?

thanks,

-- 
heikki