Re: [Intel-wired-lan] [PATCH net-next v6 5/5] ice: use debugfs to output FW log data

[Jacob Keller <jacob.e.keller@intel.com>]

On 1/13/2023 2:23 PM, Paul M Stillwell Jr wrote:
> The FW log data can be quite large so we don't want to use syslog.
> Instead take advantage of debugfs to write the data to.
> 
> The file is binary data and users should send them to us to
> work with the FW team to decode them.
> 
> An example of how to retrieve the data using debugfs is:
> 
> cat /sys/kernel/debug/ice/0000\:18\:00.0/fwlog > fwlog
> 
> Also updated the documentation to add the new parameters.
> 
> Signed-off-by: Paul M Stillwell Jr <paul.m.stillwell.jr@intel.com>
> ---
>  Documentation/networking/devlink/ice.rst      |  39 ++++++
>  drivers/net/ethernet/intel/ice/Makefile       |   4 +-
>  drivers/net/ethernet/intel/ice/ice.h          |  22 ++++
>  .../net/ethernet/intel/ice/ice_adminq_cmd.h   |   1 +
>  drivers/net/ethernet/intel/ice/ice_debugfs.c  | 109 +++++++++++++++
>  drivers/net/ethernet/intel/ice/ice_main.c     | 124 ++++++++++++++----
>  6 files changed, 271 insertions(+), 28 deletions(-)
>  create mode 100644 drivers/net/ethernet/intel/ice/ice_debugfs.c
> 
> diff --git a/Documentation/networking/devlink/ice.rst b/Documentation/networking/devlink/ice.rst
> index 625efb3777d5..546a618ae7a2 100644
> --- a/Documentation/networking/devlink/ice.rst
> +++ b/Documentation/networking/devlink/ice.rst
> @@ -7,6 +7,45 @@ ice devlink support
>  This document describes the devlink features implemented by the ``ice``
>  device driver.
>  
> +Parameters
> +=============
> +
> +.. list-table:: Driver-specific parameters implemented
> +   :widths: 5 5 5 85
> +
> +   * - Name
> +     - Type
> +     - Mode
> +     - Description
> +   * - ``fwlog_supported``
> +     - Boolean
> +     - runtime
> +     - This parameter indicates to the user whether FW loggiing is supported
> +       or not in the currently loaded FW.
> +   * - ``fwlog_enabled``
> +     - Boolean
> +     - runtime
> +     - This parameter indicates to the user whether the driver is currently
> +       getting FW logs or not.
> +   * - ``fwlog_level``
> +     - u8
> +     - runtime
> +     - This parameter indicates the current log level. Each level includes the
> +       messages from the previous/lower level. Valid values are
> +
> +          * ``0`` - no logging
> +          * ``1`` - error logging
> +          * ``2`` - warning logging
> +          * ``3`` - normal logging
> +          * ``4`` - verbose logging
> +   * - ``fwlog_resolution``
> +     - u8
> +     - runtime
> +     - This parameter indicates the number of log messages to included in a
> +       single ARQ event. The range is 1-128 (1 means push every log message,
> +       128 means push only when the max AQ command buffer is full). The
> +       suggested value is 10.
> +
>  Info versions
>  =============
>  
> diff --git a/drivers/net/ethernet/intel/ice/Makefile b/drivers/net/ethernet/intel/ice/Makefile
> index 6e4680ad097c..452a440a9810 100644
> --- a/drivers/net/ethernet/intel/ice/Makefile
> +++ b/drivers/net/ethernet/intel/ice/Makefile
> @@ -34,7 +34,8 @@ ice-y := ice_main.o	\
>  	 ice_ethtool.o  \
>  	 ice_repr.o	\
>  	 ice_tc_lib.o	\
> -	 ice_fwlog.o
> +	 ice_fwlog.o	\
> +	 ice_debugfs.o
>  ice-$(CONFIG_PCI_IOV) +=	\
>  	ice_sriov.o		\
>  	ice_virtchnl.o		\
> @@ -49,3 +50,4 @@ ice-$(CONFIG_RFS_ACCEL) += ice_arfs.o
>  ice-$(CONFIG_XDP_SOCKETS) += ice_xsk.o
>  ice-$(CONFIG_ICE_SWITCHDEV) += ice_eswitch.o
>  ice-$(CONFIG_ICE_GNSS) += ice_gnss.o
> +ice-$(CONFIG_DEBUG_FS) += ice_debugfs.o
> diff --git a/drivers/net/ethernet/intel/ice/ice.h b/drivers/net/ethernet/intel/ice/ice.h
> index 51a1a89f7b5a..49115ac9cd45 100644
> --- a/drivers/net/ethernet/intel/ice/ice.h
> +++ b/drivers/net/ethernet/intel/ice/ice.h
> @@ -550,6 +550,7 @@ struct ice_pf {
>  	struct ice_vsi_stats **vsi_stats;
>  	struct ice_sw *first_sw;	/* first switch created by firmware */
>  	u16 eswitch_mode;		/* current mode of eswitch */
> +	struct dentry *ice_debugfs_pf;
>  	struct ice_vfs vfs;
>  	DECLARE_BITMAP(features, ICE_F_MAX);
>  	DECLARE_BITMAP(state, ICE_STATE_NBITS);
> @@ -632,6 +633,8 @@ struct ice_pf {
>  #define ICE_VF_AGG_NODE_ID_START	65
>  #define ICE_MAX_VF_AGG_NODES		32
>  	struct ice_agg_node vf_agg_node[ICE_MAX_VF_AGG_NODES];
> +	struct list_head fwlog_data_list;
> +	u8 fwlog_list_count;
>  };
>  
>  struct ice_netdev_priv {
> @@ -646,6 +649,15 @@ struct ice_netdev_priv {
>  	struct list_head tc_indr_block_priv_list;
>  };
>  
> +struct ice_fwlog_data {
> +	struct list_head list;
> +	u16 data_size;
> +	u8 *data;
> +};
> +
> +/* define the maximum number of items that can be in the list */
> +#define ICE_FWLOG_MAX_SIZE	128
> +
>  /**
>   * ice_vector_ch_enabled
>   * @qv: pointer to q_vector, can be NULL
> @@ -870,6 +882,16 @@ static inline bool ice_is_adq_active(struct ice_pf *pf)
>  	return false;
>  }
>  
> +#ifdef CONFIG_DEBUG_FS
> +void ice_debugfs_fwlog_init(struct ice_pf *pf);
> +void ice_debugfs_init(void);
> +void ice_debugfs_exit(void);
> +#else
> +static inline void ice_debugfs_fwlog_init(struct ice_pf *pf) { }
> +static inline void ice_debugfs_init(void) { }
> +static inline void ice_debugfs_exit(void) { }
> +#endif /* CONFIG_DEBUG_FS */
> +
>  bool netif_is_ice(struct net_device *dev);
>  int ice_vsi_setup_tx_rings(struct ice_vsi *vsi);
>  int ice_vsi_setup_rx_rings(struct ice_vsi *vsi);
> diff --git a/drivers/net/ethernet/intel/ice/ice_adminq_cmd.h b/drivers/net/ethernet/intel/ice/ice_adminq_cmd.h
> index 1af036beeb45..27c2cea29c51 100644
> --- a/drivers/net/ethernet/intel/ice/ice_adminq_cmd.h
> +++ b/drivers/net/ethernet/intel/ice/ice_adminq_cmd.h
> @@ -2377,6 +2377,7 @@ enum ice_adminq_opc {
>  	ice_aqc_opc_fw_logs_config			= 0xFF30,
>  	ice_aqc_opc_fw_logs_register			= 0xFF31,
>  	ice_aqc_opc_fw_logs_query			= 0xFF32,
> +	ice_aqc_opc_fw_logs_event			= 0xFF33,
>  };
>  
>  #endif /* _ICE_ADMINQ_CMD_H_ */
> diff --git a/drivers/net/ethernet/intel/ice/ice_debugfs.c b/drivers/net/ethernet/intel/ice/ice_debugfs.c
> new file mode 100644
> index 000000000000..682bef0b62e8
> --- /dev/null
> +++ b/drivers/net/ethernet/intel/ice/ice_debugfs.c
> @@ -0,0 +1,109 @@
> +// SPDX-License-Identifier: GPL-2.0
> +/* Copyright (c) 2022, Intel Corporation. */
> +
> +#include <linux/fs.h>
> +#include <linux/debugfs.h>
> +#include <linux/random.h>
> +#include "ice.h"
> +
> +static struct dentry *ice_debugfs_root;
> +
> +/**
> + * ice_debugfs_command_read - read from command datum
> + * @filp: the opened file
> + * @buffer: where to write the data for the user to read
> + * @count: the size of the user's buffer
> + * @ppos: file position offset
> + */
> +static ssize_t ice_debugfs_command_read(struct file *filp, char __user *buffer,
> +					size_t count, loff_t *ppos)
> +{
> +	struct ice_pf *pf = filp->private_data;
> +	struct device *dev = ice_pf_to_dev(pf);
> +	struct ice_fwlog_data *log, *tmp_log;
> +	int data_copied = 0;
> +
> +	if (list_empty(&pf->fwlog_data_list)) {
> +		dev_info(dev, "FW log is empty\n");
> +		return 0;
> +	}

In my opinion this should be a dev_dbg. The fact  that the read returns
zero data indicates that there is no data to extract. I'm not sure we
need to make even an info message appear in this case. (What if for
example someone has a continuous read going in a loop?).

Making it dev_dbg disables it and can be enabled via dynamic debugging
in the event someone wants to know why logs aren't appearing.

> +
> +	list_for_each_entry_safe(log, tmp_log, &pf->fwlog_data_list, list) {
> +		u16 cur_buf_len = log->data_size;
> +		int retval;
> +
> +		if (cur_buf_len > count)
> +			break;
> +
> +		retval = copy_to_user(buffer, log->data, cur_buf_len);
> +		if (retval)
> +			return -EFAULT;
> +

What happens to the data here if we EFAULT in the middle of the read and
we've already copied some elements out and freed them?

Shouldn't we accumulate the data first and then free all the blocks only
after a success? If we return an error code the kernel will assume no
data was read. I would think we'd want to iterate through the list
keeping track of which ones we are going to pop off the queue and only
remove them on a success?

> +		data_copied += cur_buf_len;
> +		buffer += cur_buf_len;
> +		count -= cur_buf_len;
> +		*ppos += cur_buf_len;
> +
> +		/* don't delete the list element until we know it got copied */
> +		kfree(log->data);
> +		list_del(&log->list);
> +		kfree(log);
> +		pf->fwlog_list_count--;

So the only purpose of this is to prevent the case where we have
accumulate messages but they're never read, and the goal I assume is to
avoid running out of memory?

> +	}
> +
> +	return data_copied;
> +}
> +
> +static const struct file_operations ice_debugfs_command_fops = {
> +	.owner = THIS_MODULE,
> +	.open  = simple_open,
> +	.read = ice_debugfs_command_read,
> +};
> +
> +/**
> + * ice_debugfs_fwlog_init - setup the debugfs directory
> + * @pf: the ice that is starting up
> + */
> +void ice_debugfs_fwlog_init(struct ice_pf *pf)
> +{
> +	const char *name = pci_name(pf->pdev);
> +	struct dentry *pfile;
> +
> +	/* only support fw log commands on PF 0 */
> +	if (pf->hw.bus.func)
> +		return;
> +
> +	pf->ice_debugfs_pf = debugfs_create_dir(name, ice_debugfs_root);
> +	if (IS_ERR(pf->ice_debugfs_pf))
> +		return;
> +
> +	pfile = debugfs_create_file("fwlog", 0400, pf->ice_debugfs_pf, pf,
> +				    &ice_debugfs_command_fops);
> +	if (!pfile)
> +		goto create_failed;
> +
> +	return;
> +
> +create_failed:
> +	dev_err(ice_pf_to_dev(pf), "debugfs dir/file for %s failed\n", name);
> +	debugfs_remove_recursive(pf->ice_debugfs_pf);
> +}
> +
> +/**
> + * ice_debugfs_init - create root directory for debugfs entries
> + */
> +void ice_debugfs_init(void)
> +{
> +	ice_debugfs_root = debugfs_create_dir(KBUILD_MODNAME, NULL);
> +	if (IS_ERR(ice_debugfs_root))
> +		pr_info("init of debugfs failed\n");
> +}
> +
> +/**
> + * ice_debugfs_exit - remove debugfs entries
> + */
> +void ice_debugfs_exit(void)
> +{
> +	debugfs_remove_recursive(ice_debugfs_root);
> +	ice_debugfs_root = NULL;
> +}
> diff --git a/drivers/net/ethernet/intel/ice/ice_main.c b/drivers/net/ethernet/intel/ice/ice_main.c
> index f24693e42e35..e689b96b3ef7 100644
> --- a/drivers/net/ethernet/intel/ice/ice_main.c
> +++ b/drivers/net/ethernet/intel/ice/ice_main.c
> @@ -1212,6 +1212,43 @@ ice_handle_link_event(struct ice_pf *pf, struct ice_rq_event_info *event)
>  	return status;
>  }
>  
> +/**
> + * ice_get_fwlog_data - copy the FW log data from ARQ event
> + * @pf: PF that the FW log event is associated with
> + * @event: event structure containing FW log data
> + */
> +static void
> +ice_get_fwlog_data(struct ice_pf *pf, struct ice_rq_event_info *event)
> +{
> +	struct device *dev = ice_pf_to_dev(pf);
> +	struct ice_fwlog_data *fwlog;
> +
> +	if (pf->fwlog_list_count >= ICE_FWLOG_MAX_SIZE)
> +		return;
> +
> +	fwlog = kzalloc(sizeof(*fwlog), GFP_KERNEL);
> +	if (!fwlog) {
> +		dev_warn(dev, "Couldn't allocate memory for FWlog element\n");
> +		return;
> +	}

For data like this I wonder if we'd be better served using vmalloc so
taht it can be virtual memory. That could help since we might accumulate
quite a large amount of data before it gets read by the userspace...

I used vmalloc for the snapshots of NVM and Shadow RAM for example. I
don't think this *has* to be non-virtual memory, but I am not really
sure what other tradeoff that would have.

> +
> +	INIT_LIST_HEAD(&fwlog->list);
> +
> +	fwlog->data_size = le16_to_cpu(event->desc.datalen);
> +	fwlog->data = kzalloc(fwlog->data_size, GFP_KERNEL);
> +	if (!fwlog->data) {
> +		dev_warn(dev, "Couldn't allocate memory for FWlog data\n");
> +		kfree(fwlog);
> +		return;
> +	}
> +
> +	memcpy(fwlog->data, event->msg_buf, fwlog->data_size);
> +
> +	list_add_tail(&fwlog->list, &pf->fwlog_data_list);
> +
> +	pf->fwlog_list_count++;
> +}
> +
>  enum ice_aq_task_state {
>  	ICE_AQ_TASK_WAITING = 0,
>  	ICE_AQ_TASK_COMPLETE,
> @@ -1485,6 +1522,9 @@ static int __ice_clean_ctrlq(struct ice_pf *pf, enum ice_ctl_q q_type)
>  			if (!ice_is_malicious_vf(pf, &event, i, pending))
>  				ice_vc_process_vf_msg(pf, &event);
>  			break;
> +		case ice_aqc_opc_fw_logs_event:
> +			ice_get_fwlog_data(pf, &event);
> +			break;
>  		case ice_aqc_opc_lldp_set_mib_change:
>  			ice_dcb_process_lldp_set_mib_change(pf, &event);
>  			break;
> @@ -4497,33 +4537,6 @@ static void ice_unregister_netdev(struct ice_vsi *vsi)
>  	clear_bit(ICE_VSI_NETDEV_REGISTERED, vsi->state);
>  }
>  
> -/**
> - * ice_pf_fwlog_deinit - clear FW logging metadata on device exit
> - * @pf: pointer to the PF struct
> - */
> -static void ice_pf_fwlog_deinit(struct ice_pf *pf)
> -{
> -	struct ice_hw *hw = &pf->hw;
> -
> -	/* make sure FW logging is disabled to not put the FW in a weird state
> -	 * for the next driver load
> -	 */
> -	if (hw->fwlog_ena) {
> -		int status;
> -
> -		hw->fwlog_cfg.options &= ~ICE_FWLOG_OPTION_ARQ_ENA;
> -		status = ice_fwlog_set(hw, &hw->fwlog_cfg);
> -		if (status)
> -			dev_warn(ice_pf_to_dev(pf), "Unable to turn off FW logging, status: %d\n",
> -				 status);
> -
> -		status = ice_fwlog_unregister(hw);
> -		if (status)
> -			dev_warn(ice_pf_to_dev(pf), "Unable to unregister FW logging, status: %d\n",
> -				 status);
> -	}
> -}
> -
>  /**
>   * ice_cfg_netdev - Allocate, configure and register a netdev
>   * @vsi: the VSI associated with the new netdev
> @@ -4650,6 +4663,56 @@ static void ice_deinit_eth(struct ice_pf *pf)
>  	ice_decfg_netdev(vsi);
>  }
>  
> +/**
> + * ice_pf_fwlog_init - initialize FW logging on device init
> + * @pf: pointer to the PF struct
> + */
> +static void ice_pf_fwlog_init(struct ice_pf *pf)
> +{
> +	/* only supported on PF 0 */
> +	if (pf->hw.bus.func)
> +		return;
> +
> +	INIT_LIST_HEAD(&pf->fwlog_data_list);
> +}
> +
> +/**
> + * ice_pf_fwlog_deinit - clear FW logging metadata on device exit
> + * @pf: pointer to the PF struct
> + */
> +static void ice_pf_fwlog_deinit(struct ice_pf *pf)
> +{
> +	struct ice_fwlog_data *fwlog, *fwlog_tmp;
> +	struct ice_hw *hw = &pf->hw;
> +
> +	/* only supported on PF 0 */
> +	if (pf->hw.bus.func)
> +		return;
> +
> +	/* make sure FW logging is disabled to not put the FW in a weird state
> +	 * for the next driver load
> +	 */
> +	if (hw->fwlog_ena) {
> +		int status;
> +
> +		hw->fwlog_cfg.options &= ~ICE_FWLOG_OPTION_ARQ_ENA;
> +		status = ice_fwlog_set(hw, &hw->fwlog_cfg);
> +		if (status)
> +			dev_warn(ice_pf_to_dev(pf), "Unable to turn off FW logging, status: %d\n",
> +				 status);
> +
> +		status = ice_fwlog_unregister(hw);
> +		if (status)
> +			dev_warn(ice_pf_to_dev(pf), "Unable to unregister FW logging, status: %d\n",
> +				 status);
> +	}
> +
> +	list_for_each_entry_safe(fwlog, fwlog_tmp, &pf->fwlog_data_list, list) {
> +		kfree(fwlog->data);
> +		kfree(fwlog);
> +	}
> +}
> +
>  static int ice_init_dev(struct ice_pf *pf)
>  {
>  	struct device *dev = ice_pf_to_dev(pf);
> @@ -5153,6 +5216,9 @@ ice_probe(struct pci_dev *pdev, const struct pci_device_id __always_unused *ent)
>  		hw->debug_mask = debug;
>  #endif
>  
> +	ice_pf_fwlog_init(pf);
> +	ice_debugfs_fwlog_init(pf);
> +
>  	err = ice_init(pf);
>  	if (err)
>  		goto err_init;
> @@ -5262,6 +5328,7 @@ static void ice_remove(struct pci_dev *pdev)
>  	}
>  
>  	ice_pf_fwlog_deinit(pf);
> +	ice_debugfs_exit();
>  
>  	if (test_bit(ICE_FLAG_SRIOV_ENA, pf->flags)) {
>  		set_bit(ICE_VF_RESETS_DISABLED, pf->state);
> @@ -5725,10 +5792,13 @@ static int __init ice_module_init(void)
>  		return -ENOMEM;
>  	}
>  
> +	ice_debugfs_init();
> +
>  	status = pci_register_driver(&ice_driver);
>  	if (status) {
>  		pr_err("failed to register PCI driver, err %d\n", status);
>  		destroy_workqueue(ice_wq);
> +		ice_debugfs_exit();
>  	}
>  
>  	return status;
_______________________________________________
Intel-wired-lan mailing list
Intel-wired-lan@osuosl.org
https://lists.osuosl.org/mailman/listinfo/intel-wired-lan