Re: [PATCH v2 2/2] baseband/acc: improvement to logging mechanism

[Maxime Coquelin <maxime.coquelin@redhat.com>]

On 9/13/24 21:00, Chautru, Nicolas wrote:
> Hi Maxime,
> 
>> -----Original Message-----
>> From: Maxime Coquelin <maxime.coquelin@redhat.com>
>> Sent: Friday, September 13, 2024 7:18 AM
>> To: Chautru, Nicolas <nicolas.chautru@intel.com>; dev@dpdk.org
>> Cc: hemant.agrawal@nxp.com; Marchand, David
>> <david.marchand@redhat.com>; Vargas, Hernan <hernan.vargas@intel.com>
>> Subject: Re: [PATCH v2 2/2] baseband/acc: improvement to logging
>> mechanism
>>
>>
>>
>> On 8/29/24 22:06, Nicolas Chautru wrote:
>>> Support the new dev op to dump operations information related to a
>>> given queue and information on previous errors detected by the driver
>>> and tracked internally in PMD.
>>>
>>> Signed-off-by: Nicolas Chautru <nicolas.chautru@intel.com>
>>> ---
>>>    drivers/baseband/acc/acc_common.h  |  37 +++++++++
>>>    drivers/baseband/acc/rte_vrb_pmd.c | 128 +++++++++++++++++++++++-----
>> -
>>>    2 files changed, 138 insertions(+), 27 deletions(-)
>>>
>>> diff --git a/drivers/baseband/acc/acc_common.h
>>> b/drivers/baseband/acc/acc_common.h
>>> index e249f37e38..c8914b23e0 100644
>>> --- a/drivers/baseband/acc/acc_common.h
>>> +++ b/drivers/baseband/acc/acc_common.h
>>> @@ -149,6 +149,8 @@
>>>    #define VRB2_VF_ID_SHIFT     6
>>>
>>>    #define ACC_MAX_FFT_WIN      16
>>> +#define ACC_MAX_LOGLEN    256
>>> +#define ACC_MAX_BUFFERLEN 256
>>>
>>>    extern int acc_common_logtype;
>>>
>>> @@ -646,8 +648,43 @@ struct __rte_cache_aligned acc_queue {
>>>    	rte_iova_t fcw_ring_addr_iova;
>>>    	int8_t *derm_buffer; /* interim buffer for de-rm in SDK */
>>>    	struct acc_device *d;
>>> +	char error_bufs[ACC_MAX_BUFFERLEN][ACC_MAX_LOGLEN]; /**<
>> Buffer for
>>> +error log. */
>>
>> 65KB is quite big for each queues
>>
>> I don't see the point of all this, as errors are already logged using
>> rte_bbdev_log. Only thing you miss is the queue/device info in curretn
>> solution, no?
> 
> The rte_bbdev_log is only for std_output which would be disabled by default for real time application so very limited usability.
> Here we store the related information for the application to be able to retrieve themselves as required after the fact (not impacting real time).

If you really care about realtime, then the objects should be saved in
binary form, and post-processed into strings in the dump function.

Doing this, no wasted CPU cycles in the datapath performing strings 
processing, and less memory wasted.

> 
>>
>>> +	uint16_t error_head;  /**< Head - Buffer for error log. */
>>> +	uint16_t  error_wrap; /**< Wrap Counter - Buffer for error log. */
>>>    };
>>>
>>> +/**
>>> + * @brief Report error both through RTE logging and into internal driver
>> memory.
>>> + *
>>> + * This function is used to log an error for a specific ACC queue and
>> operation.
>>> + *
>>> + * @param q   Pointer to the ACC queue.
>>> + * @param op  Pointer to the operation.
>>> + * @param fmt Format string for the error message.
>>> + * @param ... Additional arguments for the format string.
>>> + */
>>> +__rte_format_printf(3, 4)
>>> +static inline void
>>> +acc_error_log(struct acc_queue *q, void *op, const char *fmt, ...) {
>>> +	va_list args, args2;
>>> +
>>> +	va_start(args, fmt);
>>> +	va_copy(args2, args);
>>> +	rte_vlog(RTE_LOG_ERR, acc_common_logtype, fmt, args);
>>> +	vsnprintf(q->error_bufs[q->error_head], ACC_MAX_LOGLEN, fmt,
>> args2);
>>> +	q->error_head++;
>>> +	snprintf(q->error_bufs[q->error_head], ACC_MAX_LOGLEN,
>>> +			"%s", rte_bbdev_ops_param_string(op, q->op_type));
>>> +	q->error_head++;
>>> +	if (q->error_head == ACC_MAX_LOGLEN) {
>>> +		q->error_head = 0;
>>> +		q->error_wrap++;
>>> +	}
>>> +	va_end(args);
>>> +	va_end(args2);
>>> +}
>>> +
>>>    /* Write to MMIO register address */
>>>    static inline void
>>>    mmio_write(void *addr, uint32_t value) diff --git
>>> a/drivers/baseband/acc/rte_vrb_pmd.c
>>> b/drivers/baseband/acc/rte_vrb_pmd.c
>>> index 585dc49bd6..9d0145d09b 100644
>>> --- a/drivers/baseband/acc/rte_vrb_pmd.c
>>> +++ b/drivers/baseband/acc/rte_vrb_pmd.c
>>> @@ -1022,6 +1022,10 @@ vrb_queue_setup(struct rte_bbdev *dev,
>> uint16_t queue_id,
>>>    	q->mmio_reg_enqueue = RTE_PTR_ADD(d->mmio_base,
>>>    			d->queue_offset(d->pf_device, q->vf_id, q->qgrp_id, q-
>>> aq_id));
>>>
>>> +	/** initialize the error buffer. */
>>> +	q->error_head = 0;
>>> +	q->error_wrap = 0;
>>> +
>>>    	rte_bbdev_log_debug(
>>>    			"Setup dev%u q%u: qgrp_id=%u, vf_id=%u, aq_id=%u,
>> aq_depth=%u, mmio_reg_enqueue=%p base %p\n",
>>>    			dev->data->dev_id, queue_id, q->qgrp_id, q->vf_id,
>> @@ -1434,6
>>> +1438,74 @@ vrb_queue_intr_disable(struct rte_bbdev *dev, uint16_t
>> queue_id)
>>>    	return 0;
>>>    }
>>>
>>> +
>>> +static int
>>> +vrb_queue_ops_dump(struct rte_bbdev *dev, uint16_t queue_id, FILE *f)
>>> +{
>>> +	struct acc_queue *q = dev->data->queues[queue_id].queue_private;
>>> +	struct rte_bbdev_dec_op *op;
>>> +	uint16_t start_err, end_err, i, int_nb;
>>> +	volatile union acc_info_ring_data *ring_data;
>>> +	uint16_t info_ring_head = q->d->info_ring_head;
>>> +
>>> +	if (f == NULL) {
>>> +		rte_bbdev_log(ERR, "Invalid File input");
>>> +		return -EINVAL;
>>> +	}
>>> +
>>> +	/** Print generic information on queue status. */
>>> +	fprintf(f, "Dump of operations %s on Queue %d by %s\n",
>>> +			rte_bbdev_op_type_str(q->op_type), queue_id, dev-
>>> device->driver->name);
>>> +	fprintf(f, "    AQ Enqueued %d Dequeued %d Depth %d - Available Enq
>> %d Deq %d\n",
>>> +			q->aq_enqueued, q->aq_dequeued, q->aq_depth,
>>> +			acc_ring_avail_enq(q), acc_ring_avail_deq(q));
>>> +
>>> +	/** Print information captured in the error buffer. */
>>> +	if (q->error_wrap == 0) {
>>> +		start_err = 0;
>>> +		end_err = q->error_head;
>>> +	} else {
>>> +		start_err = q->error_head;
>>> +		end_err = q->error_head + ACC_MAX_BUFFERLEN;
>>> +	}
>>> +	fprintf(f, "Error Buffer - Head %d Wrap %d\n", q->error_head, q-
>>> error_wrap);
>>> +	for (i = start_err; i < end_err; ++i)
>>> +		fprintf(f, "  %d\t%s", i, q->error_bufs[i %
>> ACC_MAX_BUFFERLEN]);
>>> +
>>> +	/** Print information captured in the info ring. */
>>> +	if (q->d->info_ring != NULL) {
>>> +		fprintf(f, "Info Ring Buffer - Head %d\n", q->d-
>>> info_ring_head);
>>> +		ring_data = q->d->info_ring + (q->d->info_ring_head &
>> ACC_INFO_RING_MASK);
>>> +		while (ring_data->valid) {
>>> +			int_nb = int_from_ring(*ring_data, q->d-
>>> device_variant);
>>> +			if ((int_nb < ACC_PF_INT_DMA_DL_DESC_IRQ) || (
>>> +					int_nb >
>> ACC_PF_INT_DMA_MLD_DESC_IRQ)) {
>>> +				fprintf(f, "  InfoRing: ITR:%d Info:0x%x",
>>> +						int_nb, ring_data-
>>> detailed_info);
>>> +				/* Initialize Info Ring entry and move forward.
>> */
>>> +				ring_data->valid = 0;
>>> +			}
>>> +			info_ring_head++;
>>> +			ring_data = q->d->info_ring + (info_ring_head &
>> ACC_INFO_RING_MASK);
>>> +		}
>>> +	}
>>> +
>>> +	fprintf(f, "Ring Content - Head %d Tail %d Depth %d\n",
>>> +			q->sw_ring_head, q->sw_ring_tail, q->sw_ring_depth);
>>> +	/** Print information about each operation in the software ring. */
>>> +	for (i = 0; i < q->sw_ring_depth; ++i) {
>>> +		op = (q->ring_addr + i)->req.op_addr;
>>> +		if (op != NULL)
>>> +			fprintf(f, "  %d\tn %d %s",
>>> +					i, (q->ring_addr + i)->req.numCBs,
>>> +					rte_bbdev_ops_param_string(op, q-
>>> op_type));
>>> +	}
>>> +
>>> +	fprintf(f, "== End of File ==\n");
>>> +
>>> +	return 0;
>>> +}
>>> +
>>>    static const struct rte_bbdev_ops vrb_bbdev_ops = {
>>>    	.setup_queues = vrb_setup_queues,
>>>    	.intr_enable = vrb_intr_enable,
>>> @@ -1443,7 +1515,8 @@ static const struct rte_bbdev_ops vrb_bbdev_ops
>> = {
>>>    	.queue_release = vrb_queue_release,
>>>    	.queue_stop = vrb_queue_stop,
>>>    	.queue_intr_enable = vrb_queue_intr_enable,
>>> -	.queue_intr_disable = vrb_queue_intr_disable
>>> +	.queue_intr_disable = vrb_queue_intr_disable,
>>> +	.queue_ops_dump = vrb_queue_ops_dump
>>>    };
>>>
>>>    /* PCI PF address map. */
>>> @@ -1680,7 +1753,7 @@ vrb_dma_desc_td_fill(struct rte_bbdev_dec_op
>> *op,
>>>    		uint32_t *in_offset, uint32_t *h_out_offset,
>>>    		uint32_t *s_out_offset, uint32_t *h_out_length,
>>>    		uint32_t *s_out_length, uint32_t *mbuf_total_left,
>>> -		uint32_t *seg_total_left, uint8_t r)
>>> +		uint32_t *seg_total_left, uint8_t r, struct acc_queue *q)
>>>    {
>>>    	int next_triplet = 1; /* FCW already done. */
>>>    	uint16_t k;
>>> @@ -1724,8 +1797,8 @@ vrb_dma_desc_td_fill(struct rte_bbdev_dec_op
>> *op,
>>>    	kw = RTE_ALIGN_CEIL(k + 4, 32) * 3;
>>>
>>>    	if (unlikely((*mbuf_total_left == 0) || (*mbuf_total_left < kw))) {
>>> -		rte_bbdev_log(ERR,
>>> -				"Mismatch between mbuf length and included
>> CB sizes: mbuf len %u, cb len %u",
>>> +		acc_error_log(q, (void *)op,
>>> +				"Mismatch between mbuf length and included
>> CB sizes: mbuf len %u,
>>> +cb len %u\n",
>>>    				*mbuf_total_left, kw);
>>>    		return -1;
>>>    	}
>>> @@ -1735,8 +1808,8 @@ vrb_dma_desc_td_fill(struct rte_bbdev_dec_op
>> *op,
>>>    			check_bit(op->turbo_dec.op_flags,
>>>    			RTE_BBDEV_TURBO_DEC_SCATTER_GATHER));
>>>    	if (unlikely(next_triplet < 0)) {
>>> -		rte_bbdev_log(ERR,
>>> -				"Mismatch between data to process and mbuf
>> data length in bbdev_op: %p",
>>> +		acc_error_log(q, (void *)op,
>>> +				"Mismatch between data to process and mbuf
>> data length in
>>> +bbdev_op: %p\n",
>>>    				op);
>>>    		return -1;
>>>    	}
>>> @@ -1748,7 +1821,7 @@ vrb_dma_desc_td_fill(struct rte_bbdev_dec_op
>> *op,
>>>    			desc, h_output, *h_out_offset,
>>>    			*h_out_length, next_triplet,
>> ACC_DMA_BLKID_OUT_HARD);
>>>    	if (unlikely(next_triplet < 0)) {
>>> -		rte_bbdev_log(ERR,
>>> +		acc_error_log(q, (void *)op,
>>>    				"Mismatch between data to process and mbuf
>> data length in bbdev_op: %p",
>>>    				op);
>>>    		return -1;
>>> @@ -1760,7 +1833,7 @@ vrb_dma_desc_td_fill(struct rte_bbdev_dec_op
>> *op,
>>>    	/* Soft output. */
>>>    	if (check_bit(op->turbo_dec.op_flags,
>> RTE_BBDEV_TURBO_SOFT_OUTPUT)) {
>>>    		if (op->turbo_dec.soft_output.data == 0) {
>>> -			rte_bbdev_log(ERR, "Soft output is not defined");
>>> +			acc_error_log(q, (void *)op, "Soft output is not
>> defined\n");
>>>    			return -1;
>>>    		}
>>>    		if (check_bit(op->turbo_dec.op_flags,
>>> @@ -1773,8 +1846,8 @@ vrb_dma_desc_td_fill(struct rte_bbdev_dec_op
>> *op,
>>>    				*s_out_offset, *s_out_length, next_triplet,
>>>    				ACC_DMA_BLKID_OUT_SOFT);
>>>    		if (unlikely(next_triplet < 0)) {
>>> -			rte_bbdev_log(ERR,
>>> -					"Mismatch between data to process
>> and mbuf data length in bbdev_op: %p",
>>> +			acc_error_log(q, (void *)op,
>>> +					"Mismatch between data to process
>> and mbuf data length in
>>> +bbdev_op: %p\n",
>>>    					op);
>>>    			return -1;
>>>    		}
>>> @@ -1797,7 +1870,8 @@ vrb_dma_desc_ld_fill(struct rte_bbdev_dec_op
>> *op,
>>>    		struct rte_mbuf **input, struct rte_mbuf *h_output,
>>>    		uint32_t *in_offset, uint32_t *h_out_offset,
>>>    		uint32_t *h_out_length, uint32_t *mbuf_total_left,
>>> -		uint32_t *seg_total_left, struct acc_fcw_ld *fcw, uint16_t
>> device_variant)
>>> +		uint32_t *seg_total_left, struct acc_fcw_ld *fcw, uint16_t
>> device_variant,
>>> +		struct acc_queue *q)
>>>    {
>>>    	struct rte_bbdev_op_ldpc_dec *dec = &op->ldpc_dec;
>>>    	int next_triplet = 1; /* FCW already done. */ @@ -1808,8 +1882,8
>> @@
>>> vrb_dma_desc_ld_fill(struct rte_bbdev_dec_op *op,
>>>    	if (device_variant == VRB1_VARIANT) {
>>>    		if (check_bit(op->ldpc_dec.op_flags,
>> RTE_BBDEV_LDPC_HARQ_4BIT_COMPRESSION) ||
>>>    				check_bit(op->ldpc_dec.op_flags,
>> RTE_BBDEV_LDPC_SOFT_OUT_ENABLE)) {
>>> -			rte_bbdev_log(ERR,
>>> -					"VRB1 does not support the requested
>> capabilities %x",
>>> +			acc_error_log(q, (void *)op,
>>> +					"VRB1 does not support the requested
>> capabilities %x\n",

You should not re-introduce "\n", David is currently working on getting
rid off them all.

>>>    					op->ldpc_dec.op_flags);
>>>    			return -1;
>>>    		}
>>> @@ -1829,8 +1903,8 @@ vrb_dma_desc_ld_fill(struct rte_bbdev_dec_op
>> *op,
>>>    	output_length = K - dec->n_filler - crc24_overlap;
>>>
>>>    	if (unlikely((*mbuf_total_left == 0) || (*mbuf_total_left <
>> input_length))) {
>>> -		rte_bbdev_log(ERR,
>>> -				"Mismatch between mbuf length and included
>> CB sizes: mbuf len %u, cb len %u",
>>> +		acc_error_log(q, (void *)op,
>>> +				"Mismatch between mbuf length and included
>> CB sizes: mbuf len %u,
>>> +cb len %u\n",
>>>    				*mbuf_total_left, input_length);
>>>    		return -1;
>>>    	}
>>> @@ -1842,15 +1916,15 @@ vrb_dma_desc_ld_fill(struct rte_bbdev_dec_op
>> *op,
>>>    			RTE_BBDEV_LDPC_DEC_SCATTER_GATHER));
>>>
>>>    	if (unlikely(next_triplet < 0)) {
>>> -		rte_bbdev_log(ERR,
>>> -				"Mismatch between data to process and mbuf
>> data length in bbdev_op: %p",
>>> +		acc_error_log(q, (void *)op,
>>> +				"Mismatch between data to process and mbuf
>> data length in
>>> +bbdev_op: %p\n",
>>>    				op);
>>>    		return -1;
>>>    	}
>>>
>>>    	if (check_bit(op->ldpc_dec.op_flags,
>> RTE_BBDEV_LDPC_HQ_COMBINE_IN_ENABLE)) {
>>>    		if (op->ldpc_dec.harq_combined_input.data == 0) {
>>> -			rte_bbdev_log(ERR, "HARQ input is not defined");
>>> +			acc_error_log(q, (void *)op, "HARQ input is not
>> defined\n");
>>>    			return -1;
>>>    		}
>>>    		h_p_size = fcw->hcin_size0 + fcw->hcin_size1; @@ -1859,7
>> +1933,7
>>> @@ vrb_dma_desc_ld_fill(struct rte_bbdev_dec_op *op,
>>>    		else if (fcw->hcin_decomp_mode == 4)
>>>    			h_p_size = h_p_size / 2;
>>>    		if (op->ldpc_dec.harq_combined_input.data == 0) {
>>> -			rte_bbdev_log(ERR, "HARQ input is not defined");
>>> +			acc_error_log(q, (void *)op, "HARQ input is not
>> defined\n");
>>>    			return -1;
>>>    		}
>>>    		acc_dma_fill_blk_type(
>>> @@ -1882,7 +1956,7 @@ vrb_dma_desc_ld_fill(struct rte_bbdev_dec_op
>>> *op,
>>>
>>>    	if (check_bit(op->ldpc_dec.op_flags,
>> RTE_BBDEV_LDPC_SOFT_OUT_ENABLE)) {
>>>    		if (op->ldpc_dec.soft_output.data == 0) {
>>> -			rte_bbdev_log(ERR, "Soft output is not defined");
>>> +			acc_error_log(q, (void *)op, "Soft output is not
>> defined\n");
>>>    			return -1;
>>>    		}
>>>    		dec->soft_output.length = fcw->rm_e; @@ -1894,7 +1968,7
>> @@
>>> vrb_dma_desc_ld_fill(struct rte_bbdev_dec_op *op,
>>>    	if (check_bit(op->ldpc_dec.op_flags,
>>>
>> 	RTE_BBDEV_LDPC_HQ_COMBINE_OUT_ENABLE)) {
>>>    		if (op->ldpc_dec.harq_combined_output.data == 0) {
>>> -			rte_bbdev_log(ERR, "HARQ output is not defined");
>>> +			acc_error_log(q, (void *)op, "HARQ output is not
>> defined\n");
>>>    			return -1;
>>>    		}
>>>
>>> @@ -2326,8 +2400,8 @@ vrb2_enqueue_ldpc_enc_one_op_tb(struct
>> acc_queue *q, struct rte_bbdev_enc_op *op
>>>    			in_length_in_bytes, &seg_total_left, next_triplet,
>>>    			check_bit(enc->op_flags,
>> RTE_BBDEV_LDPC_ENC_SCATTER_GATHER));
>>>    	if (unlikely(next_triplet < 0)) {
>>> -		rte_bbdev_log(ERR,
>>> -				"Mismatch between data to process and mbuf
>> data length in bbdev_op: %p",
>>> +		acc_error_log(q, (void *)op,
>>> +				"Mismatch between data to process and mbuf
>> data length in
>>> +bbdev_op: %p\n",
>>>    				op);
>>>    		return -1;
>>>    	}
>>> @@ -2399,7 +2473,7 @@ enqueue_dec_one_op_cb(struct acc_queue *q,
>> struct rte_bbdev_dec_op *op,
>>>    	ret = vrb_dma_desc_td_fill(op, &desc->req, &input, h_output,
>>>    			s_output, &in_offset, &h_out_offset, &s_out_offset,
>>>    			&h_out_length, &s_out_length, &mbuf_total_left,
>>> -			&seg_total_left, 0);
>>> +			&seg_total_left, 0, q);
>>>
>>>    	if (unlikely(ret < 0))
>>>    		return ret;
>>> @@ -2478,7 +2552,7 @@ vrb_enqueue_ldpc_dec_one_op_cb(struct
>> acc_queue *q, struct rte_bbdev_dec_op *op,
>>>    		ret = vrb_dma_desc_ld_fill(op, &desc->req, &input, h_output,
>>>    				&in_offset, &h_out_offset,
>>>    				&h_out_length, &mbuf_total_left,
>>> -				&seg_total_left, fcw, q->d->device_variant);
>>> +				&seg_total_left, fcw, q->d->device_variant, q);
>>>    		if (unlikely(ret < 0))
>>>    			return ret;
>>>    	}
>>> @@ -2572,7 +2646,7 @@ vrb_enqueue_ldpc_dec_one_op_tb(struct
>> acc_queue *q, struct rte_bbdev_dec_op *op,
>>>    				h_output, &in_offset, &h_out_offset,
>>>    				&h_out_length,
>>>    				&mbuf_total_left, &seg_total_left,
>>> -				&desc->req.fcw_ld, q->d->device_variant);
>>> +				&desc->req.fcw_ld, q->d->device_variant, q);
>>>
>>>    		if (unlikely(ret < 0))
>>>    			return ret;
>>> @@ -2658,7 +2732,7 @@ enqueue_dec_one_op_tb(struct acc_queue *q,
>> struct rte_bbdev_dec_op *op,
>>>    		ret = vrb_dma_desc_td_fill(op, &desc->req, &input,
>>>    				h_output, s_output, &in_offset,
>> &h_out_offset,
>>>    				&s_out_offset, &h_out_length,
>> &s_out_length,
>>> -				&mbuf_total_left, &seg_total_left, r);
>>> +				&mbuf_total_left, &seg_total_left, r, q);
>>>
>>>    		if (unlikely(ret < 0))
>>>    			return ret;
>