dpdk: improve logging 91/11891/2
authorDamjan Marion <damarion@cisco.com>
Wed, 18 Apr 2018 15:00:18 +0000 (17:00 +0200)
committerFlorin Coras <florin.coras@gmail.com>
Wed, 18 Apr 2018 18:00:56 +0000 (18:00 +0000)
- 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 <damarion@cisco.com>
src/plugins/dpdk/device/cli.c
src/plugins/dpdk/device/common.c
src/plugins/dpdk/device/dpdk.h
src/plugins/dpdk/device/init.c

index c9fcea5..2eaf17e 100644 (file)
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+
+#include <unistd.h>
+#include <fcntl.h>
+
 #include <vnet/vnet.h>
 #include <vppinfra/vec.h>
 #include <vppinfra/error.h>
 #include <vppinfra/format.h>
 #include <vppinfra/xxhash.h>
+#include <vppinfra/linux/sysfs.c>
 
 #include <vnet/ethernet/ethernet.h>
 #include <dpdk/device/dpdk.h>
@@ -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)
index 3f113aa..77a7dee 100644 (file)
@@ -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;
index d52e966..896617b 100644 (file)
@@ -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;
index 33cc445..17ae826 100755 (executable)
@@ -19,6 +19,7 @@
 #include <vppinfra/bitmap.h>
 #include <vppinfra/linux/sysfs.h>
 #include <vlib/unix/unix.h>
+#include <vlib/log.h>
 
 #include <vnet/ethernet/ethernet.h>
 #include <dpdk/device/dpdk.h>
@@ -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;
 }