From: Ed Swierk <eswierk@skyportsystems.com> To: tpmdd-devel@lists.sourceforge.net Cc: eswierk@skyportsystems.com, stefanb@us.ibm.com, jarkko.sakkinen@linux.intel.com, linux-kernel@vger.kernel.org, linux-security-module@vger.kernel.org, jgunthorpe@obsidianresearch.com Subject: [PATCH v6 2/5] tpm: Add optional logging of TPM command durations Date: Fri, 10 Jun 2016 18:55:04 -0700 [thread overview] Message-ID: <1465610107-87762-3-git-send-email-eswierk@skyportsystems.com> (raw) In-Reply-To: <1465610107-87762-1-git-send-email-eswierk@skyportsystems.com> 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
WARNING: multiple messages have this Message-ID (diff)
From: Ed Swierk <eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org> To: tpmdd-devel-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org Cc: linux-kernel-u79uwXL29TY76Z2rM5mHXA@public.gmane.org, linux-security-module-u79uwXL29TY76Z2rM5mHXA@public.gmane.org Subject: [PATCH v6 2/5] tpm: Add optional logging of TPM command durations Date: Fri, 10 Jun 2016 18:55:04 -0700 [thread overview] Message-ID: <1465610107-87762-3-git-send-email-eswierk@skyportsystems.com> (raw) In-Reply-To: <1465610107-87762-1-git-send-email-eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org> 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> Reviewed-by: Jarkko Sakkinen <jarkko.sakkinen-VuQAYsv1563Yd54FQh9/CA@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
next prev parent reply other threads:[~2016-06-11 1:56 UTC|newest] Thread overview: 121+ messages / expand[flat|nested] mbox.gz Atom feed top 2016-06-08 0:45 [PATCH v4 0/4] tpm: Command duration logging and chip-specific override Ed Swierk 2016-06-08 0:45 ` Ed Swierk 2016-06-08 0:45 ` [PATCH v4 1/4] tpm_tis: Improve reporting of IO errors Ed Swierk 2016-06-08 0:45 ` Ed Swierk 2016-06-08 0:45 ` [PATCH v4 2/4] tpm: Add optional logging of TPM command durations Ed Swierk 2016-06-08 0:45 ` Ed Swierk 2016-06-08 0:45 ` [PATCH v4 3/4] tpm: Allow TPM chip drivers to override reported " Ed Swierk 2016-06-08 0:45 ` Ed Swierk 2016-06-08 19:05 ` [tpmdd-devel] " Jason Gunthorpe 2016-06-08 19:05 ` Jason Gunthorpe 2016-06-08 20:41 ` [tpmdd-devel] " Ed Swierk 2016-06-08 0:45 ` [PATCH v4 4/4] tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup Ed Swierk 2016-06-08 0:45 ` Ed Swierk 2016-06-08 23:00 ` [PATCH v5 0/4] tpm: Command duration logging and chip-specific override Ed Swierk 2016-06-08 23:00 ` Ed Swierk 2016-06-08 23:00 ` [PATCH v5 1/4] tpm_tis: Improve reporting of IO errors Ed Swierk 2016-06-08 23:00 ` Ed Swierk 2016-06-08 23:00 ` [PATCH v5 2/4] tpm: Add optional logging of TPM command durations Ed Swierk 2016-06-08 23:00 ` Ed Swierk 2016-06-08 23:00 ` [PATCH v5 3/4] tpm: Allow TPM chip drivers to override reported " Ed Swierk 2016-06-08 23:00 ` Ed Swierk 2016-06-10 12:19 ` Jarkko Sakkinen 2016-06-10 17:34 ` Ed Swierk 2016-06-10 19:42 ` Jarkko Sakkinen 2016-06-10 19:42 ` Jarkko Sakkinen 2016-06-11 1:54 ` Ed Swierk 2016-06-11 1:54 ` Ed Swierk 2016-06-08 23:00 ` [PATCH v5 4/4] tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup Ed Swierk 2016-06-08 23:00 ` Ed Swierk 2016-06-11 1:55 ` [PATCH v6 0/5] tpm: Command duration logging and chip-specific override Ed Swierk 2016-06-11 1:55 ` Ed Swierk 2016-06-11 1:55 ` [PATCH v6 1/5] tpm_tis: Improve reporting of IO errors Ed Swierk 2016-06-11 1:55 ` Ed Swierk 2016-06-11 1:55 ` Ed Swierk [this message] 2016-06-11 1:55 ` [PATCH v6 2/5] tpm: Add optional logging of TPM command durations Ed Swierk 2016-06-11 1:55 ` [PATCH v6 3/5] tpm: Factor out reading of timeout and duration capabilities Ed Swierk 2016-06-11 1:55 ` Ed Swierk 2016-06-16 20:20 ` Jarkko Sakkinen 2016-06-16 20:20 ` Jarkko Sakkinen 2016-06-19 12:12 ` Jarkko Sakkinen 2016-06-19 12:12 ` Jarkko Sakkinen [not found] ` <20160619120157.GA29626-ral2JQCrhuEAvxtiuMwx3w@public.gmane.org> 2016-06-21 1:46 ` Ed Swierk 2016-06-11 1:55 ` [PATCH v6 4/5] tpm: Allow TPM chip drivers to override reported command durations Ed Swierk 2016-06-11 1:55 ` Ed Swierk 2016-06-16 20:26 ` Jarkko Sakkinen 2016-06-11 1:55 ` [PATCH v6 5/5] tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup Ed Swierk 2016-06-11 1:55 ` Ed Swierk 2016-06-21 1:53 ` [PATCH v7 0/5] tpm: Command duration logging and chip-specific override Ed Swierk 2016-06-21 1:53 ` Ed Swierk 2016-06-21 1:53 ` [PATCH v7 1/5] tpm_tis: Improve reporting of IO errors Ed Swierk 2016-06-21 1:53 ` Ed Swierk 2016-06-21 1:53 ` [PATCH v7 2/5] tpm: Add optional logging of TPM command durations Ed Swierk 2016-06-21 1:53 ` Ed Swierk 2016-06-21 1:54 ` [PATCH v7 3/5] tpm: Clean up reading of timeout and duration capabilities Ed Swierk 2016-06-21 1:54 ` Ed Swierk 2016-06-21 20:52 ` Jarkko Sakkinen 2016-06-21 20:52 ` Jarkko Sakkinen 2016-06-22 0:21 ` Ed Swierk 2016-06-22 0:21 ` Ed Swierk 2016-06-22 10:46 ` Jarkko Sakkinen 2016-06-22 10:46 ` Jarkko Sakkinen 2016-06-21 1:54 ` [PATCH v7 4/5] tpm: Allow TPM chip drivers to override reported command durations Ed Swierk 2016-06-21 1:54 ` Ed Swierk 2016-06-21 20:54 ` Jarkko Sakkinen 2016-06-21 20:54 ` Jarkko Sakkinen 2016-06-21 1:54 ` [PATCH v7 5/5] tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup Ed Swierk 2016-06-21 1:54 ` Ed Swierk 2016-06-21 20:55 ` Jarkko Sakkinen 2016-06-21 20:55 ` Jarkko Sakkinen 2016-06-22 1:10 ` [PATCH v8 0/5] tpm: Command duration logging and chip-specific override Ed Swierk 2016-06-22 1:10 ` Ed Swierk 2016-06-22 1:10 ` [PATCH v8 1/5] tpm_tis: Improve reporting of IO errors Ed Swierk 2016-06-22 1:10 ` Ed Swierk 2016-06-24 18:25 ` Jason Gunthorpe 2016-06-24 18:25 ` Jason Gunthorpe 2016-06-24 20:21 ` Jarkko Sakkinen 2016-06-24 20:23 ` Jarkko Sakkinen 2016-06-24 20:26 ` Jason Gunthorpe 2016-06-24 20:26 ` Jason Gunthorpe 2016-06-25 15:24 ` Jarkko Sakkinen 2016-06-25 15:24 ` Jarkko Sakkinen 2016-06-25 15:47 ` Jarkko Sakkinen 2016-06-25 15:47 ` Jarkko Sakkinen 2016-06-27 17:55 ` Jason Gunthorpe 2016-06-27 17:55 ` Jason Gunthorpe 2016-06-22 1:10 ` [PATCH v8 2/5] tpm: Add optional logging of TPM command durations Ed Swierk 2016-06-22 1:10 ` Ed Swierk 2016-06-24 18:27 ` Jason Gunthorpe 2016-06-24 18:27 ` Jason Gunthorpe 2016-06-24 20:24 ` Jarkko Sakkinen 2016-06-24 20:24 ` Jarkko Sakkinen 2016-06-22 1:10 ` [PATCH v8 3/5] tpm: Clean up reading of timeout and duration capabilities Ed Swierk 2016-06-22 1:10 ` Ed Swierk 2016-06-22 1:10 ` [PATCH v8 4/5] tpm: Allow TPM chip drivers to override reported command durations Ed Swierk 2016-06-22 1:10 ` Ed Swierk 2016-06-22 1:10 ` [PATCH v8 5/5] tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup Ed Swierk 2016-06-22 1:10 ` Ed Swierk 2016-07-13 16:19 ` [PATCH v9 0/5] tpm: Command duration logging and chip-specific override Ed Swierk 2016-07-13 16:19 ` [PATCH v9 1/5] tpm_tis: Improve reporting of IO errors Ed Swierk 2016-07-13 16:19 ` [PATCH v9 2/5] tpm: Add optional logging of TPM command durations Ed Swierk 2016-07-13 16:19 ` [PATCH v9 3/5] tpm: Clean up reading of timeout and duration capabilities Ed Swierk 2016-07-18 18:15 ` Jarkko Sakkinen 2016-07-18 18:19 ` Jarkko Sakkinen 2016-07-18 18:19 ` Jarkko Sakkinen 2016-07-18 18:20 ` Jarkko Sakkinen 2016-07-18 18:20 ` Jarkko Sakkinen 2016-07-13 16:19 ` [PATCH v9 4/5] tpm: Allow TPM chip drivers to override reported command durations Ed Swierk 2016-07-13 17:04 ` kbuild test robot 2016-07-13 17:04 ` kbuild test robot 2016-07-18 18:40 ` Jarkko Sakkinen 2016-07-18 18:40 ` Jarkko Sakkinen 2016-07-13 16:19 ` [PATCH v9 5/5] tpm_tis: Increase ST19NP18 TPM command duration to avoid chip lockup Ed Swierk 2016-07-13 16:44 ` [PATCH v9 0/5] tpm: Command duration logging and chip-specific override Ed Swierk 2016-07-13 17:36 ` Jason Gunthorpe 2016-07-13 17:36 ` Jason Gunthorpe 2016-07-13 20:00 ` Ed Swierk 2016-07-13 20:00 ` Ed Swierk 2016-07-13 20:58 ` Eric W. Biederman 2016-07-13 20:59 ` Jason Gunthorpe 2016-07-18 18:07 ` Jarkko Sakkinen 2016-07-18 18:07 ` Jarkko Sakkinen
Reply instructions: You may reply publicly to this message via plain-text email using any one of the following methods: * Save the following mbox file, import it into your mail client, and reply-to-all from there: mbox Avoid top-posting and favor interleaved quoting: https://en.wikipedia.org/wiki/Posting_style#Interleaved_style * Reply using the --to, --cc, and --in-reply-to switches of git-send-email(1): git send-email \ --in-reply-to=1465610107-87762-3-git-send-email-eswierk@skyportsystems.com \ --to=eswierk@skyportsystems.com \ --cc=jarkko.sakkinen@linux.intel.com \ --cc=jgunthorpe@obsidianresearch.com \ --cc=linux-kernel@vger.kernel.org \ --cc=linux-security-module@vger.kernel.org \ --cc=stefanb@us.ibm.com \ --cc=tpmdd-devel@lists.sourceforge.net \ /path/to/YOUR_REPLY https://kernel.org/pub/software/scm/git/docs/git-send-email.html * If your mail client supports setting the In-Reply-To header via mailto: links, try the mailto: linkBe sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.