Re: TPM operation times out (very rarely)

[Jonathan McDowell <noodles@earth.li>]

[-- Attachment #1: Type: text/plain, Size: 2051 bytes --]

On Fri, Feb 07, 2025 at 10:58:15AM +0100, Michal Suchánek wrote:
> On Fri, Feb 07, 2025 at 09:47:13AM +0000, Jonathan McDowell wrote:
> > On Fri, Feb 07, 2025 at 10:40:16AM +0100, Michal Suchánek wrote:
> > > On Fri, Feb 07, 2025 at 09:26:16AM +0000, Jonathan McDowell wrote:
> > > > So just to clarify, this more recent patch is working around a situation
> > > > where the status register gets stuck and needs a complete retry of the
> > > > command send - it's an Infineon errata, not something that would be
> > > > fixed with a longer timeout.
> > > > 
> > > > We see what looks like Michal's issue with timeouts as well, I just
> > > > haven't made the step of instrumenting it all the way he has.
> > > 
> > > And I haven't seen the issue that needs re-sending the command so far.
> > 
> > Your SLB9672 is on the latest firmware, which I believe fixes the
> > problem.
> > 
> > > Maybe it happens even less frequently than the excessive processing
> > > time.
> > > 
> > > Fully restarting the syscall would fix both issues but manual restart of
> > > the userspace task reportedly did not work so I have my doubts that
> > > this method with returning from the syscall would be effective.
> > 
> > Hmmm. I wonder if e3aaebcbb7c6b403416f442d1de70d437ce313a7 (tpm: Clean
> > up TPM space after command failure) would help the userspace restart
> 
> It's backported to the frankenkernel already so it would not help this
> particular case.
> 
> Unfortunately, it's not clear what the userspace task does, and why it
> would not complete after the first failure.
> 
> Would need to come up with some way of tracing it.

FWIW bpftrace is great for this. I'm using the attached script as a
basis for investigations. Obviously the timings it reports are the whole
command rather than just the wait for status, but over a long period it
can then show you the latency histogram. (Run it in one terminal, do TPM
stuff elsewhere, hit Ctrl-C when you're done and it dumps the
histogram.)

J.

-- 
101 things you can't have too much of : 47 - More coffee.

[-- Attachment #2: tpm-tracing.bt --]
[-- Type: text/plain, Size: 1040 bytes --]

#!/usr/bin/bpftrace

struct tpm_header {
        uint8_t tag[2];
        uint8_t length[4];
        uint8_t ordinal[4];
}
struct tpm_buf {
        uint32_t flags;
        uint32_t length;
        struct tpm_header *hdr;
}

kprobe:tpm_transmit_cmd
{
        $buf = (struct tpm_buf *) arg1;
        printf("%s (0x%02X%02X%02X%02X) (%s)\n", comm,
                $buf->hdr->ordinal[0],
                $buf->hdr->ordinal[1],
                $buf->hdr->ordinal[2],
                $buf->hdr->ordinal[3],
                str(arg3));
}

kprobe:tpm_transmit
{
        $hdr = (struct tpm_header *) arg1;
        $cmd = $hdr->ordinal[0] << 24 | $hdr->ordinal[1] << 16 |
                $hdr->ordinal[2] << 8 | $hdr->ordinal[3];
        @start[tid] = nsecs;
        @tpmcmd[tid] = $cmd;
}

kretprobe:tpm_transmit
/@start[tid]/ {
        $dur = nsecs - @start[tid];
        @cmdhist[@tpmcmd[tid]] = hist($dur);
        printf("%s (0x%08X): %d (%d ns)\n", comm, @tpmcmd[tid], retval, $dur);
        delete(@start[tid]);
        delete(@tpmcmd[tid]);
}