[v1] misc: fastrpc: Collect driver-remote processor transaction logs

  Add changes to collect driver-remote processor rpmsg transaction
logs. These logs will carry payload information for the rpmsg message
instance. These logs are channel specific and are collected in
channel context structure.

These rpmsg transaction logs can help in improving debugability as
all requests from processes are getting captured in channel context
structure.

Signed-off-by: Ekansh Gupta <quic_ekangupt@quicinc.com>
---
 drivers/misc/fastrpc.c | 88 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 88 insertions(+)
  

On Tue, Jun 06, 2023 at 10:25:55PM +0530, Ekansh Gupta wrote:
> Add changes to collect driver-remote processor rpmsg transaction
> logs. These logs will carry payload information for the rpmsg message
> instance. These logs are channel specific and are collected in
> channel context structure.
> 
> These rpmsg transaction logs can help in improving debugability as
> all requests from processes are getting captured in channel context
> structure.
> 
> Signed-off-by: Ekansh Gupta <quic_ekangupt@quicinc.com>
> ---
>  drivers/misc/fastrpc.c | 88 ++++++++++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 88 insertions(+)
> 
> diff --git a/drivers/misc/fastrpc.c b/drivers/misc/fastrpc.c
> index 30d4d04..6447cee 100644
> --- a/drivers/misc/fastrpc.c
> +++ b/drivers/misc/fastrpc.c
> @@ -104,6 +104,9 @@
>  
>  #define miscdev_to_fdevice(d) container_of(d, struct fastrpc_device, miscdev)
>  
> +/* Length of glink transaction history to store */
> +#define GLINK_MSG_HISTORY_LEN	(128)
> +
>  static const char *domains[FASTRPC_DEV_MAX] = { "adsp", "mdsp",
>  						"sdsp", "cdsp"};
>  struct fastrpc_phy_page {
> @@ -181,6 +184,28 @@ struct fastrpc_invoke_rsp {
>  	int retval;		/* invoke return value */
>  };
>  
> +struct fastrpc_tx_msg {
> +	struct fastrpc_msg msg;	/* Msg sent to remote subsystem */
> +	int rpmsg_send_err;	/* rpmsg error */
> +	s64 ns;			/* Timestamp (in ns) of msg */
> +};
> +
> +struct fastrpc_rx_msg {
> +	struct fastrpc_invoke_rsp rsp;	/* Response from remote subsystem */
> +	s64 ns;		/* Timestamp (in ns) of response */
> +};
> +
> +struct fastrpc_rpmsg_log {
> +	u32 tx_index;	/* Current index of 'tx_msgs' array */
> +	u32 rx_index;	/* Current index of 'rx_msgs' array */
> +	/* Rolling history of messages sent to remote subsystem */
> +	struct fastrpc_tx_msg tx_msgs[GLINK_MSG_HISTORY_LEN];
> +	/* Rolling history of responses from remote subsystem */
> +	struct fastrpc_rx_msg rx_msgs[GLINK_MSG_HISTORY_LEN];
> +	spinlock_t tx_lock;
> +	spinlock_t rx_lock;

Why roll your own ring-buffer logic instead of using one of the many
offerings that the kernel already provides for you?

thanks,

greg k-h
  

On 6/6/2023 11:12 PM, Greg KH wrote:
> On Tue, Jun 06, 2023 at 10:25:55PM +0530, Ekansh Gupta wrote:
>> Add changes to collect driver-remote processor rpmsg transaction
>> logs. These logs will carry payload information for the rpmsg message
>> instance. These logs are channel specific and are collected in
>> channel context structure.
>>
>> These rpmsg transaction logs can help in improving debugability as
>> all requests from processes are getting captured in channel context
>> structure.
>>
>> Signed-off-by: Ekansh Gupta <quic_ekangupt@quicinc.com>
>> ---
>>   drivers/misc/fastrpc.c | 88 ++++++++++++++++++++++++++++++++++++++++++++++++++
>>   1 file changed, 88 insertions(+)
>>
>> diff --git a/drivers/misc/fastrpc.c b/drivers/misc/fastrpc.c
>> index 30d4d04..6447cee 100644
>> --- a/drivers/misc/fastrpc.c
>> +++ b/drivers/misc/fastrpc.c
>> @@ -104,6 +104,9 @@
>>   
>>   #define miscdev_to_fdevice(d) container_of(d, struct fastrpc_device, miscdev)
>>   
>> +/* Length of glink transaction history to store */
>> +#define GLINK_MSG_HISTORY_LEN	(128)
>> +
>>   static const char *domains[FASTRPC_DEV_MAX] = { "adsp", "mdsp",
>>   						"sdsp", "cdsp"};
>>   struct fastrpc_phy_page {
>> @@ -181,6 +184,28 @@ struct fastrpc_invoke_rsp {
>>   	int retval;		/* invoke return value */
>>   };
>>   
>> +struct fastrpc_tx_msg {
>> +	struct fastrpc_msg msg;	/* Msg sent to remote subsystem */
>> +	int rpmsg_send_err;	/* rpmsg error */
>> +	s64 ns;			/* Timestamp (in ns) of msg */
>> +};
>> +
>> +struct fastrpc_rx_msg {
>> +	struct fastrpc_invoke_rsp rsp;	/* Response from remote subsystem */
>> +	s64 ns;		/* Timestamp (in ns) of response */
>> +};
>> +
>> +struct fastrpc_rpmsg_log {
>> +	u32 tx_index;	/* Current index of 'tx_msgs' array */
>> +	u32 rx_index;	/* Current index of 'rx_msgs' array */
>> +	/* Rolling history of messages sent to remote subsystem */
>> +	struct fastrpc_tx_msg tx_msgs[GLINK_MSG_HISTORY_LEN];
>> +	/* Rolling history of responses from remote subsystem */
>> +	struct fastrpc_rx_msg rx_msgs[GLINK_MSG_HISTORY_LEN];
>> +	spinlock_t tx_lock;
>> +	spinlock_t rx_lock;
> 
> Why roll your own ring-buffer logic instead of using one of the many
> offerings that the kernel already provides for you?
> 
Thanks for your suggestion, Greg. I'm looking into using kernel offered
ring-buffer logic and I'll update it in v2.
> thanks,
> 
> greg k-h
  

On 06/06/2023 17:55, Ekansh Gupta wrote:
> Add changes to collect driver-remote processor rpmsg transaction
> logs. These logs will carry payload information for the rpmsg message
> instance. These logs are channel specific and are collected in
> channel context structure.
> 

Can you provide details on who is the actual consumer of this?

Are you planning to dump this data via devcoredumps?

--srini

> These rpmsg transaction logs can help in improving debugability as
> all requests from processes are getting captured in channel context
> structure.
> 
> Signed-off-by: Ekansh Gupta <quic_ekangupt@quicinc.com>
> ---
>   drivers/misc/fastrpc.c | 88 ++++++++++++++++++++++++++++++++++++++++++++++++++
>   1 file changed, 88 insertions(+)
> 
> diff --git a/drivers/misc/fastrpc.c b/drivers/misc/fastrpc.c
> index 30d4d04..6447cee 100644
> --- a/drivers/misc/fastrpc.c
> +++ b/drivers/misc/fastrpc.c
> @@ -104,6 +104,9 @@
>   
>   #define miscdev_to_fdevice(d) container_of(d, struct fastrpc_device, miscdev)
>   
> +/* Length of glink transaction history to store */
> +#define GLINK_MSG_HISTORY_LEN	(128)
> +
>   static const char *domains[FASTRPC_DEV_MAX] = { "adsp", "mdsp",
>   						"sdsp", "cdsp"};
>   struct fastrpc_phy_page {
> @@ -181,6 +184,28 @@ struct fastrpc_invoke_rsp {
>   	int retval;		/* invoke return value */
>   };
>   
> +struct fastrpc_tx_msg {
> +	struct fastrpc_msg msg;	/* Msg sent to remote subsystem */
> +	int rpmsg_send_err;	/* rpmsg error */
> +	s64 ns;			/* Timestamp (in ns) of msg */
> +};
> +
> +struct fastrpc_rx_msg {
> +	struct fastrpc_invoke_rsp rsp;	/* Response from remote subsystem */
> +	s64 ns;		/* Timestamp (in ns) of response */
> +};
> +
> +struct fastrpc_rpmsg_log {
> +	u32 tx_index;	/* Current index of 'tx_msgs' array */
> +	u32 rx_index;	/* Current index of 'rx_msgs' array */
> +	/* Rolling history of messages sent to remote subsystem */
> +	struct fastrpc_tx_msg tx_msgs[GLINK_MSG_HISTORY_LEN];
> +	/* Rolling history of responses from remote subsystem */
> +	struct fastrpc_rx_msg rx_msgs[GLINK_MSG_HISTORY_LEN];
> +	spinlock_t tx_lock;
> +	spinlock_t rx_lock;
> +};
> +
>   struct fastrpc_buf_overlap {
>   	u64 start;
>   	u64 end;
> @@ -277,6 +302,7 @@ struct fastrpc_channel_ctx {
>   	struct fastrpc_device *fdevice;
>   	struct fastrpc_buf *remote_heap;
>   	struct list_head invoke_interrupted_mmaps;
> +	struct fastrpc_rpmsg_log gmsg_log[FASTRPC_DEV_MAX];
>   	bool secure;
>   	bool unsigned_support;
>   	u64 dma_mask;
> @@ -1097,6 +1123,64 @@ static int fastrpc_put_args(struct fastrpc_invoke_ctx *ctx,
>   	return 0;
>   }
>   
> +static s64 get_timestamp_in_ns(void)
> +{
> +	s64 ns = 0;
> +	struct timespec64 ts;
> +
> +	ktime_get_real_ts64(&ts);
> +	ns = timespec64_to_ns(&ts);
> +	return ns;
> +}
> +
> +static void fastrpc_update_txmsg_buf(struct fastrpc_channel_ctx *chan,
> +				struct fastrpc_msg *msg, int rpmsg_send_err, s64 ns)
> +{
> +	unsigned long flags = 0;
> +	u32 tx_index = 0;
> +	struct fastrpc_tx_msg *tx_msg = NULL;
> +
> +	spin_lock_irqsave(&(chan->gmsg_log[chan->domain_id].tx_lock), flags);
> +
> +	tx_index = chan->gmsg_log[chan->domain_id].tx_index;
> +	tx_msg = &(chan->gmsg_log[chan->domain_id].tx_msgs[tx_index]);
> +
> +	memcpy(&tx_msg->msg, msg, sizeof(struct fastrpc_msg));
> +	tx_msg->rpmsg_send_err = rpmsg_send_err;
> +	tx_msg->ns = ns;
> +
> +	tx_index++;
> +	chan->gmsg_log[chan->domain_id].tx_index =
> +		(tx_index > (GLINK_MSG_HISTORY_LEN - 1)) ? 0 : tx_index;
> +
> +	spin_unlock_irqrestore(&(chan->gmsg_log[chan->domain_id].tx_lock), flags);
> +}
> +
> +static void fastrpc_update_rxmsg_buf(struct fastrpc_channel_ctx *chan,
> +							u64 ctx, int retval, s64 ns)
> +{
> +	unsigned long flags = 0;
> +	u32 rx_index = 0;
> +	struct fastrpc_rx_msg *rx_msg = NULL;
> +	struct fastrpc_invoke_rsp *rsp = NULL;
> +
> +	spin_lock_irqsave(&(chan->gmsg_log[chan->domain_id].rx_lock), flags);
> +
> +	rx_index = chan->gmsg_log[chan->domain_id].rx_index;
> +	rx_msg = &(chan->gmsg_log[chan->domain_id].rx_msgs[rx_index]);
> +	rsp = &rx_msg->rsp;
> +
> +	rsp->ctx = ctx;
> +	rsp->retval = retval;
> +	rx_msg->ns = ns;
> +
> +	rx_index++;
> +	chan->gmsg_log[chan->domain_id].rx_index =
> +		(rx_index > (GLINK_MSG_HISTORY_LEN - 1)) ? 0 : rx_index;
> +
> +	spin_unlock_irqrestore(&(chan->gmsg_log[chan->domain_id].rx_lock), flags);
> +}
> +
>   static int fastrpc_invoke_send(struct fastrpc_session_ctx *sctx,
>   			       struct fastrpc_invoke_ctx *ctx,
>   			       u32 kernel, uint32_t handle)
> @@ -1124,6 +1208,7 @@ static int fastrpc_invoke_send(struct fastrpc_session_ctx *sctx,
>   
>   	if (ret)
>   		fastrpc_context_put(ctx);
> +	fastrpc_update_txmsg_buf(cctx, msg, ret, get_timestamp_in_ns());
>   
>   	return ret;
>   
> @@ -2323,6 +2408,8 @@ static int fastrpc_rpmsg_probe(struct rpmsg_device *rpdev)
>   	INIT_LIST_HEAD(&data->users);
>   	INIT_LIST_HEAD(&data->invoke_interrupted_mmaps);
>   	spin_lock_init(&data->lock);
> +	spin_lock_init(&(data->gmsg_log[data->domain_id].tx_lock));
> +	spin_lock_init(&(data->gmsg_log[data->domain_id].rx_lock));
>   	idr_init(&data->ctx_idr);
>   	data->domain_id = domain_id;
>   	data->rpdev = rpdev;
> @@ -2398,6 +2485,7 @@ static int fastrpc_rpmsg_callback(struct rpmsg_device *rpdev, void *data,
>   
>   	if (len < sizeof(*rsp))
>   		return -EINVAL;
> +	fastrpc_update_rxmsg_buf(cctx, rsp->ctx, rsp->retval, get_timestamp_in_ns());
>   
>   	ctxid = ((rsp->ctx & FASTRPC_CTXID_MASK) >> 4);
>