From owner-svn-src-all@freebsd.org Fri Oct 28 23:53:34 2016 Return-Path: Delivered-To: svn-src-all@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id D700EC25D5E; Fri, 28 Oct 2016 23:53:34 +0000 (UTC) (envelope-from cem@FreeBSD.org) Received: from repo.freebsd.org (repo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id AE7C6325; Fri, 28 Oct 2016 23:53:34 +0000 (UTC) (envelope-from cem@FreeBSD.org) Received: from repo.freebsd.org ([127.0.1.37]) by repo.freebsd.org (8.15.2/8.15.2) with ESMTP id u9SNrX7K094267; Fri, 28 Oct 2016 23:53:33 GMT (envelope-from cem@FreeBSD.org) Received: (from cem@localhost) by repo.freebsd.org (8.15.2/8.15.2/Submit) id u9SNrX2j094266; Fri, 28 Oct 2016 23:53:33 GMT (envelope-from cem@FreeBSD.org) Message-Id: <201610282353.u9SNrX2j094266@repo.freebsd.org> X-Authentication-Warning: repo.freebsd.org: cem set sender to cem@FreeBSD.org using -f From: "Conrad E. Meyer" Date: Fri, 28 Oct 2016 23:53:33 +0000 (UTC) To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r308067 - head/sys/dev/ioat X-SVN-Group: head MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: svn-src-all@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: "SVN commit messages for the entire src tree \(except for " user" and " projects" \)" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 28 Oct 2016 23:53:34 -0000 Author: cem Date: Fri Oct 28 23:53:33 2016 New Revision: 308067 URL: https://svnweb.freebsd.org/changeset/base/308067 Log: ioat(4): Add additional tracing These probes help track down driver bugs. Sponsored by: Dell EMC Isilon Modified: head/sys/dev/ioat/ioat.c Modified: head/sys/dev/ioat/ioat.c ============================================================================== --- head/sys/dev/ioat/ioat.c Fri Oct 28 23:01:11 2016 (r308066) +++ head/sys/dev/ioat/ioat.c Fri Oct 28 23:53:33 2016 (r308067) @@ -693,8 +693,8 @@ ioat_process_events(struct ioat_softc *i while (desc->hw_desc_bus_addr != status && ioat_get_active(ioat) > 0) { desc = ioat_get_ring_entry(ioat, ioat->tail); dmadesc = &desc->bus_dmadesc; - CTR4(KTR_IOAT, "channel=%u completing desc %u ok cb %p(%p)", - ioat->chan_idx, ioat->tail, dmadesc->callback_fn, + CTR5(KTR_IOAT, "channel=%u completing desc idx %u (%p) ok cb %p(%p)", + ioat->chan_idx, ioat->tail, dmadesc, dmadesc->callback_fn, dmadesc->callback_arg); if (dmadesc->callback_fn != NULL) @@ -703,6 +703,8 @@ ioat_process_events(struct ioat_softc *i completed++; ioat->tail++; } + CTR5(KTR_IOAT, "%s channel=%u head=%u tail=%u active=%u", __func__, + ioat->chan_idx, ioat->head, ioat->tail, ioat_get_active(ioat)); if (completed != 0) { ioat->last_seen = desc->hw_desc_bus_addr; @@ -760,8 +762,8 @@ out: while (ioat_get_active(ioat) > 0) { desc = ioat_get_ring_entry(ioat, ioat->tail); dmadesc = &desc->bus_dmadesc; - CTR4(KTR_IOAT, "channel=%u completing desc %u err cb %p(%p)", - ioat->chan_idx, ioat->tail, dmadesc->callback_fn, + CTR5(KTR_IOAT, "channel=%u completing desc idx %u (%p) err cb %p(%p)", + ioat->chan_idx, ioat->tail, dmadesc, dmadesc->callback_fn, dmadesc->callback_arg); if (dmadesc->callback_fn != NULL) @@ -773,6 +775,8 @@ out: ioat->stats.descriptors_processed++; ioat->stats.descriptors_error++; } + CTR5(KTR_IOAT, "%s channel=%u head=%u tail=%u active=%u", __func__, + ioat->chan_idx, ioat->head, ioat->tail, ioat_get_active(ioat)); if (ioat->is_completion_pending) { ioat->is_completion_pending = FALSE; @@ -947,7 +951,8 @@ ioat_release(bus_dmaengine_t dmaengine) struct ioat_softc *ioat; ioat = to_ioat_softc(dmaengine); - CTR2(KTR_IOAT, "%s channel=%u", __func__, ioat->chan_idx); + CTR3(KTR_IOAT, "%s channel=%u dispatch hw_head=%u", __func__, + ioat->chan_idx, ioat->hw_head & UINT16_MAX); ioat_write_2(ioat, IOAT_DMACOUNT_OFFSET, (uint16_t)ioat->hw_head); if (!ioat->is_completion_pending) { @@ -1040,7 +1045,6 @@ ioat_copy(bus_dmaengine_t dmaengine, bus struct ioat_softc *ioat; ioat = to_ioat_softc(dmaengine); - CTR2(KTR_IOAT, "%s channel=%u", __func__, ioat->chan_idx); if (((src | dst) & (0xffffull << 48)) != 0) { ioat_log_message(0, "%s: High 16 bits of src/dst invalid\n", @@ -1058,6 +1062,8 @@ ioat_copy(bus_dmaengine_t dmaengine, bus dump_descriptor(hw_desc); ioat_submit_single(ioat); + CTR6(KTR_IOAT, "%s channel=%u desc=%p dest=%lx src=%lx len=%lx", + __func__, ioat->chan_idx, &desc->bus_dmadesc, dst, src, len); return (&desc->bus_dmadesc); } @@ -1414,11 +1420,16 @@ ioat_reserve_space(struct ioat_softc *io if (ioat_get_ring_space(ioat) >= num_descs) goto out; + CTR3(KTR_IOAT, "%s channel=%u starved (%u)", __func__, + ioat->chan_idx, num_descs); + if (!dug && !ioat->is_submitter_processing && (1 << ioat->ring_size_order) > num_descs) { ioat->is_submitter_processing = TRUE; mtx_unlock(&ioat->submit_lock); + CTR2(KTR_IOAT, "%s channel=%u attempting to process events", + __func__, ioat->chan_idx); ioat_process_events(ioat); mtx_lock(&ioat->submit_lock); @@ -1433,6 +1444,8 @@ ioat_reserve_space(struct ioat_softc *io order = ioat->ring_size_order; if (ioat->is_resize_pending || order == IOAT_MAX_ORDER) { if ((mflags & M_WAITOK) != 0) { + CTR2(KTR_IOAT, "%s channel=%u blocking on completions", + __func__, ioat->chan_idx); msleep(&ioat->tail, &ioat->submit_lock, 0, "ioat_rsz", 0); continue; @@ -1794,6 +1807,9 @@ ioat_submit_single(struct ioat_softc *io ioat_get(ioat, IOAT_ACTIVE_DESCR_REF); atomic_add_rel_int(&ioat->head, 1); atomic_add_rel_int(&ioat->hw_head, 1); + CTR5(KTR_IOAT, "%s channel=%u head=%u hw_head=%u tail=%u", __func__, + ioat->chan_idx, ioat->head, ioat->hw_head & UINT16_MAX, + ioat->tail); ioat->stats.descriptors_submitted++; }