[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-Id: <1465610107-87762-3-git-send-email-eswierk@skyportsystems.com>
Date: Fri, 10 Jun 2016 18:55:04 -0700
From: Ed Swierk <eswierk@...portsystems.com>
To: tpmdd-devel@...ts.sourceforge.net
Cc: eswierk@...portsystems.com, stefanb@...ibm.com,
jarkko.sakkinen@...ux.intel.com, linux-kernel@...r.kernel.org,
linux-security-module@...r.kernel.org,
jgunthorpe@...idianresearch.com
Subject: [PATCH v6 2/5] tpm: Add optional logging of TPM command durations
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@...portsystems.com>
Reviewed-by: Jarkko Sakkinen <jarkko.sakkinen@...ux.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
Powered by blists - more mailing lists