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: 632560 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.sourceforge.net (lists.sourceforge.net [216.34.181.88]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 3rQ3nP25DMz9t3t for ; Thu, 9 Jun 2016 09:00:41 +1000 (AEST) Received: from localhost ([127.0.0.1] helo=sfs-ml-2.v29.ch3.sourceforge.com) by sfs-ml-2.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1bAmSj-0000se-C2; Wed, 08 Jun 2016 23:00:37 +0000 Received: from sog-mx-2.v43.ch3.sourceforge.com ([172.29.43.192] helo=mx.sourceforge.net) by sfs-ml-2.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1bAmSj-0000sZ-6J for tpmdd-devel@lists.sourceforge.net; Wed, 08 Jun 2016 23:00:37 +0000 Received-SPF: pass (sog-mx-2.v43.ch3.sourceforge.com: domain of skyportsystems.com designates 209.85.220.53 as permitted sender) client-ip=209.85.220.53; envelope-from=eswierk@skyportsystems.com; helo=mail-pa0-f53.google.com; Received: from mail-pa0-f53.google.com ([209.85.220.53]) by sog-mx-2.v43.ch3.sourceforge.com with esmtps (TLSv1:AES128-SHA:128) (Exim 4.76) id 1bAmSi-0000Wv-7z for tpmdd-devel@lists.sourceforge.net; Wed, 08 Jun 2016 23:00:37 +0000 Received: by mail-pa0-f53.google.com with SMTP id bz2so6525360pad.1 for ; Wed, 08 Jun 2016 16:00:36 -0700 (PDT) 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=lbZ0QsdheZEJqOoTSCW2AjLkpSyV04lg737VuFgM/nWzg7VTDXQtbdCb9PQN/oXLR7 YyqmrTmDBaxjqcgO3lgKTaG7lxeFxv5wvPi2VymAdrhrYigkrG/0tIaDuyMvSvvUN8EU CGBX6gsxmqsDx0zrSPvxVECpn92FP0J8aLE8VK0z71u5DpgM2eiy+iGm+X+SblzsCq31 VGjZQ8c4TC37XGRLrjQiGgooxNqnD1j19cy0Ey4UTwTpFukZumIjf0nVDovl64JDMDum yZPvyXHCAdV9akEoueK06g4PODDpE1fNQUHe3PRdLY6o4DWX5XjmM8kk89BDapOTzU4T Xnzg== X-Gm-Message-State: ALyK8tJdwtkP8+rJ+m5i0zyBdVGPjpGeXRXEKwKtmPVLzaJZtIow0FjZFG24TPIfs2z3eDio 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 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> X-Spam-Score: -1.6 (-) X-Spam-Report: Spam Filtering performed by mx.sourceforge.net. See http://spamassassin.org/tag/ for more details. -1.5 SPF_CHECK_PASS SPF reports sender host as permitted sender for sender-domain -0.0 SPF_PASS SPF: sender matches SPF record -0.1 DKIM_VALID_AU Message has a valid DKIM or DK signature from author's domain 0.1 DKIM_SIGNED Message has a DKIM or DK signature, not necessarily valid -0.1 DKIM_VALID Message has at least one valid DKIM or DK signature -0.0 AWL AWL: Adjusted score from AWL reputation of From: address X-Headers-End: 1bAmSi-0000Wv-7z Cc: linux-kernel@vger.kernel.org, linux-security-module@vger.kernel.org Subject: [tpmdd-devel] [PATCH v5 2/4] tpm: Add optional logging of TPM command durations X-BeenThere: tpmdd-devel@lists.sourceforge.net X-Mailman-Version: 2.1.9 Precedence: list List-Id: Tpm Device Driver maintainance List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: tpmdd-devel-bounces@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;