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,

 

My apologies, the spi_nrfx_spim port reconfigures the SPI frequency after the application calls the first spi_transceive function, as explained in the comment here:

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

 

Z.Hong said:

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

It looks like the initial communication is at 250 kHz, and it switches to 4M after successful init:

https://github.com/nrfconnect/sdk-zephyr/blob/master/subsys/disk/disk_access_spi_sdhc.c#L18-L21

 

Did you scope the communication when transferring a file?

 

Kind regards,

Håkon 

[Z.Hong]

Hi,

I do probe the CLK line when transmitting the file, and it doesn't change to 4MHz. It remains at 250KHz for some reason.

So, I manually change the SDHC_SPI_INITIAL_SPEED to 4MHZ, not sure if it is correct to do so, but it initially at 4MHZ and remains at 4MHz when doing file writing. I guess it doesn't change the speed here when it finish initialization. Also I notice the speed is not changed/updated to new value in disk_access_spi_sdhc.c, maybe it is defined somewhere?

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