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: 9227975 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 5408660B19 for ; Wed, 13 Jul 2016 16:21:36 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 42B8427FA2 for ; Wed, 13 Jul 2016 16:21:36 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 360AA27FAD; Wed, 13 Jul 2016 16:21:36 +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 D806227FA8 for ; Wed, 13 Jul 2016 16:21:35 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752597AbcGMQVZ (ORCPT ); Wed, 13 Jul 2016 12:21:25 -0400 Received: from mail-pa0-f53.google.com ([209.85.220.53]:33003 "EHLO mail-pa0-f53.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751381AbcGMQUJ (ORCPT ); Wed, 13 Jul 2016 12:20:09 -0400 Received: by mail-pa0-f53.google.com with SMTP id ks6so19225116pab.0 for ; Wed, 13 Jul 2016 09:19:53 -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=G9GzPC8JauLqvYv/0P5F4oC5nusF1VqMCi4Xk3XB938=; b=kUr3DMMiuX9AOTrA4BEhtxkDFaxm/iYdwVBu0VJomfJ6NsT5DB75DP776JCkiUPIgG 2X3hgICeV8YVj9n5GSn3BKoTEuIM4JVQ57L9eLnKehySuInejldmZu0le6yZgDmWaK4s XfHPv5vpU3VnRzsrDPAf7HNQpBjDTjIa3aOh0= 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=Z1MPFGULqadwqq+E6edDpuB4nIrpblHYDe4jHFbsKe2r9XOGbwkv3aPKrVEDUos4/V YkwStPUaxfb03NizCNfulfozgmNcDokDRLLifD7dTY3N/OjbwWHgppLcZDH2PXeGHRBC fCJQFNuDwVL43FS4hURX/5BheMP3FPmb0QzBKxKFJZt4ddw27mVlujcZAOOzG4QYhaYD VORv4yk8F+zfx+6a0IZfswDbnxmmc4PCoE/N9MxvtXq5hoXbhCoFkC6WJQhF2OO4VTTd 07fMggvWfD+E2cZ+0alCAtxJeTBtXo0ey9bO9KbaYMzkjkVSPEHd7ICtNgyxyqOH3M+n j6Eg== X-Gm-Message-State: ALyK8tKvV9wlEwZ70CnyIqu4G62w65/gXEkbJUEWyDFvbHkmDXclv15yNqu8dKkDr8Rniemc 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 Cc: jarkko.sakkinen@linux.intel.com, jgunthorpe@obsidianresearch.com, stefanb@us.ibm.com, eswierk@skyportsystems.com Subject: [PATCH v9 2/5] tpm: Add optional logging of TPM command durations 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> 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 | 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;