Date: Thu, 9 Nov 2017 13:30:39 +0000 (UTC) From: Marcin Wojtas <mw@FreeBSD.org> To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r325589 - in head/sys: contrib/ena-com dev/ena Message-ID: <201711091330.vA9DUdvS089952@repo.freebsd.org>
next in thread | raw e-mail | index | archive | help
Author: mw Date: Thu Nov 9 13:30:39 2017 New Revision: 325589 URL: https://svnweb.freebsd.org/changeset/base/325589 Log: Rework printouts and logging level in ENA driver The driver was printing out a lot of information upon failure, which does not have to be interested for the user. Changing logging level required to rebuild driver with proper flags. The proper sysctl was added, so the level now can be changed dynamically using bitmask. Levels of printouts were adjusted to keep on mind end user instead of debugging purposes. More verbose messages were added to align the driver with the Linux. Fix building error introduced by the r325506 by casting csum_flags to uint64_t. Submitted by: Michal Krawczyk <mk@semihalf.com> Reviewed by: byenduri_gmail.com Obtained from: Semihalf Sponsored by: Amazon, Inc. Differential Revision: https://reviews.freebsd.org/D12868 Modified: head/sys/contrib/ena-com/ena_plat.h head/sys/dev/ena/ena.c Directory Properties: head/sys/contrib/ena-com/ (props changed) Modified: head/sys/contrib/ena-com/ena_plat.h ============================================================================== --- head/sys/contrib/ena-com/ena_plat.h Thu Nov 9 13:09:07 2017 (r325588) +++ head/sys/contrib/ena-com/ena_plat.h Thu Nov 9 13:30:39 2017 (r325589) @@ -104,14 +104,11 @@ extern struct ena_bus_space ebs; #define ENA_IOQ (1 << 7) /* Detailed info about IO queues. */ #define ENA_ADMQ (1 << 8) /* Detailed info about admin queue. */ -#ifndef ENA_DEBUG_LEVEL -#define ENA_DEBUG_LEVEL (ENA_ALERT | ENA_WARNING) -#endif +extern int ena_log_level; -#ifdef ENA_TRACE #define ena_trace_raw(level, fmt, args...) \ do { \ - if (((level) & ENA_DEBUG_LEVEL) != (level)) \ + if (((level) & ena_log_level) != (level)) \ break; \ printf(fmt, ##args); \ } while (0) @@ -120,10 +117,6 @@ extern struct ena_bus_space ebs; ena_trace_raw(level, "%s() [TID:%d]: " \ fmt " \n", __func__, curthread->td_tid, ##args) -#else /* ENA_TRACE */ -#define ena_trace_raw(...) -#define ena_trace(...) -#endif /* ENA_TRACE */ #define ena_trc_dbg(format, arg...) ena_trace(ENA_DBG, format, ##arg) #define ena_trc_info(format, arg...) ena_trace(ENA_INFO, format, ##arg) Modified: head/sys/dev/ena/ena.c ============================================================================== --- head/sys/dev/ena/ena.c Thu Nov 9 13:09:07 2017 (r325588) +++ head/sys/dev/ena/ena.c Thu Nov 9 13:30:39 2017 (r325589) @@ -193,6 +193,13 @@ static int ena_buf_ring_size = 4096; SYSCTL_INT(_hw_ena, OID_AUTO, buf_ring_size, CTLFLAG_RWTUN, &ena_buf_ring_size, 0, "Size of the bufring"); +/* + * Logging level for changing verbosity of the output + */ +int ena_log_level = ENA_ALERT | ENA_WARNING; +SYSCTL_INT(_hw_ena, OID_AUTO, log_level, CTLFLAG_RWTUN, + &ena_log_level, 0, "Logging level indicating verbosity of the logs"); + static ena_vendor_info_t ena_vendor_info_array[] = { { PCI_VENDOR_ID_AMAZON, PCI_DEV_ID_ENA_PF, 0}, { PCI_VENDOR_ID_AMAZON, PCI_DEV_ID_ENA_LLQ_PF, 0}, @@ -243,16 +250,15 @@ ena_dma_alloc(device_t dmadev, bus_size_t size, NULL, /* lockarg */ &dma->tag); if (unlikely(error != 0)) { - device_printf(dmadev, "%s: bus_dma_tag_create failed: %d\n", - __func__, error); + ena_trace(ENA_ALERT, "bus_dma_tag_create failed: %d\n", error); goto fail_tag; } error = bus_dmamem_alloc(dma->tag, (void**) &dma->vaddr, BUS_DMA_COHERENT | BUS_DMA_ZERO, &dma->map); if (unlikely(error != 0)) { - device_printf(dmadev, "%s: bus_dmamem_alloc(%ju) failed: %d\n", - __func__, (uintmax_t)size, error); + ena_trace(ENA_ALERT, "bus_dmamem_alloc(%ju) failed: %d\n", + (uintmax_t)size, error); goto fail_map_create; } @@ -260,8 +266,7 @@ ena_dma_alloc(device_t dmadev, bus_size_t size, error = bus_dmamap_load(dma->tag, dma->map, dma->vaddr, size, ena_dmamap_callback, &dma->paddr, mapflags); if (unlikely((error != 0) || (dma->paddr == 0))) { - device_printf(dmadev, "%s: bus_dmamap_load failed: %d\n", - __func__, error); + ena_trace(ENA_ALERT, ": bus_dmamap_load failed: %d\n", error); goto fail_map_load; } @@ -530,9 +535,6 @@ ena_setup_tx_dma_tag(struct ena_adapter *adapter) NULL, /* lockfuncarg */ &adapter->tx_buf_tag); - if (unlikely(ret != 0)) - device_printf(adapter->pdev, "Unable to create Tx DMA tag\n"); - return (ret); } @@ -568,9 +570,6 @@ ena_setup_rx_dma_tag(struct ena_adapter *adapter) NULL, /* lockarg */ &adapter->rx_buf_tag); - if (unlikely(ret != 0)) - device_printf(adapter->pdev, "Unable to create Rx DMA tag\n"); - return (ret); } @@ -636,8 +635,8 @@ ena_setup_tx_resources(struct ena_adapter *adapter, in err = bus_dmamap_create(adapter->tx_buf_tag, 0, &tx_ring->tx_buffer_info[i].map); if (unlikely(err != 0)) { - device_printf(adapter->pdev, - "Unable to create Tx DMA map for buffer %d\n", i); + ena_trace(ENA_ALERT, + "Unable to create Tx DMA map for buffer %d\n", i); goto err_buf_info_unmap; } } @@ -647,7 +646,7 @@ ena_setup_tx_resources(struct ena_adapter *adapter, in tx_ring->enqueue_tq = taskqueue_create_fast("ena_tx_enque", M_NOWAIT, taskqueue_thread_enqueue, &tx_ring->enqueue_tq); if (unlikely(tx_ring->enqueue_tq == NULL)) { - device_printf(adapter->pdev, + ena_trace(ENA_ALERT, "Unable to create taskqueue for enqueue task\n"); i = tx_ring->ring_size; goto err_buf_info_unmap; @@ -827,7 +826,7 @@ ena_setup_rx_resources(struct ena_adapter *adapter, un err = bus_dmamap_create(adapter->rx_buf_tag, 0, &(rx_ring->rx_buffer_info[i].map)); if (err != 0) { - device_printf(adapter->pdev, + ena_trace(ENA_ALERT, "Unable to create Rx DMA map for buffer %d\n", i); goto err_buf_info_unmap; } @@ -874,7 +873,6 @@ err_buf_info_unmap: rx_ring->free_rx_ids = NULL; free(rx_ring->rx_buffer_info, M_DEVBUF); rx_ring->rx_buffer_info = NULL; - ena_trace(ENA_ALERT, "RX resource allocation fail"); return (ENOMEM); } @@ -890,8 +888,6 @@ ena_free_rx_resources(struct ena_adapter *adapter, uns { struct ena_ring *rx_ring = &adapter->rx_ring[qid]; - ena_trace(ENA_INFO, "%s qid %d\n", __func__, qid); - while (taskqueue_cancel(rx_ring->cmpl_tq, &rx_ring->cmpl_task, NULL) != 0) taskqueue_drain(rx_ring->cmpl_tq, &rx_ring->cmpl_task); @@ -990,7 +986,7 @@ ena_alloc_rx_mbuf(struct ena_adapter *adapter, error = bus_dmamap_load_mbuf_sg(adapter->rx_buf_tag, rx_info->map, rx_info->mbuf, segs, &nsegs, BUS_DMA_NOWAIT); if (unlikely((error != 0) || (nsegs != 1))) { - device_printf(adapter->pdev, "failed to map mbuf, error: %d, " + ena_trace(ENA_WARNING, "failed to map mbuf, error: %d, " "nsegs: %d\n", error, nsegs); counter_u64_add(rx_ring->rx_stats.dma_mapping_err, 1); goto exit; @@ -1020,8 +1016,10 @@ ena_free_rx_mbuf(struct ena_adapter *adapter, struct e struct ena_rx_buffer *rx_info) { - if (rx_info->mbuf == NULL) + if (rx_info->mbuf == NULL) { + ena_trace(ENA_WARNING, "Trying to free unallocated buffer\n"); return; + } bus_dmamap_unload(adapter->rx_buf_tag, rx_info->map); m_freem(rx_info->mbuf); @@ -1062,14 +1060,15 @@ ena_refill_rx_bufs(struct ena_ring *rx_ring, uint32_t rc = ena_alloc_rx_mbuf(adapter, rx_ring, rx_info); if (unlikely(rc != 0)) { - device_printf(adapter->pdev, - "failed to alloc buffer for rx queue\n"); + ena_trace(ENA_WARNING, + "failed to alloc buffer for rx queue %d\n", + rx_ring->qid); break; } rc = ena_com_add_single_rx_desc(rx_ring->ena_com_io_sq, &rx_info->ena_buf, req_id); if (unlikely(rc != 0)) { - device_printf(adapter->pdev, + ena_trace(ENA_WARNING, "failed to add buffer for rx queue %d\n", rx_ring->qid); break; @@ -1080,9 +1079,9 @@ ena_refill_rx_bufs(struct ena_ring *rx_ring, uint32_t if (unlikely(i < num)) { counter_u64_add(rx_ring->rx_stats.refil_partial, 1); - device_printf(adapter->pdev, - "refilled rx queue %d with %d pages only\n", - rx_ring->qid, i); + ena_trace(ENA_WARNING, + "refilled rx qid %d with only %d mbufs (from %d)\n", + rx_ring->qid, i, num); } if (likely(i != 0)) { @@ -1124,9 +1123,8 @@ ena_refill_all_rx_bufs(struct ena_adapter *adapter) rc = ena_refill_rx_bufs(rx_ring, bufs_num); if (unlikely(rc != bufs_num)) - device_printf(adapter->pdev, - "refilling Queue %d failed. allocated %d buffers" - " from: %d\n", i, rc, bufs_num); + ena_trace(ENA_WARNING, "refilling Queue %d failed. " + "Allocated %d buffers from: %d\n", i, rc, bufs_num); } } @@ -1147,6 +1145,7 @@ ena_free_all_rx_bufs(struct ena_adapter *adapter) static void ena_free_tx_bufs(struct ena_adapter *adapter, unsigned int qid) { + bool print_once = true; struct ena_ring *tx_ring = &adapter->tx_ring[qid]; ENA_RING_MTX_LOCK(tx_ring); @@ -1156,8 +1155,16 @@ ena_free_tx_bufs(struct ena_adapter *adapter, unsigned if (tx_info->mbuf == NULL) continue; - ena_trace(ENA_DBG | ENA_TXPTH | ENA_RSC, - "free uncompleted Tx mbufs qid[%d] idx: 0x%x", qid, i); + if (print_once) { + device_printf(adapter->pdev, + "free uncompleted tx mbuf qid %d idx 0x%x", + qid, i); + print_once = false; + } else { + ena_trace(ENA_DBG, + "free uncompleted tx mbuf qid %d idx 0x%x", + qid, i); + } bus_dmamap_unload(adapter->tx_buf_tag, tx_info->map); m_free(tx_info->mbuf); @@ -1208,6 +1215,7 @@ ena_destroy_all_io_queues(struct ena_adapter *adapter) static inline int validate_tx_req_id(struct ena_ring *tx_ring, uint16_t req_id) { + struct ena_adapter *adapter = tx_ring->adapter; struct ena_tx_buffer *tx_info = NULL; if (likely(req_id < tx_ring->ring_size)) { @@ -1216,6 +1224,12 @@ validate_tx_req_id(struct ena_ring *tx_ring, uint16_t return (0); } + if (tx_info->mbuf == NULL) + device_printf(adapter->pdev, + "tx_info doesn't have valid mbuf\n"); + else + device_printf(adapter->pdev, "Invalid req_id: %hu\n", req_id); + counter_u64_add(tx_ring->tx_stats.bad_req_id, 1); return (EFAULT); @@ -1355,6 +1369,9 @@ ena_tx_cleanup(struct ena_ring *tx_ring) bus_dmamap_unload(adapter->tx_buf_tag, tx_info->map); } + ena_trace(ENA_DBG | ENA_TXPTH, "tx: q %d mbuf %p completed", + tx_ring->qid, mbuf); + m_freem(mbuf); total_done += tx_info->tx_descs; @@ -1377,6 +1394,9 @@ ena_tx_cleanup(struct ena_ring *tx_ring) work_done = TX_BUDGET - budget; + ena_trace(ENA_DBG | ENA_TXPTH, "tx: q %d done. total pkts: %d", + tx_ring->qid, work_done); + /* If there is still something to commit update ring state */ if (likely(commit != TX_COMMIT)) { tx_ring->next_to_clean = next_to_clean; @@ -1526,6 +1546,10 @@ ena_rx_mbuf(struct ena_ring *rx_ring, struct ena_com_r ena_trace(ENA_WARNING, "Failed to append Rx mbuf %p", mbuf); } + + ena_trace(ENA_DBG | ENA_RXPTH, + "rx mbuf updated. len %d", mbuf->m_pkthdr.len); + /* Free already appended mbuf, it won't be useful anymore */ bus_dmamap_unload(rx_ring->adapter->rx_buf_tag, rx_info->map); m_freem(rx_info->mbuf); @@ -1554,6 +1578,7 @@ ena_rx_checksum(struct ena_ring *rx_ring, struct ena_c /* ipv4 checksum error */ mbuf->m_pkthdr.csum_flags = 0; counter_u64_add(rx_ring->rx_stats.bad_csum, 1); + ena_trace(ENA_DBG, "RX IPv4 header checksum error"); return; } @@ -1564,6 +1589,7 @@ ena_rx_checksum(struct ena_ring *rx_ring, struct ena_c /* TCP/UDP checksum error */ mbuf->m_pkthdr.csum_flags = 0; counter_u64_add(rx_ring->rx_stats.bad_csum, 1); + ena_trace(ENA_DBG, "RX L4 checksum error"); } else { mbuf->m_pkthdr.csum_flags = CSUM_IP_CHECKED; mbuf->m_pkthdr.csum_flags |= CSUM_IP_VALID; @@ -1619,6 +1645,8 @@ ena_rx_cleanup(struct ena_ring *rx_ring) io_sq = &adapter->ena_dev->io_sq_queues[ena_qid]; next_to_clean = rx_ring->next_to_clean; + ena_trace(ENA_DBG, "rx: qid %d", qid); + do { ena_rx_ctx.ena_bufs = rx_ring->ena_bufs; ena_rx_ctx.max_bufs = adapter->max_rx_sgl_size; @@ -1631,6 +1659,11 @@ ena_rx_cleanup(struct ena_ring *rx_ring) if (unlikely(ena_rx_ctx.descs == 0)) break; + ena_trace(ENA_DBG | ENA_RXPTH, "rx: q %d got packet from ena. " + "descs #: %d l3 proto %d l4 proto %d hash: %x", + rx_ring->qid, ena_rx_ctx.descs, ena_rx_ctx.l3_proto, + ena_rx_ctx.l4_proto, ena_rx_ctx.hash); + /* Receive mbuf from the ring */ mbuf = ena_rx_mbuf(rx_ring, rx_ring->ena_bufs, &ena_rx_ctx, &next_to_clean); @@ -1647,8 +1680,6 @@ ena_rx_cleanup(struct ena_ring *rx_ring) } break; } - ena_trace(ENA_DBG | ENA_RXPTH, "Rx: %d bytes", - mbuf->m_pkthdr.len); if (((ifp->if_capenable & IFCAP_RXCSUM) != 0) || ((ifp->if_capenable & IFCAP_RXCSUM_IPV6) != 0)) { @@ -1804,8 +1835,7 @@ ena_enable_msix(struct ena_adapter *adapter) adapter->msix_entries = malloc(msix_vecs * sizeof(struct msix_entry), M_DEVBUF, M_WAITOK | M_ZERO); - device_printf(dev, "Allocated msix_entries, vectors (cnt: %d)\n", - msix_vecs); + ena_trace(ENA_DBG, "trying to enable MSI-X, vectors: %d", msix_vecs); for (i = 0; i < msix_vecs; i++) { adapter->msix_entries[i].entry = i; @@ -1863,7 +1893,6 @@ ena_setup_io_intr(struct ena_adapter *adapter) { static int last_bind_cpu = -1; int irq_idx; - ena_trace(ENA_DBG, "enter"); for (int i = 0; i < adapter->num_queues; i++) { irq_idx = ENA_IO_IRQ_IDX(i); @@ -1934,7 +1963,7 @@ ena_request_mgmnt_irq(struct ena_adapter *adapter) return (rc); err_res_free: - device_printf(adapter->pdev, "releasing resource for irq %d\n", + ena_trace(ENA_INFO | ENA_ADMQ, "releasing resource for irq %d\n", irq->vector); rcc = bus_release_resource(adapter->pdev, SYS_RES_IRQ, irq->vector, irq->res); @@ -1954,7 +1983,8 @@ ena_request_io_irq(struct ena_adapter *adapter) int rc = 0, i, rcc; if (unlikely(adapter->msix_enabled == 0)) { - device_printf(adapter->pdev, "failed to request irq\n"); + device_printf(adapter->pdev, + "failed to request I/O IRQ: MSI-X is not enabled\n"); return (EINVAL); } else { flags = RF_ACTIVE | RF_SHAREABLE; @@ -1986,10 +2016,10 @@ ena_request_io_irq(struct ena_adapter *adapter) irq->requested = true; #ifdef RSS - device_printf(adapter->pdev, "queue %d - RSS bucket %d\n", + ena_trace(ENA_INFO, "queue %d - RSS bucket %d\n", i - ENA_IO_IRQ_FIRST_IDX, irq->cpu); #else - device_printf(adapter->pdev, "queue %d - cpu %d\n", + ena_trace(ENA_INFO, "queue %d - cpu %d\n", i - ENA_IO_IRQ_FIRST_IDX, irq->cpu); #endif } @@ -2306,7 +2336,7 @@ ena_media_status(if_t ifp, struct ifmediareq *ifmr) if (!adapter->link_status) { mtx_unlock(&adapter->global_mtx); - ena_trace(ENA_WARNING, "link_status = false"); + ena_trace(ENA_INFO, "link_status = false"); return; } @@ -2496,11 +2526,9 @@ ena_setup_ifnet(device_t pdev, struct ena_adapter *ada if_t ifp; int caps = 0; - ena_trace(ENA_DBG, "enter"); - ifp = adapter->ifp = if_gethandle(IFT_ETHER); if (unlikely(ifp == NULL)) { - device_printf(pdev, "can not allocate ifnet structure\n"); + ena_trace(ENA_ALERT, "can not allocate ifnet structure\n"); return (ENXIO); } if_initname(ifp, device_get_name(pdev), device_get_unit(pdev)); @@ -2783,7 +2811,7 @@ ena_xmit_mbuf(struct ena_ring *tx_ring, struct mbuf ** /* Prepare the packet's descriptors and send them to device */ rc = ena_com_prepare_tx(io_sq, &ena_tx_ctx, &nb_hw_desc); if (unlikely(rc != 0)) { - ena_trace(ENA_WARNING, "failed to prepare tx bufs\n"); + device_printf(adapter->pdev, "failed to prepare tx bufs\n"); counter_u64_add(tx_ring->tx_stats.prepare_ctx_err, 1); goto dma_error; } @@ -2839,7 +2867,7 @@ ena_start_xmit(struct ena_ring *tx_ring) while ((mbuf = drbr_peek(adapter->ifp, tx_ring->br)) != NULL) { ena_trace(ENA_DBG | ENA_TXPTH, "\ndequeued mbuf %p with flags %#x and" " header csum flags %#jx", - mbuf, mbuf->m_flags, mbuf->m_pkthdr.csum_flags); + mbuf, mbuf->m_flags, (uint64_t)mbuf->m_pkthdr.csum_flags); if (unlikely(!ena_com_sq_have_enough_space(io_sq, ENA_TX_CLEANUP_THRESHOLD))) @@ -3041,7 +3069,7 @@ ena_rss_init_default(struct ena_adapter *adapter) rc = ena_com_rss_init(ena_dev, ENA_RX_RSS_TABLE_LOG_SIZE); if (unlikely(rc != 0)) { - device_printf(dev, "Cannot init RSS\n"); + device_printf(dev, "Cannot init indirect table\n"); return (rc); } @@ -3090,7 +3118,7 @@ ena_rss_init_default_deferred(void *arg) dc = devclass_find("ena"); if (unlikely(dc == NULL)) { - ena_trace(ENA_DBG, "No devclass ena\n"); + ena_trace(ENA_ALERT, "No devclass ena\n"); return; } @@ -3370,11 +3398,10 @@ check_missing_comp_in_queue(struct ena_adapter *adapte if (unlikely(missed_tx > adapter->missing_tx_threshold)) { device_printf(adapter->pdev, - "The number of lost tx completion " - "is above the threshold (%d > %d). " - "Reset the device\n", - missed_tx, - adapter->missing_tx_threshold); + "The number of lost tx completion " + "is above the threshold (%d > %d). " + "Reset the device\n", + missed_tx, adapter->missing_tx_threshold); adapter->reset_reason = ENA_REGS_RESET_MISS_TX_CMPL; adapter->trigger_reset = true; @@ -3695,12 +3722,16 @@ ena_attach(device_t pdev) /* set up dma tags for rx and tx buffers */ rc = ena_setup_tx_dma_tag(adapter); - if (unlikely(rc != 0)) + if (unlikely(rc != 0)) { + device_printf(pdev, "Failed to create TX DMA tag\n"); goto err_com_free; + } rc = ena_setup_rx_dma_tag(adapter); - if (unlikely(rc != 0)) + if (unlikely(rc != 0)) { + device_printf(pdev, "Failed to create RX DMA tag\n"); goto err_tx_tag_free; + } /* initialize rings basic information */ device_printf(pdev, "initalize %d io queues\n", io_queue_num); @@ -3709,7 +3740,7 @@ ena_attach(device_t pdev) /* setup network interface */ rc = ena_setup_ifnet(pdev, adapter, &get_feat_ctx); if (unlikely(rc != 0)) { - device_printf(pdev,"Error with network interface setup\n"); + device_printf(pdev, "Error with network interface setup\n"); goto err_io_free; }
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201711091330.vA9DUdvS089952>