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

["Samuel Čavoj" <samuel@cavoj.net>]

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