On Wed, Feb 05, 2025 at 02:26:07PM +0100, Michal Suchánek wrote:
> On Fri, Jan 31, 2025 at 09:31:30PM +0200, Jarkko Sakkinen wrote:
> > On Fri Jan 31, 2025 at 7:28 PM EET, Michal Suchánek wrote:
> > > On Fri, Jan 31, 2025 at 07:12:06PM +0200, Jarkko Sakkinen wrote:
> > > > On Fri Jan 31, 2025 at 3:02 PM EET, Michal Suchánek wrote:
> > > > > It looks like the timeout_b is used exclusively as the ready timeout *),
> > > > > with various sources of the value depending on chip type.
> > > > >
> > > > > Then increasing it should not cause any problem other than the kernel
> > > > > waiting longer when the TPM chip is really stuck.
> > > > >
> > > > > * There is one instance of use of timeout_b for TPM_STS_VALID in
> > > > > st33zp24_pm_resume.
> > > >
> > > > Possible for you to give a shot for patch and try it out for a while?
> > > > I'm fine with 2x, or even 4x in this case.
> > >
> > > I will see what I can do. It will definitely take a while.
> > >
> > > How would you like to multiply it?
> > >
> > > At the sime the timeout_b is assigned, or at the time it's used?
> > >
> > > Any specific patch that you have in mind?
> >
> > I'll think about this a bit and send a patch with RFC tag. Might take
> > to late next week.
>
> The ready timeout is not the only one exceeded:
>
> > Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2232 of 2000 ms)
> > Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2232 of 2000 ms)
> > Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2228 of 2000 ms)
> > Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2228 of 2000 ms)
> > Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms)
> > Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms)
> > Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (2224 of 200 ms)
> > Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (2224 of 200 ms)
> > Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2228 of 2000 ms)
> > Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2228 of 2000 ms)
> > Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (556 of 200 ms)
> > Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (556 of 200 ms)
> > Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms)
> > Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms)
> > Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Timed out (272 of 200 ms)
> > Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Took (272 of 200 ms)
> > Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms)
> > Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms)
> > Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2236 of 2000 ms)
> > Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2236 of 2000 ms)
> > Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms)
> > Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms)
> > Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms)
> > Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms)
> > Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (540 of 200 ms)
> > Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (540 of 200 ms)
>
> While the ready timeout is quite consistently exceeded by around 230ms
> so far the stat timeout a few lines lower is less consistent.
>
> Failure is observed with another chip type as well:
>
> localhost kernel: tpm_tis MSFT0101:00: 2.0 TPM (device-id 0x1B, rev-id
> 22)
>
> TPM Device
> Vendor ID: IFX
> Specification Version: 2.0
> Firmware Revision: 7.83
> Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0
> Characteristics:
> Family configurable via firmware update
> Family configurable via OEM proprietary mechanism
> OEM-specific Information: 0x00000000
Also adding the patch for reference.
Thanks
Michal
diff --git a/drivers/char/tpm/tpm_tis_core.c b/drivers/char/tpm/tpm_tis_core.c
index fdef214b9f6b..05ae815dd132 100644
--- a/drivers/char/tpm/tpm_tis_core.c
+++ b/drivers/char/tpm/tpm_tis_core.c
@@ -432,19 +432,29 @@ static int tpm_tis_recv(struct tpm_chip *chip, u8 *buf, size_t count)
static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)
{
struct tpm_tis_data *priv = dev_get_drvdata(&chip->dev);
+ u32 ordinal = be32_to_cpu(*((__be32 *) (buf + 6)));
int rc, status, burstcnt;
size_t count = 0;
bool itpm = test_bit(TPM_TIS_ITPM_WORKAROUND, &priv->flags);
+ unsigned long start, timed_out;
status = tpm_tis_status(chip);
if ((status & TPM_STS_COMMAND_READY) == 0) {
tpm_tis_ready(chip);
+ timed_out = 0; start = jiffies;
+retry_ready:
if (wait_for_tpm_stat
(chip, TPM_STS_COMMAND_READY, chip->timeout_b,
&priv->int_queue, false) < 0) {
+ if (timed_out++ < 2) {
+ dev_err(&chip->dev, "%s: %u: ready: Timed out (%u of %u ms)\n", __func__, ordinal, jiffies_to_msecs(jiffies - start), jiffies_to_msecs(chip->timeout_b));
+ goto retry_ready;
+ }
rc = -ETIME;
goto out_err;
}
+ if (timed_out)
+ dev_err(&chip->dev, "%s: %u: ready: Took (%u of %u ms)\n", __func__, ordinal, jiffies_to_msecs(jiffies - start), jiffies_to_msecs(chip->timeout_b));
}
while (count < len - 1) {
@@ -479,11 +489,19 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)
if (rc < 0)
goto out_err;
+ timed_out = 0; start = jiffies;
+retry_stat:
if (wait_for_tpm_stat(chip, TPM_STS_VALID, chip->timeout_c,
&priv->int_queue, false) < 0) {
+ if (timed_out++ < 5) {
+ dev_err(&chip->dev, "%s: %u: stat: Timed out (%u of %u ms)\n", __func__, ordinal, jiffies_to_msecs(jiffies - start), jiffies_to_msecs(chip->timeout_c));
+ goto retry_stat;
+ }
rc = -ETIME;
goto out_err;
}
+ if (timed_out)
+ dev_err(&chip->dev, "%s: %u: stat: Took (%u of %u ms)\n", __func__, ordinal, jiffies_to_msecs(jiffies - start), jiffies_to_msecs(chip->timeout_c));
status = tpm_tis_status(chip);
if (!itpm && (status & TPM_STS_DATA_EXPECT) != 0) {
rc = -EIO;
--
2.47.1
