Skip to content

Conversation

@ujfalusi
Copy link
Contributor

The dtrace internal buffer is permanent from the point it is allocated.

If a SOF_IPC_TRACE_DMA_FREE IPC received the DMA channel is released and
the read/write pointer in the local dtrace buffer is reset to 0.

However, if the DSP is not powered down before the dtrace is re-enabled
then the banner is not going to be printed and since the write pointer
is reset (since the new DMA channel will start the copy from the start of
the buffer), further prints will overwrite the data which might include
the banner from the first boot when the buffer was allocated.

Print the banners in response to a dtrace enable call all the time.

Signed-off-by: Peter Ujfalusi peter.ujfalusi@linux.intel.com

The dtrace internal buffer is permanent from the point it is allocated.

If a SOF_IPC_TRACE_DMA_FREE IPC received the DMA channel is released and
the read/write pointer in the local dtrace buffer is reset to 0.

However, if the DSP is not powered down before the dtrace is re-enabled
then the banner is not going to be printed and since the write pointer
is reset (since the new DMA channel will start the copy from the start of
the buffer), further prints will overwrite the data which might include
the banner from the first boot when the buffer was allocated.

Print the banners in response to a dtrace enable call all the time.

Signed-off-by: Peter Ujfalusi <peter.ujfalusi@linux.intel.com>
@ujfalusi
Copy link
Contributor Author

ujfalusi commented Feb 24, 2022

@marc-hb, to be honest I don't understand this at all.
Reserved the adlp device and on top of this PR I have added the following diff:

diff --git a/rimage b/rimage
index ee5c3e1deb14..0f64a20183a8 160000
--- a/rimage
+++ b/rimage
@@ -1 +1 @@
-Subproject commit ee5c3e1deb1436a6e52b653bb523b594511cf330
+Subproject commit 0f64a20183a8db9bc39a4044679a51c1cc334f8f
diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c
index bb03b96593fc..39662c01f319 100644
--- a/src/trace/dma-trace.c
+++ b/src/trace/dma-trace.c
@@ -87,6 +87,7 @@ static enum task_state trace_work(void *data)
 	d->copy_in_progress = 1;
 
 	/* copy this section to host */
+	mtrace_printf(LOG_LEVEL_INFO, "copy to host_offset: %#x w_ptr: %#x, r_ptr: %#x", d->posn.host_offset, buffer->w_ptr, buffer->r_ptr);
 	size = dma_copy_to_host(&d->dc, config, d->posn.host_offset,
 				buffer->r_ptr, size);
 	if (size < 0) {
@@ -324,18 +325,21 @@ print_banners:
 	 */
 #define SOF_BANNER_COMMON  \
 	"FW ABI 0x%x DBG ABI 0x%x tags SOF:" SOF_GIT_TAG  ZEPHYR_VER_OPT  \
-	" src hash 0x%08x (ldc hash " META_QUOTE(SOF_SRC_HASH) ")"
+	" src hash 0x%08x (ldc hash " META_QUOTE(SOF_SRC_HASH) ") (Peter)"
 
 	/* It should be the very first sent log for easy identification. */
+	mtrace_printf(LOG_LEVEL_INFO, "00. addr: %#x w_ptr: %#x, r_ptr: %#x", buffer->addr, buffer->w_ptr, buffer->r_ptr);
 	mtrace_printf(LOG_LEVEL_INFO,
 		      "SHM: " SOF_BANNER_COMMON,
 		      SOF_ABI_VERSION, SOF_ABI_DBG_VERSION, SOF_SRC_HASH);
 
+	mtrace_printf(LOG_LEVEL_INFO, "01. addr: %#x w_ptr: %#x, r_ptr: %#x", buffer->addr, buffer->w_ptr, buffer->r_ptr);
 	/* Use a different, DMA: prefix to ease identification of log files */
 	tr_info(&dt_tr,
 		"DMA: " SOF_BANNER_COMMON,
 		SOF_ABI_VERSION, SOF_ABI_DBG_VERSION, SOF_SRC_HASH);
 
+	mtrace_printf(LOG_LEVEL_INFO, "02. addr: %#x w_ptr: %#x, r_ptr: %#x", buffer->addr, buffer->w_ptr, buffer->r_ptr);
 	return 0;
 }
 
@@ -508,6 +512,7 @@ void dma_trace_disable(struct dma_trace_data *d)
 	 * Reset the local read and write pointers to preserve the captured logs
 	 * while the dtrace is disabed
 	 */
+	mtrace_printf(LOG_LEVEL_INFO, "RESET w_ptr: %#x, r_ptr: %#x", buffer->w_ptr, buffer->r_ptr);
 	buffer->w_ptr = buffer->addr;
 	buffer->r_ptr = buffer->addr;
 	buffer->avail = 0;
@@ -661,6 +666,7 @@ static void dtrace_add_event(const char *e, uint32_t length)
 			ret = memcpy_s(buffer->w_ptr, length, e, length);
 			assert(!ret);
 			dcache_writeback_region(buffer->w_ptr, length);
+			mtrace_printf(LOG_LEVEL_INFO, "Event added atw_ptr: %#x, length: %u (no-wrap)", buffer->w_ptr, length);
 			buffer->w_ptr = (char *)buffer->w_ptr + length;
 		} else {
 			/* data is bigger than remaining margin so we wrap */
@@ -668,6 +674,7 @@ static void dtrace_add_event(const char *e, uint32_t length)
 			ret = memcpy_s(buffer->w_ptr, margin, e, margin);
 			assert(!ret);
 			dcache_writeback_region(buffer->w_ptr, margin);
+			mtrace_printf(LOG_LEVEL_INFO, "Event added atw_ptr: %#x, length: %u (wrap)", buffer->w_ptr, length);
 			buffer->w_ptr = buffer->addr;
 
 			dcache_invalidate_region(buffer->w_ptr,

Some run of sof-test/test-case/check-sof-logger.sh was a PASS, some FAIL. In the etrace I have:
PASS case:

2022-02-24 11:21:59 UTC [INFO] Log file logger.data.txt BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT       ktime=3804.787s  @  2022-02-24 19:21:57 +0800 CST
[  7601424849.144] (           0.000) c0 dma-trace             src/trace/dma-trace.c:338  INFO DMA: FW ABI 0x3014001 DBG ABI 0x5003000 tags SOF:v2.0-rc1-508-gb746574370bf-dirty src hash 0x9687d280 (ldc hash 0x9687d280) (Peter)
[         162.292] (         162.292) c0 ll-schedule        ./schedule/ll_schedule.c:460  INFO task add 0x9e17e370 dma-trace-task <2b972272-c5b1-4b7e-926f-0fc5cb4c4690>
[         182.083] (          19.792) c0 ll-schedule        ./schedule/ll_schedule.c:462  INFO task params pri 4 flags 0 start 500000 period 500000
[         209.635] (          27.552) c0 ll-schedule        ./schedule/ll_schedule.c:363  INFO new added task->start 3597266 at 3590311
2022-02-24 11:21:59 UTC [INFO] ::END log file logger.data.txt


2022-02-24 11:21:59 UTC [INFO] Log file logger.etrace.txt BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT       ktime=3806.845s  @  2022-02-24 19:21:59 +0800 CST
[  7601424826.749] (           0.000) c0 dma-trace             src/trace/dma-trace.c:331  INFO 00. addr: 0xbe233300 w_ptr: 0xbe233300, r_ptr: 0xbe233300
[           4.896] (           4.896) c0 dma-trace             src/trace/dma-trace.c:332  INFO SHM: FW ABI 0x3014001 DBG ABI 0x5003000 tags SOF:v2.0-rc1-508-gb746574370bf-dirty src hash 0x9687d280 (ldc hash 0x9687d280) (Peter)
[           9.427] (           4.531) c0 dma-trace             src/trace/dma-trace.c:336  INFO 01. addr: 0xbe233300 w_ptr: 0xbe233300, r_ptr: 0xbe233300
[          28.750] (          19.323) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233300, length: 32 (no-wrap)
[          35.000] (           6.250) c0 dma-trace             src/trace/dma-trace.c:342  INFO 02. addr: 0xbe233300 w_ptr: 0xbe233320, r_ptr: 0xbe233300
[         190.885] (         155.885) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233320, length: 28 (no-wrap)
[         210.729] (          19.844) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe23333c, length: 36 (no-wrap)
[         237.969] (          27.240) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233360, length: 28 (no-wrap)
[         257.969] (          20.000) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe23337c, length: 28 (no-wrap)
[         663.542] (         405.573) c0 dma-trace             src/trace/dma-trace.c:90   INFO copy to host_offset: 0 w_ptr: 0xbe233398, r_ptr: 0xbe233300
[     5002484.228] (     5001820.500) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233398, length: 24 (no-wrap)
[     5002504.176] (          19.948) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe2333b0, length: 24 (no-wrap)
[     5002524.957] (          20.781) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe2333c8, length: 28 (no-wrap)
[     5002547.041] (          22.083) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe2333e4, length: 28 (no-wrap)
[     5002565.999] (          18.958) c0 dma-trace             src/trace/dma-trace.c:515  INFO RESET w_ptr: 0xbe233400, r_ptr: 0xbe233380
Skipped 7736 bytes after the last statement.
2022-02-24 11:21:59 UTC [INFO] ::END log file logger.etrace.txt

FAIL case:

2022-02-24 11:21:34 UTC [INFO] Log file logger.data.txt BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT       ktime=3780.376s  @  2022-02-24 19:21:32 +0800 CST
2022-02-24 11:21:34 UTC [INFO] ::END log file logger.data.txt


2022-02-24 11:21:34 UTC [INFO] Log file logger.etrace.txt BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT       ktime=3782.431s  @  2022-02-24 19:21:34 +0800 CST
[  7552602381.241] (           0.000) c0 dma-trace             src/trace/dma-trace.c:331  INFO 00. addr: 0xbe233300 w_ptr: 0xbe233300, r_ptr: 0xbe233300
[           4.896] (           4.896) c0 dma-trace             src/trace/dma-trace.c:332  INFO SHM: FW ABI 0x3014001 DBG ABI 0x5003000 tags SOF:v2.0-rc1-508-gb746574370bf-dirty src hash 0x9687d280 (ldc hash 0x9687d280) (Peter)
[           9.375] (           4.479) c0 dma-trace             src/trace/dma-trace.c:336  INFO 01. addr: 0xbe233300 w_ptr: 0xbe233300, r_ptr: 0xbe233300
[          28.698] (          19.323) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233300, length: 32 (no-wrap)
[          34.896] (           6.198) c0 dma-trace             src/trace/dma-trace.c:342  INFO 02. addr: 0xbe233300 w_ptr: 0xbe233320, r_ptr: 0xbe233300
[         190.677] (         155.781) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233320, length: 28 (no-wrap)
[         210.573] (          19.896) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe23333c, length: 36 (no-wrap)
[         237.865] (          27.292) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233360, length: 28 (no-wrap)
[         257.812] (          19.948) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe23337c, length: 28 (no-wrap)
[         684.375] (         426.562) c0 dma-trace             src/trace/dma-trace.c:90   INFO copy to host_offset: 0 w_ptr: 0xbe233398, r_ptr: 0xbe233300
[     5003586.520] (     5002902.000) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe233398, length: 24 (no-wrap)
[     5003606.364] (          19.844) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe2333b0, length: 24 (no-wrap)
[     5003627.197] (          20.833) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe2333c8, length: 28 (no-wrap)
[     5003649.332] (          22.135) c0 dma-trace             src/trace/dma-trace.c:669  INFO Event added atw_ptr: 0xbe2333e4, length: 28 (no-wrap)
[     5003668.291] (          18.958) c0 dma-trace             src/trace/dma-trace.c:515  INFO RESET w_ptr: 0xbe233400, r_ptr: 0xbe233380
Skipped 7736 bytes after the last statement.
2022-02-24 11:21:34 UTC [INFO] ::END log file logger.etrace.txt

What I have in etrace is identical, the read and write pointer in local buffer got reset in both case, but way after the initial trace has been copied to host buffer.
I still have no clue why resetting the pointers matters and why it works sometimes and does not in other cases.

@ujfalusi
Copy link
Contributor Author

@marc-hb, out of desperation I reverted locally 58ce6e6 (and this PR) and run the sof-test/test-case/check-sof-logger.sh with it.
I have about the same chance to have PASS vs FAIL.

@ujfalusi
Copy link
Contributor Author

@marc-hb, I did also a check and the path this patch opens for re-printing the banner never happened. Every time (regardless of PASS or FAIL) the firmware boot was always started from a power off state.

@lgirdwood
Copy link
Member

@marc-hb @ujfalusi any update here? The dtrace pointer reset was reverted for v2.1 since as we are unsure why it impacted some tests.

@ujfalusi
Copy link
Contributor Author

ujfalusi commented Mar 1, 2022

Since the "dma-trace: Preserve logs while dtrace is disabled" is reverted now, this PR is not needed. We will deliver random trace info to the host if the dtrace is reconfigured, so it does not matter if we print a banner or not, the information is worthless, which is going to come out anyways.

I'll close this.

@ujfalusi ujfalusi closed this Mar 1, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants