Index: sys/contrib/ena-com/ena_plat.h =================================================================== --- sys/contrib/ena-com/ena_plat.h +++ sys/contrib/ena-com/ena_plat.h @@ -104,14 +104,11 @@ #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 @@ 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) Index: sys/dev/ena/ena.c =================================================================== --- sys/dev/ena/ena.c +++ sys/dev/ena/ena.c @@ -193,6 +193,13 @@ 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 @@ 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 @@ 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; } @@ -448,8 +453,8 @@ txr->br = buf_ring_alloc(ena_buf_ring_size, M_DEVBUF, M_WAITOK, &txr->ring_mtx); if (unlikely(txr->br == NULL)) { - device_printf(adapter->pdev, - "Error while setting up bufring\n"); + ena_trace(ENA_ALERT, + "Error while setting up bufring\n"); rc = ENOMEM; goto err_que_free; } @@ -545,9 +550,6 @@ NULL, /* lockfuncarg */ &adapter->tx_buf_tag); - if (unlikely(ret != 0)) - device_printf(adapter->pdev, "Unable to create Tx DMA tag\n"); - return (ret); } @@ -583,9 +585,6 @@ NULL, /* lockarg */ &adapter->rx_buf_tag); - if (unlikely(ret != 0)) - device_printf(adapter->pdev, "Unable to create Rx DMA tag\n"); - return (ret); } @@ -651,8 +650,8 @@ 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; } } @@ -662,7 +661,7 @@ 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; @@ -846,7 +845,7 @@ 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; } @@ -871,7 +870,7 @@ taskqueue_thread_enqueue, &rx_ring->cmpl_tq); if (unlikely(rx_ring->cmpl_tq == NULL)) { - device_printf(adapter->pdev, + ena_trace(ENA_ALERT, "Unable to create taskqueue for cmpl task\n"); i = rx_ring->ring_size; goto err_lro_free; @@ -904,7 +903,6 @@ free(rx_ring->rx_buffer_info, M_DEVBUF); rx_ring->rx_buffer_info = NULL; err_no_mem: - ena_trace(ENA_ALERT, "RX resource allocation fail"); return (ENOMEM); } @@ -920,8 +918,6 @@ { 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)) taskqueue_drain(rx_ring->cmpl_tq, &rx_ring->cmpl_task); @@ -1020,7 +1016,7 @@ 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; @@ -1050,8 +1046,10 @@ 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); @@ -1092,14 +1090,15 @@ 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; @@ -1110,9 +1109,9 @@ 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)) { @@ -1154,9 +1153,8 @@ 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); } } @@ -1177,6 +1175,7 @@ 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); @@ -1186,8 +1185,16 @@ 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); @@ -1238,6 +1245,7 @@ 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)) { @@ -1246,6 +1254,12 @@ 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); @@ -1385,6 +1399,9 @@ 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; @@ -1407,6 +1424,9 @@ 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; @@ -1555,6 +1575,10 @@ 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); @@ -1588,6 +1612,7 @@ /* 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; } @@ -1598,6 +1623,7 @@ /* 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; @@ -1653,6 +1679,8 @@ 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; @@ -1665,6 +1693,11 @@ 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); @@ -1681,8 +1714,6 @@ } 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)) { @@ -1842,8 +1873,8 @@ "Failed to allocate msix_entries, vectors %d\n", msix_vecs); return (ENOMEM); } - 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; @@ -1901,7 +1932,6 @@ { 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); @@ -1972,7 +2002,7 @@ 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); @@ -1992,7 +2022,8 @@ 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; @@ -2024,10 +2055,10 @@ 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 } @@ -2344,7 +2375,7 @@ if (adapter->link_status == false) { mtx_unlock(&adapter->global_mtx); - ena_trace(ENA_WARNING, "link_status = false"); + ena_trace(ENA_INFO, "link_status = false"); return; } @@ -2534,11 +2565,9 @@ 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)); @@ -2821,7 +2850,7 @@ /* 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; } @@ -3080,7 +3109,7 @@ 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); } @@ -3129,7 +3158,7 @@ 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; } @@ -3409,11 +3438,10 @@ 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; @@ -3744,25 +3772,29 @@ /* 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); rc = ena_init_io_rings(adapter); if (unlikely(rc != 0)) { - device_printf(pdev,"Error with initialization of IO rings\n"); + device_printf(pdev, "Error with initialization of IO rings\n"); goto err_rx_tag_free; } /* 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; }