From patchwork Wed Jun 22 01:10:28 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ed Swierk X-Patchwork-Id: 9191641 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 309F66075E for ; Wed, 22 Jun 2016 01:11:02 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 1FF9728365 for ; Wed, 22 Jun 2016 01:11:02 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 0E91328383; Wed, 22 Jun 2016 01:11:02 +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.9 required=2.0 tests=BAYES_00,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 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 mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 9A72928365 for ; Wed, 22 Jun 2016 01:11:01 +0000 (UTC) Received: from localhost ([127.0.0.1] helo=sfs-ml-1.v29.ch3.sourceforge.com) by sfs-ml-1.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1bFWh2-00032k-C6; Wed, 22 Jun 2016 01:11:00 +0000 Received: from sog-mx-4.v43.ch3.sourceforge.com ([172.29.43.194] helo=mx.sourceforge.net) by sfs-ml-1.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1bFWh1-00032L-2l for tpmdd-devel@lists.sourceforge.net; Wed, 22 Jun 2016 01:10:59 +0000 Received-SPF: pass (sog-mx-4.v43.ch3.sourceforge.com: domain of skyportsystems.com designates 209.85.192.173 as permitted sender) client-ip=209.85.192.173; envelope-from=eswierk@skyportsystems.com; helo=mail-pf0-f173.google.com; Received: from mail-pf0-f173.google.com ([209.85.192.173]) by sog-mx-4.v43.ch3.sourceforge.com with esmtps (TLSv1:AES128-SHA:128) (Exim 4.76) id 1bFWh0-0002yh-8d for tpmdd-devel@lists.sourceforge.net; Wed, 22 Jun 2016 01:10:59 +0000 Received: by mail-pf0-f173.google.com with SMTP id c2so11851737pfa.2 for ; Tue, 21 Jun 2016 18:10:58 -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=ir4KwlxzOqGsT87w9A/tlbm4CdED2QMUjTONZ2xKuEoTkJnEKVY6gXDJKYPxh1+UPo VFFBfwQY9x/jeyXnMQLNrOgPnWIomhjFloRLPmJNN/c1zyKlkNPAfbtFRE8xh4RkoSjl xLZo6u1NBB6vxj7R0r6RQKEQyHwJw6xSh3eCkuUZZ3n1lHpiAWzqvqyiyC7CibOC16w6 4Ia4p+1AaE3Bmm6GqeRFBuhYHUjXSS03/NkyzG9/oCn8svefhUQ7F5QY15wqBXsHseSH ZTMv8NS5ydwf810Gn2z40QakGREiS+PG2UVE6HsuhDAubnrytCblcCizK4AfIB66m6yx tNAQ== X-Gm-Message-State: ALyK8tIJnJexCFuzSdSCrCLvdA5v03E9Z1jjSFfXbWGu6AasZanyM8DQz7WQ1N/uD3OrwiWy X-Received: by 10.98.73.198 with SMTP id r67mr31801925pfi.50.1466557852526; Tue, 21 Jun 2016 18:10:52 -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 g26sm74800523pfj.82.2016.06.21.18.10.51 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 21 Jun 2016 18:10:51 -0700 (PDT) From: Ed Swierk To: tpmdd-devel@lists.sourceforge.net, linux-kernel@vger.kernel.org, linux-security-module@vger.kernel.org Date: Tue, 21 Jun 2016 18:10:28 -0700 Message-Id: <1466557831-113440-3-git-send-email-eswierk@skyportsystems.com> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1466557831-113440-1-git-send-email-eswierk@skyportsystems.com> References: <1466474042-110773-1-git-send-email-eswierk@skyportsystems.com> <1466557831-113440-1-git-send-email-eswierk@skyportsystems.com> X-Headers-End: 1bFWh0-0002yh-8d Subject: [tpmdd-devel] [PATCH v8 2/5] 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 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;