Re: 2.6.23-rc1-mm1 - seems OK on Dell Latitude D820, except for tpm_tis

From: Valdis . Kletnieks
Date: Fri Jul 27 2007 - 00:01:05 EST

On Wed, 25 Jul 2007 20:37:37 PDT, Andrew Morton said:

> I can't imagine what we did to break tpm_tis, sorry. Nothing has changed
> in there for ages.
>
> Perhaps something broke at the bus level. It would be useful to add

OK, so I made a more intrusive printk-all-over patch to track what it was
doing, and got several tests in under 2.6.22-rc6-mm1 and 2.6.23-rc1-mm1.

I've attached:

debug.22-rc6-mm1 - things apparently working under the previous kernel.
debug.rc1-a - this one complained but didn't time out for long times. I've
only seen 23-rc1-mm1 *not* take timeouts this one time. Oddness.
debug.rc1-b - this one complained, and took 2 120-second waits
debug.patch - the printf's I added, for those who want to follow along..

Apparently, things go pear-shaped in tis_tpm_send(), when they get to the
'if (chip->vendor.irq)' - under 22-rc6-mm1, we never got into this code,
because earlier initialization complained it couldn't get IRQ8. Now, we
get IRQ3, and apparently get into this if statement, and then spend 120
seconds while wait_for_stat() times out. So the root cause does look like
it's this IRQ8/IRQ3 issue.

I'll try to find time to do a bisect on -rc1-mm1 tomorrow to track down
what exactly did this.

(And remember to keep in mind the very real possibility that in fact, both
releases are broken in different ways - I've never actually *done* anything
with the chip further than "the driver loads". Anybody got a very basic
userspace program to test-harness /dev/tpm0 (open, do a few test calls, close)?
[ 32.324000] tpm_tis_pnp_init: start=4275306496, len=20480
[ 32.324000] tpm_tis 00:0f: 1.2 TPM (device-id 0x1001, rev-id 2)
[ 32.324000] tpm_tis 00:0f: TPM interface capabilities (0x97):
[ 32.324000] tpm_tis 00:0f: Command Ready Int Support
[ 32.324000] tpm_tis 00:0f: Interrupt Level Low
[ 32.324000] tpm_tis 00:0f: Locality Change Int Support
[ 32.324000] tpm_tis 00:0f: Sts Valid Int Support
[ 32.324000] tpm_tis 00:0f: Data Avail Int Support
[ 32.324000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.324000] tis_send ready_for_command
[ 32.324000] tis_send wait for tis_ready
[ 32.330000] tis_send ready to go
[ 32.330000] tis_send after iowrite8 loop
[ 32.330000] tis_send after second wait_for_stat
[ 32.330000] tis_send after second tis_status
[ 32.330000] tis_send after last iowrite8
[ 32.330000] tis_send after 3rd wait_for_stat
[ 32.330000] tis_send after 3rd tis_status
[ 32.330000] tis_send after STS_GO
[ 32.336000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.336000] tis_send ready_for_command
[ 32.336000] tis_send wait for tis_ready
[ 32.342000] tis_send ready to go
[ 32.342000] tis_send after iowrite8 loop
[ 32.342000] tis_send after second wait_for_stat
[ 32.342000] tis_send after second tis_status
[ 32.342000] tis_send after last iowrite8
[ 32.342000] tis_send after 3rd wait_for_stat
[ 32.342000] tis_send after 3rd tis_status
[ 32.342000] tis_send after STS_GO
[ 32.348000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.348000] tis_send ready_for_command
[ 32.348000] tis_send wait for tis_ready
[ 32.354000] tis_send ready to go
[ 32.354000] tis_send after iowrite8 loop
[ 32.354000] tis_send after second wait_for_stat
[ 32.354000] tis_send after second tis_status
[ 32.354000] tis_send after last iowrite8
[ 32.354000] tis_send after 3rd wait_for_stat
[ 32.354000] tis_send after 3rd tis_status
[ 32.354000] tis_send after STS_GO
[ 32.360000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.360000] tis_send ready_for_command
[ 32.360000] tis_send wait for tis_ready
[ 32.366000] tis_send ready to go
[ 32.366000] tis_send after iowrite8 loop
[ 32.366000] tis_send after second wait_for_stat
[ 32.366000] tis_send after second tis_status
[ 32.366000] tis_send after last iowrite8
[ 32.366000] tis_send after 3rd wait_for_stat
[ 32.366000] tis_send after 3rd tis_status
[ 32.366000] tis_send after STS_GO
[ 32.372000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.372000] tis_send ready_for_command
[ 32.372000] tis_send wait for tis_ready
[ 32.378000] tis_send ready to go
[ 32.378000] tis_send after iowrite8 loop
[ 32.378000] tis_send after second wait_for_stat
[ 32.378000] tis_send after second tis_status
[ 32.378000] tis_send after last iowrite8
[ 32.378000] tis_send after 3rd wait_for_stat
[ 32.378000] tis_send after 3rd tis_status
[ 32.378000] tis_send after STS_GO
[ 32.384000] tpm_tis 00:0f: Unable to request irq: 8 for probe
[ 32.384000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.384000] tis_send ready_for_command
[ 32.384000] tis_send wait for tis_ready
[ 32.390000] tis_send ready to go
[ 32.390000] tis_send after iowrite8 loop
[ 32.390000] tis_send after second wait_for_stat
[ 32.390000] tis_send after second tis_status
[ 32.390000] tis_send after last iowrite8
[ 32.390000] tis_send after 3rd wait_for_stat
[ 32.390000] tis_send after 3rd tis_status
[ 32.390000] tis_send after STS_GO
[ 32.396000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.396000] tis_send ready_for_command
[ 32.396000] tis_send wait for tis_ready
[ 32.402000] tis_send ready to go
[ 32.402000] tis_send after iowrite8 loop
[ 32.402000] tis_send after second wait_for_stat
[ 32.402000] tis_send after second tis_status
[ 32.402000] tis_send after last iowrite8
[ 32.402000] tis_send after 3rd wait_for_stat
[ 32.402000] tis_send after 3rd tis_status
[ 32.402000] tis_send after STS_GO
[ 32.408000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.408000] tis_send ready_for_command
[ 32.408000] tis_send wait for tis_ready
[ 32.414000] tis_send ready to go
[ 32.414000] tis_send after iowrite8 loop
[ 32.414000] tis_send after second wait_for_stat
[ 32.414000] tis_send after second tis_status
[ 32.414000] tis_send after last iowrite8
[ 32.414000] tis_send after 3rd wait_for_stat
[ 32.414000] tis_send after 3rd tis_status
[ 32.414000] tis_send after STS_GO
[ 32.420000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.420000] tis_send ready_for_command
[ 32.420000] tis_send wait for tis_ready
[ 32.426000] tis_send ready to go
[ 32.426000] tis_send after iowrite8 loop
[ 32.426000] tis_send after second wait_for_stat
[ 32.426000] tis_send after second tis_status
[ 32.426000] tis_send after last iowrite8
[ 32.426000] tis_send after 3rd wait_for_stat
[ 32.426000] tis_send after 3rd tis_status
[ 32.426000] tis_send after STS_GO
[ 32.432000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.432000] tis_send ready_for_command
[ 32.432000] tis_send wait for tis_ready
[ 32.438000] tis_send ready to go
[ 32.438000] tis_send after iowrite8 loop
[ 32.438000] tis_send after second wait_for_stat
[ 32.438000] tis_send after second tis_status
[ 32.438000] tis_send after last iowrite8
[ 32.438000] tis_send after 3rd wait_for_stat
[ 32.438000] tis_send after 3rd tis_status
[ 32.438000] tis_send after STS_GO
[ 32.444000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.444000] tis_send ready_for_command
[ 32.444000] tis_send wait for tis_ready
[ 32.450000] tis_send ready to go
[ 32.450000] tis_send after iowrite8 loop
[ 32.450000] tis_send after second wait_for_stat
[ 32.450000] tis_send after second tis_status
[ 32.450000] tis_send after last iowrite8
[ 32.450000] tis_send after 3rd wait_for_stat
[ 32.450000] tis_send after 3rd tis_status
[ 32.450000] tis_send after STS_GO
[ 32.456000] in tpm_tis_send buffer=18446604435840957488 len=22
[ 32.456000] tis_send ready_for_command
[ 32.456000] tis_send wait for tis_ready
[ 32.462000] tis_send ready to go
[ 32.462000] tis_send after iowrite8 loop
[ 32.462000] tis_send after second wait_for_stat
[ 32.462000] tis_send after second tis_status
[ 32.462000] tis_send after last iowrite8
[ 32.462000] tis_send after 3rd wait_for_stat
[ 32.462000] tis_send after 3rd tis_status
[ 32.462000] tis_send after STS_GO
[ 32.468000] in tpm_tis_send buffer=18446604435840957472 len=22
[ 32.468000] tis_send ready_for_command
[ 32.468000] tis_send wait for tis_ready
[ 32.474000] tis_send ready to go
[ 32.474000] tis_send after iowrite8 loop
[ 32.474000] tis_send after second wait_for_stat
[ 32.474000] tis_send after second tis_status
[ 32.474000] tis_send after last iowrite8
[ 32.474000] tis_send after 3rd wait_for_stat
[ 32.474000] tis_send after 3rd tis_status
[ 32.474000] tis_send after STS_GO
[ 32.480000] in tpm_tis_send buffer=18446604435840957472 len=22
[ 32.480000] tis_send ready_for_command
[ 32.480000] tis_send wait for tis_ready
[ 32.486000] tis_send ready to go
[ 32.486000] tis_send after iowrite8 loop
[ 32.486000] tis_send after second wait_for_stat
[ 32.486000] tis_send after second tis_status
[ 32.486000] tis_send after last iowrite8
[ 32.486000] tis_send after 3rd wait_for_stat
[ 32.486000] tis_send after 3rd tis_status
[ 32.486000] tis_send after STS_GO
[ 32.492000] in tpm_tis_send buffer=18446604435840957528 len=10
[ 32.492000] tis_send ready_for_command
[ 32.492000] tis_send wait for tis_ready
[ 32.498000] tis_send ready to go
[ 32.498000] tis_send after iowrite8 loop
[ 32.498000] tis_send after second wait_for_stat
[ 32.498000] tis_send after second tis_status
[ 32.498000] tis_send after last iowrite8
[ 32.498000] tis_send after 3rd wait_for_stat
[ 32.498000] tis_send after 3rd tis_status
[ 32.498000] tis_send after STS_GO
[ 1357.392943] tpm_tis_pnp_init: start=4275306496, len=20480
[ 1357.394579] SELinux: initialized (dev securityfs, type securityfs), not configured for labeling
[ 1357.394615] tpm_tis 00:0f: 1.2 TPM (device-id 0x1001, rev-id 2)
[ 1357.394620] tpm_tis 00:0f: TPM interface capabilities (0x97):
[ 1357.394622] tpm_tis 00:0f: Command Ready Int Support
[ 1357.394624] tpm_tis 00:0f: Interrupt Level Low
[ 1357.394625] tpm_tis 00:0f: Locality Change Int Support
[ 1357.394627] tpm_tis 00:0f: Sts Valid Int Support
[ 1357.394628] tpm_tis 00:0f: Data Avail Int Support
[ 1357.394652] tpm0 (IRQ 3) handled a spurious interrupt
[ 1357.394669] in tpm_tis_send buffer=18446604435799350304 len=22
[ 1357.394675] tis_send ready_for_command
[ 1357.394677] tis_send wait for tis_ready
[ 1357.394680] tis_send ready to go
[ 1357.394696] tis_send after iowrite8 loop
[ 1357.394701] tis_send after second wait_for_stat
[ 1357.394704] tis_send after second tis_status
[ 1357.394705] tis_send after last iowrite8
[ 1357.394709] tis_send after 3rd wait_for_stat
[ 1357.394712] tis_send after 3rd tis_status
[ 1357.394713] tis_send after STS_GO
[ 1357.394714] tis_send before last wait_for_stat
[ 1358.966290] in tpm_tis_send buffer=18446604435799350304 len=22
[ 1358.966296] tis_send ready_for_command
[ 1358.966298] tis_send wait for tis_ready
[ 1358.966303] tis_send ready to go
[ 1358.966319] tis_send after iowrite8 loop
[ 1358.966324] tis_send after second wait_for_stat
[ 1358.966327] tis_send after second tis_status
[ 1358.966328] tis_send after last iowrite8
[ 1358.966331] tis_send after 3rd wait_for_stat
[ 1358.966334] tis_send after 3rd tis_status
[ 1358.966336] tis_send after STS_GO
[ 1358.966337] tis_send before last wait_for_stat
[ 1358.966345] tis_send after last wait_for_stat
[ 1358.966347] tis_send before last tis_ready
[ 1358.966348] tis_send after last tis_ready
[ 1358.966354] tis_send after release_locality
[ 1358.966357] tpm_tis 00:0f: tpm_transmit: tpm_send: error -62
[ 1358.966359] in tpm_tis_send buffer=18446604435799350360 len=10
[ 1358.966364] tis_send ready_for_command
[ 1358.966365] tis_send wait for tis_ready
[ 1358.966373] tis_send timed out waiting for command_ready
[ 1358.966374] tis_send before last tis_ready
[ 1358.966375] tis_send after last tis_ready
[ 1358.966379] tis_send after release_locality
[ 1358.966380] tpm_tis 00:0f: tpm_transmit: tpm_send: error -62
[20013.799019] tpm_tis_pnp_init: start=4275306496, len=20480
[20013.804544] tpm_tis 00:0f: 1.2 TPM (device-id 0x1001, rev-id 2)
[20013.804701] tpm_tis 00:0f: TPM interface capabilities (0x97):
[20013.804761] tpm_tis 00:0f: Command Ready Int Support
[20013.804820] tpm_tis 00:0f: Interrupt Level Low
[20013.804875] tpm_tis 00:0f: Locality Change Int Support
[20013.804948] tpm_tis 00:0f: Sts Valid Int Support
[20013.805005] tpm_tis 00:0f: Data Avail Int Support
[20013.805083] tpm0 (IRQ 3) handled a spurious interrupt
[20013.805203] in tpm_tis_send buffer=18446604435978689568 len=22
[20013.805267] tis_send ready to go
[20013.805334] tis_send after iowrite8 loop
[20013.805390] tis_send after second wait_for_stat
[20013.805446] tis_send after second tis_status
[20013.805499] tis_send after last iowrite8
[20013.805553] tis_send after 3rd wait_for_stat
[20013.805608] tis_send after 3rd tis_status
[20013.805661] tis_send after STS_GO
[20013.805712] tis_send before last wait_for_stat
[20133.740241] tis_send after last wait_for_stat
[20133.740251] tis_send before last tis_ready
[20133.740256] tis_send after last tis_ready
[20133.740261] tis_send after release_locality
[20133.740267] tpm_tis 00:0f: tpm_transmit: tpm_send: error -62
[20133.740274] in tpm_tis_send buffer=18446604435978689568 len=22
[20133.740282] tis_send ready_for_command
[20133.740285] tis_send wait for tis_ready
[20135.739111] tis_send timed out waiting for command_ready
[20135.739121] tis_send before last tis_ready
[20135.739127] tis_send after last tis_ready
[20135.739132] tis_send after release_locality
[20135.739138] tpm_tis 00:0f: tpm_transmit: tpm_send: error -62
[20135.739144] in tpm_tis_send buffer=18446604435978689624 len=10
[20135.739153] tis_send ready to go
[20135.739162] tis_send after iowrite8 loop
[20135.739167] tis_send after second wait_for_stat
[20135.739172] tis_send after second tis_status
[20135.739175] tis_send after last iowrite8
[20135.739179] tis_send after 3rd wait_for_stat
[20135.739184] tis_send after 3rd tis_status
[20135.739189] tis_send after STS_GO
[20135.739193] tis_send before last wait_for_stat
[20255.671378] tis_send after last wait_for_stat
[20255.671387] tis_send before last tis_ready
[20255.671394] tis_send after last tis_ready
[20255.671399] tis_send after release_locality
[20255.671405] tpm_tis 00:0f: tpm_transmit: tpm_send: error -62
--- linux-2.6.23-rc1-mm1/drivers/char/tpm/tpm_tis.c.tis-pim1 2007-07-08 19:32:17.000000000 -0400
+++ linux-2.6.23-rc1-mm1/drivers/char/tpm/tpm_tis.c 2007-07-26 17:51:35.000000000 -0400
@@ -16,6 +16,7 @@
* published by the Free Software Foundation, version 2 of the
* License.
*/
+#define DEBUG
#include <linux/init.h>
#include <linux/module.h>
#include <linux/moduleparam.h>
@@ -266,20 +267,25 @@ static int tpm_tis_send(struct tpm_chip
size_t count = 0;
u32 ordinal;

+printk(KERN_DEBUG "in tpm_tis_send buffer=%llu len=%d\n",buf,len);
if (request_locality(chip, 0) < 0)
return -EBUSY;

status = tpm_tis_status(chip);
if ((status & TPM_STS_COMMAND_READY) == 0) {
+printk(KERN_DEBUG "tis_send ready_for_command\n");
tpm_tis_ready(chip);
+printk(KERN_DEBUG "tis_send wait for tis_ready\n");
if (wait_for_stat
(chip, TPM_STS_COMMAND_READY, chip->vendor.timeout_b,
&chip->vendor.int_queue) < 0) {
+printk(KERN_DEBUG "tis_send timed out waiting for command_ready\n");
rc = -ETIME;
goto out_err;
}
}

+printk(KERN_DEBUG "tis_send ready to go\n");
while (count < len - 1) {
burstcnt = get_burstcount(chip);
for (; burstcnt > 0 && count < len - 1; burstcnt--) {
@@ -288,9 +294,12 @@ static int tpm_tis_send(struct tpm_chip
count++;
}

+printk(KERN_DEBUG "tis_send after iowrite8 loop\n");
wait_for_stat(chip, TPM_STS_VALID, chip->vendor.timeout_c,
&chip->vendor.int_queue);
+printk(KERN_DEBUG "tis_send after second wait_for_stat\n");
status = tpm_tis_status(chip);
+printk(KERN_DEBUG "tis_send after second tis_status\n");
if ((status & TPM_STS_DATA_EXPECT) == 0) {
rc = -EIO;
goto out_err;
@@ -301,9 +310,12 @@ static int tpm_tis_send(struct tpm_chip
iowrite8(buf[count],
chip->vendor.iobase +
TPM_DATA_FIFO(chip->vendor.locality));
+printk(KERN_DEBUG "tis_send after last iowrite8\n");
wait_for_stat(chip, TPM_STS_VALID, chip->vendor.timeout_c,
&chip->vendor.int_queue);
+printk(KERN_DEBUG "tis_send after 3rd wait_for_stat\n");
status = tpm_tis_status(chip);
+printk(KERN_DEBUG "tis_send after 3rd tis_status\n");
if ((status & TPM_STS_DATA_EXPECT) != 0) {
rc = -EIO;
goto out_err;
@@ -313,20 +325,26 @@ static int tpm_tis_send(struct tpm_chip
iowrite8(TPM_STS_GO,
chip->vendor.iobase + TPM_STS(chip->vendor.locality));

+printk(KERN_DEBUG "tis_send after STS_GO\n");
if (chip->vendor.irq) {
ordinal = be32_to_cpu(*((__be32 *) (buf + 6)));
+printk(KERN_DEBUG "tis_send before last wait_for_stat\n");
if (wait_for_stat
(chip, TPM_STS_DATA_AVAIL | TPM_STS_VALID,
tpm_calc_ordinal_duration(chip, ordinal),
&chip->vendor.read_queue) < 0) {
+printk(KERN_DEBUG "tis_send after last wait_for_stat\n");
rc = -ETIME;
goto out_err;
}
}
return len;
out_err:
+printk(KERN_DEBUG "tis_send before last tis_ready\n");
tpm_tis_ready(chip);
+printk(KERN_DEBUG "tis_send after last tis_ready\n");
release_locality(chip, chip->vendor.locality, 0);
+printk(KERN_DEBUG "tis_send after release_locality\n");
return rc;
}

@@ -595,9 +613,11 @@ static int __devinit tpm_tis_pnp_init(st
const struct pnp_device_id *pnp_id)
{
resource_size_t start, len;
+
start = pnp_mem_start(pnp_dev, 0);
len = pnp_mem_len(pnp_dev, 0);
-
+ printk(KERN_DEBUG "tpm_tis_pnp_init: start=%llu, len=%llu\n",
+ (unsigned long long)start, (unsigned long long)len);
return tpm_tis_init(&pnp_dev->dev, start, len);
}

Attachment: pgp00000.pgp
Description: PGP signature