From 217e7c9741596e3ad424f80b3f746faf050c2161 Mon Sep 17 00:00:00 2001 From: Damjan Marion Date: Mon, 17 Jun 2019 20:44:19 +0200 Subject: [PATCH 1/1] avf: add logging macros and improve logging Type: feature Change-Id: I3d7009505ddbb2c41d8619d9195c6a5373fa9a04 Signed-off-by: Damjan Marion --- src/plugins/avf/avf.h | 16 ++++++ src/plugins/avf/device.c | 118 +++++++++++++++++++++++++++++++++++++++++---- src/plugins/avf/virtchnl.h | 13 +++-- 3 files changed, 134 insertions(+), 13 deletions(-) diff --git a/src/plugins/avf/avf.h b/src/plugins/avf/avf.h index 9836451e012..b0779f2706b 100644 --- a/src/plugins/avf/avf.h +++ b/src/plugins/avf/avf.h @@ -38,6 +38,21 @@ #define AVF_TXD_CMD_RS AVF_TXD_CMD(1) #define AVF_TXD_CMD_RSV AVF_TXD_CMD(2) +#define avf_log_err(dev, f, ...) \ + vlib_log (VLIB_LOG_LEVEL_ERR, avf_main.log_class, "%U: " f, \ + format_vlib_pci_addr, &dev->pci_addr, \ + ## __VA_ARGS__) + +#define avf_log_warn(dev, f, ...) \ + vlib_log (VLIB_LOG_LEVEL_WARNING, avf_main.log_class, "%U: " f, \ + format_vlib_pci_addr, &dev->pci_addr, \ + ## __VA_ARGS__) + +#define avf_log_debug(dev, f, ...) \ + vlib_log (VLIB_LOG_LEVEL_DEBUG, avf_main.log_class, "%U: " f, \ + format_vlib_pci_addr, &dev->pci_addr, \ + ## __VA_ARGS__) + #define foreach_avf_device_flags \ _(0, INITIALIZED, "initialized") \ _(1, ERROR, "error") \ @@ -158,6 +173,7 @@ typedef struct u32 rss_key_size; u32 rss_lut_size; virtchnl_link_speed_t link_speed; + vlib_pci_addr_t pci_addr; /* stats */ virtchnl_eth_stats_t eth_stats; diff --git a/src/plugins/avf/device.c b/src/plugins/avf/device.c index 8f75b828468..8172c8324f7 100644 --- a/src/plugins/avf/device.c +++ b/src/plugins/avf/device.c @@ -43,6 +43,18 @@ static pci_device_id_t avf_pci_device_ids[] = { {0}, }; +const static char *virtchnl_event_names[] = { +#define _(v, n) [v] = #n, + foreach_virtchnl_event_code +#undef _ +}; + +const static char *virtchnl_link_speed_str[] = { +#define _(v, n, s) [v] = s, + foreach_virtchnl_link_speed +#undef _ +}; + static inline void avf_irq_0_disable (avf_device_t * ad) { @@ -487,6 +499,8 @@ avf_op_version (vlib_main_t * vm, avf_device_t * ad, .minor = VIRTCHNL_VERSION_MINOR, }; + avf_log_debug (ad, "version: major %u minor %u", myver.major, myver.minor); + err = avf_send_to_pf (vm, ad, VIRTCHNL_OP_VERSION, &myver, sizeof (virtchnl_version_info_t), ver, sizeof (virtchnl_version_info_t)); @@ -501,12 +515,37 @@ clib_error_t * avf_op_get_vf_resources (vlib_main_t * vm, avf_device_t * ad, virtchnl_vf_resource_t * res) { + clib_error_t *err = 0; u32 bitmap = (VIRTCHNL_VF_OFFLOAD_L2 | VIRTCHNL_VF_OFFLOAD_RSS_PF | VIRTCHNL_VF_OFFLOAD_WB_ON_ITR | VIRTCHNL_VF_OFFLOAD_VLAN | VIRTCHNL_VF_OFFLOAD_RX_POLLING); - return avf_send_to_pf (vm, ad, VIRTCHNL_OP_GET_VF_RESOURCES, &bitmap, - sizeof (u32), res, sizeof (virtchnl_vf_resource_t)); + avf_log_debug (ad, "get_vf_reqources: bitmap 0x%x", bitmap); + err = avf_send_to_pf (vm, ad, VIRTCHNL_OP_GET_VF_RESOURCES, &bitmap, + sizeof (u32), res, sizeof (virtchnl_vf_resource_t)); + + if (err == 0) + { + int i; + avf_log_debug (ad, "get_vf_reqources: num_vsis %u num_queue_pairs %u " + "max_vectors %u max_mtu %u vf_offload_flags 0x%04x " + "rss_key_size %u rss_lut_size %u", + res->num_vsis, res->num_queue_pairs, res->max_vectors, + res->max_mtu, res->vf_offload_flags, res->rss_key_size, + res->rss_lut_size); + for (i = 0; i < res->num_vsis; i++) + avf_log_debug (ad, "get_vf_reqources_vsi[%u]: vsi_id %u " + "num_queue_pairs %u vsi_type %u qset_handle %u " + "default_mac_addr %U", i, + res->vsi_res[i].vsi_id, + res->vsi_res[i].num_queue_pairs, + res->vsi_res[i].vsi_type, + res->vsi_res[i].qset_handle, + format_ethernet_address, + res->vsi_res[i].default_mac_addr); + } + + return err; } clib_error_t * @@ -524,6 +563,10 @@ avf_op_config_rss_lut (vlib_main_t * vm, avf_device_t * ad) for (i = 0; i < ad->rss_lut_size; i++) rl->lut[i] = i % ad->n_rx_queues; + avf_log_debug (ad, "config_rss_lut: vsi_id %u rss_lut_size %u lut %U", + rl->vsi_id, rl->lut_entries, format_hex_bytes, rl->lut, + rl->lut_entries); + return avf_send_to_pf (vm, ad, VIRTCHNL_OP_CONFIG_RSS_LUT, msg, msg_len, 0, 0); } @@ -544,6 +587,10 @@ avf_op_config_rss_key (vlib_main_t * vm, avf_device_t * ad) for (i = 0; i < ad->rss_key_size; i++) rk->key[i] = (u8) random_u32 (&seed); + avf_log_debug (ad, "config_rss_key: vsi_id %u rss_key_size %u key %U", + rk->vsi_id, rk->key_len, format_hex_bytes, rk->key, + rk->key_len); + return avf_send_to_pf (vm, ad, VIRTCHNL_OP_CONFIG_RSS_KEY, msg, msg_len, 0, 0); } @@ -551,6 +598,8 @@ avf_op_config_rss_key (vlib_main_t * vm, avf_device_t * ad) clib_error_t * avf_op_disable_vlan_stripping (vlib_main_t * vm, avf_device_t * ad) { + avf_log_debug (ad, "disable_vlan_stripping"); + return avf_send_to_pf (vm, ad, VIRTCHNL_OP_DISABLE_VLAN_STRIPPING, 0, 0, 0, 0); } @@ -562,6 +611,11 @@ avf_config_promisc_mode (vlib_main_t * vm, avf_device_t * ad) pi.vsi_id = ad->vsi_id; pi.flags = FLAG_VF_UNICAST_PROMISC | FLAG_VF_MULTICAST_PROMISC; + + avf_log_debug (ad, "config_promisc_mode: unicast %s multicast %s", + pi.flags & FLAG_VF_UNICAST_PROMISC ? "on" : "off", + pi.flags & FLAG_VF_MULTICAST_PROMISC ? "on" : "off"); + return avf_send_to_pf (vm, ad, VIRTCHNL_OP_CONFIG_PROMISCUOUS_MODE, &pi, sizeof (virtchnl_promisc_info_t), 0, 0); } @@ -582,6 +636,9 @@ avf_op_config_vsi_queues (vlib_main_t * vm, avf_device_t * ad) ci->vsi_id = ad->vsi_id; ci->num_queue_pairs = n_qp; + avf_log_debug (ad, "config_vsi_queues: vsi_id %u num_queue_pairs %u", + ad->vsi_id, ci->num_queue_pairs); + for (i = 0; i < n_qp; i++) { virtchnl_txq_info_t *txq = &ci->qpair[i].txq; @@ -598,6 +655,10 @@ avf_op_config_vsi_queues (vlib_main_t * vm, avf_device_t * ad) rxq->dma_ring_addr = avf_dma_addr (vm, ad, (void *) q->descs); avf_reg_write (ad, AVF_QRX_TAIL (i), q->size - 1); } + avf_log_debug (ad, "config_vsi_queues_rx[%u]: max_pkt_size %u " + "ring_len %u databuffer_size %u dma_ring_addr 0x%llx", + i, rxq->max_pkt_size, rxq->ring_len, + rxq->databuffer_size, rxq->dma_ring_addr); avf_txq_t *q = vec_elt_at_index (ad->txqs, i); txq->vsi_id = ad->vsi_id; @@ -607,6 +668,9 @@ avf_op_config_vsi_queues (vlib_main_t * vm, avf_device_t * ad) txq->ring_len = q->size; txq->dma_ring_addr = avf_dma_addr (vm, ad, (void *) q->descs); } + avf_log_debug (ad, "config_vsi_queues_tx[%u]: ring_len %u " + "dma_ring_addr 0x%llx", i, txq->ring_len, + txq->dma_ring_addr); } return avf_send_to_pf (vm, ad, VIRTCHNL_OP_CONFIG_VSI_QUEUES, msg, msg_len, @@ -629,6 +693,11 @@ avf_op_config_irq_map (vlib_main_t * vm, avf_device_t * ad) imi->vecmap[0].vector_id = 1; imi->vecmap[0].vsi_id = ad->vsi_id; imi->vecmap[0].rxq_map = 1; + + avf_log_debug (ad, "config_irq_map: vsi_id %u vector_id %u rxq_map %u", + ad->vsi_id, imi->vecmap[0].vector_id, + imi->vecmap[0].rxq_map); + return avf_send_to_pf (vm, ad, VIRTCHNL_OP_CONFIG_IRQ_MAP, msg, msg_len, 0, 0); } @@ -647,8 +716,16 @@ avf_op_add_eth_addr (vlib_main_t * vm, avf_device_t * ad, u8 count, u8 * macs) al = (virtchnl_ether_addr_list_t *) msg; al->vsi_id = ad->vsi_id; al->num_elements = count; + + avf_log_debug (ad, "add_eth_addr: vsi_id %u num_elements %u", + ad->vsi_id, al->num_elements); + for (i = 0; i < count; i++) - clib_memcpy_fast (&al->list[i].addr, macs + i * 6, 6); + { + clib_memcpy_fast (&al->list[i].addr, macs + i * 6, 6); + avf_log_debug (ad, "add_eth_addr[%u]: %U", i, + format_ethernet_address, &al->list[i].addr); + } return avf_send_to_pf (vm, ad, VIRTCHNL_OP_ADD_ETH_ADDR, msg, msg_len, 0, 0); } @@ -661,6 +738,10 @@ avf_op_enable_queues (vlib_main_t * vm, avf_device_t * ad, u32 rx, u32 tx) qs.vsi_id = ad->vsi_id; qs.rx_queues = rx; qs.tx_queues = tx; + + avf_log_debug (ad, "enable_queues: vsi_id %u rx_queues %u tx_queues %u", + ad->vsi_id, qs.rx_queues, qs.tx_queues); + while (rx) { if (rx & (1 << i)) @@ -681,6 +762,9 @@ avf_op_get_stats (vlib_main_t * vm, avf_device_t * ad, { virtchnl_queue_select_t qs = { 0 }; qs.vsi_id = ad->vsi_id; + + avf_log_debug (ad, "get_stats: vsi_id %u", ad->vsi_id); + return avf_send_to_pf (vm, ad, VIRTCHNL_OP_GET_STATS, &qs, sizeof (virtchnl_queue_select_t), es, sizeof (virtchnl_eth_stats_t)); @@ -694,6 +778,8 @@ avf_device_reset (vlib_main_t * vm, avf_device_t * ad) u32 rstat; int n_retry = 20; + avf_log_debug (ad, "reset"); + d.opcode = 0x801; d.v_opcode = VIRTCHNL_OP_RESET_VF; if ((error = avf_aq_desc_enq (vm, ad, &d, 0, 0))) @@ -707,7 +793,10 @@ retry: return 0; if (--n_retry == 0) - return clib_error_return (0, "reset failed (timeout)"); + { + avf_log_err (ad, "reset failed"); + return clib_error_return (0, "reset failed (timeout)"); + } goto retry; } @@ -722,6 +811,8 @@ avf_request_queues (vlib_main_t * vm, avf_device_t * ad, u16 num_queue_pairs) res_req.num_queue_pairs = num_queue_pairs; + avf_log_debug (ad, "request_queues: num_queue_pairs %u", num_queue_pairs); + error = avf_send_to_pf (vm, ad, VIRTCHNL_OP_REQUEST_QUEUES, &res_req, sizeof (virtchnl_vf_res_request_t), &res_req, sizeof (virtchnl_vf_res_request_t)); @@ -825,9 +916,8 @@ avf_device_init (vlib_main_t * vm, avf_main_t * am, avf_device_t * ad, else if (args->rxq_num > ad->num_queue_pairs) { args->rxq_num = ad->num_queue_pairs; - vlib_log_warn (am->log_class, "Requested more rx queues than" - "queue pairs available. Using %u rx queues.", - args->rxq_num); + avf_log_warn (ad, "Requested more rx queues than queue pairs available." + "Using %u rx queues.", args->rxq_num); } for (i = 0; i < args->rxq_num; i++) @@ -892,6 +982,7 @@ avf_process_one_device (vlib_main_t * vm, avf_device_t * ad, int is_irq) if ((r & 0xf0000000) != (1ULL << 31)) { ad->error = clib_error_return (0, "arq not enabled, arqlen = 0x%x", r); + avf_log_err (ad, "error: %U", format_clib_error, ad->error); goto error; } @@ -899,6 +990,7 @@ avf_process_one_device (vlib_main_t * vm, avf_device_t * ad, int is_irq) if ((r & 0xf0000000) != (1ULL << 31)) { ad->error = clib_error_return (0, "atq not enabled, atqlen = 0x%x", r); + avf_log_err (ad, "error: %U", format_clib_error, ad->error); goto error; } @@ -908,6 +1000,8 @@ avf_process_one_device (vlib_main_t * vm, avf_device_t * ad, int is_irq) /* *INDENT-OFF* */ vec_foreach (e, ad->events) { + avf_log_debug (ad, "event: %s (%u) sev %d", + virtchnl_event_names[e->event], e->event, e->severity); if (e->event == VIRTCHNL_EVENT_LINK_CHANGE) { int link_up = e->event_data.link_event.link_status; @@ -915,6 +1009,11 @@ avf_process_one_device (vlib_main_t * vm, avf_device_t * ad, int is_irq) u32 flags = 0; u32 kbps = 0; + avf_log_debug (ad, "event_link_change: status %d speed '%s' (%d)", + link_up, + speed < ARRAY_LEN (virtchnl_link_speed_str) ? + virtchnl_link_speed_str[speed] : "unknown", speed); + if (link_up && (ad->flags & AVF_DEVICE_F_LINK_UP) == 0) { ad->flags |= AVF_DEVICE_F_LINK_UP; @@ -1233,6 +1332,7 @@ avf_create_if (vlib_main_t * vm, avf_create_if_args_t * args) return; } ad->pci_dev_handle = h; + ad->pci_addr = args->addr; ad->numa_node = vlib_pci_get_numa_node (vm, h); vlib_pci_set_private_data (vm, h, ad->dev_instance); @@ -1345,7 +1445,7 @@ error: args->rv = VNET_API_ERROR_INVALID_INTERFACE; args->error = clib_error_return (error, "pci-addr %U", format_vlib_pci_addr, &args->addr); - vlib_log_err (am->log_class, "%U", format_clib_error, args->error); + avf_log_err (ad, "error: %U", format_clib_error, args->error); } static clib_error_t * @@ -1438,7 +1538,7 @@ avf_init (vlib_main_t * vm) vec_validate_aligned (am->per_thread_data, tm->n_vlib_mains - 1, CLIB_CACHE_LINE_BYTES); - am->log_class = vlib_log_register_class ("avf_plugin", 0); + am->log_class = vlib_log_register_class ("avf", 0); vlib_log_debug (am->log_class, "initialized"); return 0; diff --git a/src/plugins/avf/virtchnl.h b/src/plugins/avf/virtchnl.h index 493384cb1d7..7561b65b52b 100644 --- a/src/plugins/avf/virtchnl.h +++ b/src/plugins/avf/virtchnl.h @@ -179,12 +179,17 @@ typedef struct virtchnl_vsi_resource_t vsi_res[1]; } virtchnl_vf_resource_t; +#define foreach_virtchnl_event_code \ + _(0, UNKNOWN) \ + _(1, LINK_CHANGE) \ + _(2, RESET_IMPENDING) \ + _(3, PF_DRIVER_CLOSE) + typedef enum { - VIRTCHNL_EVENT_UNKNOWN = 0, - VIRTCHNL_EVENT_LINK_CHANGE, - VIRTCHNL_EVENT_RESET_IMPENDING, - VIRTCHNL_EVENT_PF_DRIVER_CLOSE, +#define _(a,b) VIRTCHNL_EVENT_##b = (a), + foreach_virtchnl_event_code +#undef _ } virtchnl_event_codes_t; #define foreach_virtchnl_link_speed \ -- 2.16.6