The frdm_k64f board resets itself periodically/A possible NXP MPU bug

[tgorochowik]

Describe the bug
The frdm_k64f board seems to simply reset itself periodically, no error or fault is shown.
It happens more or less often depending on the sample and its configuration.

To Reproduce
I've found, that it is the easiest to reproduce this issue using the samples/net/gptp sample, with NET_BUF_POOL_USAGE and NET_DEBUG_NET_PKT_ALLOC enabled. In such configuration, the board resets itself almost instantly (like every second), here is a sample output:

uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-251-gd079ce05c7 *****
                                                                
                                                                
[00:00:00.007,651] <inf> net_config: Initializing network       
[00:00:00.007,676] <inf> net_config: IPv4 address: 192.0.2.1    
[00:00:00.110,076] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
[00:00:00.110,163] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-251-gd079ce05c7 *****
                                                                
                                                                
[00:00:00.007,651] <inf> net_config: Initializing network       
[00:00:00.007,676] <inf> net_config: IPv4 address: 192.0.2.1    
[00:00:00.110,076] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
[00:00:00.110,163] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-251-gd079ce05c7 *****
                                                                
                                                                
[00:00:00.007,651] <inf> net_config: Initializing network       
[00:00:00.007,676] <inf> net_config: IPv4 address: 192.0.2.1    
[00:00:00.110,076] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
[00:00:00.110,163] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-251-gd079ce05c7 *****
                                                                
                                                                
[00:00:00.007,651] <inf> net_config: Initializing network       
[00:00:00.007,676] <inf> net_config: IPv4 address: 192.0.2.1    
[00:00:00.110,076] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
[00:00:00.110,163] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62

(...)

It does happen with other configurations/samples too. Just less often. I think that the number of threads plays a significant role too.

Also note, that even though it is a networking sample, the Ethernet cable does not even have to be connected to reproduce this.

Expected behavior
The resets should not be happening.

Environment (please complete the following information):

• OS: Linux
• Zephyr SDK
• Commit SHA: d079ce0

Additional context

I bisected the code, and found, that this PR is when it started: #12817.

Looking at what is different to what was happening earlier, is that the main MPU region mapping is deleted and re-created each time the dynamic regions are to be changed (so when a thread is created or switched) - it seems that earlier, the main MPU mapping for RAM was done just once and left unchanged.

Looking at what actually happens there, I've noticed that there are some spinlocks, but the interrupts are never disabled - shouldn't they be?

I've come with a following fix:

From fc5b87fb2dff32d4348725da1e22fd276acb2f81 Mon Sep 17 00:00:00 2001
From: Tomasz Gorochowik <tgorochowik@antmicro.com>
Date: Mon, 18 Feb 2019 16:08:01 +0100
Subject: [PATCH] arch: arm: mpu: Lock interrupts before re-mapping MPU

This fixes the issue with periodical resets of the frdm_k64f board.

Signed-off-by: Tomasz Gorochowik <tgorochowik@antmicro.com>
---
 arch/arm/core/cortex_m/mpu/arm_core_mpu.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/arch/arm/core/cortex_m/mpu/arm_core_mpu.c b/arch/arm/core/cortex_m/mpu/arm_core_mpu.c
index 6ebedd1948..1e395c855f 100644
--- a/arch/arm/core/cortex_m/mpu/arm_core_mpu.c
+++ b/arch/arm/core/cortex_m/mpu/arm_core_mpu.c
@@ -130,6 +130,7 @@ void _arch_configure_dynamic_mpu_regions(struct k_thread *thread)
 	struct k_mem_partition dynamic_regions[_MAX_DYNAMIC_MPU_REGIONS_NUM];
 
 	u8_t region_num = 0;
+	int key;
 
 #if defined(CONFIG_USERSPACE)
 	/* Memory domain */
@@ -208,9 +209,13 @@ void _arch_configure_dynamic_mpu_regions(struct k_thread *thread)
 	region_num++;
 #endif /* CONFIG_MPU_STACK_GUARD */
 
+	key = irq_lock();
+
 	/* Configure the dynamic MPU regions */
 	arm_core_mpu_configure_dynamic_mpu_regions(dynamic_regions,
 		region_num);
+
+	irq_unlock(key);
 }
 
 #if defined(CONFIG_USERSPACE)
-- 
2.20.1

This seems to fully resolve the issue for me. However I am not sure if that is the correct approach to solving this issue and thus I decided to post it as an issue rather than a PR.

@ioannisg would you mind taking a look at this as the author of the PR I mentioned?

[ioannisg]

Thanks for reporting this, @tgorochowik , actually, this is exactly what we wanted to avoid:

• disabling and re-enabling interrupts while we re-program MPU
• disable and re-enabling MPU while we re-program regions

I am not able to reproduce this with current master HEAD (f9e73c9)

uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-252-gf9e73c90f2 *****


[00:00:00.007,401] <inf> net_config: Initializing network
[00:00:00.007,427] <inf> net_config: IPv4 address: 192.0.2.1
[00:00:00.110,073] <inf> net_config: IPv6 address: fe80::204:9fff:fe31:b346
[00:00:00.110,155] <inf> net_config: IPv6 address: fe80::204:9fff:fe31:b346
[00:00:01.060,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:02.120,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:03.180,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:04.240,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:05.300,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:06.360,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:07.420,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:08.480,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:09.540,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:10.600,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:11.660,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:12.720,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:13.780,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:14.840,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:15.900,022] <wrn> net_gptp: Reset Pdelay requests
[00:00:16.960,022] <wrn> net_gptp: Reset Pdelay requests
uart:~$

Could you check that you can still see the re-initialization all the time?

[tgorochowik]

@ioannisg thanks for testing this! Yes, it still happens on the commit you pointed.

uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-252-gf9e73c90f2 *****
                                                        
                                                        
[00:00:00.007,651] <inf> net_config: Initializing network
[00:00:00.007,676] <inf> net_config: IPv4 address: 192.0.2.1
[00:00:00.110,076] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
[00:00:00.110,163] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-252-gf9e73c90f2 *****
                                                        
                                                        
[00:00:00.007,651] <inf> net_config: Initializing network
[00:00:00.007,676] <inf> net_config: IPv4 address: 192.0.2.1
[00:00:00.110,076] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
[00:00:00.110,163] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-252-gf9e73c90f2 *****
                                                        
                                                        
[00:00:00.007,651] <inf> net_config: Initializing network
[00:00:00.007,676] <inf> net_config: IPv4 address: 192.0.2.1
[00:00:00.110,076] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
[00:00:00.110,163] <inf> net_config: IPv6 address: fe80::204:9fff:fe36:bf62
uart:~$ ***** Booting Zephyr OS v1.14.0-rc1-252-gf9e73c90f2 *****

Please make sure you enable NET_BUF_POOL_USAGE and NET_DEBUG_NET_PKT_ALLOC - I am not sure what is so special about these two symbols in this case, but enabling them makes the reset period much, much shorter. Without them, it takes about 30s to 60s for it to reset (but it is still reproducible every time for me).

actually, this is exactly what we wanted to avoid:

• disabling and re-enabling interrupts while we re-program MPU
• disable and re-enabling MPU while we re-program regions

Ok, I understand.

But I think that the exact moment where the problem is happening is when the whole static region is un-mapped, and before it is re-mapped, an interrupt happens. Or at least it appears to be so.

If I completely remove the main/static re-initialization call:

diff --git a/arch/arm/core/cortex_m/mpu/nxp_mpu.c b/arch/arm/core/cortex_m/mpu/nxp_mpu.c
index 9be959affc..ece9011fb6 100644
--- a/arch/arm/core/cortex_m/mpu/nxp_mpu.c
+++ b/arch/arm/core/cortex_m/mpu/nxp_mpu.c
@@ -328,8 +328,8 @@ static int _mpu_configure_dynamic_mpu_regions(const struct k_mem_partition
        /* Reset MPU regions inside which dynamic memory regions may
         * be programmed.
         */
-       _region_init(mpu_config.sram_region, (const struct nxp_mpu_region *)
-               &mpu_config.mpu_regions[mpu_config.sram_region]);
+       //_region_init(mpu_config.sram_region, (const struct nxp_mpu_region *)
+               //&mpu_config.mpu_regions[mpu_config.sram_region]);
 
        u32_t mpu_reg_index = static_regions_num;

It starts to work too, however I guess it won't if there actually are any dynamic regions to configure? (Currently there are none and its the whole ram that gets un-mapped and re-mapped, nothing else is actually happening there)