Possible race condition when accessing SPI NOR Flash ?
Valentin Longchamp
valentin.longchamp at keymile.com
Thu May 1 04:52:55 PDT 2014
Hello,
I am currently seeing a very strange behavior on one our PowerPC based systems
(P2041 from Freescale). We have u-boot as a bootloader, currently using the
2013.10 release. The u-boot environment variables are stored in a SPI NOR Flash
(from which the CPU also boots u-boot), in two dedicated partitions in a
Spansion s25fl256s1 NOR Flash:
> spi at 110000 {
> flash at 0 {
> #address-cells = <1>;
> #size-cells = <1>;
> compatible = "spansion,s25fl256s1";
> reg = <0>;
> spi-max-frequency = <20000000>; /* input clock */
> partition at u-boot {
> label = "u-boot";
> reg = <0x00000000 0x00100000>;
> read-only;
> };
> partition at env {
> label = "env";
> reg = <0x00100000 0x00010000>;
> };
> partition at envred {
> label = "envred";
> reg = <0x00110000 0x00010000>;
> };
> partition at fman {
> label = "fman-ucode";
> reg = <0x00120000 0x00010000>;
> };
> };
>
I have never noticed a problem when accessing the environment variables from
u-boot itself, nor the CPU not booting from the NOR Flash, so I assume the
hardware is OK (and I am able to reproduce it on Freescale's dev board).
Now when fw_setenv ([1], [2]) updates the environment variables, it sometimes
(approximately 1 out of 100 runs) triggers such kernel errors:
>
> Unable to handle kernel paging request for data at address 0x54cc2178
> Faulting instruction address: 0xc01187e8
> Oops: Kernel access of bad area, sig: 11 [#2]
> SMP NR_CPUS=8 Keymile kmp204x
> Modules linked in:
> CPU: 2 PID: 1628 Comm: loop_setenv Tainted: G B D 3.10.36-7.0.9-00435-g228e7e3 #21
> task: db720cb0 ti: db92e000 task.ti: db92e000
> NIP: c01187e8 LR: c011866c CTR: 00000000
> REGS: db92fd80 TRAP: 0300 Tainted: G B D (3.10.36-7.0.9-00435-g228e7e3)
> MSR: 00021002 <CE,ME> CR: 24002424 XER: 20000000
> DEAR: 54cc2178, ESR: 00800000
>
> GPR00: c011978c db92fe30 db720cb0 db8400c0 000000d0 00000000 db66f5bc 7f7f7f7f
> GPR08: db0b4e90 db008a44 54cc2174 00000fec 24002422 1001c6ec 00000000 c0890000
> GPR16: db008a54 db008a4c c0890000 00100100 00200200 00000001 db008a44 db008a40
> GPR24: c0893444 00000000 000000d0 db92e000 db003dc0 db0b4e00 0000001b db840000
> NIP [c01187e8] cache_alloc_refill+0x208/0x710
> LR [c011866c] cache_alloc_refill+0x8c/0x710
> Call Trace:
> [db92fe30] [c000ede8] handle_page_fault+0xc/0x80 (unreliable)
> [db92fe80] [c011978c] kmem_cache_alloc+0xec/0x180
> [db92fea0] [c00580a4] prepare_creds+0x24/0x1c0
> [db92feb0] [c0058964] prepare_exec_creds+0x14/0x50
> [db92fec0] [c012635c] prepare_bprm_creds+0x2c/0x70
> [db92fed0] [c01264bc] do_execve+0xbc/0x520
> [db92ff20] [c0126b6c] SyS_execve+0x3c/0x70
> [db92ff40] [c000e944] ret_from_syscall+0x0/0x3c
> --- Exception: c01 at 0xfed2d24
> LR = 0xfe6aef8
> Instruction dump:
> 39090004 39290001 5508103a 7d1d4214 90680004 913d0000 813f0010 815c0018
> 7f095040 41f8ff94 813f0004 815f0000 <912a0004> 91490000 927f0000 929f0004
> ---[ end trace 85ac86b7cd18b604 ]---
OR:
> Unable to handle kernel paging request for data at address 0x54cc2178
> Faulting instruction address: 0xc0117c5c
> Oops: Kernel access of bad area, sig: 11 [#1]
> SMP NR_CPUS=8 Keymile kmp204x
> Modules linked in:
> CPU: 2 PID: 29 Comm: kworker/2:1 Not tainted 3.10.36-7.0.9-00435-g228e7e3 #21
> Workqueue: events cache_reap
> task: db2c12f0 ti: db2c6000 task.ti: db2c6000
> NIP: c0117c5c LR: c011816c CTR: 00000000
> REGS: db2c7d50 TRAP: 0300 Not tainted (3.10.36-7.0.9-00435-g228e7e3)
> MSR: 00021002 <CE,ME> CR: 24002424 XER: 20000000
> DEAR: 54cc2178, ESR: 00800000
>
> GPR00: c011816c db2c7e00 db2c12f0 db003cc0 db800000 00000000 00000080 54cc2174
> GPR08: 00005000 db008980 db800040 00021002 24000422 00000000 c0050300 db0d3de8
> GPR16: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 c1167740
> GPR24: 00000000 c0893260 00100100 00200200 00000002 db003cc0 db0afdd4 00000000
> NIP [c0117c5c] free_block+0xbc/0x180
> LR [c011816c] drain_array+0xfc/0x150
> Call Trace:
> [db2c7e30] [c011816c] drain_array+0xfc/0x150
> [db2c7e60] [c01183cc] cache_reap+0xac/0x170
> [db2c7e90] [c0046ce0] process_one_work+0x150/0x3d0
> [db2c7ec0] [c00473ac] worker_thread+0x12c/0x390
> [db2c7ef0] [c00503a8] kthread+0xa8/0xb0
> [db2c7f40] [c000ea7c] ret_from_kernel_thread+0x5c/0x64
> Instruction dump:
> 3d0a4000 5508c9f4 81390000 7cc9402e 7ce94214 70c58000 40c200c4 80870014
> 813d0050 80e40000 81040004 7d29c02e <91070004> 90e80000 38c90004 93440000
> ---[ end trace 721e12de4b707566 ]---
Notice that this does not necessarily happen in fw_setenv itself, but rather in
the next "task" that tries to allocate/free some virtual memory.
I see the same behavior with both the 2013.10 and the 2014.04 releases of
u-boot/fw_env. The kernel we are using is 3.10.36.
I suspect that the problem is related to SPI NOR/m25p80 driver: on the system we
have a NAND Flash device with UBI volumes. If I create 2 ubi volumes on the NAND
Flash and configure fw_setenv (/etc/fw_env.config) to use them instead of the
the mtd devices targetting the s25fl256s1, I am not able to reproduce the
problem, even over more than 10'000 runs.
I suspect that it is a race condition because it happens ~1 out of 100 times
and if I disable SMP in the kernel I am never able to reproduce the problem.
Finally, after having analyzed the fw_env behavior, I have tried to write a very
silly program that mimics the fw_env mtd accesses in my use case (attached with
this email) and I am able to reproduce the problem with it.
One other possible culprit that I see is the fsl_espi.c driver for the
underlying hardware connection from the CPU to the NOR Flash, but I wanted to
ask here if someone had an idea about what's going wrong.
Valentin
[1] http://elinux.org/U-boot_environment_variables_in_linux
[2]
http://git.denx.de/?p=u-boot.git;a=tree;f=tools/env;h=99706ce668db90bd4a476a12e6c07fe2e4b85fbb;hb=master
-------------- next part --------------
#include <sys/types.h>
#include <sys/ioctl.h>
#include <stdio.h>
#include <unistd.h>
#include <string.h>
#include <errno.h>
#include <fcntl.h>
#include <mtd/mtd-user.h>
int mtd_open(const char *file, mode_t mode) {
int fd = open(file, mode);
if (fd == -1) {
printf("Error opening file %s: %s\n", file, strerror(errno));
return -1;
}
return fd;
}
int mtd_read(int fd, void *buf, size_t count) {
int sz = read(fd, buf, count);
if (sz == -1) {
printf("Error reading fd %d: %s\n", fd, strerror(errno));
}
return sz;
}
int mtd_write(int fd, void *buf, size_t count) {
int sz = write(fd, buf, count);
if (sz == -1) {
printf("Error reading fd %d: %s\n", fd, strerror(errno));
}
return sz;
}
int mtd_seek(int fd, off_t offset) {
int ret = lseek(fd, offset, SEEK_SET);
if (ret == -1) {
printf("Error closing fd %d: %s\n", fd, strerror(errno));
}
return ret;
}
int mtd_erase(int fd, off_t offset) {
int ret = ioctl(fd, MEMERASE, &offset);
if (ret == -1) {
printf("Error erasing fd %d: %s\n", fd, strerror(errno));
}
return ret;
}
int mtd_close(int fd) {
int ret = close(fd);
if (ret) {
printf("Error closing fd %d: %s\n", fd, strerror(errno));
}
return ret;
}
int main(int argc, char *argv[])
{
int retValue;
int i;
int readSz1 = 0x4000;
int readSz2 = 0x10000;
char buffer1[readSz1];
char buffer2[readSz2];
char * file1 = "/dev/mtd6";
char * file2 = "/dev/mtd7";
for (i=0; i < 1000; i++) {
int ret, sz1, sz2, fd1, fd2;
fd1 = mtd_open(file1, O_RDONLY);
ret = mtd_seek(fd1, 0);
sz1 = mtd_read(fd1, buffer1, readSz1);
ret = mtd_close(fd1);
fd2 = mtd_open(file2, O_RDONLY);
ret = mtd_seek(fd2, 0);
sz2 = mtd_read(fd2, buffer2, readSz1);
ret = mtd_close(fd2);
fd1 = mtd_open(file1, O_RDWR);
fd2 = mtd_open(file2, O_RDWR);
sz1 = mtd_read(fd2, buffer2, readSz2);
ret = mtd_seek(fd2, 0);
ret = mtd_erase(fd2, 0);
sz1 = mtd_write(fd2, buffer2, readSz2);
ret = mtd_seek(fd1, 4);
sz2 = mtd_write(fd1, "\0", 1);
ret = mtd_close(fd1);
ret = mtd_close(fd2);
if (!(i%50))
printf("mtd, loop i=%d \n", i);
}
return 0;
}
More information about the linux-mtd
mailing list