From patchwork Tue Jun 21 01:53:59 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ed Swierk X-Patchwork-Id: 9189191 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 A1A6E6075E for ; Tue, 21 Jun 2016 02:02:48 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 8EBA627E78 for ; Tue, 21 Jun 2016 02:02:48 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 83A5A27F17; Tue, 21 Jun 2016 02:02:48 +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 0130827E78 for ; Tue, 21 Jun 2016 02:02:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753930AbcFUCCo (ORCPT ); Mon, 20 Jun 2016 22:02:44 -0400 Received: from mail-pf0-f174.google.com ([209.85.192.174]:36235 "EHLO mail-pf0-f174.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753593AbcFUCCE (ORCPT ); Mon, 20 Jun 2016 22:02:04 -0400 Received: by mail-pf0-f174.google.com with SMTP id t190so993827pfb.3 for ; Mon, 20 Jun 2016 19:02:04 -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=bGFljOJIne6qEbkixRtZFpCapGOVCsazeCLwZC/l/rd4FZUjzxppUDA7RRBxYnr2nw qWSMBGCmu/YSD6YJvh6sKXRuM+vfTsOvOr8zBenEin+NB9m1DqV62MlmKkieN1TI2941 fazx5pC5QFfTGKH9WZWulSf7nbZrfxWXMzrXE= 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=PJms8maZ3OAuosJPdXwC8QrbAZf9aHvPxaLdbDqT4eSndwNpq0R01m2sYepNQT5yOO EFIx5SuQ3uxkSCmOhEalxNNgfqfWFMjqs+/sGug2Ga/W37xlmRo1hz7t/Sjq02fD4F7R RHbIuL97mTY9FG3YXQMbNwcpOtnh53C6f56OHeax60T3o2YDGuYcr3aHwVKlbQV+1XVX coeiiDUP5VWGXlPriIuJwxQ13UjnIbONXWoddJsD9HryMVTUt43BLZMzz/Vc9/DqS+sp 84ShIygMpQ2aU/3WN0W2OUyPFGg+kbx48nvf6x1VZIy23Ym4GquRUbMnCYkH/5YKSB+4 fcNw== X-Gm-Message-State: ALyK8tLSVm0OHxxGg1KJgZWG7ktGifWfXq95uNY7TI2LDiHV2qSi/lSrrn94mOq9TisUeip1 X-Received: by 10.98.130.65 with SMTP id w62mr25173220pfd.5.1466474058914; Mon, 20 Jun 2016 18:54:18 -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 i8sm91219159pao.26.2016.06.20.18.54.17 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Mon, 20 Jun 2016 18:54:18 -0700 (PDT) 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: 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;