Added some debug output to the init process to see what’s going on.
Old driver init process
First checkpoint block: 0
Last checkpoint block: 526
Finding last group in block 526 with 4 groups
log2_ppc=4, log2_ppb=6
is free, page=33680, used_marker=ffffffff,
is free, page=33696, used_marker=ffffffff,
is free, page=33696, used_marker=ffffffff,
is free, page=33712, used_marker=ffffffff,
is free, page=33713, used_marker=ffffffff,
is free, page=33714, used_marker=ffffffff,
is free, page=33715, used_marker=ffffffff,
is free, page=33716, used_marker=ffffffff,
is free, page=33717, used_marker=ffffffff,
is free, page=33718, used_marker=ffffffff,
is free, page=33719, used_marker=ffffffff,
is free, page=33720, used_marker=ffffffff,
is free, page=33721, used_marker=ffffffff,
is free, page=33722, used_marker=ffffffff,
is free, page=33723, used_marker=ffffffff,
is free, page=33724, used_marker=ffffffff,
is free, page=33725, used_marker=ffffffff,
is free, page=33726, used_marker=ffffffff,
is free, page=33727, used_marker=ffffffff,
Last checkpoint group page: 33696
Journal root page: 33710
Restored tail: 19946, bb_current: 0, bb_last: 16
is free, page=33697, used_marker=ffffffff,
is free, page=33698, used_marker=ffffffff,
is free, page=33699, used_marker=ffffffff,
is free, page=33700, used_marker=ffffffff,
is free, page=33701, used_marker=ffffffff,
is free, page=33702, used_marker=ffffffff,
is free, page=33703, used_marker=ffffffff,
is free, page=33704, used_marker=ffffffff,
is free, page=33705, used_marker=ffffffff,
is free, page=33706, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33701, used_marker=ffffffff,
is free, page=33702, used_marker=ffffffff,
is free, page=33703, used_marker=ffffffff,
is free, page=33704, used_marker=ffffffff,
is free, page=33705, used_marker=ffffffff,
is free, page=33706, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33702, used_marker=ffffffff,
is free, page=33703, used_marker=ffffffff,
is free, page=33704, used_marker=ffffffff,
is free, page=33705, used_marker=ffffffff,
is free, page=33706, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33703, used_marker=ffffffff,
is free, page=33704, used_marker=ffffffff,
is free, page=33705, used_marker=ffffffff,
is free, page=33706, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33704, used_marker=ffffffff,
is free, page=33705, used_marker=ffffffff,
is free, page=33706, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33705, used_marker=ffffffff,
is free, page=33706, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33706, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33707, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33708, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33709, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33710, used_marker=ffffffff,
is free, page=33711, used_marker=ffffffff,
is free, page=33712, used_marker=ffffffff,
is free, page=33713, used_marker=ffffffff,
is free, page=33714, used_marker=ffffffff,
is free, page=33715, used_marker=ffffffff,
is free, page=33716, used_marker=ffffffff,
is free, page=33717, used_marker=ffffffff,
is free, page=33718, used_marker=ffffffff,
is free, page=33719, used_marker=ffffffff,
is free, page=33720, used_marker=ffffffff,
is free, page=33721, used_marker=ffffffff,
is free, page=33722, used_marker=ffffffff,
is free, page=33723, used_marker=ffffffff,
is free, page=33724, used_marker=ffffffff,
is free, page=33725, used_marker=ffffffff,
is free, page=33726, used_marker=ffffffff,
is free, page=33727, used_marker=ffffffff,
Journal head page: 33712
First checkpoint block: 0
Last checkpoint block: 526
Finding last group in block 526 with 4 groups
log2_ppc=4, log2_ppb=6
is free, page=33680, used_marker=ffffffff,
is free, page=33696, used_marker=ffffffff,
is free, page=33696, used_marker=ffffffff,
...
Last checkpoint group page: 33696
Journal root page: 33710
Restored tail: 19946, bb_current: 0, bb_last: 16
is free, page=33697, used_marker=ffffffff,
is free, page=33698, used_marker=ffffffff,
is free, page=33699, used_marker=ffffffff,
is free, page=33700, used_marker=ffffffff,
...
is free, page=33701, used_marker=ffffffff,
is free, page=33702, used_marker=ffffffff,
...
is free, page=33702, used_marker=ffffffff,
is free, page=33703, used_marker=ffffffff,
Journal head page: 33712
This is a lot to break down, but the scanning of pages is out of order and often redundant.
New driver init
HiZ> ls
diskio_initialize called with drv=0
Initializing SPI NAND flash on SPI port 4003C000 with CS pin 26
Starting NAND chip detection...
[D][nand_flash] detect_chip: manufacturer_id: 2c
Detected SPI NAND Manufacturer ID: 0x2C
NAND chip detected and unprotected successfully.
[D][spi_nand] is_bad, block=0, page=0,indicator = ffff
First checkpoint block at 0
[D][spi_nand] is_bad, block=511, page=32704,indicator = ffff
[D][spi_nand] is_bad, block=512, page=32768,indicator = ffff
[D][spi_nand] is_bad, block=767, page=49088,indicator = ffff
[D][spi_nand] is_bad, block=768, page=49152,indicator = ffff
[D][spi_nand] is_bad, block=769, page=49216,indicator = ffff
[D][spi_nand] is_bad, block=770, page=49280,indicator = ffff
[D][spi_nand] is_bad, block=771, page=49344,indicator = ffff
[D][spi_nand] is_bad, block=772, page=49408,indicator = ffff
[D][spi_nand] is_bad, block=773, page=49472,indicator = ffff
[D][spi_nand] is_bad, block=774, page=49536,indicator = ffff
[D][spi_nand] is_bad, block=639, page=40896,indicator = ffff
[D][spi_nand] is_bad, block=640, page=40960,indicator = ffff
[D][spi_nand] is_bad, block=641, page=41024,indicator = ffff
[D][spi_nand] is_bad, block=642, page=41088,indicator = ffff
[D][spi_nand] is_bad, block=643, page=41152,indicator = ffff
[D][spi_nand] is_bad, block=644, page=41216,indicator = ffff
[D][spi_nand] is_bad, block=645, page=41280,indicator = ffff
[D][spi_nand] is_bad, block=646, page=41344,indicator = ffff
[D][spi_nand] is_bad, block=575, page=36800,indicator = ffff
[D][spi_nand] is_bad, block=576, page=36864,indicator = ffff
[D][spi_nand] is_bad, block=577, page=36928,indicator = ffff
[D][spi_nand] is_bad, block=578, page=36992,indicator = ffff
[D][spi_nand] is_bad, block=579, page=37056,indicator = ffff
[D][spi_nand] is_bad, block=580, page=37120,indicator = ffff
[D][spi_nand] is_bad, block=581, page=37184,indicator = ffff
[D][spi_nand] is_bad, block=582, page=37248,indicator = ffff
[D][spi_nand] is_bad, block=543, page=34752,indicator = ffff
[D][spi_nand] is_bad, block=544, page=34816,indicator = ffff
[D][spi_nand] is_bad, block=545, page=34880,indicator = ffff
[D][spi_nand] is_bad, block=546, page=34944,indicator = ffff
[D][spi_nand] is_bad, block=547, page=35008,indicator = ffff
[D][spi_nand] is_bad, block=548, page=35072,indicator = ffff
[D][spi_nand] is_bad, block=549, page=35136,indicator = ffff
[D][spi_nand] is_bad, block=550, page=35200,indicator = ffff
[D][spi_nand] is_bad, block=527, page=33728,indicator = ffff
[D][spi_nand] is_bad, block=528, page=33792,indicator = ffff
[D][spi_nand] is_bad, block=529, page=33856,indicator = ffff
[D][spi_nand] is_bad, block=530, page=33920,indicator = ffff
[D][spi_nand] is_bad, block=531, page=33984,indicator = ffff
[D][spi_nand] is_bad, block=532, page=34048,indicator = ffff
[D][spi_nand] is_bad, block=533, page=34112,indicator = ffff
[D][spi_nand] is_bad, block=534, page=34176,indicator = ffff
[D][spi_nand] is_bad, block=519, page=33216,indicator = ffff
[D][spi_nand] is_bad, block=520, page=33280,indicator = ffff
[D][spi_nand] is_bad, block=523, page=33472,indicator = ffff
[D][spi_nand] is_bad, block=524, page=33536,indicator = ffff
[D][spi_nand] is_bad, block=525, page=33600,indicator = ffff
[D][spi_nand] is_bad, block=526, page=33664,indicator = ffff
[D][spi_nand] is_bad, block=526, page=33664,indicator = ffff
[D][spi_nand] is_bad, block=527, page=33728,indicator = ffff
[D][spi_nand] is_bad, block=528, page=33792,indicator = ffff
[D][spi_nand] is_bad, block=529, page=33856,indicator = ffff
[D][spi_nand] is_bad, block=530, page=33920,indicator = ffff
[D][spi_nand] is_bad, block=531, page=33984,indicator = ffff
[D][spi_nand] is_bad, block=532, page=34048,indicator = ffff
[D][spi_nand] is_bad, block=533, page=34112,indicator = ffff
[D][spi_nand] is_bad, block=534, page=34176,indicator = ffff
Last checkpoint block at 526
Finding last group in block 526 with 4 groups
log2_ppc=4, log2_ppb=6
[D][spi_nand] is free, page=33680, used_marker=ffff,
[D][spi_nand] is free, page=33681, used_marker=ffff,
[D][spi_nand] is free, page=33682, used_marker=ffff,
[D][spi_nand] is free, page=33683, used_marker=ffff,
[D][spi_nand] is free, page=33684, used_marker=ffff,
[D][spi_nand] is free, page=33685, used_marker=ffff,
[D][spi_nand] is free, page=33686, used_marker=ffff,
[D][spi_nand] is free, page=33687, used_marker=ffff,
[D][spi_nand] is free, page=33688, used_marker=ffff,
[D][spi_nand] is free, page=33689, used_marker=ffff,
[D][spi_nand] is free, page=33690, used_marker=ffff,
[D][spi_nand] is free, page=33691, used_marker=ffff,
[D][spi_nand] is free, page=33692, used_marker=ffff,
[D][spi_nand] is free, page=33693, used_marker=ffff,
[D][spi_nand] is free, page=33694, used_marker=ffff,
[D][spi_nand] is free, page=33695, used_marker=ffff,
[D][spi_nand] is free, page=33664, used_marker=ffff,
[D][spi_nand] is free, page=33665, used_marker=ffff,
[D][spi_nand] is free, page=33666, used_marker=ffff,
[D][spi_nand] is free, page=33667, used_marker=ffff,
[D][spi_nand] is free, page=33668, used_marker=ffff,
[D][spi_nand] is free, page=33669, used_marker=ffff,
[D][spi_nand] is free, page=33670, used_marker=ffff,
[D][spi_nand] is free, page=33671, used_marker=ffff,
[D][spi_nand] is free, page=33672, used_marker=ffff,
[D][spi_nand] is free, page=33673, used_marker=ffff,
[D][spi_nand] is free, page=33674, used_marker=ffff,
[D][spi_nand] is free, page=33675, used_marker=ffff,
[D][spi_nand] is free, page=33676, used_marker=ffff,
[D][spi_nand] is free, page=33677, used_marker=ffff,
[D][spi_nand] is free, page=33678, used_marker=ffff,
[D][spi_nand] is free, page=33679, used_marker=ffff,
Last checkpoint group page 33664
Journal root page 33678
Restored tail=19916, bb_current=0, bb_last=16
[D][spi_nand] is free, page=33665, used_marker=ffff,
[D][spi_nand] is free, page=33666, used_marker=ffff,
[D][spi_nand] is free, page=33667, used_marker=ffff,
[D][spi_nand] is free, page=33668, used_marker=ffff,
[D][spi_nand] is free, page=33669, used_marker=ffff,
[D][spi_nand] is free, page=33670, used_marker=ffff,
[D][spi_nand] is free, page=33671, used_marker=ffff,
[D][spi_nand] is free, page=33672, used_marker=ffff,
[D][spi_nand] is free, page=33673, used_marker=ffff,
[D][spi_nand] is free, page=33674, used_marker=ffff,
[D][spi_nand] is free, page=33675, used_marker=ffff,
[D][spi_nand] is free, page=33676, used_marker=ffff,
[D][spi_nand] is free, page=33677, used_marker=ffff,
[D][spi_nand] is free, page=33678, used_marker=ffff,
[D][spi_nand] is free, page=33679, used_marker=ffff,
[D][spi_nand] is free, page=33680, used_marker=ffff,
Journal head page 33665
Error code from dhara_map_resume: 0, 0
spi_nand_flash_init_device returned 0
Error code: 13
First checkpoint block at 0
Last checkpoint block at 526
Finding last group in block 526 with 4 groups
log2_ppc=4, log2_ppb=6
[D][spi_nand] is free, page=33680, used_marker=ffff,
[D][spi_nand] is free, page=33681, used_marker=ffff,
[D][spi_nand] is free, page=33682, used_marker=ffff,
[D][spi_nand] is free, page=33683, used_marker=ffff,
[D][spi_nand] is free, page=33684, used_marker=ffff,
[D][spi_nand] is free, page=33685, used_marker=ffff,
[D][spi_nand] is free, page=33686, used_marker=ffff,
[D][spi_nand] is free, page=33687, used_marker=ffff,
[D][spi_nand] is free, page=33688, used_marker=ffff,
[D][spi_nand] is free, page=33689, used_marker=ffff,
[D][spi_nand] is free, page=33690, used_marker=ffff,
...
[D][spi_nand] is free, page=33664, used_marker=ffff,
[D][spi_nand] is free, page=33665, used_marker=ffff,
[D][spi_nand] is free, page=33666, used_marker=ffff,
[D][spi_nand] is free, page=33667, used_marker=ffff,
[D][spi_nand] is free, page=33668, used_marker=ffff,
[D][spi_nand] is free, page=33669, used_marker=ffff,
...
Last checkpoint group page 33664
Journal root page 33678
Restored tail=19916, bb_current=0, bb_last=16
[D][spi_nand] is free, page=33665, used_marker=ffff,
[D][spi_nand] is free, page=33666, used_marker=ffff,
[D][spi_nand] is free, page=33667, used_marker=ffff,
...
[D][spi_nand] is free, page=33676, used_marker=ffff,
[D][spi_nand] is free, page=33677, used_marker=ffff,
[D][spi_nand] is free, page=33678, used_marker=ffff,
[D][spi_nand] is free, page=33679, used_marker=ffff,
[D][spi_nand] is free, page=33680, used_marker=ffff,
Journal head page 33665
The new driver seems to be a lot more sequential in scanning the pages. I note it does not scan 33696 at all.
int spi_nand_page_is_free(row_address_t row, bool* is_free) {
// page read will validate block & page address
size_t page_and_oob_len = SPI_NAND_PAGE_SIZE + SPI_NAND_OOB_SIZE();
int ret = spi_nand_page_read(row, 0, page_main_and_largest_oob_buffer, page_and_oob_len);
if (SPI_NAND_RET_OK != ret) {
return ret;
}
*is_free = true; // innocent until proven guilty
// iterate through page & oob to make sure its 0xff's all the way down
// TODO: static_assert( sizeof(page_main_and_oob_buffer) % sizeof(uint32_t) == 0, "page_main_and_oob_buffer size
// must be a multiple of 4" );
uint32_t comp_word = 0xffffffff;
for (size_t i = 0; i < page_and_oob_len; i += sizeof(comp_word)) {
if (0 != memcmp(&comp_word, &page_main_and_largest_oob_buffer[i], sizeof(comp_word))) {
*is_free = false;
break;
}
}
printf("is free, page=%d, used_marker=%04x,\r\n", row, comp_word);
return SPI_NAND_RET_OK;
}
So where is the is_free scan happening. Here’s the old driver. It is in a function provided by the NAND layer, not dhara. From what I can tell, it is loading the full page + ECC, then scanning the whole thing in 4 byte increments to make sure it’s blank?
esp_err_t nand_is_free(spi_nand_flash_device_t *handle, uint32_t page, bool *is_free_status)
{
esp_err_t ret = ESP_OK;
uint16_t used_marker;
GOTO_ON_ERROR(read_page_and_wait(handle, page, NULL), fail);
uint32_t block = page >> handle->chip.log2_ppb;
uint16_t column_addr = get_column_address(handle, block, handle->chip.page_size + 2);
GOTO_ON_ERROR(spi_nand_read(handle, (uint8_t *)handle->read_buffer, column_addr, 2), fail);
memcpy(&used_marker, handle->read_buffer, sizeof(used_marker));
NAND_LOGD(TAG, "is free, page=%"PRIu32", used_marker=%04x,", page, used_marker);
*is_free_status = (used_marker == 0xFFFF);
return ret;
fail:
NAND_LOGE(TAG, "Error in nand_is_free %d", ret);
return ret;
}
The new driver uses a drastically different is_free search (I think?). It grabs the first 2 bytes from a page and then checks if it is 0xffff.
I guess the question now is who is right? Will need to read how dhara journal works.
Seems the new driver has several problems, the first two to address:
- Non-standard bad block marking/checking
- Incorrect determination of blank pages
First checkpoint block at 0
Last checkpoint block at 526
Last checkpoint group page 33696
Journal root page 33710
Restored tail=19946, bb_current=0, bb_last=16
Journal head page 33712
FatFS Error code: 3
Yeah! now we find the same locations as the old driver. Before we got fatfs error 13 (no file system), now we get 3 (not ready).
Maybe if we fix the other bugs in the new driver we can get it going.