incorrect remaining time calculation (ESF-179)

[nikitos1550]

Port

raspberry

Target chip

ESP32S3

Hardware Configuration

ESP32-S3-WROOM-1U based pcba connected via UART to custom mdm9207 (GNU/Linux OS) based pcba.

Log output

Port '/dev/ttyHSL2'
Default baudrate 115200

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 read_char: cannot read byte because of timeout
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 read_char: cannot read byte because of timeout
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 
--- WRITE ---
c0 00 14 00 00 00 00 00 00 c0 
--- READ ---
c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 read_char: cannot read byte because of timeout

--- WRITE ---
c0 00 0a 04 00 00 00 00 00 00 10 00 40 c0 
--- READ ---
00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 read_char: cannot read byte because of timeout
Cannot connect to target. Error: 2

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 14 18 00 07 07 12 20 00 00 00 00 00 00 00 00 00 00 00 0c 09 00 00 00 00 00 00 00 00 00 00 00 c0 00 00 c0 01 0a 04 00 09 00 00 00 00 00 00 00 c0 00 00 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 read_char: cannot read byte because of timeout

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 read_char: cannot read byte because of timeout

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 read_char: cannot read byte because of timeout

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 read_char: cannot read byte because of timeout

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 read_char: cannot read byte because of timeout

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 read_char: cannot read byte because of timeout

--- WRITE ---
c0 00 08 24 00 00 00 00 00 07 07 12 20 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 55 c0 
--- READ ---
08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 08 04 00 07 07 12 20 00 00 00 00 c0 c0 01 read_char: cannot read byte because of timeout

More Information

https://github.com/espressif/esp-serial-flasher/blob/f1183069e23ee89dbab9b411724e88e170dbd874/port/raspberry_port.c#L292C1-L297C1

void loader_port_start_timer(uint32_t ms)
{
    s_time_end = clock() + (ms * (CLOCKS_PER_SEC / 1000));
}

uint32_t loader_port_remaining_time(void)
{
    int64_t remaining = (s_time_end - clock()) / 1000;
    return (remaining > 0) ? (uint32_t)remaining : 0;
}

Here if (s_time_end - clock()) will be less then 1000, then we still have some time to wait, but function will return 0.

I locally patched it

void loader_port_start_timer(uint32_t ms)
{
#if SERIAL_FLASHER_DEBUG_TRACE
    printf("%s: ms = %u\n", __func__, ms);
#endif
    s_time_end = ((clock() / CLOCKS_PER_SEC) /*seconds*/ * 1000)/*ms*/ + ms;
}

uint32_t loader_port_remaining_time(void)
{
        int r;
        int64_t remaining = (s_time_end - ((clock() / CLOCKS_PER_SEC) /* seconds*/ * 1000 /* ms */) );
        r = (remaining > 0) ? (uint32_t) remaining : 0;

//#if SERIAL_FLASHER_DEBUG_TRACE
//      if (r == 0) {
//              printf("%s: r = %u\n", __func__, r);
//      }
//#endif

        return r;
}

And now I can sucessfully burn esp32s3. Seems I faced some hardware compatibility issue, because our previous ESP32-S3-WROOM-1U based pcba did not have such issue, anyway I think my point is reasonable.

[Dzarda7]

Hi @nikitos1550, thanks for noticing this. You are right, calculation is incorrect. This reminded me the already opened issue here. Your solution fixes the issue you talk about, but another problem is that clock() function measures time consumed by program, real time might be a bit different. Are you willing to open pull request with the solution or you want us to take care of it? If you are not, I will try to fix it soon, just so you know that timeout with clock() function might be a bit longer.

[nikitos1550]

Hi @nikitos1550, thanks for noticing this. You are right, calculation is incorrect. This reminded me the already opened issue here. Your solution fixes the issue you talk about, but another problem is that clock() function measures time consumed by program, real time might be a bit different. Are you willing to open pull request with the solution or you want us to take care of it? If you are not, I will try to fix it soon, just so you know that timeout with clock() function might be a bit longer.

Hi! You are right about clock(), so I reworked it following way (added https://github.com/solemnwarning/timespec to submodules )

static struct timespec s_time_end;
// ...
void loader_port_start_timer(uint32_t ms)
{
    struct timespec now, add;

    clock_gettime(CLOCK_MONOTONIC, &now);
    add = timespec_from_ms(ms);
    s_time_end = timespec_add(now, add);
}

uint32_t loader_port_remaining_time(void)
{
    struct timespec now, diff;

    clock_gettime(CLOCK_MONOTONIC, &now);

    if (timespec_ge(s_time_end, now)) {
        diff = timespec_sub(s_time_end, now);
        return timespec_to_ms(diff);
    }

    return 0;
}

If you are ok with additional submodule dep I can make PR.

[nikitos1550]

anyway here you are

[Dzarda7]

I will close the PR and implement it directly without submodule if you are OK with that. Anyway thanks for noticing.

[nikitos1550]

I will close the PR and implement it directly without submodule if you are OK with that. Anyway thanks for noticing.

I am ok, sure! I am using respberry based Linux port with custom utility, so it make no sense for me.

[nikitos1550]

I will close the PR and implement it directly without submodule if you are OK with that. Anyway thanks for noticing.

Please also pay attention to open tty dev file flags, there is NONBLOCK flag that means VMIN, VTIME options will not work.
Today I also got issue on some device samples, after more detailed debug I found that start timer, remaining timer does not cover all issues (as I thought before), It comes out that during read VTIME is setuped (each time), but as port opened NONBLOCKING, it does not work. I removed flag and it become much better. But I still expirience issue when first esp32-serial connection attempt does not work, need run it twice, something about tty port options I suppose, but I cannot figure out what exactly.

P.S. I will provide log later, maybe you can help me figure out what is going on.

[nikitos1550]

I cannot reproduce it right now :( Maybe later I will have luck.

[Dzarda7]

Thanks for letting me know. It is planned to rewrite the Raspberry pi port completely in the future. Feel free to send the log later, I can take a look.