Zephyr 3.7.1 and MIMXRT1166 - possible SDRAM corruption

[rtborg]

I have a custom board using MIMXRT1166CVM5A and SDRAM Winbond W9812G6KB-6I running ar 148.5 MHz. When flashing a simple application, the stack utilization of the threads seems to rise on its own, without the thread work being modified in any way. For example, at beginning of application run, the stacks are:

proto:~$kernel stacks
0x800ffca0 lvgl_handler_tid                 (real size 8192):	unused 6344	usage 1848 / 8192 (22 %)
0x801003e8 lvgl_flush_thread                (real size 4096):	unused 3856	usage  240 / 4096 ( 5 %)
0x800ffd68 blinky_tid                       (real size 4096):	unused 3736	usage  360 / 4096 ( 8 %)
0x800ffe30 shell_uart                       (real size 8192):	unused 7376	usage  816 / 8192 ( 9 %)
0x8010d368 sysworkq                         (real size 8192):	unused 7344	usage  848 / 8192 (10 %)
0x8010d0b0 idle                             (real size 4096):	unused 4032	usage   64 / 4096 ( 1 %)
0x8010d178 main                             (real size 8192):	unused 6344	usage 1848 / 8192 (22 %)
0x8011d0c0 IRQ 00                           (real size 4096):	unused 3792	usage  304 / 4096 ( 7 %)

After a few minutes of running, the following appears:

proto:~$kernel stacks
0x800ffca0 lvgl_handler_tid                 (real size 8192):	unused  132	usage 8060 / 8192 (98 %)
0x801003e8 lvgl_flush_thread                (real size 4096):	unused  189	usage 3907 / 4096 (95 %)
0x800ffd68 blinky_tid                       (real size 4096):	unused   23	usage 4073 / 4096 (99 %)
0x800ffe30 shell_uart                       (real size 8192):	unused  924	usage 7268 / 8192 (88 %)
0x8010d368 sysworkq                         (real size 8192):	unused 1054	usage 7138 / 8192 (87 %)
0x8010d0b0 idle                             (real size 4096):	unused  709	usage 3387 / 4096 (82 %)
0x8010d178 main                             (real size 8192):	unused  773	usage 7419 / 8192 (90 %)
0x8011d0c0 IRQ 00                           (real size 4096):	unused 1009	usage 3087 / 4096 (75 %)

which eventually leads to a crash:

[00:04:45.185,000] <err> os: ***** USAGE FAULT *****
[00:04:45.190,000] <err> os:   Attempt to execute undefined instruction
[00:04:45.192,000] <err> os: r0/a1:  0xf36f88bf  r1/a2:  0x8010d178  r2/a3:  0x8010d178
[00:04:45.195,000] <err> os: r3/a4:  0x000000e3 r12/ip:  0x000000cd r14/lr:  0x300328ad
[00:04:45.202,000] <err> os:  xpsr:  0x21000000
[00:04:45.203,000] <err> os: Faulting instruction address (r15/pc): 0x30100cfc
[00:04:45.209,000] <err> os: >>> ZEPHYR FATAL ERROR 36: Unknown error on CPU 0
[00:04:45.212,000] <err> os: Current thread: 0x8010d178 (main)
[00:04:45.217,000] <err> os: Halting system

However, the crash description varies each time, along with the duration it takes to appear.

  s[00:00:16.475,000] <err> os: ***** USAGE FAULT *****  
[00:00:16.483,000] <err> os: Unaligned memory access  
[00:00:16.491,000] <err> os: r0/a1: 0x55555555 r1/a2: 0x0000008c r2/a3: 0x0000008c  
[00:00:16.501,000] <err> os: r3/a4: 0x80709511 r12/ip: 0x000000fe r14/lr: 0x30046723  
[00:00:16.512,000] <err> os: xpsr: 0x21000000  
[00:00:16.520,000] <err> os: Faulting instruction address (r15/pc): 0x30046728  
[00:00:16.530,000] <err> os: >>> ZEPHYR FATAL ERROR 31: Unknown error on CPU 0  
[00:00:16.540,000] <err> os: Current thread: 0x80101cc0 (lvgl_handler_tid)  
[00:00:16.549,000] <err> os: Halting system

#####
&nbsp; history i2c kernel lvgl pwm rem ASSERTION FAIL [z_spin_lock_valid(l)] @ WEST_TOPDIR/zephyr/include/zephyr/spinlock.h:136  
    Invalid spinlock 0x80119a7c  
[00:00:55.417,000] <err> os: r0/a1: 0x00000004 r1/a2: 0x00000088 r2/a3: 0x00000000  
[00:00:55.428,000] <err> os: r3/a4: 0x00000004 r12/ip: 0x00000001 r14/lr: 0x30035eed  
[00:00:55.439,000] <err> os: xpsr: 0x01000031  
[00:00:55.447,000] <err> os: Faulting instruction address (r15/pc): 0x3003919c  
[00:00:55.457,000] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0  
[00:00:55.468,000] <err> os: Fault during interrupt handling

[00:00:55.477,000] <err> os: Current thread: 0x80101e50 (shell_uart)  
[00:00:55.486,000] <err> os: Halting system

#######
[00:00:14.518,000] <err> os: ***** MPU FAULT *****  
[00:00:14.526,000] <err> os: Instruction Access Violation  
[00:00:14.534,000] <err> os: r0/a1: 0xab00ab00 r1/a2: 0x8011b7a0 r2/a3: 0x00000000  
[00:00:14.545,000] <err> os: r3/a4: 0x2a532100 r12/ip: 0x000000e6 r14/lr: 0x3001f1fd  
[00:00:14.556,000] <err> os: xpsr: 0x40000000  
[00:00:14.563,000] <err> os: Faulting instruction address (r15/pc): 0xab00ab00  
[00:00:14.573,000] <err> os: >>> ZEPHYR FATAL ERROR 20: Unknown error on CPU 0  
[00:00:14.583,000] <err> os: Current thread: 0x80101cc0 (lvgl_handler_tid)  
[00:00:14.593,000] <err> os: Halting system

I am thinking that the problem is in SDRAM and possible corruption in reading or writing, however I am not 100% sure it's that. I tried running a bare-metal MCUXpresso application which constantly reads and writes to the whole SDRAM, and it runs for hours with no fault.
I am using same DCD to initialize the flash in both Zephyr and MCUXpresso.

Any pointers will be greatly appreciated.

[DerekSnell]

Hi @rtborg ,
That is an odd issue. If this is caused by SDRAM corruption, this manifestation seems weird to me. If the SDRAM interface is marginal and some reads/writes are corrupted, I would expect the errors to seem random. But if I understand the behavior you see, all the stacks steadily increase their usage until one overflows. And otherwise, the app runs as expected to that point? Do you see other signs of corrupting in the RAM?

To me, that does not sound like random corruption, but some application issue. Have you ruled out your app by trying some simple sample app from the tree? Or maybe hack your app so none of your threads do anything, see if the stacks continue to grow, and if not, enable parts of the app until you see the issue surface.

It's odd to me that all of the stacks grow like this. Could there be some interrupt that is constantly firing, pushing onto each thread, and somehow not popping everything off? Can you use a debugger and debug one of the threads, maybe a simple one like the idle thread, and watch the stack pointer to see what is causing it to increase? Or at least see if it increments by a consistent amount each time. You could also look at that data getting added to the stack, and see if it is random or has a pattern and give clues to what causes it.

Let us know what you find

[rtborg]

I created a minimal Zephyr application which only blinks a LED and logs to console, however the issue persists. When tracing thread stack usage with the k_thread_stack_space_get API, the thread is not affected by, while others still are. Below is the result of adding stack tracing via logging to the idle thread:

proto:~$kernel stacks 
0x80003330 shell_uart                       (real size 8192):	unused   37	usage 8155 / 8192 (99 %)
0x80003a50 sysworkq                         (real size 8192):	unused  514	usage 7678 / 8192 (93 %)
0x80002228 logging                          (real size 8192):	unused  855	usage 7337 / 8192 (89 %)
0x80003798 idle                             (real size 4096):	unused 4008	usage   88 / 4096 ( 2 %)
0x80003860 main                             (real size 8192):	unused  584	usage 7608 / 8192 (92 %)
0x80008d00 IRQ 00                           (real size 4096):	unused   31	usage 4065 / 4096 (99 %)

I tried making some sense of the values that are scattered in the stacks, but can't find a pattern. The commonality is that they are single bytes with one flipped bit - instead of aa there are a bunch of ae, 2a, ab, a8.

Same thing occurs when logging is disabled. Here's the result of minimal application running for less than a minute, with logging in idle thread:

proto:~$kernel stacks
0x80003330 shell_uart                       (real size 8192):	unused 7384	usage  808 / 8192 ( 9 %)
0x80003a50 sysworkq                         (real size 8192):	unused 7992	usage  200 / 8192 ( 2 %)
0x80002228 logging                          (real size 8192):	unused 7980	usage  212 / 8192 ( 2 %)
0x80003798 idle                             (real size 4096):	unused 4008	usage   88 / 4096 ( 2 %)
0x80003860 main                             (real size 8192):	unused 7744	usage  448 / 8192 ( 5 %)
0x80008d00 IRQ 00                           (real size 4096):	unused 3848	usage  248 / 4096 ( 6 %)


proto:~$kernel stacks
0x80003330 shell_uart                       (real size 8192):	unused 7224	usage  968 / 8192 (11 %)
0x80003a50 sysworkq                         (real size 8192):	unused 4951	usage 3241 / 8192 (39 %)
0x80002228 logging                          (real size 8192):	unused 3311	usage 4881 / 8192 (59 %)
0x80003798 idle                             (real size 4096):	unused 4008	usage   88 / 4096 ( 2 %)
0x80003860 main                             (real size 8192):	unused 5517	usage 2675 / 8192 (32 %)
0x80008d00 IRQ 00                           (real size 4096):	unused 3848	usage  248 / 4096 ( 6 %)

I'm attaching a dump of the main_stack.txt

[DerekSnell]

Hi @rtborg ,
And you have confirmed that when you build this same minimal app but move the data to internal RAM instead of SDRAM, this issue goes away?

[rtborg]

If I use ocram for Zephyr, and disabled sdram, the error goes away.

Another possible relevant details is that during execution of the faulting application, SEMC register INTR@0x400d403C is set to 0x8 - flag AXIBUSERR is set:

[DerekSnell]

Hi @rtborg ,
Yes, this issue does sound like a HW configuration issue with the SDRAM. I suggest you use the NXP support forum at https://community.nxp.com/ to search for help and get HW support for interfacing to this SDRAM.
Best regards

[rtborg]

Hi @DerekSnell,
I've also posted the question at NXP community, had the SDRAM schematic reviewed and no obvious problems were found. I've brought the SDRAM timings in sync with the values specified in the datasheet and the stack overflow has stopped, however when using LVGL the application crashes within seconds with a variety of error messages such as:

[00:01:45.669,000] <err> os: ***** USAGE FAULT *****
[00:01:45.677,000] <err> os:   Illegal use of the EPSR

[00:00:37.485,000] <err> os: ***** USAGE FAULT *****
[00:00:37.493,000] <err> os:   Attempt to execute undefined instruction

[00:00:08.247,000] <err> os: ***** MPU FAULT *****
[00:00:08.254,000] <err> os:   Data Access Violation

[00:02:04.827,000] <err> os: ***** BUS FAULT *****
[00:02:04.834,000] <err> os:   Instruction bus error

Disabling EDMA does not rectify the problem, however disabling LVGL altogether stops the crashes. I run lv_task_handler() in my main thread and do nothing else but update a label on screen, no other threads are started. Stacks are quite large too, and i've disabled compiler optimizations. The trace below shows the PC being loaded with RAM address, which should not happen at all:

[00:01:26.920,000] <err> os: ***** MPU FAULT *****
[00:01:26.928,000] <err> os:   Instruction Access Violation
[00:01:26.936,000] <err> os: r0/a1:  0x00000001  r1/a2:  0x00000058  r2/a3:  0x40cc0000
[00:01:26.947,000] <err> os: r3/a4:  0x00000001 r12/ip:  0x00005385 r14/lr:  0x3007a505
[00:01:26.958,000] <err> os:  xpsr:  0x80000000
[00:01:26.966,000] <err> os: Faulting instruction address (r15/pc): 0x80100d64
[00:01:26.976,000] <err> os: >>> ZEPHYR FATAL ERROR 20: Unknown error on CPU 0
[00:01:26.986,000] <err> os: Current thread: 0x80124a38 (main)
[00:01:26.995,000] <err> os: Halting system

The LR is loaded with address of lv_style_get_prop():

lv_style_res_t lv_style_get_prop(const lv_style_t * style, lv_style_prop_t prop, lv_style_value_t * value)
{
    return lv_style_get_prop_inlined(style, prop, value);
}