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
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@criticallink.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 <jcormier@criticallink.com>

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.

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@criticallink.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,

On Wed, Aug 20, 2025 at 4:04 PM Andrew Davis <afd@ti.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

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@criticallink.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

On 8/22/25 11:05 AM, Jon Cormier wrote:
> On Wed, Aug 20, 2025 at 4:04 PM Andrew Davis <afd@ti.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`
trace, the contents would always be the same as `ti_sci_xfer_end`.

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@criticallink.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,
>>
> 
> 

On Fri, Aug 22, 2025 at 1:39 PM Andrew Davis <afd@ti.com> wrote:
>
> On 8/22/25 11:05 AM, Jon Cormier wrote:
> > On Wed, Aug 20, 2025 at 4:04 PM Andrew Davis <afd@ti.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@criticallink.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