ASoC: SOF: send time stamp to FW for alignment by bardliao · Pull Request #756 · thesofproject/linux

bardliao · 2019-03-28T06:07:35Z

Timer will be reset when DSP is powered down. So the time stamp of trace
log will be reset after resume. Send time stamp to FW can align the time
stamp and avoid reset time stamp in trace log.

Signed-off-by: Bard liao yung-chuan.liao@linux.intel.com

plbossart

@bardliao I have concerns about backwards compatibility, I don't think we can add a field without additional care, or we should use a different struct.
Adding @lgirdwood for comments.

plbossart · 2019-03-28T12:58:18Z

Gah, this is not a backwards-compatible change, is it?

@bardliao Looking at this again, we should be able to make this MINOR via a new cmd and struct

diff --git a/src/include/uapi/ipc/header.h b/src/include/uapi/ipc/header.h index 915448c6..b081ccb6 100644 --- a/src/include/uapi/ipc/header.h +++ b/src/include/uapi/ipc/header.h @@ -169,6 +169,7 @@ #define SOF_IPC_TRACE_DMA_PARAMS SOF_CMD_TYPE(0x001) #define SOF_IPC_TRACE_DMA_POSITION SOF_CMD_TYPE(0x002) +#define SOF_IPC_TRACE_DMA_PARAMS_EXT SOF_CMD_TYPE(0x003) /** @} */ diff --git a/src/include/uapi/ipc/trace.h b/src/include/uapi/ipc/trace.h index 06c9cef0..3a8ad8f5 100644 --- a/src/include/uapi/ipc/trace.h +++ b/src/include/uapi/ipc/trace.h @@ -49,12 +49,22 @@ #define SOF_TRACE_FILENAME_SIZE 32 /* DMA for Trace params info - SOF_IPC_DEBUG_DMA_PARAMS */ +/* Deprecated - use sof_ipc_dma_trace_params_ext */ struct sof_ipc_dma_trace_params { struct sof_ipc_cmd_hdr hdr; struct sof_ipc_host_buffer buffer; uint32_t stream_tag; } __attribute__((packed)); +/* DMA for Trace params info - SOF_IPC_DEBUG_DMA_PARAMS_EXT */ +struct sof_ipc_dma_trace_params_ext { + struct sof_ipc_cmd_hdr hdr; + struct sof_ipc_host_buffer buffer; + uint32_t stream_tag; + uint64_t timestamp; + uint32_t reserved[8]; +} __attribute__((packed)); + /* DMA for Trace params info - SOF_IPC_DEBUG_DMA_PARAMS */ struct sof_ipc_dma_trace_posn { struct sof_ipc_reply rhdr;

@lgirdwood Yeah. I think we have the same thought about how to keep backward compatible.

@lgirdwood @plbossart We don't need to support new kernel with old firmware, right? If we replace current cmd with a new one in kernel, it definitely won't work with older firmware which doesn't recognize the new cmd.

plbossart · 2019-03-28T13:00:27Z

that also looks like a non backwards compatible change? we'd need to create two separate structures and play with v3/v4.
@lgirdwood I can't recall why we don't have reserved fields in that trace structure? Or maybe we need to pass the time in a different struct?

@plbossart this change is definitely not backwards compatible. But is backwards compatibility a requirement or can we make it a new enhancement and bump up the major version to make it incompatible with older versions?

@plbossart @ranj063 Can we create a new ipc command type to send timestamp? e.g. SOF_IPC_TRACE_TIMESTAMP. So FW will not receive the ipc if kernel version is old and FW will return -EINVAL and ignore the ipc if FW version is old. It seems to be backwards compatible if we do so.

ranj063 · 2019-03-28T15:48:38Z

@plbossart @bardliao i never really understood what the SOF_ABI_PATCH is meant for. Why do we increment patch here and not MAJOR?

@ranj063 Please see https://semver.org/

Thanks @bardliao so are we going to drop this PR and just send the offset to the logger instead?

@ranj063 Yes. I am going to use debugfs to set/get the time stamp instead of ipc

plbossart

Thanks @bardliao. I like the idea of avoiding time calculations in the firmware, and just record a timestamp in debugfs. However I have a set of comments on the PR, see below.

plbossart · 2019-04-01T13:42:27Z

Sorry, I did not understand the comment here. My understanding was that the firmware only counts timer ticks since boot so isn't even aware of any offset and the number of resumes.

@plbossart Here we record the time stamp of first firmware boot. It should be closed to the time stamp of system boot. If we don't do this and use the absolute jiffies, we could get a huge value. I think what we need is the time stamp of system boot up instead of a time stamp since long time age. Maybe there is a more suitable value than jiffies, I will check it latter this week.

plbossart · 2019-04-01T13:44:23Z

We need to figure out what time base will be used here. If this REALTIME, MONOTONIC or MONOTONIC_RAW? I suggest the latter so that there is no offset/correction introduced by the kernel. Also is jiffies_64 the way to get the time, or is there a ktime_() function?

@plbossart According to https://elinux.org/Kernel_Timer_Systems I think it is MONOTONIC_RAW. jiffies is common used in the kernel but maybe we can use ktime_get() and ktime_to_us()?

plbossart · 2019-04-01T13:46:45Z

we should avoid such local variables, let's move this in sof-priv.h

@plbossart got it

plbossart · 2019-04-01T13:48:13Z

Why do you want to represent the offset in ms, the firmware time resolution is based on the oscillator (42ns and lower). The shift should not be quantized in ms?

@plbossart The resolution of jiffies is based on the value of HZ which typically is 1000. I don't like to quantized it but it is ms originally.

bardliao · 2019-04-04T07:51:04Z

@plbossart This version uses ktime_ functions instead of jiffies. It looks much clearer than previously version. Now I am thinking about Liam's proposal, and trying to implement it. But it may take some time.

plbossart · 2019-04-23T18:00:57Z

On 4/23/19 7:31 AM, Bard Liao wrote: ***@***.**** commented on this pull request. ------------------------------------------------------------------------ In include/sound/sof/trace.h <#756 (comment)>: > @@ -23,6 +23,7 @@ struct sof_ipc_dma_trace_params { struct sof_ipc_cmd_hdr hdr; struct sof_ipc_host_buffer buffer; uint32_t stream_tag; + uint64_t timestamp; @lgirdwood <https://github.com/lgirdwood> @plbossart <https://github.com/plbossart> We don't need to support new kernel with old firmware, right? If we replace current cmd with a new one in kernel, it definitely won't work with older firmware which doesn't recognize the new cmd.

Of course we do. A user could update their kernel at any point of time, and we want the solution to keep working without requiring a firmware update. The case with an old kernel supporting a new kernel is not a requirement.

bardliao · 2019-04-24T01:50:53Z

@plbossart Thanks for clarification. There should be no problem since we can send different cmd to FW according to different FW ABI version.

lgirdwood · 2019-05-02T15:48:40Z

Links to thesofproject/sof#1194

lgirdwood · 2019-05-02T15:51:03Z

@bardliao ABI MINOR 7 approved.

plbossart

Thanks @bardliao, the code looks ok and the backwards compatibility is well handled. I just have two detailed questions on the precision of the timing below.

plbossart · 2019-05-02T17:28:56Z

+	if (v->abi_version >= SOF_ABI_VER(3, 7, 0)) {
+		params.hdr.size = sizeof(struct sof_ipc_dma_trace_params_ext);
+		params.hdr.cmd |= SOF_IPC_TRACE_DMA_PARAMS_EXT;
+		params.timestamp = ktime_to_us(ktime_get());


why limit to microseconds? You have a 64bit value for the IPC, send it as is and let the firmware chop what it can't use.

@plbossart I will do it. Thanks

plbossart · 2019-05-02T17:31:43Z

+	if (v->abi_version >= SOF_ABI_VER(3, 7, 0)) {
+		params.hdr.size = sizeof(struct sof_ipc_dma_trace_params_ext);
+		params.hdr.cmd |= SOF_IPC_TRACE_DMA_PARAMS_EXT;
+		params.timestamp = ktime_to_us(ktime_get());


would be good to comment what time based is used here?
Also wondering if when the trace lasts for a very long time how the firmware will remain in alignment with e.g. kernel logs. Is there a need for an update or realignment from time to time?

@plbossart I will add comments here and at trace.h. I am not sure if the clock on kernel and firmware are skew. If not, I think we will only need to align it when the timer on firmware is reset.

@bardliao The change looks very useful and I had the same comment on the timestamp. The timebase is not documented in the uapi headers, but the unit would seem to be be DSP ticks.

So shouldn't you convert kernel time into DSP ticks (19.2 or 24 XTAL, sof-logger -c arg) when filling the params.timestamp to ensure the clocks share the same timebase?

@plbossart
Skewing will happen as well (most machines will sync via NTP/cellular to an external clock), but that is perhaps a lesser concern and could be fixed with period timebase updates. In practical scenarios, I doubt this is an issue as runtime PM will happen frequently.

@bardliao The change looks very useful and I had the same comment on the timestamp. The timebase is not documented in the uapi headers, but the unit would seem to be be DSP ticks.

So shouldn't you convert kernel time into DSP ticks (19.2 or 24 XTAL, sof-logger -c arg) when filling the params.timestamp to ensure the clocks share the same timebase?

Good point. The current unit is ns and the expectation was that the firmware would convert to its internal base which is currently not known to the kernel. we could alternatively pass the information directly in a unit that's native to the DSP, but we would first need to know the frequency. I am not sure if the firmware reports anywhere what its internal tick is?

@plbossart
Skewing will happen as well (most machines will sync via NTP/cellular to an external clock), but that is perhaps a lesser concern and could be fixed with period timebase updates. In practical scenarios, I doubt this is an issue as runtime PM will happen frequently.

Yes, agree, if we have issues with NTP adjustments then we'd already be in a good place :-)

@kv2019i Agree with @plbossart it will be easier to convert the time base in firmware side. Kernel don't need to know the DSP ticks base.

@bardliao Ack, but that indeed requires changes to FW side as the previous implementation already got merged. But I see you have PR1358 already running, so that seems ok.

lgirdwood · 2019-05-03T13:21:46Z

@plbossart @bardliao I didn't see the time base comments before I merged FW part. I wont revert since it's inactive, but it needs an incremental update to align on any time base agreed here.

plbossart · 2019-05-03T16:28:06Z

@bardliao ABI MINOR 7 approved.

we are jumping from MINOR 5 to 7 here, what's MINOR 6 then?

bardliao · 2019-05-05T05:20:06Z

@bardliao ABI MINOR 7 approved.

we are jumping from MINOR 5 to 7 here, what's MINOR 6 then?

@plbossart MINOR 6 is ipc: tplg: add effect type comp for keyword detect
It is not on kernel side yet.

plbossart · 2019-05-08T00:08:26Z


 /* SOF ABI version major, minor and patch numbers */
 #define SOF_ABI_MAJOR 3
-#define SOF_ABI_MINOR 5


@bardliao I am fine with the changes but this would need to be updated once we get the kernel updates for MINOR6.
@wenqingfu all kernel PRs that touch the ABI will have to be serialized, and are now gated by the MINOR6 issues.

kv2019i

See my comment on filling IPC "timestamp" field.

kv2019i

Seems good to go now once the ABI dependencies are cleared. Thanks!

bardliao · 2019-05-15T05:09:13Z

@plbossart MINOR 6 is ipc: tplg: add effect type comp for keyword detect
It is not on kernel side yet.

@plbossart Sorry for the wrong information. I checked it again. The corresponding PR on kernel side is #771 But the ABI number is changed to 4 at the PR which is not aligned with FW side. Actually, #762 and #771 tried to change ABI minor to 4
Below is the ABI minor mapping table between kernel and FW

Function                                       kernel               FW
add SOF_IPC_PANIC_ASSERT                          4                 4
soundwire support                                 5                 5
Keyword detect	                                  4                 6

And @xiulipan file an issue for that #858, but no conclusion yet.

plbossart · 2019-05-15T11:48:02Z

@bardliao i'll push a PR to force the MINOR to 6 and yours will be 7 after rebase.

Timer will be reset when DSP is powered down. So the time stamp of trace log will be reset after resume. Send time stamp to FW can align the time stamp and avoid reset time stamp in trace log. Signed-off-by: Bard liao <yung-chuan.liao@linux.intel.com>

plbossart · 2019-05-17T01:37:54Z

@bardliao can you rebase this one and resubmit, this should be ABI MINOR 7 as described at https://github.com/orgs/thesofproject/projects/2#card-20443578

bardliao · 2019-05-17T01:38:43Z

@plbossart I have rebased and force updated the PR, but don't know why it didn't show the updated commit here. The new commit is at bardliao@91103fa

plbossart · 2019-05-17T01:54:19Z

do you mind checking that the force push actually worked?

bardliao · 2019-05-17T08:51:43Z

do you mind checking that the force push actually worked?

@plbossart I don't know why, but it works now. Seems to be late around 1 hr.

plbossart

Thanks @bardliao
need a 2nd reviewer!

plbossart · 2019-05-17T15:07:23Z

I have to move on so I'll merge and see what happens.

kv2019i · 2019-05-20T13:03:19Z

Post-merge approval. Ideally you'd merged this at the same time with SOF PR1358 (to fix fw to understand nanoseconds), but I guess there is limited harm. Ok.

bardliao requested review from plbossart and ranj063 March 28, 2019 06:07

bardliao mentioned this pull request Mar 28, 2019

Send time since boot to the firmware upon resume #41

Closed

plbossart requested changes Mar 28, 2019

View reviewed changes

ranj063 reviewed Mar 28, 2019

View reviewed changes

bardliao force-pushed the trace_timer branch 2 times, most recently from aea4312 to 9ffa1ca Compare April 1, 2019 13:25

bardliao changed the title ~~RFC: ASoC: SOF: send time stamp to DSP~~ [RFC] ASoC: SOF: show time stamp in debugfs Apr 1, 2019

plbossart requested changes Apr 1, 2019

View reviewed changes

bardliao force-pushed the trace_timer branch from 9ffa1ca to aa3d11a Compare April 4, 2019 07:46

bardliao force-pushed the trace_timer branch from aa3d11a to a190f3c Compare May 2, 2019 12:15

bardliao changed the title ~~[RFC] ASoC: SOF: show time stamp in debugfs~~ [RFC] ASoC: SOF: send time stamp to FW for alignment May 2, 2019

bardliao requested review from lgirdwood, plbossart and ranj063 May 2, 2019 12:43

lgirdwood mentioned this pull request May 2, 2019

[RFC] trace: get time stamp from kernel thesofproject/sof#1194

Merged

plbossart reviewed May 2, 2019

View reviewed changes

bardliao force-pushed the trace_timer branch from a190f3c to 374d28a Compare May 3, 2019 11:40

bardliao force-pushed the trace_timer branch from 374d28a to 3578910 Compare May 5, 2019 05:25

bardliao mentioned this pull request May 5, 2019

trace: convert trace time stamp to ticks thesofproject/sof#1358

Merged

plbossart reviewed May 8, 2019

View reviewed changes

kv2019i requested changes May 8, 2019

View reviewed changes

kv2019i reviewed May 9, 2019

View reviewed changes

bardliao changed the title ~~[RFC] ASoC: SOF: send time stamp to FW for alignment~~ ASoC: SOF: send time stamp to FW for alignment May 15, 2019

bardliao force-pushed the trace_timer branch from 3578910 to 91103fa Compare May 17, 2019 02:31

bardliao requested review from dbaluta, juimonen, keyonjie and lyakh as code owners May 17, 2019 02:31

plbossart approved these changes May 17, 2019

View reviewed changes

plbossart merged commit ceec549 into thesofproject:topic/sof-dev May 17, 2019

Conversation

bardliao commented Mar 28, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

lgirdwood Apr 18, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

plbossart Apr 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

bardliao commented Apr 4, 2019

Uh oh!

plbossart commented Apr 23, 2019 via email

Uh oh!

bardliao commented Apr 24, 2019

Uh oh!

lgirdwood commented May 2, 2019

Uh oh!

lgirdwood commented May 2, 2019

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

plbossart May 8, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

bardliao commented Mar 28, 2019 •

edited

Loading

lgirdwood Apr 18, 2019 •

edited

Loading

plbossart Apr 1, 2019 •

edited

Loading

plbossart May 8, 2019 •

edited

Loading

bardliao commented May 17, 2019 •

edited

Loading