From patchwork Wed Jun 8 23:00:16 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ed Swierk X-Patchwork-Id: 9165879 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 9A1E56088F for ; Wed, 8 Jun 2016 23:00:58 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 6FAF5281F9 for ; Wed, 8 Jun 2016 23:00:58 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 6461F28326; Wed, 8 Jun 2016 23:00:58 +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 DF1D2281F9 for ; Wed, 8 Jun 2016 23:00:57 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1423951AbcFHXAf (ORCPT ); Wed, 8 Jun 2016 19:00:35 -0400 Received: from mail-pa0-f51.google.com ([209.85.220.51]:35744 "EHLO mail-pa0-f51.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1423746AbcFHXAb (ORCPT ); Wed, 8 Jun 2016 19:00:31 -0400 Received: by mail-pa0-f51.google.com with SMTP id hl6so6530254pac.2 for ; Wed, 08 Jun 2016 16:00:31 -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=dHKV+BDUn7XfttaCDzHUVq80I1aHnZqbMGVQ4RPK3vtX/9hYGfMei829+uVxLDgCvL +A3+4/N0XQwy8yyT1bFWzsAEasjm62T79hjjdF/i1rOeRxrDeNBnkvMR6GJq7/RHMvUX vd6JyBl650wG3tN5IeptX8zLcio5RZ0MWg7fA= 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=j8kDNArBiUFLPNqWrE7qINXNkI+1a9MVaVOL6Q7/OSA9xqdJxo1C7ot9CUlxlw5XCh JTBU269NeRyDs3uvmSuC2HCVTNRkmanD3qxdKAsTHDQI8eMNV7hyxx9lUinVh59GYK0a W5Aq+B/MSALCqeXB2bLecKAyEXiEk576uMKZPmRY67lBEX6fZ80JXeBXq8xrJ6t8FNDO vtofuQldXYaAW4m9mVJ5/36MyNJ4nUwTojyQ7ZGWsMQdbzCbkxEY5V+/BJ9wztx/Nr9o o85EZg8ctu9re2OhfNQMaaZ+yk9w+8UEkFQ8AW//nFUGfXyFp8EI0/chLy+gv5U3fBKr L8Ww== X-Gm-Message-State: ALyK8tJ7TgXxiU7dUaMsOXXpJlNguJptdkNvUNXEpJXSyyiE9BZBF4Bp8yHRfv+e4l1WjpV1 X-Received: by 10.66.15.8 with SMTP id t8mr8225979pac.154.1465426830480; Wed, 08 Jun 2016 16:00:30 -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 x187sm4726352pfx.87.2016.06.08.16.00.29 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 08 Jun 2016 16:00:29 -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 v5 2/4] tpm: Add optional logging of TPM command durations Date: Wed, 8 Jun 2016 16:00:16 -0700 Message-Id: <1465426818-89356-3-git-send-email-eswierk@skyportsystems.com> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1465426818-89356-1-git-send-email-eswierk@skyportsystems.com> References: <1465346740-60120-1-git-send-email-eswierk@skyportsystems.com> <1465426818-89356-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;