SD card writing speed issue

[Z.Hong]

Hi,

I am new to nrf9160 and zephyr. I was using the SD card and a breakout board on SPI bus to write the raw data coming from the PDM interface on nrf9160 Feather. Before that I want to do a SD write test to see how the speed is, so I wrote a simple test as attached.
The problem I am facing is:

• I am able to mount, write and read the file on the SD card, but only on a limit speed of ~ 29KBytes/s, which according to this thread , is using a SPI speed of 4MHz. On my overlay file, I set spi-max-frequency = <8000000> . So I expect it should be at least faster than 29KBytes/s on SD write but not. Then I try changing the spi-max-frequency as different value, like 24MHz, 4MHz, even 800KHz. None of them change the speed and still keep the SD write speed as 29KBytes/s. I wonder if I have done in the wrong way of setting the SPI frequency?
• Second thing I’ve found from the ‘disk_access_spi_sdhc.c’ under ‘zephyr/subsys/disk/’ path that it #define SDHC_SPI_SPEED 4000000, it kind of make sense that why it is running on 4MHz SPI speed, but again, it should be able to change the SPI frequency in some way, which back to my first question if I have done in the wrong way of setting the SPI frequency?
• Third thing I want to ask, as I checked the data sheet of nrf9160, it doesn’t said anything on SPI frequency but from the register, it only list from 125kbps to 8Mbps. I wonder if it is correct to say SPI only run at a maximum speed of 8MHz on nrf9160?

Can anyone help with the issue please, thanks in advanced!!

Zirun

Attachment:
my .overlay:

&spi2 {   
	compatible = "nordic,nrf-spim";
	status = "okay";
        sck-pin = <1>;
        mosi-pin = <30>;
        miso-pin = <0>;
	cs-gpios = <&gpio0 29 GPIO_ACTIVE_LOW>;
	sdhc0: sdhc@0 {
                compatible = "zephyr,mmc-spi-slot";
                reg = <0>;
                status = "okay";
                label = "SDHC0";
                spi-max-frequency = <8000000>;
        };
};

my prj.conf:

#SPI
CONFIG_GPIO=y
CONFIG_SPI=y
CONFIG_SPI_2=y
CONFIG_NRFX_SPIM=y

#Disk access
CONFIG_DISK_ACCESS=y
CONFIG_DISK_ACCESS_SDHC=y
CONFIG_DISK_ACCESS_SPI_SDHC=y

#File system
CONFIG_LOG=y
CONFIG_FILE_SYSTEM=y
CONFIG_FAT_FILESYSTEM_ELM=y
CONFIG_FS_FATFS_LFN=y
CONFIG_PRINTK=y
CONFIG_PRINTK64=y
CONFIG_SPI_NRFX_RAM_BUFFER_SIZE=8

# Stacks and heaps
CONFIG_MAIN_STACK_SIZE=4096
CONFIG_HEAP_MEM_POOL_SIZE=16384

CONFIG_NEWLIB_LIBC=y
#CONFIG_DEBUG=y
CONFIG_BOOTLOADER_MCUBOOT=y

My code:

#include <zephyr.h>
#include <device.h>
#include <disk/disk_access.h>
#include <logging/log.h>
#include <fs/fs.h>
#include <ff.h>

#include <nrf.h>
#include <stdio.h>
#include <string.h>
#include <stdlib.h> 

#define BUF_SIZE 16128
int16_t writebuff[BUF_SIZE];

LOG_MODULE_REGISTER(main);

char testbuff[] = "this is a test buffer";

struct fs_file_t filep;

static FATFS fat_fs;
/* mounting info */
static struct fs_mount_t mp = {
	.type = FS_FATFS,
	.fs_data = &fat_fs,
};

static const char *disk_mount_pt = "/SD:"; 

static int lsdir(const char *path)
{
	int res;
	struct fs_dir_t dirp;
	static struct fs_dirent entry;                                

	/* Verify fs_opendir() */
	res = fs_opendir(&dirp, path);
	if (res) {
		printk("Error opening dir %s [%d]\n", path, res);
		return res;
	}

	printk("\nListing dir %s ...\n", path);
	for (;;) {
		/* Verify fs_readdir() */
		res = fs_readdir(&dirp, &entry);

		/* entry.name[0] == 0 means end-of-dir */
		if (res || entry.name[0] == 0) {
			break;
		}

		if (entry.type == FS_DIR_ENTRY_DIR) {
			printk("[DIR ] %s\n", entry.name);
		} else {
			printk("[FILE] %s (size = %zu)\n",
				entry.name, entry.size);
		}
	}

	/* Verify fs_closedir() */
	fs_closedir(&dirp);

	return res;
}

int FSInit(void)
{
    int res;
	static const char *disk_pdrv = "SD";
	uint64_t memory_size_mb;
	uint32_t block_count;
	uint32_t block_size;

	printk("Filesystem init...\n");
	if (disk_access_init(disk_pdrv) != 0) {
		LOG_ERR("Storage init ERROR!");
		return 0;
	}

	if (disk_access_ioctl(disk_pdrv,
			DISK_IOCTL_GET_SECTOR_COUNT, &block_count)) {
		LOG_ERR("Unable to get sector count");
		return 0;
	}
	LOG_INF("Block count %u", block_count);

	if (disk_access_ioctl(disk_pdrv,
			DISK_IOCTL_GET_SECTOR_SIZE, &block_size)) {
		LOG_ERR("Unable to get sector size");
		return 0;
	}
	printk("Sector size %u\n", block_size);

	memory_size_mb = (uint64_t)block_count * block_size;
	printk("Memory Size(MB) %u\n", (uint32_t)(memory_size_mb >> 20));
	
	mp.mnt_point = disk_mount_pt;
	res = fs_mount(&mp);
	if (res == FR_OK) {
		printk("Disk mounted.\n");
		lsdir(disk_mount_pt);
	} else {
		printk("Error mounting disk.\n");
		return 0;
	}
    return 1;
}

static int SDWriteSpeedTest(void)
{
	int res;
	for (int32_t i = 0; i < BUF_SIZE; i++)
	{
		//Gernate random number into buffer
		writebuff[i] = rand() % 32768;
	}
	LOG_INF("Opening file path");
	res = fs_open(&filep, "/SD:/test.bin", FS_O_CREATE | 
							FS_O_WRITE);
	if (res) {
		LOG_ERR("Error opening file [%d]", res);
		return 0;
	}
	LOG_INF("Done opening file path");
	if (fs_write(&filep, writebuff, BUF_SIZE*sizeof(int16_t)) 
					!= BUF_SIZE*sizeof(int16_t))
	{
		LOG_ERR("failed to wirte buff");
		fs_close(&filep);
		return 0;
	}
	LOG_INF("Done writing");
	fs_close(&filep);
	return 1;
}

void main(void)
{
	int res;
	/* raw disk i/o */
	res = FSInit();
	if (!res)
	{
		LOG_ERR("failed to init filesystem");
	}

	res = SDWriteSpeedTest();
	if (!res)
	{
		LOG_ERR("failed to write");
	}
}

Hers is the result from the terminal:

[00:00:09.860,168] <inf> sdhc_spi: Found a 29664 MiB SDHC card.
[00:00:09.861,450] <inf> sdhc_spi: Manufacturer ID=39 OEM=‘PH’ Name=‘SD32G’ Revision=0×60 Serial=0xda44af6e
[00:00:09.861,480] <inf> main: Block count 60751872
[00:00:09.891,082] <inf> sdhc_spi: Found a 29664 MiB SDHC card.
[00:00:09.892,364] <inf> sdhc_spi: Manufacturer ID=39 OEM=‘PH’ Name=‘SD32G’ Revision=0×60 Serial=0xda44af6e
[00:00:10.551,940] <inf> main: Opening file path
[00:00:10.573,150] <inf> main: Done opening file path
[00:00:11.652,130] <inf> main: Done writing

In this way, speed is 32256 Bytes / (11.652130 - 10.573150) sec ~= 29.19KB/s

[Håkon Alseth]

Hi,

 

The driver sets the frequency configuration to 4MHz:

https://github.com/nrfconnect/sdk-zephyr/blob/v2.4.0-ncs2/drivers/spi/spi_nrfx_spim.c#L431

 

The DMA length is 12 bit, meaning that you have 2047 bytes max per transaction: https://infocenter.nordicsemi.com/topic/ps_nrf9160/spim.html?cp=2_0_0_5_12_5_27#register.RXD.MAXCNT

The configuration "CONFIG_SPI_NRFX_RAM_BUFFER_SIZE=8" gives a chunk size of 8 bytes, as the DMA can only transfer from a RAM buffer. You can try to change this to a higher value, lets say 64, and see if this affects the transfer speed. That being said; you're using a filesystem on your SDHC card, which requires handling as well. Changing the SPI speed can reduce the physical delay between the nRF and SD-card, but you still have to conform to the fatfs filesystem.

 

Could you also try to store a larger file to see if this speed is the same then as well?

 

Kind regards,

Håkon

[Z.Hong]

Hi,

Thanks for your reply.

The driver sets the frequency configuration to 4MHz:

- So can I set it a different value by setting spi-max-frequency in the overlay file? 

 Or maybe, in another approach, setting 

spi_nrfx_config.frequency = NRF_SPIM_FREQ_8M

 

You can try to change this to a higher value, lets say 64, and see if this affects the transfer speed & Could you also try to store a larger file to see if this speed is the same then as well?

- I try in both approach, the result is still the same, even worse when I store a larger file with a speed ~ 24KB/sec.

   Also I probe the CLK line and find that it is at 250KHz.

Zirun

[Håkon Alseth]

Hi,

 

The speeds you're getting (just below 30kB/s) seems to correspond with the numbers provided in this zephyr PR:

https://github.com/zephyrproject-rtos/zephyr/pull/26319

 

It looks like you are writing at 4MHz SPI speed, given the speed results you're seeing. As you can see from the comparison with 250k/4M, its not a linear speed difference, which indicates that it takes quite some processing to conform to the specific filesystem.

 

Kind regards,

Håkon

[Z.Hong]

Hi,

I understand what you mentioned in the answer. However, I just wonder why changing the SPI speed doesn't work, at least different frequency(or speed) will give you a different frequency in the scope, not matter what the value is. Or maybe I defined it in the wrong way. 

From my observation, the only way that the speed changed is changing the SDHC_SPI_INITIAL_SPEED to a different value, which is a hard coding define value. Additionally, this is the initial value, the speed should change to another value (SDHC_SPI_SPEED) after initialization here, but it doesn't.  

So my question is:

- What is the correct way to change/define the SPI frequency in my case?

- Why the hard coding value SDHC_SPI_SPEED doesn't affect the actual read/write speed?

My apology if my expression makes you confused.

Thanks,

Zirun

[Håkon Alseth]

Hi,

Z.Hong said:

From my observation, the only way that the speed changed is changing the SDHC_SPI_INITIAL_SPEED to a different value, which is a hard coding define value. Additionally, this is the initial value, the speed should change to another value (SDHC_SPI_SPEED) after initialization here, but it doesn't.  

Z.Hong said:

- What is the correct way to change/define the SPI frequency in my case?

Z.Hong said:

- Why the hard coding value SDHC_SPI_SPEED doesn't affect the actual read/write speed?

As the frequency in the SDHC library is hard-coded, a change to the zephyr project is needed to allow other frequencies at initial speed and "normal speed".

By looking at the driver port, spi_nrfx_spim.c, it looks like a weakness there (or a intentional implementation), where you can only configure the device once:

https://github.com/nrfconnect/sdk-zephyr/blob/master/drivers/spi/spi_nrfx_spim.c#L112-L114

I would recommend that you either remove this check, or set the SDHC_SPI_INITIAL_SPEED equal to SDHC_SPI_SPEED, ie. up to 8 MHz.

 

Kind regards,

Håkon

  

[Z.Hong]

Thank you so much for the help!

[liteyear]

I hit this obstacle recently too. SD Card reads capped at about 27kB/s. My my, what a mission to get to the bottom of it. After a long battle, the issue is now resolved for me. I ended up using a few fixes that have been applied to the Zephyr upstream project, and back-porting them to the now very out of date nRF Connect SDK downstream project. I've summarised the changes in these three diffs:

sdhc-speed-fix.patch

spi-devicetree-fix-part1.patch

spi-devicetree-fix-part2.patch

My next issue is that SD Card reading disrupts I2S comms... and so the saga continues.