From patchwork Wed Jun 8 00:45:38 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ed Swierk X-Patchwork-Id: 9162973 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 0FF6360571 for ; Wed, 8 Jun 2016 00:47:54 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 021F628371 for ; Wed, 8 Jun 2016 00:47:54 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id EB52928377; Wed, 8 Jun 2016 00:47:53 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.8 required=2.0 tests=BAYES_00,DKIM_SIGNED, RCVD_IN_DNSWL_HI,T_DKIM_INVALID autolearn=unavailable version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 78CD228371 for ; Wed, 8 Jun 2016 00:47:53 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751965AbcFHArf (ORCPT ); Tue, 7 Jun 2016 20:47:35 -0400 Received: from mail-pa0-f48.google.com ([209.85.220.48]:36453 "EHLO mail-pa0-f48.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754113AbcFHAqe (ORCPT ); Tue, 7 Jun 2016 20:46:34 -0400 Received: by mail-pa0-f48.google.com with SMTP id b5so22177955pas.3 for ; Tue, 07 Jun 2016 17:46:33 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=skyportsystems.com; s=google; h=from:to:cc:subject:date:message-id:in-reply-to:references; bh=+wPGmQRRCyjbvY4BVI8er6KyBjedNLjCS2Q4FBBiyAE=; b=be6lR3AbI7n9CwTKq0MUKgnqsHQeqBbcmZyH7GDaByvvz7VT7BAgg5tGcXXxuOyOrC oavH81UIKVr6OjhNd/p5Q0b3XT+zEepFgY9zVX8jf44diBPndasFEJO4MC151OnDBHL8 u9cp7UxxOuva3tJnPNqbtuw5DW8PeuXmxSK+U= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references; bh=+wPGmQRRCyjbvY4BVI8er6KyBjedNLjCS2Q4FBBiyAE=; b=OCWpJDlyXFC0UEFZyY/dFw8IrN0pYJ6Nmx8CdqxUmensLMsXkCMRwF1wSPopnP/znp igfAREc1DHkeihrn4MMQ8/dXLzNPZ0v1hJKVck8HAQ8KsJoPdQCARNPSWqB8KWEhaRei wT9YbvS9Gvm02lizVQGdEp0vr7QXCRQQxPOVhRnCtpXVk0Mo3sxRJyNOzseDwX5EWdfx XhqTnYW7qHatLImh+d7kNrykY9OMoo44hJTKkOdcYH6C4xTIJOUEdKKWYXvHnAheQV2G oe8j9GcR1SQWHFxdl/C6J2RZOL/rDqViq8qajAcuwasi+HMrPzhVPFaVONUpXWcePXd4 bfAQ== X-Gm-Message-State: ALyK8tKKOPioeDfWu10uLEuX//JqH7BnHzMwUPsaw46POFEgm5c4uKup1ajdSS44NrvJIxgU X-Received: by 10.66.14.227 with SMTP id s3mr2477835pac.12.1465346793183; Tue, 07 Jun 2016 17:46:33 -0700 (PDT) Received: from eswierk-sc.localdomain (67-207-112-138.static.wiline.com. [67.207.112.138]) by smtp.gmail.com with ESMTPSA id m1sm29489077pab.46.2016.06.07.17.46.32 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 07 Jun 2016 17:46:32 -0700 (PDT) From: Ed Swierk 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 Subject: [PATCH v4 2/4] tpm: Add optional logging of TPM command durations Date: Tue, 7 Jun 2016 17:45:38 -0700 Message-Id: <1465346740-60120-3-git-send-email-eswierk@skyportsystems.com> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1465346740-60120-1-git-send-email-eswierk@skyportsystems.com> References: <1465346740-60120-1-git-send-email-eswierk@skyportsystems.com> Sender: owner-linux-security-module@vger.kernel.org Precedence: bulk List-ID: X-Virus-Scanned: ClamAV using ClamSMTP 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;