Message-ID: <CADL8D3aMOcuWY+5wy92Vvd=WK4kgOiSz2z+OEoUtwL_6Z8CDVw@mail.gmail.com>
Date: Fri, 22 Aug 2025 14:30:09 -0400
From: Jon Cormier <jcormier@...ticallink.com>
To: Andrew Davis <afd@...com>
Cc: Nishanth Menon <nm@...com>, Tero Kristo <kristo@...nel.org>, 
	Santosh Shilimkar <ssantosh@...nel.org>, Steven Rostedt <rostedt@...dmis.org>, 
	Masami Hiramatsu <mhiramat@...nel.org>, Mathieu Desnoyers <mathieu.desnoyers@...icios.com>, 
	Vignesh Raghavendra <vigneshr@...com>, linux-kernel@...r.kernel.org, 
	linux-arm-kernel@...ts.infradead.org, linux-trace-kernel@...r.kernel.org
Subject: Re: [PATCH 0/2] PATCH: firmware: ti_sci: Add trace events to TI SCI

On Fri, Aug 22, 2025 at 1:39 PM Andrew Davis <afd@...com> wrote:
>
> On 8/22/25 11:05 AM, Jon Cormier wrote:
> > On Wed, Aug 20, 2025 at 4:04 PM Andrew Davis <afd@...com> wrote:
> >>
> >> On 8/20/25 1:10 PM, Jonathan Cormier wrote:
> >>> Add trace events to help debug and measure the speed of the
> >>> communication channel.
> >>>
> >>> Add parsing of the messages types but I am not sure how to parse the
> >>> flags, since the REQ and RESP flags conflict. Left as seperate commit to
> >>
> >> The REQ and RESP flags should be handled by different TRACE_EVENTs. Right
> >> now you only dump the content of the response messages (the ones in
> >> rx_callback), also tracing what is sent is just as important, so you
> >> might want to add slightly different ti_sci_msg_dump EVENT for the
> >> sending side which uses the different REQ flag parser.
> >
> >
> > Does it make sense to have seperate trace events, one that only decode
> > the hdrs and ones that also include the buffers?
> >
> > I'm bothered by the code duplication, but am trying to convince myself
> > it doesn't matter.
> >
> > Currently, with the above updates, if you enabled all the traces,
> > you'd see something like:
> >
> > [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 status=0
> > [15.xxxxxxx] ti_sci_tx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 data=<data>
> > [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> > [15.xxxxxxx] ti_sci_rx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 data=<data>
> > [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> >
> > Presumably if you were worried about timing, you'd disable the
> > msg_dumps, avoiding the extra memcpy's.  And if you only cared about
> > the data being sent, you'd only enable the msg_dumps.  Does this make
> > sense / is it worth the extra trace calls?
> >
> > Or removing the buffer decoding in the msg_dumps, removes the duplication:
> >
> > [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 status=0
> > [15.xxxxxxx] ti_sci_msg_dump: data=<data>
> > [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> > [15.xxxxxxx] ti_sci_msg_dump: data=<data>
> > [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> >
>
> I like this one ^^^ but I'd also just remove the `ti_sci_rx_callback`

Sounds good
>
> trace, the contents would always be the same as `ti_sci_xfer_end`.


So in TI's 6.12 branch, there is a response_expected variable which
skips waiting for a response message. Indicating that there won't
always be a rx buffer.  If I keep the rx_callback scheme, it cleanly
handles both cases without changes.
However if I change xfer_end to track the rx buffer, sometimes it
won't have a header to parse. Or sometimes it will use the TX header
and sometimes it would be the RX header, which would be confusing.

I could keep and move the ti_sci_rx_callback trace into ti_sci_do_xfer
(-> ti_sci_xfer_rx), right after the completion and timeout check.
This would keep all the tracing in this one function, though if
someone wanted to know if there is lost time in waiting on the
completion it wouldn't be tracked.

https://lore.kernel.org/all/20241220114118.uwi5bsefxnue46re@lcpd911/
>
>
> This way you have two sets of symmetrical trace events, a "begin" and "end"
> that can be used for timing measurements, and a dump message for "send" and
> "receive" that would help with debugging based on the message contents.
>
> As for the code duplication in the send/receive traces, I'm not sure
> what can be done, these trace macros already confuse me enough without
> trying to optimize them :)
>
> Andrew
>
> > Or do condense the trace calls so they all have the data into something like:
> >
> > [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 status=0  data=<data>
> > [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0 data=<data>
> > [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> >
> > Simplifying the code in the trace header.
> >>
> >>
> >> Andrew
> >>
> >>> make it easier to drop or make changes depending on comments.  The two
> >>> commits should squash easily.
> >>>
> >>> Nishanth Menon and Vignesh Raghavendra requested I send this patch
> >>> upstream.
> >>>
> >>> Signed-off-by: Jonathan Cormier <jcormier@...ticallink.com>
> >>> ---
> >>> Jonathan Cormier (2):
> >>>         firmware: ti_sci: Add trace events
> >>>         firmware: ti_sci: trace: Decode message types
> >>>
> >>>    MAINTAINERS                     |   1 +
> >>>    drivers/firmware/Makefile       |   3 +
> >>>    drivers/firmware/ti_sci.c       |  11 +++
> >>>    drivers/firmware/ti_sci_trace.h | 146 ++++++++++++++++++++++++++++++++++++++++
> >>>    4 files changed, 161 insertions(+)
> >>> ---
> >>> base-commit: d7b8f8e20813f0179d8ef519541a3527e7661d3a
> >>> change-id: 20250709-linux_master_ti_sci_trace-91fd2af65dca
> >>>
> >>> Best regards,
> >>
> >
> >
>


-- 
Jonathan Cormier
Senior Software Engineer

Voice:  315.425.4045 x222

http://www.CriticalLink.com
6712 Brooklawn Parkway, Syracuse, NY 13211

Powered by blists - more mailing lists