diff mbox

[v8,2/5] tpm: Add optional logging of TPM command durations

Message ID 1466557831-113440-3-git-send-email-eswierk@skyportsystems.com (mailing list archive)
State New, archived
Headers show

Commit Message

Ed Swierk June 22, 2016, 1:10 a.m. UTC 
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(-)

Comments

Jason Gunthorpe June 24, 2016, 6:27 p.m. UTC | #1 
On Tue, Jun 21, 2016 at 06:10:28PM -0700, Ed Swierk wrote:

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

[..]

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

No sense in logging twice, just enhance the existingerror message.

Jason

------------------------------------------------------------------------------
Attend Shape: An AT&T Tech Expo July 15-16. Meet us at AT&T Park in San
Francisco, CA to explore cutting-edge tech and listen to tech luminaries
present their vision of the future. This family event has something for
everyone, including kids. Get more information and register today.
http://sdm.link/attshape
Jarkko Sakkinen June 24, 2016, 8:24 p.m. UTC | #2 
On Fri, Jun 24, 2016 at 12:27:27PM -0600, Jason Gunthorpe wrote:
> On Tue, Jun 21, 2016 at 06:10:28PM -0700, Ed Swierk wrote:
> 
> >  		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));
> 
> [..]
> 
> >  	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));
> 
> No sense in logging twice, just enhance the existingerror message.

Absolutely agree. Jason, thanks for pointing this out!

/Jarkko

------------------------------------------------------------------------------
Attend Shape: An AT&T Tech Expo July 15-16. Meet us at AT&T Park in San
Francisco, CA to explore cutting-edge tech and listen to tech luminaries
present their vision of the future. This family event has something for
everyone, including kids. Get more information and register today.
http://sdm.link/attshape
diff mbox

Patch

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;