Re: [PATCH v3 17/17] nvmet-fc: add extensive debug logging

[Hannes Reinecke <hare@suse.de>]

On 12/18/23 16:31, Daniel Wagner wrote:
> Signed-off-by: Daniel Wagner <dwagner@suse.de>

Well ... all previous patches had 'XX/16', only this has '17/17'.
Late addendum?
But in either case, please ensure correct counting (and spelling!)
on the next submission.

> ---
>   drivers/nvme/target/configfs.c |   4 +
>   drivers/nvme/target/core.c     |  13 ++++
>   drivers/nvme/target/fc.c       | 132 +++++++++++++++++++++++++++++----
>   3 files changed, 135 insertions(+), 14 deletions(-)
> 
> diff --git a/drivers/nvme/target/configfs.c b/drivers/nvme/target/configfs.c
> index e307a044b1a1..ea05e8c62d4b 100644
> --- a/drivers/nvme/target/configfs.c
> +++ b/drivers/nvme/target/configfs.c
> @@ -965,6 +965,7 @@ static int nvmet_port_subsys_allow_link(struct config_item *parent,
>   			goto out_free_link;
>   	}
>   
> +	pr_info("%s: %s\n", __func__, subsys->subsysnqn);

If this is debug logging, would 'pr_debug' be more accurate?

>   	if (list_empty(&port->subsystems)) {
>   		ret = nvmet_enable_port(port);
>   		if (ret)
> @@ -1050,6 +1051,7 @@ static int nvmet_allowed_hosts_allow_link(struct config_item *parent,
>   		if (!strcmp(nvmet_host_name(p->host), nvmet_host_name(host)))
>   			goto out_free_link;
>   	}
> +	pr_info("%s: adding hostnqn %s\n", __func__, nvmet_host_name(host));
>   	list_add_tail(&link->entry, &subsys->hosts);
>   	nvmet_subsys_disc_changed(subsys, host);
>   
> @@ -1879,6 +1881,8 @@ static struct config_group *nvmet_ports_make(struct config_group *group,
>   	u16 portid;
>   	u32 i;
>   
> +	pr_info("%s\n", __func__);
> +
The meaning of this is ... what?
Of course this function is called when a port is created. So why do you 
need to log that in the message log?

>   	if (kstrtou16(name, 0, &portid))
>   		return ERR_PTR(-EINVAL);
>   
> diff --git a/drivers/nvme/target/core.c b/drivers/nvme/target/core.c
> index 3935165048e7..4d5a9e4fcc9d 100644
> --- a/drivers/nvme/target/core.c
> +++ b/drivers/nvme/target/core.c
> @@ -308,8 +308,11 @@ void nvmet_port_del_ctrls(struct nvmet_port *port, struct nvmet_subsys *subsys)
>   {
>   	struct nvmet_ctrl *ctrl;
>   
> +	pr_info("%s: subsys %s port %p\n", __func__, subsys->subsysnqn, port);
> +
pr_debug()

>   	mutex_lock(&subsys->lock);
>   	list_for_each_entry(ctrl, &subsys->ctrls, subsys_entry) {
> +		pr_info("%s: ctrl %p ctrl->port %p\n", __func__, ctrl, ctrl->port);
>   		if (ctrl->port == port)
>   			ctrl->ops->delete_ctrl(ctrl);
>   	}
> @@ -1458,6 +1461,8 @@ u16 nvmet_alloc_ctrl(const char *subsysnqn, const char *hostnqn,
>   	mutex_unlock(&subsys->lock);
>   
>   	*ctrlp = ctrl;
> +
> +	pr_info("%s: ctrl %p, subsysnqn %s hostnqn %s\n", __func__, ctrl, subsysnqn, hostnqn);

Wouldn't it be better to list the controller id, too?

>   	return 0;
>   
>   out_free_sqs:
> @@ -1477,6 +1482,8 @@ static void nvmet_ctrl_free(struct kref *ref)
>   	struct nvmet_ctrl *ctrl = container_of(ref, struct nvmet_ctrl, ref);
>   	struct nvmet_subsys *subsys = ctrl->subsys;
>   
> +	pr_info("%s: ctrl %p %s\n", __func__, ctrl, ctrl->subsysnqn);
> +

Please, no pointer, use the controller id instead.

>   	mutex_lock(&subsys->lock);
>   	nvmet_release_p2p_ns_map(ctrl);
>   	list_del(&ctrl->subsys_entry);
> @@ -1550,6 +1557,8 @@ struct nvmet_subsys *nvmet_subsys_alloc(const char *subsysnqn,
>   	char serial[NVMET_SN_MAX_SIZE / 2];
>   	int ret;
>   
> +	pr_info("%s\n", __func__);
> +
See above. Pretty pointless.

>   	subsys = kzalloc(sizeof(*subsys), GFP_KERNEL);
>   	if (!subsys)
>   		return ERR_PTR(-ENOMEM);
> @@ -1620,6 +1629,8 @@ static void nvmet_subsys_free(struct kref *ref)
>   
>   	WARN_ON_ONCE(!xa_empty(&subsys->namespaces));
>   
> +	pr_info("%s\n", __func__);
> +
>   	xa_destroy(&subsys->namespaces);
>   	nvmet_passthru_subsys_free(subsys);
>   
> @@ -1633,6 +1644,8 @@ void nvmet_subsys_del_ctrls(struct nvmet_subsys *subsys)
>   {
>   	struct nvmet_ctrl *ctrl;
>   
> +	pr_info("%s\n", __func__);
> +
>   	mutex_lock(&subsys->lock);
>   	list_for_each_entry(ctrl, &subsys->ctrls, subsys_entry)
>   		ctrl->ops->delete_ctrl(ctrl);
> diff --git a/drivers/nvme/target/fc.c b/drivers/nvme/target/fc.c
> index 455d35ef97eb..d50ff29697fc 100644
> --- a/drivers/nvme/target/fc.c
> +++ b/drivers/nvme/target/fc.c
> @@ -242,6 +242,31 @@ static LIST_HEAD(nvmet_fc_target_list);
>   static DEFINE_IDA(nvmet_fc_tgtport_cnt);
>   static LIST_HEAD(nvmet_fc_portentry_list);
>   
> +static void __nvmet_fc_tgtport_put(struct nvmet_fc_tgtport *tgtport);
> +static int __nvmet_fc_tgtport_get(struct nvmet_fc_tgtport *tgtport);
> +
> +#if 1
> +#define nvmet_fc_tgtport_put(p)						\
> +({									\
> +	pr_info("nvmet_fc_tgtport_put: %p %d %s:%d\n",	\
> +		p, atomic_read(&p->ref.refcount.refs),			\
> +		__func__, __LINE__);					\
> +	__nvmet_fc_tgtport_put(p);					\
> +})
> +
> +#define nvmet_fc_tgtport_get(p)						\
> +({									\
> +	int ___r = __nvmet_fc_tgtport_get(p);				\
> +									\
> +	pr_info("nvmet_fc_tgtport_get: %p %d %s:%d\n",			\
> +		p, atomic_read(&p->ref.refcount.refs),			\
> +		__func__, __LINE__);					\
> +	___r;								\
> +})
> +#else
> +#define nvmet_fc_tgtport_put(p) __nvmet_fc_tgtport_put(p)
> +#define nvmet_fc_tgtport_get(p) __nvmet_fc_tgtport_get(p)
> +#endif
>   
>   static void nvmet_fc_handle_ls_rqst_work(struct work_struct *work);
>   static void nvmet_fc_fcp_rqst_op_defer_work(struct work_struct *work);
> @@ -252,12 +277,84 @@ static void nvmet_fc_put_tgtport_work(struct work_struct *work)
>   
>   	nvmet_fc_tgtport_put(tgtport);
>   }
> -static void nvmet_fc_tgt_a_put(struct nvmet_fc_tgt_assoc *assoc);
> -static int nvmet_fc_tgt_a_get(struct nvmet_fc_tgt_assoc *assoc);
> -static void nvmet_fc_tgt_q_put(struct nvmet_fc_tgt_queue *queue);
> -static int nvmet_fc_tgt_q_get(struct nvmet_fc_tgt_queue *queue);
> -static void nvmet_fc_tgtport_put(struct nvmet_fc_tgtport *tgtport);
> -static int nvmet_fc_tgtport_get(struct nvmet_fc_tgtport *tgtport);
> +static void __nvmet_fc_tgt_a_put(struct nvmet_fc_tgt_assoc *assoc);
> +static int __nvmet_fc_tgt_a_get(struct nvmet_fc_tgt_assoc *assoc);
> +
> +#if 1
> +#define nvmet_fc_tgt_a_put(a)						\
> +({									\
> +	pr_info("nvmet_fc_tgt_a_put: %d %d %s:%d \n",			\
> +		a->a_id, atomic_read(&a->ref.refcount.refs),		\
> +		__func__, __LINE__);					\
> +	__nvmet_fc_tgt_a_put(a);					\
> +})
> +
> +#define nvmet_fc_tgt_a_get(a)						\
> +({									\
> +	int ___r = __nvmet_fc_tgt_a_get(a);				\
> +									\
> +	pr_info("nvmet_fc_tgt_a_get: %d %d %s:%d\n",			\
> +		a->a_id, atomic_read(&a->ref.refcount.refs),		\
> +		__func__, __LINE__);					\
> +	___r;								\
> +})
> +#else
> +#define nvmet_fc_tgt_a_put(a) __nvmet_fc_tgt_a_put(a)
> +#define nvmet_fc_tgt_a_get(a) __nvmet_fc_tgt_a_get(a)
> +#endif
> +
> +static void __nvmet_fc_hostport_put(struct nvmet_fc_hostport *hostport);
> +static int __nvmet_fc_hostport_get(struct nvmet_fc_hostport *hostport);
> +
> +#if 0
> +#define nvmet_fc_hostport_put(p)					\
> +({									\
> +	pr_info("nvmet_fc_hostport_put: %p %d %s:%d\n",			\
> +		p, atomic_read(&p->ref.refcount.refs),			\
> +		__func__, __LINE__);					\
> +	__nvmet_fc_hostport_put(p);					\
> +})
> +
> +#define nvmet_fc_hostport_get(p)					\
> +({									\
> +	int ___r = __nvmet_fc_hostport_get(p);				\
> +									\
> +	pr_info("nvmet_fc_hostport_get: %p %d %s:%d\n",			\
> +		p, atomic_read(&p->ref.refcount.refs),			\
> +		__func__, __LINE__);					\
> +	___r;								\
> +})
> +#else
> +#define nvmet_fc_hostport_put(p) __nvmet_fc_hostport_put(p)
> +#define nvmet_fc_hostport_get(p) __nvmet_fc_hostport_get(p)
> +#endif
> +
> +static void __nvmet_fc_tgt_q_put(struct nvmet_fc_tgt_queue *queue);
> +static int __nvmet_fc_tgt_q_get(struct nvmet_fc_tgt_queue *queue);
> +
> +#if 0
If '0'?
Please, no.
Use dynamic debugging.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke                Kernel Storage Architect
hare@suse.de                              +49 911 74053 688
SUSE Software Solutions GmbH, Maxfeldstr. 5, 90409 Nürnberg
HRB 36809 (AG Nürnberg), GF: Ivo Totev, Andrew McDonald,
Werner Knoblich