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

Valdis.Kletnieks
2007-07-27T04:00:52Z

[-- Attachment #1.1: Type: text/plain, Size: 1567 bytes --]

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)?

[-- Attachment #1.2: debug.22-rc6-mm1 --]
[-- Type: text/plain , Size: 8092 bytes --]

[ 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

[-- Attachment #1.3: debug.rc1-a --]
[-- Type: text/plain , Size: 2395 bytes --]

[ 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

[-- Attachment #1.4: debug.rc1-b --]
[-- Type: text/plain , Size: 2377 bytes --]

[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

[-- Attachment #1.5: debug.patch --]
[-- Type: application/x-patch , Size: 3487 bytes --]

[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]