[PATCH v3 0/4] tpm: Command duration logging and chip-specific override

[PATCH v3 0/4] tpm: Command duration logging and chip-specific override

[Ed Swierk]

This series
- improves TPM command error reporting
- adds optional logging of TPM command durations
- allows chip-specific override of command durations, analogous
  to existing override of protocol timeouts
- overrides ST19NP18 TPM command duration to avoid lockups

Ed Swierk (4):
  tpm_tis: Improve reporting of IO errors
  tpm: Add optional logging of TPM command durations
  tpm: Allow TPM chip drivers to override reported command durations
  tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup

 drivers/char/tpm/tpm-interface.c | 60 ++++++++++++++++++++++++++--------------
 drivers/char/tpm/tpm_tis.c       | 52 +++++++++++++++++++++++++++++++++-
 include/linux/tpm.h              |  2 ++
 3 files changed, 92 insertions(+), 22 deletions(-)

-- 
1.9.1


------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

[PATCH v3 1/4] tpm_tis: Improve reporting of IO errors

[Ed Swierk]

Mysterious TPM behavior can be difficult to track down through all the
layers of software. Add error messages for conditions that should
never happen. Also include the manufacturer ID along with other chip
data printed during init.

Signed-off-by: Ed Swierk <eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org>
---
 drivers/char/tpm/tpm_tis.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/drivers/char/tpm/tpm_tis.c b/drivers/char/tpm/tpm_tis.c
index 65f7eec..088fa86 100644
--- a/drivers/char/tpm/tpm_tis.c
+++ b/drivers/char/tpm/tpm_tis.c
@@ -299,6 +299,8 @@ static int tpm_tis_recv(struct tpm_chip *chip, u8 *buf, size_t count)
 
 	expected = be32_to_cpu(*(__be32 *) (buf + 2));
 	if (expected > count) {
+		dev_err(chip->pdev, "Response too long (wanted %zd, got %d)\n",
+			count, expected);
 		size = -EIO;
 		goto out;
 	}
@@ -366,6 +368,8 @@ static int tpm_tis_send_data(struct tpm_chip *chip, u8 *buf, size_t len)
 				  &chip->vendor.int_queue, false);
 		status = tpm_tis_status(chip);
 		if (!itpm && (status & TPM_STS_DATA_EXPECT) == 0) {
+			dev_err(chip->pdev, "Chip not accepting %zd bytes\n",
+				len - count);
 			rc = -EIO;
 			goto out_err;
 		}
@@ -378,6 +382,7 @@ static int tpm_tis_send_data(struct tpm_chip *chip, u8 *buf, size_t len)
 			  &chip->vendor.int_queue, false);
 	status = tpm_tis_status(chip);
 	if ((status & TPM_STS_DATA_EXPECT) != 0) {
+		dev_err(chip->pdev, "Chip not accepting last byte\n");
 		rc = -EIO;
 		goto out_err;
 	}
@@ -689,8 +694,9 @@ static int tpm_tis_init(struct device *dev, struct tpm_info *tpm_info,
 	vendor = ioread32(chip->vendor.iobase + TPM_DID_VID(0));
 	chip->vendor.manufacturer_id = vendor;
 
-	dev_info(dev, "%s TPM (device-id 0x%X, rev-id %d)\n",
+	dev_info(dev, "%s TPM (manufacturer-id 0x%X, device-id 0x%X, rev-id %d)\n",
 		 (chip->flags & TPM_CHIP_FLAG_TPM2) ? "2.0" : "1.2",
+		 chip->vendor.manufacturer_id,
 		 vendor >> 16, ioread8(chip->vendor.iobase + TPM_RID(0)));
 
 	if (!itpm) {
-- 
1.9.1


------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

[PATCH v3 2/4] tpm: Add optional logging of TPM command durations

[Ed Swierk]

Some TPMs violate their own advertised command durations. This is much
easier to debug with data about how long each command actually takes
to complete. Add debug messages that can be enabled by running

  echo -n 'module tpm +p' >/sys/kernel/debug/dynamic_debug/control

on a kernel configured with DYNAMIC_DEBUG=y.

Signed-off-by: Ed Swierk <eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org>
---
 drivers/char/tpm/tpm-interface.c | 17 +++++++++++++----
 1 file changed, 13 insertions(+), 4 deletions(-)

diff --git a/drivers/char/tpm/tpm-interface.c b/drivers/char/tpm/tpm-interface.c
index c50637d..cc1e5bc 100644
--- a/drivers/char/tpm/tpm-interface.c
+++ b/drivers/char/tpm/tpm-interface.c
@@ -333,13 +333,14 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
 {
 	ssize_t rc;
 	u32 count, ordinal;
-	unsigned long stop;
+	unsigned long start, stop;
 
 	if (bufsiz > TPM_BUFSIZE)
 		bufsiz = TPM_BUFSIZE;
 
 	count = be32_to_cpu(*((__be32 *) (buf + 2)));
 	ordinal = be32_to_cpu(*((__be32 *) (buf + 6)));
+	dev_dbg(chip->pdev, "starting command %d count %d\n", ordinal, count);
 	if (count == 0)
 		return -ENODATA;
 	if (count > bufsiz) {
@@ -360,18 +361,24 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
 	if (chip->vendor.irq)
 		goto out_recv;
 
+	start = jiffies;
 	if (chip->flags & TPM_CHIP_FLAG_TPM2)
-		stop = jiffies + tpm2_calc_ordinal_duration(chip, ordinal);
+		stop = start + tpm2_calc_ordinal_duration(chip, ordinal);
 	else
-		stop = jiffies + tpm_calc_ordinal_duration(chip, ordinal);
+		stop = start + tpm_calc_ordinal_duration(chip, ordinal);
 	do {
 		u8 status = chip->ops->status(chip);
 		if ((status & chip->ops->req_complete_mask) ==
-		    chip->ops->req_complete_val)
+		    chip->ops->req_complete_val) {
+			dev_dbg(chip->pdev, "completed command %d in %d ms\n",
+				ordinal, jiffies_to_msecs(jiffies - start));
 			goto out_recv;
+		}
 
 		if (chip->ops->req_canceled(chip, status)) {
 			dev_err(chip->pdev, "Operation Canceled\n");
+			dev_dbg(chip->pdev, "canceled command %d after %d ms\n",
+				ordinal, jiffies_to_msecs(jiffies - start));
 			rc = -ECANCELED;
 			goto out;
 		}
@@ -382,6 +389,8 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
 
 	chip->ops->cancel(chip);
 	dev_err(chip->pdev, "Operation Timed out\n");
+	dev_dbg(chip->pdev, "command %d timed out after %d ms\n", ordinal,
+		jiffies_to_msecs(jiffies - start));
 	rc = -ETIME;
 	goto out;
 
-- 
1.9.1


------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

[PATCH v3 3/4] tpm: Allow TPM chip drivers to override reported command durations

[Ed Swierk]

Some TPM chips report bogus command durations in their capabilities,
just as others report incorrect timeouts. Add an update_durations()
function and an implementation for tpm_tis, and move the existing
BCM0102 workaround out of the common tpm_get_timeouts() code.

Signed-off-by: Ed Swierk <eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org>
---
 drivers/char/tpm/tpm-interface.c | 43 ++++++++++++++++++++++++----------------
 drivers/char/tpm/tpm_tis.c       | 40 +++++++++++++++++++++++++++++++++++++
 include/linux/tpm.h              |  2 ++
 3 files changed, 68 insertions(+), 17 deletions(-)

diff --git a/drivers/char/tpm/tpm-interface.c b/drivers/char/tpm/tpm-interface.c
index cc1e5bc..91332dd 100644
--- a/drivers/char/tpm/tpm-interface.c
+++ b/drivers/char/tpm/tpm-interface.c
@@ -507,7 +507,8 @@ int tpm_get_timeouts(struct tpm_chip *chip)
 	struct tpm_cmd_t tpm_cmd;
 	unsigned long new_timeout[4];
 	unsigned long old_timeout[4];
-	struct duration_t *duration_cap;
+	unsigned long new_duration[3];
+	unsigned long old_duration[3];
 	ssize_t rc;
 
 	tpm_cmd.header.in = tpm_getcap_header;
@@ -599,26 +600,34 @@ duration:
 	    != sizeof(tpm_cmd.header.out) + sizeof(u32) + 3 * sizeof(u32))
 		return -EINVAL;
 
-	duration_cap = &tpm_cmd.params.getcap_out.cap.duration;
+	old_duration[TPM_SHORT] =
+		be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_short);
+	old_duration[TPM_MEDIUM] =
+		be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_medium);
+	old_duration[TPM_LONG] =
+		be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_long);
+	memcpy(new_duration, old_duration, sizeof(new_duration));
+
+	if (chip->ops->update_durations != NULL)
+		chip->vendor.duration_adjusted =
+			chip->ops->update_durations(chip, new_duration);
+
+	/* Report adjusted durations */
+	if (chip->vendor.duration_adjusted) {
+		dev_info(chip->pdev,
+			 HW_ERR "Adjusting reported durations: short %lu->%luus medium %lu->%luus long %lu->%luus\n",
+			 old_duration[TPM_SHORT], new_duration[TPM_SHORT],
+			 old_duration[TPM_MEDIUM], new_duration[TPM_MEDIUM],
+			 old_duration[TPM_LONG], new_duration[TPM_LONG]);
+	}
+
 	chip->vendor.duration[TPM_SHORT] =
-	    usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_short));
+		usecs_to_jiffies(new_duration[TPM_SHORT]);
 	chip->vendor.duration[TPM_MEDIUM] =
-	    usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_medium));
+		usecs_to_jiffies(new_duration[TPM_MEDIUM]);
 	chip->vendor.duration[TPM_LONG] =
-	    usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_long));
+		usecs_to_jiffies(new_duration[TPM_LONG]);
 
-	/* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
-	 * value wrong and apparently reports msecs rather than usecs. So we
-	 * fix up the resulting too-small TPM_SHORT value to make things work.
-	 * We also scale the TPM_MEDIUM and -_LONG values by 1000.
-	 */
-	if (chip->vendor.duration[TPM_SHORT] < (HZ / 100)) {
-		chip->vendor.duration[TPM_SHORT] = HZ;
-		chip->vendor.duration[TPM_MEDIUM] *= 1000;
-		chip->vendor.duration[TPM_LONG] *= 1000;
-		chip->vendor.duration_adjusted = true;
-		dev_info(chip->pdev, "Adjusting TPM timeout parameters.");
-	}
 	return 0;
 }
 EXPORT_SYMBOL_GPL(tpm_get_timeouts);
diff --git a/drivers/char/tpm/tpm_tis.c b/drivers/char/tpm/tpm_tis.c
index 088fa86..3baba73 100644
--- a/drivers/char/tpm/tpm_tis.c
+++ b/drivers/char/tpm/tpm_tis.c
@@ -505,6 +505,45 @@ static bool tpm_tis_update_timeouts(struct tpm_chip *chip,
 	return false;
 }
 
+struct tis_vendor_duration_override {
+	u32 did_vid;
+	unsigned long duration_us[3];
+};
+
+static const struct tis_vendor_duration_override vendor_duration_overrides[] = {
+};
+
+static bool tpm_tis_update_durations(struct tpm_chip *chip,
+				     unsigned long *duration_cap)
+{
+	int i;
+	u32 did_vid;
+
+	did_vid = ioread32(chip->vendor.iobase + TPM_DID_VID(0));
+
+	for (i = 0; i != ARRAY_SIZE(vendor_duration_overrides); i++) {
+		if (vendor_duration_overrides[i].did_vid != did_vid)
+			continue;
+		memcpy(duration_cap, vendor_duration_overrides[i].duration_us,
+		       sizeof(vendor_duration_overrides[i].duration_us));
+		return true;
+	}
+
+	/* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
+	 * value wrong and apparently reports msecs rather than usecs. So we
+	 * fix up the resulting too-small TPM_SHORT value to make things work.
+	 * We also scale the TPM_MEDIUM and -_LONG values by 1000.
+	 */
+	if (duration_cap[TPM_SHORT] < (HZ / 100)) {
+		duration_cap[TPM_SHORT] = HZ;
+		duration_cap[TPM_MEDIUM] *= 1000;
+		duration_cap[TPM_LONG] *= 1000;
+		return true;
+	}
+
+	return false;
+}
+
 /*
  * Early probing for iTPM with STS_DATA_EXPECT flaw.
  * Try sending command without itpm flag set and if that
@@ -570,6 +609,7 @@ static const struct tpm_class_ops tpm_tis = {
 	.send = tpm_tis_send,
 	.cancel = tpm_tis_ready,
 	.update_timeouts = tpm_tis_update_timeouts,
+	.update_durations = tpm_tis_update_durations,
 	.req_complete_mask = TPM_STS_DATA_AVAIL | TPM_STS_VALID,
 	.req_complete_val = TPM_STS_DATA_AVAIL | TPM_STS_VALID,
 	.req_canceled = tpm_tis_req_canceled,
diff --git a/include/linux/tpm.h b/include/linux/tpm.h
index 706e63e..862d0a1 100644
--- a/include/linux/tpm.h
+++ b/include/linux/tpm.h
@@ -43,6 +43,8 @@ struct tpm_class_ops {
 	u8 (*status) (struct tpm_chip *chip);
 	bool (*update_timeouts)(struct tpm_chip *chip,
 				unsigned long *timeout_cap);
+	bool (*update_durations)(struct tpm_chip *chip,
+				unsigned long *duration_cap);
 
 };
 
-- 
1.9.1


------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

[PATCH v3 4/4] tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup

[Ed Swierk]

The STMicro ST19NP18-TPM sometimes takes much longer to execute
commands than it reports in its capabilities. For example, command 186
(TPM_FlushSpecific) has been observed to take 14560 msec to complete,
far longer than the 3000 msec limit for "short" commands reported by
the chip. The behavior has also been seen with command 101
(TPM_GetCapability).

Worse, when the tpm_tis driver attempts to cancel the current command
(by writing commandReady = 1 to TPM_STS_x), the chip locks up
completely, returning all-1s from all memory-mapped register
reads. The lockup can be cleared only by resetting the system.

The occurrence of this excessive command duration depends on the
sequence of commands preceding it. One sequence is creating at least 2
new keys via TPM_CreateWrapKey, then letting the TPM idle for at least
30 seconds, then loading a key via TPM_LoadKey2. The next
TPM_FlushSpecific occasionally takes tens of seconds to
complete. Another sequence is creating many keys in a row without
pause. The TPM_CreateWrapKey operation gets much slower after the
first few iterations, as one would expect when the pool of precomputed
keys is exhausted. Then after a 35-second pause, the same TPM_LoadKey2
followed by TPM_FlushSpecific sequence triggers the behavior.

Our working theory is that this older TPM sometimes pauses to
precompute keys, which modern chips implement as a background
process. Without access to the chip's implementation details it's
impossible to know whether any commands are immune to being blocked by
this process. So it seems safest to ignore the chip's reported command
durations, and use a value much higher than any observed duration,
like 180 sec (which is the duration this chip reports for "long"
commands).

Signed-off-by: Ed Swierk <eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org>
---
 drivers/char/tpm/tpm_tis.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/drivers/char/tpm/tpm_tis.c b/drivers/char/tpm/tpm_tis.c
index 3baba73..6b95667 100644
--- a/drivers/char/tpm/tpm_tis.c
+++ b/drivers/char/tpm/tpm_tis.c
@@ -511,6 +511,10 @@ struct tis_vendor_duration_override {
 };
 
 static const struct tis_vendor_duration_override vendor_duration_overrides[] = {
+	/* STMicro ST19NP18-TPM */
+	{ 0x0000104a, { (180*USEC_PER_SEC),
+			(180*USEC_PER_SEC),
+			(180*USEC_PER_SEC) } },
 };
 
 static bool tpm_tis_update_durations(struct tpm_chip *chip,
-- 
1.9.1


------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

Re: [tpmdd-devel] [PATCH v3 1/4] tpm_tis: Improve reporting of IO errors

[Jarkko Sakkinen]

On Mon, Jun 06, 2016 at 08:37:26PM -0700, Ed Swierk wrote:
> Mysterious TPM behavior can be difficult to track down through all the
> layers of software. Add error messages for conditions that should
> never happen. Also include the manufacturer ID along with other chip
> data printed during init.
> 
> Signed-off-by: Ed Swierk <eswierk@skyportsystems.com>

Reviewed-by: Jarkko Sakkinen <jarkko.sakkinen@linux.intel.com>

PS. Please include at minimum also linux-kernel@vger.kernel.org and
linux-security-module@vger.kernel.org for these patches. Thanks.

> ---
>  drivers/char/tpm/tpm_tis.c | 8 +++++++-
>  1 file changed, 7 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/char/tpm/tpm_tis.c b/drivers/char/tpm/tpm_tis.c
> index 65f7eec..088fa86 100644
> --- a/drivers/char/tpm/tpm_tis.c
> +++ b/drivers/char/tpm/tpm_tis.c
> @@ -299,6 +299,8 @@ static int tpm_tis_recv(struct tpm_chip *chip, u8 *buf, size_t count)
>  
>  	expected = be32_to_cpu(*(__be32 *) (buf + 2));
>  	if (expected > count) {
> +		dev_err(chip->pdev, "Response too long (wanted %zd, got %d)\n",
> +			count, expected);
>  		size = -EIO;
>  		goto out;
>  	}
> @@ -366,6 +368,8 @@ static int tpm_tis_send_data(struct tpm_chip *chip, u8 *buf, size_t len)
>  				  &chip->vendor.int_queue, false);
>  		status = tpm_tis_status(chip);
>  		if (!itpm && (status & TPM_STS_DATA_EXPECT) == 0) {
> +			dev_err(chip->pdev, "Chip not accepting %zd bytes\n",
> +				len - count);
>  			rc = -EIO;
>  			goto out_err;
>  		}
> @@ -378,6 +382,7 @@ static int tpm_tis_send_data(struct tpm_chip *chip, u8 *buf, size_t len)
>  			  &chip->vendor.int_queue, false);
>  	status = tpm_tis_status(chip);
>  	if ((status & TPM_STS_DATA_EXPECT) != 0) {
> +		dev_err(chip->pdev, "Chip not accepting last byte\n");
>  		rc = -EIO;
>  		goto out_err;
>  	}
> @@ -689,8 +694,9 @@ static int tpm_tis_init(struct device *dev, struct tpm_info *tpm_info,
>  	vendor = ioread32(chip->vendor.iobase + TPM_DID_VID(0));
>  	chip->vendor.manufacturer_id = vendor;
>  
> -	dev_info(dev, "%s TPM (device-id 0x%X, rev-id %d)\n",
> +	dev_info(dev, "%s TPM (manufacturer-id 0x%X, device-id 0x%X, rev-id %d)\n",
>  		 (chip->flags & TPM_CHIP_FLAG_TPM2) ? "2.0" : "1.2",
> +		 chip->vendor.manufacturer_id,
>  		 vendor >> 16, ioread8(chip->vendor.iobase + TPM_RID(0)));
>  
>  	if (!itpm) {
> -- 
> 1.9.1

/Jarko

Re: [tpmdd-devel] [PATCH v3 2/4] tpm: Add optional logging of TPM command durations

[Jarkko Sakkinen]

On Mon, Jun 06, 2016 at 08:37:27PM -0700, Ed Swierk wrote:
> Some TPMs violate their own advertised command durations. This is much
> easier to debug with data about how long each command actually takes
> to complete. Add debug messages that can be enabled by running
> 
>   echo -n 'module tpm +p' >/sys/kernel/debug/dynamic_debug/control
> 
> on a kernel configured with DYNAMIC_DEBUG=y.
> 
> Signed-off-by: Ed Swierk <eswierk@skyportsystems.com>

Reviewed-by: Jarkko Sakkinen <jarkko.sakkinen@linux.intel.com>

> ---
>  drivers/char/tpm/tpm-interface.c | 17 +++++++++++++----
>  1 file changed, 13 insertions(+), 4 deletions(-)
> 
> diff --git a/drivers/char/tpm/tpm-interface.c b/drivers/char/tpm/tpm-interface.c
> index c50637d..cc1e5bc 100644
> --- a/drivers/char/tpm/tpm-interface.c
> +++ b/drivers/char/tpm/tpm-interface.c
> @@ -333,13 +333,14 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
>  {
>  	ssize_t rc;
>  	u32 count, ordinal;
> -	unsigned long stop;
> +	unsigned long start, stop;
>  
>  	if (bufsiz > TPM_BUFSIZE)
>  		bufsiz = TPM_BUFSIZE;
>  
>  	count = be32_to_cpu(*((__be32 *) (buf + 2)));
>  	ordinal = be32_to_cpu(*((__be32 *) (buf + 6)));
> +	dev_dbg(chip->pdev, "starting command %d count %d\n", ordinal, count);
>  	if (count == 0)
>  		return -ENODATA;
>  	if (count > bufsiz) {
> @@ -360,18 +361,24 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
>  	if (chip->vendor.irq)
>  		goto out_recv;
>  
> +	start = jiffies;
>  	if (chip->flags & TPM_CHIP_FLAG_TPM2)
> -		stop = jiffies + tpm2_calc_ordinal_duration(chip, ordinal);
> +		stop = start + tpm2_calc_ordinal_duration(chip, ordinal);
>  	else
> -		stop = jiffies + tpm_calc_ordinal_duration(chip, ordinal);
> +		stop = start + tpm_calc_ordinal_duration(chip, ordinal);
>  	do {
>  		u8 status = chip->ops->status(chip);
>  		if ((status & chip->ops->req_complete_mask) ==
> -		    chip->ops->req_complete_val)
> +		    chip->ops->req_complete_val) {
> +			dev_dbg(chip->pdev, "completed command %d in %d ms\n",
> +				ordinal, jiffies_to_msecs(jiffies - start));
>  			goto out_recv;
> +		}
>  
>  		if (chip->ops->req_canceled(chip, status)) {
>  			dev_err(chip->pdev, "Operation Canceled\n");
> +			dev_dbg(chip->pdev, "canceled command %d after %d ms\n",
> +				ordinal, jiffies_to_msecs(jiffies - start));
>  			rc = -ECANCELED;
>  			goto out;
>  		}
> @@ -382,6 +389,8 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
>  
>  	chip->ops->cancel(chip);
>  	dev_err(chip->pdev, "Operation Timed out\n");
> +	dev_dbg(chip->pdev, "command %d timed out after %d ms\n", ordinal,
> +		jiffies_to_msecs(jiffies - start));
>  	rc = -ETIME;
>  	goto out;
>  
> -- 
> 1.9.1
> 
> 
> ------------------------------------------------------------------------------
> What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
> patterns at an interface-level. Reveals which users, apps, and protocols are 
> consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
> J-Flow, sFlow and other flows. Make informed decisions using capacity 
> planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e
> _______________________________________________
> tpmdd-devel mailing list
> tpmdd-devel@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/tpmdd-devel

/Jarkko

Re: [PATCH v3 3/4] tpm: Allow TPM chip drivers to override reported command durations

[Jarkko Sakkinen]

On Mon, Jun 06, 2016 at 08:37:28PM -0700, Ed Swierk wrote:
> Some TPM chips report bogus command durations in their capabilities,
> just as others report incorrect timeouts. Add an update_durations()
> function and an implementation for tpm_tis, and move the existing
> BCM0102 workaround out of the common tpm_get_timeouts() code.
> 
> Signed-off-by: Ed Swierk <eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org>


> ---
>  drivers/char/tpm/tpm-interface.c | 43 ++++++++++++++++++++++++----------------
>  drivers/char/tpm/tpm_tis.c       | 40 +++++++++++++++++++++++++++++++++++++
>  include/linux/tpm.h              |  2 ++
>  3 files changed, 68 insertions(+), 17 deletions(-)
> 
> diff --git a/drivers/char/tpm/tpm-interface.c b/drivers/char/tpm/tpm-interface.c
> index cc1e5bc..91332dd 100644
> --- a/drivers/char/tpm/tpm-interface.c
> +++ b/drivers/char/tpm/tpm-interface.c
> @@ -507,7 +507,8 @@ int tpm_get_timeouts(struct tpm_chip *chip)
>  	struct tpm_cmd_t tpm_cmd;
>  	unsigned long new_timeout[4];
>  	unsigned long old_timeout[4];
> -	struct duration_t *duration_cap;
> +	unsigned long new_duration[3];
> +	unsigned long old_duration[3];
>  	ssize_t rc;
>  
>  	tpm_cmd.header.in = tpm_getcap_header;
> @@ -599,26 +600,34 @@ duration:
>  	    != sizeof(tpm_cmd.header.out) + sizeof(u32) + 3 * sizeof(u32))
>  		return -EINVAL;
>  
> -	duration_cap = &tpm_cmd.params.getcap_out.cap.duration;
> +	old_duration[TPM_SHORT] =
> +		be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_short);
> +	old_duration[TPM_MEDIUM] =
> +		be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_medium);
> +	old_duration[TPM_LONG] =
> +		be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_long);
> +	memcpy(new_duration, old_duration, sizeof(new_duration));
> +
> +	if (chip->ops->update_durations != NULL)
> +		chip->vendor.duration_adjusted =
> +			chip->ops->update_durations(chip, new_duration);
> +
> +	/* Report adjusted durations */
> +	if (chip->vendor.duration_adjusted) {
> +		dev_info(chip->pdev,
> +			 HW_ERR "Adjusting reported durations: short %lu->%luus medium %lu->%luus long %lu->%luus\n",
> +			 old_duration[TPM_SHORT], new_duration[TPM_SHORT],
> +			 old_duration[TPM_MEDIUM], new_duration[TPM_MEDIUM],
> +			 old_duration[TPM_LONG], new_duration[TPM_LONG]);
> +	}
> +
>  	chip->vendor.duration[TPM_SHORT] =
> -	    usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_short));
> +		usecs_to_jiffies(new_duration[TPM_SHORT]);
>  	chip->vendor.duration[TPM_MEDIUM] =
> -	    usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_medium));
> +		usecs_to_jiffies(new_duration[TPM_MEDIUM]);
>  	chip->vendor.duration[TPM_LONG] =
> -	    usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_long));
> +		usecs_to_jiffies(new_duration[TPM_LONG]);
>  
> -	/* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
> -	 * value wrong and apparently reports msecs rather than usecs. So we
> -	 * fix up the resulting too-small TPM_SHORT value to make things work.
> -	 * We also scale the TPM_MEDIUM and -_LONG values by 1000.
> -	 */
> -	if (chip->vendor.duration[TPM_SHORT] < (HZ / 100)) {
> -		chip->vendor.duration[TPM_SHORT] = HZ;
> -		chip->vendor.duration[TPM_MEDIUM] *= 1000;
> -		chip->vendor.duration[TPM_LONG] *= 1000;
> -		chip->vendor.duration_adjusted = true;
> -		dev_info(chip->pdev, "Adjusting TPM timeout parameters.");
> -	}
>  	return 0;
>  }
>  EXPORT_SYMBOL_GPL(tpm_get_timeouts);
> diff --git a/drivers/char/tpm/tpm_tis.c b/drivers/char/tpm/tpm_tis.c
> index 088fa86..3baba73 100644
> --- a/drivers/char/tpm/tpm_tis.c
> +++ b/drivers/char/tpm/tpm_tis.c
> @@ -505,6 +505,45 @@ static bool tpm_tis_update_timeouts(struct tpm_chip *chip,
>  	return false;
>  }
>  
> +struct tis_vendor_duration_override {
> +	u32 did_vid;
> +	unsigned long duration_us[3];
> +};
> +
> +static const struct tis_vendor_duration_override vendor_duration_overrides[] = {
> +};
> +
> +static bool tpm_tis_update_durations(struct tpm_chip *chip,
> +				     unsigned long *duration_cap)
> +{
> +	int i;
> +	u32 did_vid;
> +
> +	did_vid = ioread32(chip->vendor.iobase + TPM_DID_VID(0));
> +
> +	for (i = 0; i != ARRAY_SIZE(vendor_duration_overrides); i++) {
> +		if (vendor_duration_overrides[i].did_vid != did_vid)
> +			continue;
> +		memcpy(duration_cap, vendor_duration_overrides[i].duration_us,
> +		       sizeof(vendor_duration_overrides[i].duration_us));
> +		return true;
> +	}
> +
> +	/* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
> +	 * value wrong and apparently reports msecs rather than usecs. So we
> +	 * fix up the resulting too-small TPM_SHORT value to make things work.
> +	 * We also scale the TPM_MEDIUM and -_LONG values by 1000.
> +	 */
> +	if (duration_cap[TPM_SHORT] < (HZ / 100)) {
> +		duration_cap[TPM_SHORT] = HZ;
> +		duration_cap[TPM_MEDIUM] *= 1000;
> +		duration_cap[TPM_LONG] *= 1000;
> +		return true;
> +	}
> +
> +	return false;
> +}
> +
>  /*
>   * Early probing for iTPM with STS_DATA_EXPECT flaw.
>   * Try sending command without itpm flag set and if that
> @@ -570,6 +609,7 @@ static const struct tpm_class_ops tpm_tis = {
>  	.send = tpm_tis_send,
>  	.cancel = tpm_tis_ready,
>  	.update_timeouts = tpm_tis_update_timeouts,
> +	.update_durations = tpm_tis_update_durations,
>  	.req_complete_mask = TPM_STS_DATA_AVAIL | TPM_STS_VALID,
>  	.req_complete_val = TPM_STS_DATA_AVAIL | TPM_STS_VALID,
>  	.req_canceled = tpm_tis_req_canceled,
> diff --git a/include/linux/tpm.h b/include/linux/tpm.h
> index 706e63e..862d0a1 100644
> --- a/include/linux/tpm.h
> +++ b/include/linux/tpm.h
> @@ -43,6 +43,8 @@ struct tpm_class_ops {
>  	u8 (*status) (struct tpm_chip *chip);
>  	bool (*update_timeouts)(struct tpm_chip *chip,
>  				unsigned long *timeout_cap);
> +	bool (*update_durations)(struct tpm_chip *chip,
> +				unsigned long *duration_cap);

I don't think this callback makes sense if only TIS driver is using it.
You are fixing a simple problem with over engineered solution.

>  
>  };
>  
> -- 
> 1.9.1

/Jarkko

------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

Re: [PATCH v3 3/4] tpm: Allow TPM chip drivers to override reported command durations

[Ed Swierk]

I followed the example of the existing update_timeouts callback, which
is also used only by tpm_tis.

But I can put the STMicro workaround directly in tpm_get_timeouts() if
you prefer that approach.

--Ed


On Tue, Jun 7, 2016 at 7:15 AM, Jarkko Sakkinen
<jarkko.sakkinen-VuQAYsv1563Yd54FQh9/CA@public.gmane.org> wrote:
> On Mon, Jun 06, 2016 at 08:37:28PM -0700, Ed Swierk wrote:
>> Some TPM chips report bogus command durations in their capabilities,
>> just as others report incorrect timeouts. Add an update_durations()
>> function and an implementation for tpm_tis, and move the existing
>> BCM0102 workaround out of the common tpm_get_timeouts() code.
>>
>> Signed-off-by: Ed Swierk <eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org>
>
>
>> ---
>>  drivers/char/tpm/tpm-interface.c | 43 ++++++++++++++++++++++++----------------
>>  drivers/char/tpm/tpm_tis.c       | 40 +++++++++++++++++++++++++++++++++++++
>>  include/linux/tpm.h              |  2 ++
>>  3 files changed, 68 insertions(+), 17 deletions(-)
>>
>> diff --git a/drivers/char/tpm/tpm-interface.c b/drivers/char/tpm/tpm-interface.c
>> index cc1e5bc..91332dd 100644
>> --- a/drivers/char/tpm/tpm-interface.c
>> +++ b/drivers/char/tpm/tpm-interface.c
>> @@ -507,7 +507,8 @@ int tpm_get_timeouts(struct tpm_chip *chip)
>>       struct tpm_cmd_t tpm_cmd;
>>       unsigned long new_timeout[4];
>>       unsigned long old_timeout[4];
>> -     struct duration_t *duration_cap;
>> +     unsigned long new_duration[3];
>> +     unsigned long old_duration[3];
>>       ssize_t rc;
>>
>>       tpm_cmd.header.in = tpm_getcap_header;
>> @@ -599,26 +600,34 @@ duration:
>>           != sizeof(tpm_cmd.header.out) + sizeof(u32) + 3 * sizeof(u32))
>>               return -EINVAL;
>>
>> -     duration_cap = &tpm_cmd.params.getcap_out.cap.duration;
>> +     old_duration[TPM_SHORT] =
>> +             be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_short);
>> +     old_duration[TPM_MEDIUM] =
>> +             be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_medium);
>> +     old_duration[TPM_LONG] =
>> +             be32_to_cpu(tpm_cmd.params.getcap_out.cap.duration.tpm_long);
>> +     memcpy(new_duration, old_duration, sizeof(new_duration));
>> +
>> +     if (chip->ops->update_durations != NULL)
>> +             chip->vendor.duration_adjusted =
>> +                     chip->ops->update_durations(chip, new_duration);
>> +
>> +     /* Report adjusted durations */
>> +     if (chip->vendor.duration_adjusted) {
>> +             dev_info(chip->pdev,
>> +                      HW_ERR "Adjusting reported durations: short %lu->%luus medium %lu->%luus long %lu->%luus\n",
>> +                      old_duration[TPM_SHORT], new_duration[TPM_SHORT],
>> +                      old_duration[TPM_MEDIUM], new_duration[TPM_MEDIUM],
>> +                      old_duration[TPM_LONG], new_duration[TPM_LONG]);
>> +     }
>> +
>>       chip->vendor.duration[TPM_SHORT] =
>> -         usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_short));
>> +             usecs_to_jiffies(new_duration[TPM_SHORT]);
>>       chip->vendor.duration[TPM_MEDIUM] =
>> -         usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_medium));
>> +             usecs_to_jiffies(new_duration[TPM_MEDIUM]);
>>       chip->vendor.duration[TPM_LONG] =
>> -         usecs_to_jiffies(be32_to_cpu(duration_cap->tpm_long));
>> +             usecs_to_jiffies(new_duration[TPM_LONG]);
>>
>> -     /* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
>> -      * value wrong and apparently reports msecs rather than usecs. So we
>> -      * fix up the resulting too-small TPM_SHORT value to make things work.
>> -      * We also scale the TPM_MEDIUM and -_LONG values by 1000.
>> -      */
>> -     if (chip->vendor.duration[TPM_SHORT] < (HZ / 100)) {
>> -             chip->vendor.duration[TPM_SHORT] = HZ;
>> -             chip->vendor.duration[TPM_MEDIUM] *= 1000;
>> -             chip->vendor.duration[TPM_LONG] *= 1000;
>> -             chip->vendor.duration_adjusted = true;
>> -             dev_info(chip->pdev, "Adjusting TPM timeout parameters.");
>> -     }
>>       return 0;
>>  }
>>  EXPORT_SYMBOL_GPL(tpm_get_timeouts);
>> diff --git a/drivers/char/tpm/tpm_tis.c b/drivers/char/tpm/tpm_tis.c
>> index 088fa86..3baba73 100644
>> --- a/drivers/char/tpm/tpm_tis.c
>> +++ b/drivers/char/tpm/tpm_tis.c
>> @@ -505,6 +505,45 @@ static bool tpm_tis_update_timeouts(struct tpm_chip *chip,
>>       return false;
>>  }
>>
>> +struct tis_vendor_duration_override {
>> +     u32 did_vid;
>> +     unsigned long duration_us[3];
>> +};
>> +
>> +static const struct tis_vendor_duration_override vendor_duration_overrides[] = {
>> +};
>> +
>> +static bool tpm_tis_update_durations(struct tpm_chip *chip,
>> +                                  unsigned long *duration_cap)
>> +{
>> +     int i;
>> +     u32 did_vid;
>> +
>> +     did_vid = ioread32(chip->vendor.iobase + TPM_DID_VID(0));
>> +
>> +     for (i = 0; i != ARRAY_SIZE(vendor_duration_overrides); i++) {
>> +             if (vendor_duration_overrides[i].did_vid != did_vid)
>> +                     continue;
>> +             memcpy(duration_cap, vendor_duration_overrides[i].duration_us,
>> +                    sizeof(vendor_duration_overrides[i].duration_us));
>> +             return true;
>> +     }
>> +
>> +     /* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
>> +      * value wrong and apparently reports msecs rather than usecs. So we
>> +      * fix up the resulting too-small TPM_SHORT value to make things work.
>> +      * We also scale the TPM_MEDIUM and -_LONG values by 1000.
>> +      */
>> +     if (duration_cap[TPM_SHORT] < (HZ / 100)) {
>> +             duration_cap[TPM_SHORT] = HZ;
>> +             duration_cap[TPM_MEDIUM] *= 1000;
>> +             duration_cap[TPM_LONG] *= 1000;
>> +             return true;
>> +     }
>> +
>> +     return false;
>> +}
>> +
>>  /*
>>   * Early probing for iTPM with STS_DATA_EXPECT flaw.
>>   * Try sending command without itpm flag set and if that
>> @@ -570,6 +609,7 @@ static const struct tpm_class_ops tpm_tis = {
>>       .send = tpm_tis_send,
>>       .cancel = tpm_tis_ready,
>>       .update_timeouts = tpm_tis_update_timeouts,
>> +     .update_durations = tpm_tis_update_durations,
>>       .req_complete_mask = TPM_STS_DATA_AVAIL | TPM_STS_VALID,
>>       .req_complete_val = TPM_STS_DATA_AVAIL | TPM_STS_VALID,
>>       .req_canceled = tpm_tis_req_canceled,
>> diff --git a/include/linux/tpm.h b/include/linux/tpm.h
>> index 706e63e..862d0a1 100644
>> --- a/include/linux/tpm.h
>> +++ b/include/linux/tpm.h
>> @@ -43,6 +43,8 @@ struct tpm_class_ops {
>>       u8 (*status) (struct tpm_chip *chip);
>>       bool (*update_timeouts)(struct tpm_chip *chip,
>>                               unsigned long *timeout_cap);
>> +     bool (*update_durations)(struct tpm_chip *chip,
>> +                             unsigned long *duration_cap);
>
> I don't think this callback makes sense if only TIS driver is using it.
> You are fixing a simple problem with over engineered solution.
>
>>
>>  };
>>
>> --
>> 1.9.1
>
> /Jarkko

------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

Re: [PATCH v3 3/4] tpm: Allow TPM chip drivers to override reported command durations

[Jason Gunthorpe]

On Tue, Jun 07, 2016 at 07:25:24AM -0700, Ed Swierk wrote:
> I followed the example of the existing update_timeouts callback, which
> is also used only by tpm_tis.

The callback is because only TIS has the did_vid stuff which is needed
to key the adjustment. Other interfaces do not have that information.

This was an ugly historical mistake:

> >> -     /* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
> >> -      * value wrong and apparently reports msecs rather than usecs. So we
> >> -      * fix up the resulting too-small TPM_SHORT value to make things work.
> >> -      * We also scale the TPM_MEDIUM and -_LONG values by 1000.
> >> -      */
> >> -     if (chip->vendor.duration[TPM_SHORT] < (HZ / 100)) {
> >> -             chip->vendor.duration[TPM_SHORT] = HZ;
> >> -             chip->vendor.duration[TPM_MEDIUM] *= 1000;
> >> -             chip->vendor.duration[TPM_LONG] *= 1000;
> >> -             chip->vendor.duration_adjusted = true;

It should have been did/vid key'd as well, not heuristic.

Can the existing update_timeouts be broadened to do both adjustments,
or do they really need to be at different times?

Jason

------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e

Re: [PATCH v3 3/4] tpm: Allow TPM chip drivers to override reported command durations

[Jarkko Sakkinen]

On Tue, Jun 07, 2016 at 11:32:35AM -0600, Jason Gunthorpe wrote:
> On Tue, Jun 07, 2016 at 07:25:24AM -0700, Ed Swierk wrote:
> > I followed the example of the existing update_timeouts callback, which
> > is also used only by tpm_tis.
> 
> The callback is because only TIS has the did_vid stuff which is needed
> to key the adjustment. Other interfaces do not have that information.
> 
> This was an ugly historical mistake:
> 
> > >> -     /* The Broadcom BCM0102 chipset in a Dell Latitude D820 gets the above
> > >> -      * value wrong and apparently reports msecs rather than usecs. So we
> > >> -      * fix up the resulting too-small TPM_SHORT value to make things work.
> > >> -      * We also scale the TPM_MEDIUM and -_LONG values by 1000.
> > >> -      */
> > >> -     if (chip->vendor.duration[TPM_SHORT] < (HZ / 100)) {
> > >> -             chip->vendor.duration[TPM_SHORT] = HZ;
> > >> -             chip->vendor.duration[TPM_MEDIUM] *= 1000;
> > >> -             chip->vendor.duration[TPM_LONG] *= 1000;
> > >> -             chip->vendor.duration_adjusted = true;
> 
> It should have been did/vid key'd as well, not heuristic.
> 
> Can the existing update_timeouts be broadened to do both adjustments,
> or do they really need to be at different times?

This would be a better idea.

> Jason

/Jarkko

------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e