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: 9191661 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 1013A6075E for ; Wed, 22 Jun 2016 01:12:06 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 005B228365 for ; Wed, 22 Jun 2016 01:12:06 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id E946E28383; Wed, 22 Jun 2016 01:12:05 +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 6FF1F28365 for ; Wed, 22 Jun 2016 01:12:05 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752106AbcFVBK4 (ORCPT ); Tue, 21 Jun 2016 21:10:56 -0400 Received: from mail-pf0-f180.google.com ([209.85.192.180]:33367 "EHLO mail-pf0-f180.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752054AbcFVBKx (ORCPT ); Tue, 21 Jun 2016 21:10:53 -0400 Received: by mail-pf0-f180.google.com with SMTP id i123so11845856pfg.0 for ; Tue, 21 Jun 2016 18:10: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=+wPGmQRRCyjbvY4BVI8er6KyBjedNLjCS2Q4FBBiyAE=; b=k9nRvr1BkKl7jWRkcPcgim+tanp8H9RtQwitPX1jy8NY1VgOERLE24h68m8bLNIxC7 TNY9SJhdOJ75qQZXdZPyC1xND9aSSowevvVQQuegasRRebRPdlEnhgCNAzX1vq8nVu+1 FqfjMU4+IUDXaRcpNLzX7/MpRbPowImnjWETo= 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=OChHBmdRs7S/v7SVeuc3QPtv+0O7VuuVNvyF1E1JanH1HplNvC1tJ2g+ifO1rpmKQ/ e52wcGSvCf+qrNG4rPqUzjVEL4FGtsj8prvE7jaQJiFO3m9BbR5ZudM9PtXh1KE0YPcp Oi/qYExM1sJEBGK7WfVv22d+gAJZk/pPWSu91PF1CrU6sdZv5/M0NxG3Bh8A39bmj8s6 zSH0SGos23r6ZypyHGI1iEUfK0yauc3eGIdvRUBiGC6kls8tBU0iWhezrMPmdLEgCYa7 tkOvJtkN+YB6Xv6fFrUXb1Jsf8cV7Qyw+JHz8mqvqU+DUe2YfDXQJnGqokckIQMhvs// bkjw== X-Gm-Message-State: ALyK8tL980f7p/EfbY3WBD8KUsRli6lpVjszgVJCA2D6lyq93f/vI4snDzBR1ZuIsX+7VN9F 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 Cc: jarkko.sakkinen@linux.intel.com, jgunthorpe@obsidianresearch.com, stefanb@us.ibm.com, eswierk@skyportsystems.com Subject: [PATCH v8 2/5] tpm: Add optional logging of TPM command durations 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> 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 | 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;