[BUG] DSP panic with Zephyr on Intel MTL, regression 27th June

[kv2019i]

Describe the bug
A DSP panic started showing up in CI runs on 27th June. No individual PR merged recently shows this in test results, so suspcion is a combination of PRs merged. Current suspect:

• west.yml: update Zephyr to 97a97c744a29 #9241
• app: boards: intel_adsp_ace15_mtpm: disable IMR context-save #9232

Both passed tested independently, but in together there seem to be DSP panics.

To Reproduce
https://sof-ci.01.org/sofpr/PR9267/build6051/devicetest/index.html

Reproduction Rate
Very high (most PR CI runs on 27th June)

Expected behavior
No DSP panics

Impact
Blocking CI

Environment
https://sof-ci.01.org/sofpr/PR9265/build6047/devicetest/index.html
https://sof-ci.01.org/sofpr/PR9267/build6051/devicetest/index.html

[kv2019i]

Also seen in:

• https://sof-ci.01.org/sofpr/PR9260/build6001/devicetest/index.html of pipeline 2.0 - introduce abstract audio_buffer api #9260
• https://sof-ci.01.org/sofpr/PR9258/build5967/devicetest/index.html of [DNM] west.ytml: update to Zephyr 243783243cbd (June 25th) #9258

[lyakh]

git bisect reliably brought to an SOF commit, that obviously cannot be the real reason - in a sense that that commit only adds 2 new functions without calling them and without touching a single line of runnable code, so it's purely modifying the build layout.
The crash happens at https://github.com/zephyrproject-rtos/zephyr/blob/b82b5b0734c30490368e21627423f10036487343/soc/intel/intel_adsp/ace/power_down.S#L64
That location is trying to lock in cache a variable on caller's stack https://github.com/zephyrproject-rtos/zephyr/blob/b82b5b0734c30490368e21627423f10036487343/soc/intel/intel_adsp/ace/power.c#L342 which all looks valid. However, it causes an exception. As a WA moving that variable to .bss by making it static seems to eliminate the problem.

[lyakh]

@ceolin any ideas?

[lyakh]

• [DNM][TEST] work around an exception during power down #9270
• intel-adsp/ace: fix firmware panic on MTL zephyrproject-rtos/zephyr#75108

[teburd]

What does the assembly dump look like for pm_state_set and power_down?

[andyross]

One thing to clean up in power_down assembly is window exceptions. You're called in a context where register windowing is enabled, which means that any access to registers other than A0-A3 can in principle trap. And the first use of A11+ (the last window, after which no window exceptions will occur) doesn't happen until after you've locked three data and four instruction lines into the cache. I don't see why that's illegal, but if I wanted to place bets on "how to exercise weird core behavior", this would be on the list. Strongly suggest "pre-spilling" all registers by e.g. putting a and a15, a15, a15 # force window exceptions right after the ENTRY instruction.

Also, I note there are two "MOVI" pseudo instructions after you start locking cache lines which are going to end up pointing into an arbitrary literals location. You need an explicit L32R to be sure it lands in valid memory, not a compiler-generated MOVI.

[andyross]

Also, I note there are two "MOVI" pseudo instructions after you start locking cache lines

Oooh, and there are lots more in asm_memory_management.h in contexts where you've already started shutting down memory! I'm going to place my chips on this as the culprit. I give it 60%+ odds.

Someone needs to comb through these files and make sure there's no "MOVI" usage (which again to be clear: is only a CPU instruction for small values, for big ones the compiler gets fancy and emits a .literals record for the linker to find and place). I mean, maybe I'll lose the bet and these will turn out to all be valid/non-loading variants. But still I think style would demand this be cleaned up.

[lyakh]

Also, I note there are two "MOVI" pseudo instructions after you start locking cache lines

Oooh, and there are lots more in asm_memory_management.h in contexts where you've already started shutting down memory! I'm going to place my chips on this as the culprit. I give it 60%+ odds.

Someone needs to comb through these files and make sure there's no "MOVI" usage (which again to be clear: is only a CPU instruction for small values, for big ones the compiler gets fancy and emits a .literals record for the linker to find and place). I mean, maybe I'll lose the bet and these will turn out to all be valid/non-loading variants. But still I think style would demand this be cleaned up.

@andyross ouch, yes, that sounds like a problem. Thanks for finding it! Now somebody just needs to fix it...

[lyakh]

Also, I note there are two "MOVI" pseudo instructions after you start locking cache lines which are going to end up pointing into an arbitrary literals location. You need an explicit L32R to be sure it lands in valid memory, not a compiler-generated MOVI.

@andyross I looked again at these. And TBH I don't see a problem with those specific ones. Here are the lines we're talking about:
https://github.com/zephyrproject-rtos/zephyr/blob/cfbe2adabc511663776642616cdc75510db882d3/soc/intel/intel_adsp/ace/power_down.S#L53-L61
Firstly, they just lock some cache lines, all the memory is still powered on. The problem would occur if we tried to access RAM after it's powered off, correct? So, those locations before powering down RAM should be safe? Same about these two lines https://github.com/zephyrproject-rtos/zephyr/blob/cfbe2adabc511663776642616cdc75510db882d3/soc/intel/intel_adsp/ace/power_down.S#L67-L68

Oooh, and there are lots more in asm_memory_management.h in contexts where you've already started shutting down memory! I'm going to place my chips on this as the culprit. I give it 60%+ odds.

These ones - yes, agree, look dangerous...

[lyakh]

These ones - yes, agree, look dangerous...

@andyross @teburd that was a nice theory, but it doesn't seem to help: zephyrproject-rtos/zephyr#75174 doesn't fix the problem. What exactly did we bet, Andy? ;-)

[andyross]

Bah. I was sure I had it. Is the panic you're seeing on the DPFL instruction itself? Reading the ISA ref, that's only supposed to happen if:

1. The MPU or MMU doesn't provide access to the virtual address. Obviously not relevant on MTL which has neither.
2. The cache in question (dcache or icache) does not have two[1] free lines/ways available at the addressed index.

Possibility 2 seems not... entirely impossible? This gets down to details about the hardware cache layout, which aren't completely clear from core-isa.h. But my read is that MTL has a 48k dcache laid out in three ways with a 16k stride. So if you have two cache lines pinned in the dcache at the same address modulo 16k, you can't add a third. I see the code here adding two essentially unrestricted dcache addresses (the literals and the stack). Is it possible there's another somewhere else, maybe leftover from the ROM? If so, then bad luck with memory layout would (I think) be able to make this happen.

[1] Presumably "two" so that there's always one available to populate via normal memory operation

[andyross]

(Deleted a comment again to avoid confusion: thought I had it, but missed a spot where it's loading the mask values.)

FWIW, regarding the earlier point: it wouldn't be too hard in the failing configuration to dump the actual addresses and see if the low 14 bits of the mask and literals regions match (there are two lines in literals).

And if that does turn out to be the problem, you could resolve it by reserving space in that literals area and coping the mask words there. That way they live sequentially in memory and can't collide on cache index.

[marc-hb]

IPC4 Daily tests are mostly red right now because of this, which means other, unrelated regressions WILL sneak unnoticed.

tl;dr: IPC4 CI is dead right now.

[ceolin]

(Deleted a comment again to avoid confusion: thought I had it, but missed a spot where it's loading the mask values.)

FWIW, regarding the earlier point: it wouldn't be too hard in the failing configuration to dump the actual addresses and see if the low 14 bits of the mask and literals regions match (there are two lines in literals).

And if that does turn out to be the problem, you could resolve it by reserving space in that literals area and coping the mask words there. That way they live sequentially in memory and can't collide on cache index.

If I have to bet I would put my money here. I was looking the documentation and stumbled in the same implementation notes that you commented. That would explain why moving that variable out of the stack solves the problem.

[lyakh]

If I have to bet I would put my money here. I was looking the documentation and stumbled in the same implementation notes that you commented. That would explain why moving that variable out of the stack solves the problem.

@ceolin @andyross this bug is making me rich. Looks like this idea isn't correct either. We've tried various ways to unlock or even to free all cache lines - no success. Maybe we do have to use zephyrproject-rtos/zephyr#75108 as long as we don't have a better solution

[lyakh]

There's also an incorrectness in the Zephyr code at https://github.com/zephyrproject-rtos/zephyr/blob/2c34da96f0e3ba07764db3ac7def9b400bbd1729/soc/intel/intel_adsp/ace/power_down.S#L92-L104 - that code expects pu32_hpsram_mask to point to an array of MAX_MEMORY_SEGMENTS masks. Whereas when locking at https://github.com/zephyrproject-rtos/zephyr/blob/2c34da96f0e3ba07764db3ac7def9b400bbd1729/soc/intel/intel_adsp/ace/power_down.S#L63-L64 the code only locks one cache-line. And it isn't just that it knows, that the array will fit in one cache line, it isn't even guaranteed that it's cache-line aligned. So if the array even just had 2 elements, it could cross 2 cache lines. And the caller at https://github.com/zephyrproject-rtos/zephyr/blob/2c34da96f0e3ba07764db3ac7def9b400bbd1729/soc/intel/intel_adsp/ace/power.c#L342-L352 doesn't bother with an array at all, it just uses a single 32-bit value for a mask.

[kv2019i]

One more idea. The exception seems to be right after first reference to windowed registers set up by call8. This is when the window overflow would be handled. The registers are stored to the stack frame, so these writes may go to the same cache line as we are trying to lock with dpfl (on caller's stack) -- or some other interaction between windowoverflow and dpfl. An ugly change following this hypothesis seems to be holding up -> zephyrproject-rtos/zephyr#75285 -- let's see full results.

[marc-hb]

so even if complex, it seems to have been fairly low-maintainance to keep using this approach.

Did you say low maintenance?

• [BUG] MTL firmware does not resume any more #9308
• intel_adsp/ace: power: pad the hpsram_mask passed to power_down zephyrproject-rtos/zephyr#76046

Sorry if I'm jumping to conclusions; I couldn't resist :-)

[lyakh]

It's back https://sof-ci.01.org/sofpr/PR9430/build7664/devicetest/index.html

[lyakh]

and a new attempt to fix it zephyrproject-rtos/zephyr#78057

[andyross]

Posted this in the PR by accident, copying here:

FWIW: I still bet that if you whiteboxed a rig to enumerate all the dcache indexes and check how many of them can be pinned, we'd discover that something in the boot ROM or elsewhere has left a line pinned accidentally, preventing more pinning at that index, and we're just hitting that by bad luck in the linker.

Would be non-trivial assembly to write, and tedious to debug as the only feedback is a panic, but not "hard" hopefully.

[lyakh]

@andyross I think what I've tested that back when debugging this last time by doing either one or both of the following things:

1. trying to lock (and unlock) cache lines at all offsets to cover the entire associativity set - all succeeded
2. by trying to speculatively unlock the entire data cache by using DIU

diff --git a/soc/intel/intel_adsp/ace/power.c b/soc/intel/intel_adsp/ace/power.c
index 20efc8e6f97..61830897397 100644
--- a/soc/intel/intel_adsp/ace/power.c
+++ b/soc/intel/intel_adsp/ace/power.c
@@ -46,6 +46,9 @@ __imr void power_init(void)
 	cache_data_flush_range((__sparse_force void *)
 			sys_cache_cached_ptr_get(&adsp_pending_buffer),
 			sizeof(adsp_pending_buffer));
+	/* unlock entire data cache */
+	for (unsigned int i = 0; i < 16 * 1024; i += 64)
+		__asm__ __volatile__("diu %0, 0" : "r"(0xa0000000 + i));
 #endif /* CONFIG_SOC_INTEL_ACE15_MTPM */
 }

Neither had helped

[andyross]

@lyakh my read is there are three ways, so you need to prove you can lock two lines at each index to saturate. IIRC there are two separate dcache regions in the code in question, right? So if those overlap in index and happen to collide with something already in the cache, then we'd be in a situation where we're trying to lock the same index in all three ways, which is illegal.

Maybe. :)

[lyakh]

@andyross sure, but as I said - I also tried unlocking all cache lines and it didn't help either

[wszypelt]

@lyakh is everything working now? Can we close this issue?

[marc-hb]

@wszypelt the last words are "... and it didn't help either"

?

[lyakh]

@wszypelt the last words are "... and it didn't help either"

?

@marc-hb that was a reply to a specific question, not a statement about the state of this bug

[lyakh]

@lyakh is everything working now? Can we close this issue?

@wszypelt yes, so far zephyrproject-rtos/zephyr#78283 has fixed it