From patchwork Wed Jun 8 00:45:38 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ed Swierk X-Patchwork-Id: 9162925 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 7DFFF60571 for ; Wed, 8 Jun 2016 00:46:43 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 6F7F628371 for ; Wed, 8 Jun 2016 00:46:43 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 646A428376; Wed, 8 Jun 2016 00:46:43 +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 C7AEE28371 for ; Wed, 8 Jun 2016 00:46:42 +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 1bARdo-0004OH-VY; Wed, 08 Jun 2016 00:46:40 +0000 Received: from sog-mx-1.v43.ch3.sourceforge.com ([172.29.43.191] helo=mx.sourceforge.net) by sfs-ml-1.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1bARdn-0004OC-LJ for tpmdd-devel@lists.sourceforge.net; Wed, 08 Jun 2016 00:46:39 +0000 Received-SPF: pass (sog-mx-1.v43.ch3.sourceforge.com: domain of skyportsystems.com designates 209.85.220.46 as permitted sender) client-ip=209.85.220.46; envelope-from=eswierk@skyportsystems.com; helo=mail-pa0-f46.google.com; Received: from mail-pa0-f46.google.com ([209.85.220.46]) by sog-mx-1.v43.ch3.sourceforge.com with esmtps (TLSv1:AES128-SHA:128) (Exim 4.76) id 1bARdm-0000pr-TU for tpmdd-devel@lists.sourceforge.net; Wed, 08 Jun 2016 00:46:39 +0000 Received: by mail-pa0-f46.google.com with SMTP id ec8so44931197pac.0 for ; Tue, 07 Jun 2016 17:46:38 -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=YI4VOd9xg3SGQeiKK5Z3bIZWFTQLarDMmEmQHHId5LFcC+kpikl9DKhzdONEySv31J wPHMoT5hCtONjpb5qKZihzhWWaZlQmMtL9GmKlp3vQDyoncPpvgrXdlEY5gY0+88Sdu4 O+wm9qEABCb5mifiZzZqWaJJUyjg7UJSTbpNboLv9kVZYSH28U0DFScxSsbCaEIa+Zec gRTpMxmXb6wQh7E+wSv4JHh7ynLUBU+Lump7j+uQRktMRoqLQdq3g8ptTjhMyg5iudud pQGcmPaNmDH1PTb7yfyyKisUaXIRXA1oxUVWB6jkVuBZtR6q9Tgg6tOyHQvN9aODoNrT SP0Q== X-Gm-Message-State: ALyK8tID5/FHQAx+mPtGcjeT8SVnKGijPHTkilExECcjEOLNrQx8NstwpFgTeliAyvVrWCbn X-Received: by 10.66.14.227 with SMTP id s3mr2477835pac.12.1465346793183; Tue, 07 Jun 2016 17:46:33 -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 m1sm29489077pab.46.2016.06.07.17.46.32 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 07 Jun 2016 17:46:32 -0700 (PDT) From: Ed Swierk To: tpmdd-devel@lists.sourceforge.net Date: Tue, 7 Jun 2016 17:45:38 -0700 Message-Id: <1465346740-60120-3-git-send-email-eswierk@skyportsystems.com> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1465346740-60120-1-git-send-email-eswierk@skyportsystems.com> References: <1465346740-60120-1-git-send-email-eswierk@skyportsystems.com> X-Headers-End: 1bARdm-0000pr-TU Cc: linux-security-module@vger.kernel.org, linux-kernel@vger.kernel.org Subject: [tpmdd-devel] [PATCH v4 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 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;