Skip to content

ipc4: handler: Kconfig option to add IPC processing timing prints #9897

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
lgirdwood merged 1 commit into from
Mar 19, 2025
Merged

ipc4: handler: Kconfig option to add IPC processing timing prints #9897

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 13 additions & 0 deletions Kconfig.sof
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -198,6 +198,19 @@ config DEBUG_IPC_COUNTERS
help
Select for enabling tracing IPC counter in SRAM_REG mailbox

config DEBUG_IPC_TIMINGS
bool "Enable IPC message handling time logging"
depends on DEBUG
default n
help
Adds a logging after IPC handling before putting IPC reply
to send queue. The logging contains both the reply and the
original request message headers and the time that it took
to process the request in micro seconds. The value can be
used to collect statistics on changes in firmware response
times. This also disables the logging of the received
request on core 0 to avoid flooding the logs too much.

config SCHEDULE_LOG_CYCLE_STATISTICS
bool "Log cycles per tick statistics for each task separately"
default y
Expand Down
17 changes: 15 additions & 2 deletions src/ipc/ipc4/handler.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1556,11 +1556,19 @@ void ipc_cmd(struct ipc_cmd_hdr *_hdr)
{
struct ipc4_message_request *in = ipc4_get_message_request();
enum ipc4_message_target target;
#ifdef CONFIG_DEBUG_IPC_TIMINGS
struct ipc4_message_request req;
uint64_t tstamp;
#endif
int err;

#ifdef CONFIG_DEBUG_IPC_TIMINGS
req = *in;
tstamp = sof_cycle_get_64();
#else
if (cpu_is_primary(cpu_get_id()))
tr_info(&ipc_tr, "rx\t: %#x|%#x", in->primary.dat, in->extension.dat);

#endif
/* no process on scheduled thread */
atomic_set(&msg_data.delayed_reply, 0);
msg_data.delayed_error = 0;
Expand Down Expand Up @@ -1674,9 +1682,14 @@ void ipc_cmd(struct ipc_cmd_hdr *_hdr)

msg_reply.header = reply.primary.dat;

#ifdef CONFIG_DEBUG_IPC_TIMINGS
tr_info(&ipc_tr, "tx-reply\t: %#x|%#x to %#x|%#x in %llu us", msg_reply.header,
msg_reply.extension, req.primary.dat, req.extension.dat,
k_cyc_to_us_near64(sof_cycle_get_64() - tstamp));
Copy link
Collaborator

@lyakh lyakh Mar 14, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this function only prepares IPCs and ipc4_send_reply() below only queues them, they're actually sent in ipc_send_queued_msg() in the IPC work handler. But maybe indeed for our purposes we only need the processing time, not the request-response time, just something to be aware of. So maybe the Kconfig description isn't quite correct - it's not before sending, it's before queuing

Copy link
Member

@lgirdwood lgirdwood Mar 14, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this not be E2E timing, i.e we stop the timer when we actually send the reply ?

Copy link
Collaborator

@lyakh lyakh Mar 17, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this not be E2E timing, i.e we stop the timer when we actually send the reply ?

@lgirdwood I guess both are needed for different kinds of analysis - depending on what we want to measure.

#else
tr_dbg(&ipc_tr, "tx-reply\t: %#x|%#x", msg_reply.header,
msg_reply.extension);

#endif
ipc4_send_reply(&reply);
}
}