PSOC6, retarget_io printf vs vTaskDelay - what is really happening

Even though this is an Infineon cpu i wanted to post here first because my question may be more kernel related.

I ran into a problem where 2 tasks would not always behave correctly at a fixed interval of time - I cannot root cause this yet, described below.
BUT I found a work around that I also cannot make sense of.

If i put a simple printf statement in task #1 that prints 16 hex chars to the debug part at 115200 bps, which takes maybe a few milliseconds, both tasks work correctly.

If I replace the printf statement with one vTaskDelay() of any amount of time, 10-500ms say, the problem still exists.

vTaskDelay(100); <— does not work

 printf(16 chars @ 115200);  <-- has been working non stop for 4 days

more detailed descritpion:
Basically task1 is writing to NAND flash and incrementing a write_page_counter AFTER the write is completed, task2 is reading from NAND flash but waits on the write_page_counter to pass the read_page_counter, which means, there is new data to read. Essentially task2 sits in a forever loop comparing the counters. If the write_ page_counter passes the read_page_counter it reads a new flash page. After task1 writes 128 pages to flash, task2 fails to read page 127. Every time.

If I put the printf() in task1 immediately after it does the write to NAND flash this problem goes away completely, i have been run-in the code nonstop for 4 days.

If i put a vTaskDelay after the flash write the problem does not go away. I thought it would be like the printf, just delaying things…

So question is this: what is the kernel really doing during a printf vs vTaskDelay? something is for sure different.

thanks for letting me ramble…

This certainly does not sound right.

Can you share code snippets? I want to see if there is some data race.

Is it possible to step through the code and find out the cause of the failure?

Also, make sure to define configASSERT and enable stack overflow and malloc failed checks.

Hi Gaurav,
thanks for quick response…
i think this may be a hardware related issue but… what is weird is the difference between sticking a printf() in the code vs a vTaskDelay… the printf() always works.
Also, the code does not crash it just reads the wrong data from the flash ONLY after certain ERASE cycles…not all ERASE cycles…only every other one, like multiples of N*128… it looks like.

  1. yes i have those flags set in FreeRTOSConfig.h
  2. i have stepped thru the code and its somewhat difficult to do im using ModusToolbox and you cannot set conditional breakpoints unfortunately, but when i do step thru the code the read and write pointers look correct
  3. there are 2 tasks: flash_writer and flash_reader here are some code snips (flash_writer waits for data in a queue, flash_reader waits for the write pointer to pass the read pointer)
  4. the NAND flash driver i have written using macros like ERASE_BLOCK(), WRITE_FLASH() and READ_FLASH() that actually encapulate low-level QSPI transactions for this particular PSOC6 cpu.
  5. print_array() is just a function that just does a bunch of printf’s, so it is calling a function there. I noted in the snip below where it passes and fails with “<—”
  6. flash_reader has the write_page_counter as an extern so it can see it of course
  7. i dont expect you to dive into the details of the NAND flash and how that works from a QSPI point of view but i am very curious why vTaskDelay() does not work but the print_array() does work
  8. i have also included a snip of what it looks like when it fails to read the flash correctly and the code checks for “FF” then halts, its as if the flash_reader is reading “too soon” like right after the ERASE but before the next FLASH_WRITE

---------------- flashwriter--------------

void flash_writer(void *params){
    write_page_counter = 0;
    write_blk_counter = 0;
    uint32_t current_space = PAGE_REAL_SIZE;
    enum which ping_pong_flag = ping;
        xQueueReceive(Q_SensorBuffers, temp_buff, portMAX_DELAY);
//        if( xSemaphoreTake( xMutex1, ( TickType_t ) 10 ) == pdTRUE ){
//        	printf("\r\nflash_writer: wr_pg_ctr: %ld wr_block= %ld space= %ld\r\n",write_page_counter, write_blk_counter, current_space);
//        	//print_array("flash_writer", temp_buff, 10);
//      	  xSemaphoreGive( xMutex1 );
//        }
#if 1
			if(temp_buff[2] <= current_space){  /* LEN is third byte in the buffer */
				/* (ping_pong_flag==Ping)? (copy into ping):(copy into pong)*/
				(ping_pong_flag == ping) ? memcpy(&ping_buff[PAGE_REAL_SIZE-current_space],temp_buff,temp_buff[2]) :
				/* decrement current space by LEN */
				current_space -= temp_buff[2];
			else {
					WRITE_FLASH(write_page_counter, ping_buff, (PAGE_REAL_SIZE-current_space));
					//printf("\r\nflash_writer: wr_pg_ctr: %ld wr_block= %ld space= %ld\r\n",write_page_counter, write_blk_counter, current_space);
					//print_array("writer", ping_buff,16);
					/* put the last queue entry into the pong buffer */
					memcpy(pong_buff, temp_buff, temp_buff[2]);
					ping_pong_flag = pong;
					/* clear the ping buffer */
					memset(ping_buff, 0, PAGE_REAL_SIZE);

				} /* end of write to PING */
				else {
					WRITE_FLASH(write_page_counter, pong_buff, (PAGE_REAL_SIZE-current_space));
					//printf("\r\nflash_writer: wr_pg_ctr: %ld wr_block= %ld space= %ld\r\n",write_page_counter, write_blk_counter, current_space);
					//print_array("writer", pong_buff,16);<---WORKS!
					vTaskDelay(10); <<---FAILS
					/* put last queue entry into the ping buffer */
					memcpy(ping_buff, temp_buff, temp_buff[2]);
					ping_pong_flag = ping;
					/* clear the pong buffer */
					memset(pong_buff, 0, PAGE_REAL_SIZE);

				}  /* end of write to PONG */

				/* set current space = 2048 */
				current_space = PAGE_REAL_SIZE;
				/* check for getting close to block boundary ! */
				if (((write_page_counter) % 64) == 0){
					printf("\r\ntime to erase next block!\r\n");
			} /* end of ELSE, which means WRITE FLASH happened */

			/* wrap around when full */
			if(write_page_counter == 0x20000){
			   if( xSemaphoreTake( xMutex1, ( TickType_t ) 10 ) == pdTRUE ){
				   printf("\r\nFLASH FULL- WRAPPING\r\n");
				   xSemaphoreGive( xMutex1 );
				 write_page_counter = 0;
				 write_blk_counter = 0;
				 current_space = PAGE_REAL_SIZE;

    } /* END OF for(;;) LOOP */
} /* END OF flash_writer */

----------------- flash reader ----------------

extern uint32_t write_page_counter;
static uint32_t read_page_counter = 0;
static uint8_t nand_read_buff[PAGE_SIZE];

void flash_reader(void *params){

    /* Read flash for non-0xff data */

	  for (;;) {
		if ((write_page_counter > read_page_counter)){
		   READ_FLASH(read_page_counter, nand_read_buff, PAGE_REAL_SIZE);
		   if( xSemaphoreTake( xMutex1, ( TickType_t ) 10 ) == pdTRUE ){
			   printf("\r\n************FLASH READER: rd_pg_ctr: %ld wr_pg_ctr: %ld **********\r\n",read_page_counter,write_page_counter);
		       print_array("flash read", nand_read_buff, 16);
 	    	   xSemaphoreGive( xMutex1 );
		       if(nand_read_buff[0] == 0xff) vTaskSuspend(NULL);
	       if (read_page_counter == 0x1ffff)
	    	   read_page_counter = 0;  // account for wrap around
		} // end of if(...

---------------flash read WRONG -----------------------------
************FLASH READER: rd_pg_ctr: 126 wr_pg_ctr: 127 **********

flash read (16 bytes):

0xA5 0x8A 0x1E 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02

time to erase next block!

************FLASH READER: rd_pg_ctr: 127 wr_pg_ctr: 128 **********

flash read (16 bytes):

0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF 0xFF

------------------- flash read CORRECT --------------------
************FLASH READER: rd_pg_ctr: 126 wr_pg_ctr: 127 **********

flash read (16 bytes):

0xA5 0x8A 0x1E 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02 0x02

writer (16 bytes):

0xA5 0x8D 0x0A 0x01 0x01 0x01 0x01 0x01 0x01 0x01 0xA5 0x8B 0x46 0x03 0x03 0x03

time to erase
********* next block!***FLASH RE
ADER: rd_pg_ctr: 127 wr_pg_ctr: 128 **********

flash read (16 bytes):

0xA5 0x8D 0x0A 0x01 0x01 0x01 0x01 0x01 0x01 0x01 0xA5 0x8B 0x46 0x03 0x03 0x03

The difference is when you call print_array, the flash_writer task continues and probably gets swapped out at a later point and the flash_reader task is swapped in. On the other hand, when you call vTaskDelay, the flash_writer task is immediately swapped out and the flash_reader task is swapped in. As a result, in the latter case, the read would likely happen earlier.

Is it possible that you need to add some busy wait to your implementation of WRITE_FLASH so that it does not return before the write is actually complete? Does the flash provide you any notification when the write is complete?

Also, I assume that these QSPI transactions should not be interrupted and you are taking care of that.

Ok thanks for the explanation I had that same thought about printf and vtaskdelay…

i will try some things today but also i have put the whole ERASE macro - which calls 2 low-level QSPI functions - in a critical section and that did not work.

the low-level QSPI functions are provided by the chip vendor, and should be atomic operations as the QSPI interface cannot be shared, if someone tried to access the QSPI interface at the same time there would be an error thrown, as a matter of fact each QSPI function returns a status value that is checked.

Also the flash ERASE macro includes a check of the an internal status register that shows the progress of the erase and i have been printing that out and it looks correct so the ERASE does not end until the status register says it is complete.

thanks for your help … if something changes I will let you know

Double check to ensure that those QSPI functions are okay to interrupted. Another thing to note is that if you are calling more than QSPI functions in for one operation, is it okay if the code is interrupted in between?

Is that needed for all the flash operations and not just erase?