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 <damarion@cisco.com>

4 files changed, 187 insertions, 35 deletions

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 <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,
@@ -385,6 +390,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 <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;
@@ -915,6 +916,37 @@ dpdk_device_config (dpdk_config_main_t * conf, vlib_pci_addr_t pci_addr,
 }
 
 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)
 {
   clib_error_t *error = 0;
@@ -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;
 }