From 5b6ae8de4fd0d7855f8f38426dd4524ebcb15fee Mon Sep 17 00:00:00 2001 From: Damjan Marion Date: Wed, 18 Apr 2018 17:00:18 +0200 Subject: dpdk: improve logging - use of vlib_log for non-dataplane logging - redirect of dpdk logs trough unix pipe into vlib_log - "show dpdk physmem" cli Change-Id: I5da70f9c130273072a8cc80d169df31fc216b2c2 Signed-off-by: Damjan Marion --- src/plugins/dpdk/device/cli.c | 92 +++++++++++++++++++++++++++++++++++++++- src/plugins/dpdk/device/common.c | 30 +++++++------ src/plugins/dpdk/device/dpdk.h | 12 ++++++ src/plugins/dpdk/device/init.c | 88 ++++++++++++++++++++++++++++---------- 4 files changed, 187 insertions(+), 35 deletions(-) (limited to 'src/plugins') diff --git a/src/plugins/dpdk/device/cli.c b/src/plugins/dpdk/device/cli.c index c9fcea5c8d5..2eaf17e55a5 100644 --- a/src/plugins/dpdk/device/cli.c +++ b/src/plugins/dpdk/device/cli.c @@ -12,11 +12,16 @@ * See the License for the specific language governing permissions and * limitations under the License. */ + +#include +#include + #include #include #include #include #include +#include #include #include @@ -376,7 +381,7 @@ show_dpdk_buffer (vlib_main_t * vm, unformat_input_t * input, * @cliexend ?*/ /* *INDENT-OFF* */ -VLIB_CLI_COMMAND (cmd_show_dpdk_bufferr,static) = { +VLIB_CLI_COMMAND (cmd_show_dpdk_buffer,static) = { .path = "show dpdk buffer", .short_help = "show dpdk buffer", .function = show_dpdk_buffer, @@ -384,6 +389,91 @@ VLIB_CLI_COMMAND (cmd_show_dpdk_bufferr,static) = { }; /* *INDENT-ON* */ +static clib_error_t * +show_dpdk_physmem (vlib_main_t * vm, unformat_input_t * input, + vlib_cli_command_t * cmd) +{ + clib_error_t *err = 0; + u32 pipe_max_size; + int fds[2]; + u8 *s = 0; + int n, n_try; + FILE *f; + + err = clib_sysfs_read ("/proc/sys/fs/pipe-max-size", "%u", &pipe_max_size); + + if (err) + return err; + + if (pipe (fds) == -1) + return clib_error_return_unix (0, "pipe"); + +#ifndef F_SETPIPE_SZ +#define F_SETPIPE_SZ (1024 + 7) +#endif + + if (fcntl (fds[1], F_SETPIPE_SZ, pipe_max_size) == -1) + { + err = clib_error_return_unix (0, "fcntl(F_SETPIPE_SZ)"); + goto error; + } + + if (fcntl (fds[0], F_SETFL, O_NONBLOCK) == -1) + { + err = clib_error_return_unix (0, "fcntl(F_SETFL)"); + goto error; + } + + if ((f = fdopen (fds[1], "a")) == 0) + { + err = clib_error_return_unix (0, "fdopen"); + goto error; + } + + rte_dump_physmem_layout (f); + fflush (f); + + n = n_try = 4096; + while (n == n_try) + { + uword len = vec_len (s); + vec_resize (s, len + n_try); + + n = read (fds[0], s + len, n_try); + if (n < 0 && errno != EAGAIN) + { + err = clib_error_return_unix (0, "read"); + goto error; + } + _vec_len (s) = len + (n < 0 ? 0 : n); + } + + vlib_cli_output (vm, "%v", s); + +error: + close (fds[0]); + close (fds[1]); + vec_free (s); + return err; +} + +/*? + * This command displays DPDK physmem layout + * + * @cliexpar + * Example of how to display DPDK physmem layout: + * @cliexstart{show dpdk physmem} + * @cliexend +?*/ +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (cmd_show_dpdk_physmem,static) = { + .path = "show dpdk physmem", + .short_help = "show dpdk physmem", + .function = show_dpdk_physmem, + .is_mp_safe = 1, +}; +/* *INDENT-ON* */ + static clib_error_t * test_dpdk_buffer (vlib_main_t * vm, unformat_input_t * input, vlib_cli_command_t * cmd) diff --git a/src/plugins/dpdk/device/common.c b/src/plugins/dpdk/device/common.c index 3f113aaf22f..77a7dee8a1b 100644 --- a/src/plugins/dpdk/device/common.c +++ b/src/plugins/dpdk/device/common.c @@ -30,6 +30,9 @@ void dpdk_device_error (dpdk_device_t * xd, char *str, int rv) { + dpdk_log_err ("Interface %U error %d: %s", + format_dpdk_device_name, xd->device_index, rv, + rte_strerror (rv)); xd->errors = clib_error_return (xd->errors, "%s[port:%d, errno:%d]: %s", str, xd->device_index, rv, rte_strerror (rv)); @@ -166,6 +169,9 @@ dpdk_device_start (dpdk_device_t * xd) rte_eth_allmulticast_enable (dpdk_port); } } + + dpdk_log_info ("Interface %U started", + format_dpdk_device_name, xd->device_index); } void @@ -188,6 +194,8 @@ dpdk_device_stop (dpdk_device_t * xd) rte_eth_dev_stop (dpdk_port); } } + dpdk_log_info ("Interface %U stopped", + format_dpdk_device_name, xd->device_index); } /* Even type for send_garp_na_process */ @@ -258,7 +266,7 @@ dpdk_port_state_callback_inline (dpdk_portid_t port_id, RTE_SET_USED (param); if (type != RTE_ETH_EVENT_INTR_LSC) { - clib_warning ("Unknown event %d received for port %d", type, port_id); + dpdk_log_info ("Unknown event %d received for port %d", type, port_id); return -1; } @@ -269,12 +277,10 @@ dpdk_port_state_callback_inline (dpdk_portid_t port_id, { uword bd_port = xd->bond_port; int bd_mode = rte_eth_bond_mode_get (bd_port); -#if 0 - clib_warning ("Port %d state to %s, " - "slave of port %d BondEthernet%d in mode %d", - port_id, (link_up) ? "UP" : "DOWN", - bd_port, xd->port_id, bd_mode); -#endif + dpdk_log_info ("Port %d state to %s, " + "slave of port %d BondEthernet%d in mode %d", + port_id, (link_up) ? "UP" : "DOWN", + bd_port, xd->port_id, bd_mode); if (bd_mode == BONDING_MODE_ACTIVE_BACKUP) { vl_api_force_rpc_call_main_thread @@ -289,12 +295,12 @@ dpdk_port_state_callback_inline (dpdk_portid_t port_id, else /* Should not happen as callback not setup for "normal" links */ { if (link_up) - clib_warning ("Port %d Link Up - speed %u Mbps - %s", - port_id, (unsigned) link.link_speed, - (link.link_duplex == ETH_LINK_FULL_DUPLEX) ? - "full-duplex" : "half-duplex"); + dpdk_log_info ("Port %d Link Up - speed %u Mbps - %s", + port_id, (unsigned) link.link_speed, + (link.link_duplex == ETH_LINK_FULL_DUPLEX) ? + "full-duplex" : "half-duplex"); else - clib_warning ("Port %d Link Down\n\n", port_id); + dpdk_log_info ("Port %d Link Down\n\n", port_id); } return 0; diff --git a/src/plugins/dpdk/device/dpdk.h b/src/plugins/dpdk/device/dpdk.h index d52e96634e2..896617bd55f 100644 --- a/src/plugins/dpdk/device/dpdk.h +++ b/src/plugins/dpdk/device/dpdk.h @@ -400,6 +400,9 @@ typedef struct /* API message ID base */ u16 msg_id_base; + + /* logging */ + vlib_log_class_t log_default; } dpdk_main_t; extern dpdk_main_t dpdk_main; @@ -450,6 +453,15 @@ typedef enum DPDK_N_ERROR, } dpdk_error_t; +#define dpdk_log_err(...) \ + vlib_log(VLIB_LOG_LEVEL_ERR, dpdk_main.log_default, __VA_ARGS__) +#define dpdk_log_warn(...) \ + vlib_log(VLIB_LOG_LEVEL_WARNING, dpdk_main.log_default, __VA_ARGS__) +#define dpdk_log_notice(...) \ + vlib_log(VLIB_LOG_LEVEL_NOTICE, dpdk_main.log_default, __VA_ARGS__) +#define dpdk_log_info(...) \ + vlib_log(VLIB_LOG_LEVEL_INFO, dpdk_main.log_default, __VA_ARGS__) + void dpdk_update_link_state (dpdk_device_t * xd, f64 now); format_function_t format_dpdk_device_name; diff --git a/src/plugins/dpdk/device/init.c b/src/plugins/dpdk/device/init.c index 33cc4455657..17ae826e8b1 100755 --- a/src/plugins/dpdk/device/init.c +++ b/src/plugins/dpdk/device/init.c @@ -19,6 +19,7 @@ #include #include #include +#include #include #include @@ -227,11 +228,11 @@ dpdk_lib_init (dpdk_main_t * dm) nports = rte_eth_dev_count (); if (nports < 1) { - clib_warning ("DPDK drivers found no ports..."); + dpdk_log_notice ("DPDK drivers found no ports..."); } if (CLIB_DEBUG > 0) - clib_warning ("DPDK drivers found %d ports...", nports); + dpdk_log_notice ("DPDK drivers found %d ports...", nports); if (dm->conf->enable_tcp_udp_checksum) dm->buffer_flags_template &= ~(VNET_BUFFER_F_L4_CHECKSUM_CORRECT @@ -660,7 +661,7 @@ dpdk_lib_init (dpdk_main_t * dm) dpdk_device_setup (xd); if (vec_len (xd->errors)) - clib_warning ("setup failed for device %U. Errors:\n %U", + dpdk_log_err ("setup failed for device %U. Errors:\n %U", format_dpdk_device_name, i, format_dpdk_device_errors, xd); @@ -683,7 +684,7 @@ dpdk_lib_init (dpdk_main_t * dm) if (devconf->vlan_strip_offload != DPDK_DEVICE_VLAN_STRIP_OFF) vlan_strip = 1; /* remove vlan tag from VIC port by default */ else - clib_warning ("VLAN strip disabled for interface\n"); + dpdk_log_warn ("VLAN strip disabled for interface\n"); } else if (devconf->vlan_strip_offload == DPDK_DEVICE_VLAN_STRIP_ON) vlan_strip = 1; @@ -695,9 +696,9 @@ dpdk_lib_init (dpdk_main_t * dm) vlan_off |= ETH_VLAN_STRIP_OFFLOAD; xd->port_conf.rxmode.hw_vlan_strip = vlan_off; if (rte_eth_dev_set_vlan_offload (xd->device_index, vlan_off) == 0) - clib_warning ("VLAN strip enabled for interface\n"); + dpdk_log_info ("VLAN strip enabled for interface\n"); else - clib_warning ("VLAN strip cannot be supported by interface\n"); + dpdk_log_warn ("VLAN strip cannot be supported by interface\n"); } if (hi) @@ -710,7 +711,7 @@ dpdk_lib_init (dpdk_main_t * dm) } if (nb_desc > dm->conf->num_mbufs) - clib_warning ("%d mbufs allocated but total rx/tx ring size is %d\n", + dpdk_log_err ("%d mbufs allocated but total rx/tx ring size is %d\n", dm->conf->num_mbufs, nb_desc); return 0; @@ -788,7 +789,7 @@ dpdk_bind_devices_to_uio (dpdk_config_main_t * conf) } else { - clib_warning ("Unsupported PCI device 0x%04x:0x%04x found " + dpdk_log_warn ("Unsupported PCI device 0x%04x:0x%04x found " "at PCI address %s\n", (u16) d->vendor_id, (u16) d->device_id, pci_addr); continue; @@ -914,6 +915,37 @@ dpdk_device_config (dpdk_config_main_t * conf, vlib_pci_addr_t pci_addr, return error; } +static clib_error_t * +dpdk_log_read_ready (clib_file_t * uf) +{ + unformat_input_t input; + u8 *line, *s = 0; + int n, n_try; + + n = n_try = 4096; + while (n == n_try) + { + uword len = vec_len (s); + vec_resize (s, len + n_try); + + n = read (uf->file_descriptor, s + len, n_try); + if (n < 0 && errno != EAGAIN) + return clib_error_return_unix (0, "read"); + _vec_len (s) = len + (n < 0 ? 0 : n); + } + + unformat_init_vector (&input, s); + + while (unformat_user (&input, unformat_line, &line)) + { + dpdk_log_notice ("%v", line); + vec_free (line); + } + + unformat_free (&input); + return 0; +} + static clib_error_t * dpdk_config (vlib_main_t * vm, unformat_input_t * input) { @@ -1264,6 +1296,19 @@ dpdk_config (vlib_main_t * vm, unformat_input_t * input) /* Set up DPDK eal and packet mbuf pool early. */ rte_log_set_global_level (log_level); + int log_fds[2] = { 0 }; + if (pipe (log_fds) == 0) + { + FILE *f = fdopen (log_fds[1], "a"); + if (f && rte_openlog_stream (f) == 0) + { + clib_file_t t = { 0 }; + t.read_function = dpdk_log_read_ready; + t.file_descriptor = log_fds[0]; + t.description = format (0, "DPDK logging pipe"); + clib_file_add (&file_main, &t); + } + } vm = vlib_get_main (); @@ -1272,10 +1317,9 @@ dpdk_config (vlib_main_t * vm, unformat_input_t * input) conf->eal_init_args_str = format (conf->eal_init_args_str, "%s ", conf->eal_init_args[i]); - clib_warning ("EAL init args: %s", conf->eal_init_args_str); - ret = - rte_eal_init (vec_len (conf->eal_init_args), - (char **) conf->eal_init_args); + dpdk_log_warn ("EAL init args: %s", conf->eal_init_args_str); + ret = rte_eal_init (vec_len (conf->eal_init_args), + (char **) conf->eal_init_args); /* lazy umount hugepages */ umount2 ((char *) huge_dir_path, MNT_DETACH); @@ -1285,10 +1329,6 @@ dpdk_config (vlib_main_t * vm, unformat_input_t * input) if (ret < 0) return clib_error_return (0, "rte_eal_init returned %d", ret); - /* Dump the physical memory layout prior to creating the mbuf_pool */ - fprintf (stdout, "DPDK physical memory layout:\n"); - rte_dump_physmem_layout (stdout); - /* set custom ring memory allocator */ { struct rte_mempool_ops *ops = NULL; @@ -1432,7 +1472,7 @@ dpdk_update_link_state (dpdk_device_t * xd, f64 now) case 0: break; default: - clib_warning ("unknown link speed %d", xd->link.link_speed); + dpdk_log_warn ("unknown link speed %d", xd->link.link_speed); break; } } @@ -1517,12 +1557,12 @@ dpdk_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f) (slink[0], (struct ether_addr *) addr); /* Set MAC of bounded interface to that of 1st slave link */ - clib_warning ("Set MAC for bond port %d BondEthernet%d", - i, xd->port_id); + dpdk_log_info ("Set MAC for bond port %d BondEthernet%d", + i, xd->port_id); rv = rte_eth_bond_mac_address_set (i, (struct ether_addr *) addr); if (rv) - clib_warning ("Set MAC addr failure rv=%d", rv); + dpdk_log_warn ("Set MAC addr failure rv=%d", rv); /* Populate MAC of bonded interface in VPP hw tables */ bhi = vnet_get_hw_interface @@ -1547,11 +1587,13 @@ dpdk_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f) /* Add MAC to all slave links except the first one */ if (nlink) { - clib_warning ("Add MAC for slave port %d", slave); + dpdk_log_info ("Add MAC for slave port %d", + slave); rv = rte_eth_dev_mac_addr_add (slave, (struct ether_addr *) addr, 0); if (rv) - clib_warning ("Add MAC addr failure rv=%d", rv); + dpdk_log_warn ("Add MAC addr failure rv=%d", + rv); } /* Setup slave link state change callback handling */ rte_eth_dev_callback_register @@ -1665,6 +1707,8 @@ dpdk_init (vlib_main_t * vm) if ((error = vlib_call_init_function (vm, dpdk_cli_init))) return error; + dm->log_default = vlib_log_register_class ("dpdk", 0); + return error; } -- cgit 1.2.3-korg