[bardliao]

Timer will be reset when DSP is powered down. So the time stamp of trace
log will be reset after resume. Get time stamp from kernel and adding it
as a shift of time stamp can avoid the reset.

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

[lgirdwood]

This would be easier done via userspace in logger providing the driver can export (via debugFS) a timestamp and log offset upon each FW boot. Logger can read this and add to FW timestamps.

[bardliao]

@lgirdwood good idea. I will do it next week.

[bardliao]

@lgirdwood I update the RFC and get time stamp from debugFS. However, it seems that there is a limitation here. If there are more than 1 bootup before sog-logger is started, we will only get the latest time stamp. In other words, we will use the same time stamp in all boot cycles before sof-logger is started. Do you have any idea about that? Thanks.

[lgirdwood]

@lgirdwood I update the RFC and get time stamp from debugFS. However, it seems that there is a limitation here. If there are more than 1 bootup before sog-logger is started, we will only get the latest time stamp. In other words, we will use the same time stamp in all boot cycles before sof-logger is started. Do you have any idea about that? Thanks.

I would expect your timestamp debugFS contain several timestamp and offsets. However this could be complex to align, so it may be better to extend trace data to allow more message types (where one could be used to adjust timestamp delta). e.g.

lrg@lofn:~/work/sof/sof$ git diff
diff --git a/src/include/uapi/user/trace.h b/src/include/uapi/user/trace.h
index cc7ac8bc..79d2792f 100644
--- a/src/include/uapi/user/trace.h
+++ b/src/include/uapi/user/trace.h
@@ -105,6 +105,17 @@ struct log_buffer_status {
 
 #define TRACE_ID_LENGTH 12
 
+struct log_type_pipe {
+       uint32_t id_0 : TRACE_ID_LENGTH;        /* e.g. Pipeline ID */
+       uint32_t id_1 : TRACE_ID_LENGTH;        /* e.g. Component ID */
+       uint32_t core_id : 8;           /* Reporting core's id */
+
+};
+
+struct log_type_clockchange {
+       uint64_t timestamp_delta;               /* new time stamp delta */
+};
+
 /*
  *  Log entry header.
  *
@@ -112,12 +123,17 @@ struct log_buffer_status {
  * Number of arguments is specified by the params_num field of log_entry
  */
 struct log_entry_header {
-       uint32_t id_0 : TRACE_ID_LENGTH;        /* e.g. Pipeline ID */
-       uint32_t id_1 : TRACE_ID_LENGTH;        /* e.g. Component ID */
-       uint32_t core_id : 8;           /* Reporting core's id */
-
+       uint32_t type:8;                                /* message type */
+       uint32_t size:8;                                /* message size in words */
+       uint32_t sequence:16;                   /* message sequence number */
        uint64_t timestamp;             /* Timestamp (in dsp ticks) */
        uint32_t log_entry_address;     /* Address of log entry in ELF */
+
+       /* type defines the content here */
+       union {
+               struct log_type_pipe pipe[];
+               struct log_type_clockchange clockchange[];
+       };
 } __attribute__((packed));
 
 #endif //#ifndef __INCLUDE_LOGGING__

This should be rolled into the next major ABI update though.

[plbossart]

@lgirdwood we can't use bitfields in IPC messages, the position is undefined. We have to use explicit masks to write/read the information.

[lgirdwood]

@lgirdwood we can't use bitfields in IPC messages, the position is undefined. We have to use explicit masks to write/read the information.

We already use bitfields in the trace message today. I guess this has worked so far since xt-xcc uses the GCC frontend and aligns with the kernel (again using GCC). We will probably need to bump the major ABI sooner, especially if xtensa LLVM is used for FW builds.

[bardliao]

@lgirdwood The concept is we need to read time stamp once er receive the clock change trace, right?
Assume we record the time stamp for every dsp boot up and dsp send a clock change trace in each boot.
My question is how do we know which time stamp should we use in the clock change when some trace log is overwrote(lost)? e.g. Imagine that we run sof-logger after 5 DSP boot, but the trace log of first 2 boot are lost. So we have trace log from the 3rd dsp boot. There should be 3 clock change trace in the trace log but 5 time stamps in the debugFS. Ideally, we should align trace time stamp with the 3rd, 4th, and 5th time stamps in the debugFS. But how do we know the trace log of first 2 boot has lost?

[plbossart]

We already use bitfields in the trace message today. I guess this has worked so far since xt-xcc uses the GCC frontend and aligns with the kernel (again using GCC). We will probably need to bump the major ABI sooner, especially if xtensa LLVM is used for FW builds.

Yeah, this looks like a mistake and it works by accident. for SSP quirks we explicitly added masks to avoid any dependencies on bitfields. This needs to be fixed.

…

[lgirdwood]

@lgirdwood The concept is we need to read time stamp once er receive the clock change trace, right?
Assume we record the time stamp for every dsp boot up and dsp send a clock change trace in each boot.
My question is how do we know which time stamp should we use in the clock change when some trace log is overwrote(lost)? e.g. Imagine that we run sof-logger after 5 DSP boot, but the trace log of first 2 boot are lost. So we have trace log from the 3rd dsp boot. There should be 3 clock change trace in the trace log but 5 time stamps in the debugFS. Ideally, we should align trace time stamp with the 3rd, 4th, and 5th time stamps in the debugFS. But how do we know the trace log of first 2 boot has lost?

This wont be perfect without the major ABI update which I'm trying to avoid atm. The first PR had the need for 64bit additions for every trace message in the FW (on 32bit DSPs) and the need to synchronize the clocks on an async basis (on receipt of the trace IPC message).

However, if we can easily fix when we update MAJOR ABI since we can include a trace IPC with the delta. i.e.

1. FW boots and send FW ready message. Driver can reply with uint64_t host time.
2. FW stores host time after subtracting the current DSP time. This is now called the delta_time.
3. Delta time can now be sent as first trace and probe message.
4. Userpsace uses delta to craete true timestamps for probe and trace.

[plbossart]

@lgirdwood isn't your proposal adding quite a bit of complexity? Your tool will need to detect non-monotonic changes in the trace delta values and re-create a monotonic set of timestamps by fetching all the stored 'host' times. a timestamp provided by the firmware cannot possibly use 32 bits only, so we have to go for 64 bits and at that point it's simple enough to just add the host time instead of always going back to zero.
Also I wonder if there is a dependency on the trace buffer being flushed on each suspend. I don't think we ever complete this work.

[bardliao]

@lgirdwood @plbossart It seems we will back to use ipc instead of debugFS for time stamp sharing, right?

[lgirdwood]

@lgirdwood isn't your proposal adding quite a bit of complexity? Your tool will need to detect non-monotonic changes in the trace delta values and re-create a monotonic set of timestamps by fetching all the stored 'host' times.

No more complexity with extra trace message types, as the delta values will be part of the trace message stream now (with the ABI update). i.e. we will have occasional "timestamp update" messages in the trace stream.

a timestamp provided by the firmware cannot possibly use 32 bits only, so we have to go for 64 bits and at that point it's simple enough to just add the host time instead of always going back to zero.

I'm not keen on 64bit maths since it can't easily be done in a couple of instruction on 32bit DSPs but I can live with it (fwiw, it's 7 instructions, excluding loads and stores on BYT).

uint64_t test64(uint64_t a, uint64_t b)
{
	uint64_t c;

	c = a + b;
	return c;
}

00000000 <test64>:
   0:   008136                  entry   a1, 64
   3:   017d                    mov.n   a7, a1
   5:   4729                    s32i.n  a2, a7, 16
   7:   5739                    s32i.n  a3, a7, 20
   9:   6749                    s32i.n  a4, a7, 24
   b:   7759                    s32i.n  a5, a7, 28
   d:   4748                    l32i.n  a4, a7, 16
   f:   5758                    l32i.n  a5, a7, 20
  11:   6788                    l32i.n  a8, a7, 24
  13:   7798                    l32i.n  a9, a7, 28
  15:   248a                    add.n   a2, a4, a8
  17:   160c                    movi.n  a6, 1
  19:   013247                  bltu    a2, a4, 1e <test64+0x1e>
  1c:   060c                    movi.n  a6, 0
  1e:   359a                    add.n   a3, a5, a9
  20:   463a                    add.n   a4, a6, a3
  22:   043d                    mov.n   a3, a4
  24:   0729                    s32i.n  a2, a7, 0
  26:   1739                    s32i.n  a3, a7, 4
  28:   0728                    l32i.n  a2, a7, 0
  2a:   1738                    l32i.n  a3, a7, 4
  2c:   f01d                    retw.n

Also I wonder if there is a dependency on the trace buffer being flushed on each suspend. I don't think we ever complete this work.

Agree, there will be a race with host sending host time.

So I can live with 64 bit additions for trace/probes if we send the host time on receipt of the FW boot message. This could be done using a fast IPC (i.e. no mailbox, registers only missing the host time LSBs), that way FW wont need to schedule work and can handle it immediately.

[lgirdwood]

@bardliao any update ?

[bardliao]

@bardliao any update ?

@lgirdwood No, sorry, I am blocked by customer issues.

[jajanusz]

logger looks ok, but I guess you need still something on fw/kernel side

[lgirdwood]

Can you confirm that the deprecated method will still work ? (albeit with no timestamp)

[bardliao]

@lgirdwood Yes, I tried with older kernel and it works.

[lgirdwood]

links to thesofproject/linux#756

outdated.

[plbossart]

this is ready to be merged at the kernel level, but I don't see any reviews from firmware folks? Any blockers here or are we good to go?