From patchwork Sat Jun 11 01:55:04 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ed Swierk X-Patchwork-Id: 9170929 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 60829607D9 for ; Sat, 11 Jun 2016 01:56:30 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 50C2227D07 for ; Sat, 11 Jun 2016 01:56:30 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 43E0328325; Sat, 11 Jun 2016 01:56:30 +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 E9E0C27D07 for ; Sat, 11 Jun 2016 01:56:29 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751761AbcFKB41 (ORCPT ); Fri, 10 Jun 2016 21:56:27 -0400 Received: from mail-pa0-f52.google.com ([209.85.220.52]:36425 "EHLO mail-pa0-f52.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751889AbcFKBzU (ORCPT ); Fri, 10 Jun 2016 21:55:20 -0400 Received: by mail-pa0-f52.google.com with SMTP id b5so28471566pas.3 for ; Fri, 10 Jun 2016 18:55:20 -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=M+SfIwXvvoOHjv4DqWHh8VPLfdnHxaMGJ5zR+D7x9h9Ai4yeE9D9HLOP4iC5kDTjn3 pIuZePaIccLSUEdiPsaPNrhUQelz2jiCo87flqdLIn0zocYR33l0grDY52/jzlo56jUO BpHyFYJY2LMOXjP6AEP70ZGIdkTsI1nrnOZyI= 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=CtE2LJX4LV1olH8yvnWuZuBMjs5Gt5j9YVcnGzau1nqf0RpCVUblgHfPLXTII7DFra kaJZ+PtKSt2FVQSJvpR4Z7D48DCVhEin1gRMg8ds5KbRudNoWZJ41oxpNZgVaLmCCDd4 enOgy/5UMcz7KMPAxYZnJ9EUDEXHypjyjTYwWgIwb8Ui+M4PQqFcTgCxHXfaosNS/x29 FSu1MkfosDvlrS+qOv3xnK9rWRX06bnGQGInVvGog+71srnmVjCuzAFAiI77V9AmPiZ/ 5G76wZy/y07hMJBI2s0CE2cSZuP4hQWqDVa7I+i/QKjhgZgdd4FAhhS2zShrNb+Ftv63 A+Eg== X-Gm-Message-State: ALyK8tJpI+Zoo/cEwMu+19df5qVU8xz+5/1JfHjYHq1VlrqPBRZX0+NcpYjYErTEXKOrdC/3 X-Received: by 10.66.220.168 with SMTP id px8mr5527438pac.83.1465610119400; Fri, 10 Jun 2016 18:55:19 -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 i89sm335594pfi.22.2016.06.10.18.55.18 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Fri, 10 Jun 2016 18:55:18 -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, 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 Message-Id: <1465610107-87762-3-git-send-email-eswierk@skyportsystems.com> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1465610107-87762-1-git-send-email-eswierk@skyportsystems.com> References: <1465426818-89356-1-git-send-email-eswierk@skyportsystems.com> <1465610107-87762-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;