From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752762AbcFUB4A (ORCPT ); Mon, 20 Jun 2016 21:56:00 -0400 Received: from mail-pf0-f178.google.com ([209.85.192.178]:32939 "EHLO mail-pf0-f178.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751653AbcFUBzw (ORCPT ); Mon, 20 Jun 2016 21:55:52 -0400 From: Ed Swierk To: tpmdd-devel@lists.sourceforge.net, linux-kernel@vger.kernel.org, linux-security-module@vger.kernel.org Cc: jarkko.sakkinen@linux.intel.com, jgunthorpe@obsidianresearch.com, stefanb@us.ibm.com, eswierk@skyportsystems.com Subject: [PATCH v7 2/5] tpm: Add optional logging of TPM command durations Date: Mon, 20 Jun 2016 18:53:59 -0700 Message-Id: <1466474042-110773-3-git-send-email-eswierk@skyportsystems.com> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1466474042-110773-1-git-send-email-eswierk@skyportsystems.com> References: <1465610107-87762-1-git-send-email-eswierk@skyportsystems.com> <1466474042-110773-1-git-send-email-eswierk@skyportsystems.com> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.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 Reviewed-by: Jarkko Sakkinen --- 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 From mboxrd@z Thu Jan 1 00:00:00 1970 From: Ed Swierk Subject: [PATCH v7 2/5] tpm: Add optional logging of TPM command durations Date: Mon, 20 Jun 2016 18:53:59 -0700 Message-ID: <1466474042-110773-3-git-send-email-eswierk@skyportsystems.com> References: <1465610107-87762-1-git-send-email-eswierk@skyportsystems.com> <1466474042-110773-1-git-send-email-eswierk@skyportsystems.com> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Return-path: In-Reply-To: <1466474042-110773-1-git-send-email-eswierk-FilZDy9cOaHkQYj/0HfcvtBPR1lH4CV8@public.gmane.org> List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: tpmdd-devel-bounces-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org To: tpmdd-devel-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org, linux-kernel-u79uwXL29TY76Z2rM5mHXA@public.gmane.org, linux-security-module-u79uwXL29TY76Z2rM5mHXA@public.gmane.org List-Id: tpmdd-devel@lists.sourceforge.net 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 Reviewed-by: Jarkko Sakkinen --- 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 ------------------------------------------------------------------------------ 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