From patchwork Wed Jul 13 16:19:33 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ed Swierk X-Patchwork-Id: 9228029 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 8EE836075D for ; Wed, 13 Jul 2016 17:02:46 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 7C34827F94 for ; Wed, 13 Jul 2016 17:02:46 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 6FD1B27FE4; Wed, 13 Jul 2016 17:02:46 +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=unavailable 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 D891627FBE for ; Wed, 13 Jul 2016 17:02:43 +0000 (UTC) Received: from localhost ([127.0.0.1] helo=sfs-ml-4.v29.ch3.sourceforge.com) by sfs-ml-4.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1bNNYX-00053I-Ri; Wed, 13 Jul 2016 17:02:41 +0000 Received: from sog-mx-1.v43.ch3.sourceforge.com ([172.29.43.191] helo=mx.sourceforge.net) by sfs-ml-4.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1bNMy4-0006U6-Mx for tpmdd-devel@lists.sourceforge.net; Wed, 13 Jul 2016 16:25:00 +0000 Received-SPF: pass (sog-mx-1.v43.ch3.sourceforge.com: domain of skyportsystems.com designates 209.85.220.51 as permitted sender) client-ip=209.85.220.51; envelope-from=eswierk@skyportsystems.com; helo=mail-pa0-f51.google.com; Received: from mail-pa0-f51.google.com ([209.85.220.51]) by sog-mx-1.v43.ch3.sourceforge.com with esmtps (TLSv1:AES128-SHA:128) (Exim 4.76) id 1bNMy3-0003Wi-Q4 for tpmdd-devel@lists.sourceforge.net; Wed, 13 Jul 2016 16:25:00 +0000 Received: by mail-pa0-f51.google.com with SMTP id fi15so19187604pac.1 for ; Wed, 13 Jul 2016 09:24:59 -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=G9GzPC8JauLqvYv/0P5F4oC5nusF1VqMCi4Xk3XB938=; b=Cl1i4KAdcmC1JEw0WOTPyMC5rFBgI41Jni6rWFOCOpzARC9jloJ/fwjXvDp2YtJ3x6 hHU7Wn1BvgY5CO5DP7Fdz6rMDG4Xd7b2GiyGtYPYHpXuUiFwpHmBcL5VSW7Q5M8CNX3r XAxqLUKc0haWl0Ur0rQsjI/PoeXqY/tfIcfY9yvgGSPBg+xDiW4D4rKYW0RkyZxZkPLx q7n/xQQLn9lROO8YkuZEUr6SerREZl68PUcz2/jk1Fkx23haIBTKaujv1doynIFFBdLD 33Q0J8vZIucIQ7Xd+UArsgtwtPjV9RkiDYSOXsyRxl9A5Y6GZ8X81gjyif//lZD7Uu2T Yr9A== X-Gm-Message-State: ALyK8tI3qVNaHPnvBmiVwkWehHcgXQ5zzlhhtvYRbRmi3xoSWV7dnuM5guKVdkElkP8YvxIO X-Received: by 10.66.52.11 with SMTP id p11mr14848048pao.155.1468426787744; Wed, 13 Jul 2016 09:19:47 -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 15sm6015473pfz.36.2016.07.13.09.19.46 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 13 Jul 2016 09:19:47 -0700 (PDT) From: Ed Swierk To: tpmdd-devel@lists.sourceforge.net, linux-kernel@vger.kernel.org, linux-security-module@vger.kernel.org Date: Wed, 13 Jul 2016 09:19:33 -0700 Message-Id: <1468426776-42762-3-git-send-email-eswierk@skyportsystems.com> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1468426776-42762-1-git-send-email-eswierk@skyportsystems.com> References: <1466557831-113440-1-git-send-email-eswierk@skyportsystems.com> <1468426776-42762-1-git-send-email-eswierk@skyportsystems.com> X-Headers-End: 1bNMy3-0003Wi-Q4 Subject: [tpmdd-devel] [PATCH v9 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 | 19 +++++++++++++------ 1 file changed, 13 insertions(+), 6 deletions(-) diff --git a/drivers/char/tpm/tpm-interface.c b/drivers/char/tpm/tpm-interface.c index 5e3c1b6..a4beb53 100644 --- a/drivers/char/tpm/tpm-interface.c +++ b/drivers/char/tpm/tpm-interface.c @@ -335,13 +335,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->dev, "starting command %d count %d\n", ordinal, count); if (count == 0) return -ENODATA; if (count > bufsiz) { @@ -362,18 +363,23 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf, if (chip->flags & TPM_CHIP_FLAG_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->dev, "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->dev, "Operation Canceled\n"); + dev_err(&chip->dev, "canceled command %d after %d ms\n", + ordinal, jiffies_to_msecs(jiffies - start)); rc = -ECANCELED; goto out; } @@ -383,7 +389,8 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf, } while (time_before(jiffies, stop)); chip->ops->cancel(chip); - dev_err(&chip->dev, "Operation Timed out\n"); + dev_err(&chip->dev, "command %d timed out after %d ms\n", ordinal, + jiffies_to_msecs(jiffies - start)); rc = -ETIME; goto out;