From patchwork Tue Jul 29 20:14:30 2014 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ben Widawsky X-Patchwork-Id: 4642281 Return-Path: X-Original-To: patchwork-intel-gfx@patchwork.kernel.org Delivered-To: patchwork-parsemail@patchwork2.web.kernel.org Received: from mail.kernel.org (mail.kernel.org [198.145.19.201]) by patchwork2.web.kernel.org (Postfix) with ESMTP id 27876C0338 for ; Tue, 29 Jul 2014 20:12:26 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id 2660820127 for ; Tue, 29 Jul 2014 20:12:25 +0000 (UTC) Received: from gabe.freedesktop.org (gabe.freedesktop.org [131.252.210.177]) by mail.kernel.org (Postfix) with ESMTP id 0ADCF2012D for ; Tue, 29 Jul 2014 20:12:23 +0000 (UTC) Received: from gabe.freedesktop.org (localhost [127.0.0.1]) by gabe.freedesktop.org (Postfix) with ESMTP id 4CEA76E135; Tue, 29 Jul 2014 13:12:21 -0700 (PDT) X-Original-To: intel-gfx@lists.freedesktop.org Delivered-To: intel-gfx@lists.freedesktop.org Received: from mga09.intel.com (mga09.intel.com [134.134.136.24]) by gabe.freedesktop.org (Postfix) with ESMTP id 60D356E135 for ; Tue, 29 Jul 2014 13:12:20 -0700 (PDT) Received: from orsmga002.jf.intel.com ([10.7.209.21]) by orsmga102.jf.intel.com with ESMTP; 29 Jul 2014 13:06:36 -0700 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.01,759,1400050800"; d="scan'208";a="580815394" Received: from statham.jf.intel.com ([10.7.197.60]) by orsmga002.jf.intel.com with ESMTP; 29 Jul 2014 13:12:19 -0700 From: Ben Widawsky To: Intel GFX Date: Tue, 29 Jul 2014 13:14:30 -0700 Message-Id: <1406664870-29970-2-git-send-email-benjamin.widawsky@intel.com> X-Mailer: git-send-email 2.0.2 In-Reply-To: <1406664870-29970-1-git-send-email-benjamin.widawsky@intel.com> References: <1406664870-29970-1-git-send-email-benjamin.widawsky@intel.com> Cc: Ben Widawsky , Ben Widawsky Subject: [Intel-gfx] [PATCH 2/2] drm/i915: Embellish wait_end trace X-BeenThere: intel-gfx@lists.freedesktop.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: Intel graphics driver community testing & development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: intel-gfx-bounces@lists.freedesktop.org Sender: "Intel-gfx" X-Spam-Status: No, score=-4.9 required=5.0 tests=BAYES_00, RCVD_IN_DNSWL_MED, RP_MATCHES_RCVD, UNPARSEABLE_RELAY autolearn=unavailable version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on mail.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP This adds two new data points to the trace event, wait time, and whether or not the event slept. Both of these should already be obtainable through various means. This patch just makes the data more accessible. Wait is obtainable with the current code by matching seqnos in begin/end. In simple cases where begin/ends are always paired, this is trivial. However, if you queue up multiple begins/ends, it can get confusing. We're already calculating wait time, so it's trivially added here. This patch also provides the slightly more accurate wait_time as opposed to the timestamps from the tracepoint. It's observable, but just noise. The second bit of information, whether or not the operation slept is helpful in determining where time went. This is probably also obtainable through the scheduler events. However, we have the information easily at our fingertips, we may as well give it out. This results in an event which looks like: gem_gtt_hog 409 [000] 32.012641: i915:i915_gem_request_wait_end: dev=0, ring=3, seqno=4294963203, duration=0.000368225 (slept=yes) While here, rename sleep_time to wait_time since the verb sleep hasn't been true for a long time (several conditions exist where it won't sleep). Signed-off-by: Ben Widawsky --- drivers/gpu/drm/i915/i915_gem.c | 12 +++++++----- drivers/gpu/drm/i915/i915_trace.h | 29 ++++++++++++++++++++++++++--- 2 files changed, 33 insertions(+), 8 deletions(-) diff --git a/drivers/gpu/drm/i915/i915_gem.c b/drivers/gpu/drm/i915/i915_gem.c index 17f7ac9..bb7fed6 100644 --- a/drivers/gpu/drm/i915/i915_gem.c +++ b/drivers/gpu/drm/i915/i915_gem.c @@ -1161,6 +1161,8 @@ static int __wait_seqno(struct intel_engine_cs *ring, u32 seqno, struct timespec before, now; DEFINE_WAIT(wait); unsigned long timeout_expire; + struct timespec wait_time; + bool slept = false; int ret; WARN(!intel_irqs_enabled(dev_priv), "IRQs disabled"); @@ -1216,6 +1218,7 @@ static int __wait_seqno(struct intel_engine_cs *ring, u32 seqno, break; } + slept = true; timer.function = NULL; if (timeout || missed_irq(dev_priv, ring)) { unsigned long expire; @@ -1233,17 +1236,16 @@ static int __wait_seqno(struct intel_engine_cs *ring, u32 seqno, } } getrawmonotonic(&now); - trace_i915_gem_request_wait_end(ring, seqno); if (!irq_test_in_progress) ring->irq_put(ring); finish_wait(&ring->irq_queue, &wait); + wait_time = timespec_sub(now, before); + trace_i915_gem_request_wait_end(ring, seqno, wait_time, slept); - if (timeout) { - struct timespec sleep_time = timespec_sub(now, before); - *timeout = timespec_sub(*timeout, sleep_time); - } + if (timeout) + *timeout = timespec_sub(*timeout, wait_time); return ret; } diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h index f5aa006..0936066 100644 --- a/drivers/gpu/drm/i915/i915_trace.h +++ b/drivers/gpu/drm/i915/i915_trace.h @@ -476,9 +476,32 @@ TRACE_EVENT(i915_gem_request_wait_begin, __entry->blocking ? "yes (NB)" : "no") ); -DEFINE_EVENT(i915_gem_request, i915_gem_request_wait_end, - TP_PROTO(struct intel_engine_cs *ring, u32 seqno), - TP_ARGS(ring, seqno) +TRACE_EVENT(i915_gem_request_wait_end, + TP_PROTO(struct intel_engine_cs *ring, u32 seqno, struct timespec delta, bool slept), + TP_ARGS(ring, seqno, delta, slept), + + TP_STRUCT__entry( + __field(u32, dev) + __field(u32, ring) + __field(u32, seqno) + __field(long long, s) + __field(long, ns) + __field(bool, slept) + ), + + TP_fast_assign( + __entry->dev = ring->dev->primary->index; + __entry->ring = ring->id; + __entry->seqno = seqno; + __entry->s = (long long)delta.tv_sec; + __entry->ns = delta.tv_nsec; + __entry->slept = slept; + ), + + TP_printk("dev=%u, ring=%u, seqno=%u, duration=%lld.%.9ld (slept=%s)", + __entry->dev, __entry->ring, __entry->seqno, + __entry->s, __entry->ns, + __entry->slept ? "yes" : "no") ); DECLARE_EVENT_CLASS(i915_ring,