Re: [PATCH v2 03/10] drivers: qcom: rpmh-rsc: log RPMH requests in FTRACE

[Steven Rostedt]

On Thu, 15 Feb 2018 10:35:00 -0700
Lina Iyer <ilina@xxxxxxxxxxxxxx> wrote:

> @@ -298,6 +303,7 @@ static void __tcs_buffer_write(struct rsc_drv *drv, int m, int n,
>  		write_tcs_reg(drv, RSC_DRV_CMD_MSGID, m, n + i, msgid);
>  		write_tcs_reg(drv, RSC_DRV_CMD_ADDR, m, n + i, cmd->addr);
>  		write_tcs_reg(drv, RSC_DRV_CMD_DATA, m, n + i, cmd->data);
> +		trace_rpmh_send_msg(drv, m, n + i, msgid, cmd);

No biggy, but I'm curious to why you didn't do something this:

+static void __tcs_buffer_write(struct rsc_drv *drv, int m, int n,
+                             struct tcs_request *msg)
+{
+       u32 msgid, cmd_msgid = 0;
+       u32 cmd_enable = 0;
+       u32 cmd_complete;
+       struct tcs_cmd *cmd;
+       int i;
+
+       cmd_msgid = CMD_MSGID_LEN;
+       cmd_msgid |= (msg->is_complete) ? CMD_MSGID_RESP_REQ : 0;
+       cmd_msgid |= CMD_MSGID_WRITE;
+
+       cmd_complete = read_tcs_reg(drv, RSC_DRV_CMD_WAIT_FOR_CMPL, m, 0);
+
+       for (i = 0; i < msg->num_payload; i++) {

		int bit = n + i;

+               cmd = &msg->payload[i];
+               cmd_enable |= BIT(bit);
+               cmd_complete |= cmd->complete << (n + i);
+               msgid = cmd_msgid;
+               msgid |= (cmd->complete) ? CMD_MSGID_RESP_REQ : 0;
+               write_tcs_reg(drv, RSC_DRV_CMD_MSGID, m, bit, msgid);
+               write_tcs_reg(drv, RSC_DRV_CMD_ADDR, m, bit, cmd->addr);
+               write_tcs_reg(drv, RSC_DRV_CMD_DATA, m, bit, cmd->data);

		trace_rpmh_send_msg(drv, m, bit, msgid, cmd);

The compiler should optimize that, so this isn't really a big deal, but
I was just curious.


+       }
+
+       write_tcs_reg(drv, RSC_DRV_CMD_WAIT_FOR_CMPL, m, 0, cmd_complete);
+       cmd_enable |= read_tcs_reg(drv, RSC_DRV_CMD_ENABLE, m, 0);
+       write_tcs_reg(drv, RSC_DRV_CMD_ENABLE, m, 0, cmd_enable);
+}
  
>  	}
>  
>  	write_tcs_reg(drv, RSC_DRV_CMD_WAIT_FOR_CMPL, m, 0, cmd_complete);

[..]

> +TRACE_EVENT(rpmh_send_msg,
> +
> +	TP_PROTO(struct rsc_drv *d, int m, int n, u32 h, struct tcs_cmd *c),
> +
> +	TP_ARGS(d, m, n, h, c),
> +
> +	TP_STRUCT__entry(
> +		__field(const char*, d->name)
> +		__field(int, m)
> +		__field(int, n)
> +		__field(u32, hdr)
> +		__field(u32, addr)
> +		__field(u32, data)
> +		__field(bool, complete)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->name = s;
> +		__entry->m = m;
> +		__entry->n = n;
> +		__entry->hdr = h;
> +		__entry->addr = c->addr;
> +		__entry->data = c->data;
> +		__entry->complete = c->complete;
> +	),
> +
> +	TP_printk("%s: send-msg: tcs(m): %d cmd(n): %d msgid: 0x%08x addr: 0x%08x data: 0x%08x complete: %d",
> +			__entry->name, __entry->m, __entry->n, __entry->hdr,

I'm sorry I didn't catch this in my other reviews, but please don't use
direct strings in TP_printk(). In trace-cmd and perf, it has no access
to that information when reading this trace event. Not to mention, if
drv is freed between the time it is recorded, and the time it is read
in the trace buffer, you are now referencing random memory.

The way to do this in a trace event is to use the string functionality:

	TP_STRUCT__entry(
		__string(name, d->name)
		[..]
	TP_fast_assign(
		__assign_string(name, d->name)
		[..]
	TP_printk("%s: ...",
		__get_str(name), ...

Then the name is recorded in the ring buffer at the time of execution
of the trace event, and trace-cmd and perf can read it, and there's no
worries about it being freed between recording and reading the tracing
buffer.

-- Steve



> +			__entry->addr, __entry->data, __entry->complete)
> +);
> +