timer not working on esp32 with zephyr

[georgedlu]

Testing zephyr using lf-cli-0.5.2-SNAPSHOT-nightly-20231201050232-Linux-x86_64.

target C {
  platform: {
    name: Zephyr,
    board: native_sim,
  },
}

main reactor {
  timer t(0, 1 sec)

  reaction(t) {=
    printf("Hello\n");
  =}
}

Builds and runs fine for native_sim:

~/lf-zephyr-workspace/apps/Timer$ west lfc src/Timer.lf --build "-p always -b native_sim"
~/lf-zephyr-workspace/apps/Timer$ ./build/zephyr/zephyr.exe 
~/lf-zephyr-workspace/apps/Timer$ ./build/zephyr/zephyr.exe 
*** Booting Zephyr OS build zephyr-v3.5.0 ***
---- Start execution at time Wed Dec 31 16:00:00 1969
---- plus 0 nanoseconds
Environment 0: ---- Intializing start tag
Environment 0: ---- Spawning 1 workers.
Hello
Hello
Hello
Hello
Hello
^C---- Terminating environment 0

Now changed to board: esp32_devkitc_wroom (actually a Adafruit HUZZAH32 - ESP32 Feather). Prior to this, I have confirmed zephyr's blinky works on it with west build -b esp32_devkitc_wroom samples/basic/blinky -p always

~/lf-zephyr-workspace/apps/Timer$ west lfc src/Timer.lf --build "-p always -b esp32_devkitc_wroom"
~/lf-zephyr-workspace/apps/Timer$ west flash
~/lf-zephyr-workspace/apps/Timer$ west espressif monitor
Serial port /dev/ttyUSB0
Connecting.....
Detecting chip type... Unsupported detection protocol, switching and trying again...
Connecting....
Detecting chip type... ESP32
--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57
rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
flash read err, 1000
ets_main.c 371 
ets Jun  8 2016 00:22:57
rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6604
ho 0 tail 12 room 4
load:0x40078000,len:15224
ho 0 tail 12 room 4
load:0x40080400,len:3992
entry 0x40080634
I (31) boot: ESP-IDF 31fc5758f 2nd stage bootloader
I (31) boot: compile time 09:12:50
I (31) boot: chip revision: 1
I (34) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (41) boot.esp32: SPI Speed      : 40MHz
I (45) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 4MB
I (55) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (64) boot: ## Label            Usage          Type ST Offset   Length
I (71) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (78) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  2 factory          factory app      00 00 00010000 00100000
I (93) boot: End of partition table
I (97) boot_comm: chip revision: 1, min. application chip revision: 0
I (105) esp_image: segment 0: paddr=00010020 vaddr=00000020 size=0001ch (    28) 
I (113) esp_image: segment 1: paddr=00010044 vaddr=3ffb0000 size=00a0ch (  2572) load
I (122) esp_image: segment 2: paddr=00010a58 vaddr=3ffb0a0c size=00180h (   384) load
I (130) esp_image: segment 3: paddr=00010be0 vaddr=40080000 size=0f458h ( 62552) load
I (164) esp_image: segment 4: paddr=00020040 vaddr=3f400040 size=03a1ch ( 14876) map
I (170) esp_image: segment 5: paddr=00023a64 vaddr=4008f458 size=00880h (  2176) load
I (171) esp_image: segment 6: paddr=000242ec vaddr=00000000 size=0bd2ch ( 48428) 
I (196) esp_image: segment 7: paddr=00030020 vaddr=400d0020 size=067dch ( 26588) map
I (213) boot: Loaded app from partition at offset 0x10000
I (214) boot: Disabling RNG early entropy source...
*** Booting Zephyr OS build zephyr-v3.5.0 ***


Backtrace:0x4000be2f:0x3ffe6410 0x40001fda:0x3ffe6430 0x40001f49:0x3ffe6450 0x40001fc5:0x3ffe6480 0x4008701a:0x3ffe64b0 0x40087000:0x3ffe6510 0x4008398b:0x3ffe6530 0x40083915:0x3ffe6560 0x40083596:0x3ffe6580 0x400d535d:0x3ffe65a0 0x400d07a5:0x3ffe65e0 0x40081517:0x3ffe6600 0x400d085b:0x3ffe6620 
0x4008701a: _tzset_unlocked_r at ??:?

0x40087000: _tzset_unlocked at ??:?

0x4008398b: localtime_r at ??:?

0x40083915: localtime at ??:?

0x40083596: ctime at ??:?

0x400d535d: lf_reactor_c_main at /home/lu/lf-zephyr-workspace/apps/Timer/src-gen/Timer/core/threaded/reactor_threaded.c:1143

0x400d07a5: main at /home/lu/lf-zephyr-workspace/apps/Timer/src-gen/Timer/Timer.c:17

0x40081517: bg_thread_main at /home/lu/lf-zephyr-workspace/deps/zephyr/kernel/init.c:376

0x400d085b: z_thread_entry at /home/lu/lf-zephyr-workspace/deps/zephyr/lib/os/thread_entry.c:48

The same test repeated on nucleo_h7a3zi_q and rpi_pico have gotten the expected "Hello" output. Am I missing something for it to work on esp32?

[lhstrh]

Thanks for the report, @georgedlu! I've tagged two people who might be able to assist with this.

[erlingrj]

Thanks for reporting this @georgedlu! I don't have this board myself so I will need some help to debug it. The program crashes when calling ctime which is part of the C standard library, that is odd. Are you able to enable debug flags, flash it and step through the code? This way you could inspect the stacktrace and exactly what is happening?

You could also try commenting out those lines in reactor_threaded.c and recompiling. You can make changes in src-gen/Timer/core/threaded/reactor_threaded.c , e.g. commenting out lines 1142-1144 (where ctime is called) and then you can build it manually with west. Do cd src-gen/timer && west build -p always.

[georgedlu]

Hi @erlingrj , thanks for your contribution on zephyr support. I don't have the JTAG interface handy. I have commented out 1142-1144:

    LF_PRINT_DEBUG("Start time: " PRINTF_TIME "ns", start_time);
    //struct timespec physical_time_timespec = {start_time / BILLION, start_time % BILLION};
    //lf_print("---- Start execution at time %s---- plus %ld nanoseconds",
        //ctime(&physical_time_timespec.tv_sec), physical_time_timespec.tv_nsec);

then "cd src-gen/timer && west build -p always":

*** Booting Zephyr OS build zephyr-v3.5.0 ***


Backtrace:0x4000be2f:0x3ffe62a0 0x40001e26:0x3ffe62c0 0x40001e3b:0x3ffe62e0 0x40087f0a:0x3ffe6300 0x4008a27d:0x3ffe64c0 0x400d5a62:0x3ffe64f0 0x400d5a97:0x3ffe6520 0x400d5ab9:0x3ffe6560 0x400d537e:0x3ffe65b0 0x400d07a1:0x3ffe65e0 0x40081407:0x3ffe6600 0x400d0857:0x3ffe6620 
0x40087f0a: _vfprintf_r at ??:?

0x4008a27d: vfprintf at ??:?

0x400d5a62: _lf_message_print at /home/lu/lf-zephyr-workspace/apps/Timer/src-gen/Timer/core/utils/util.c:123

0x400d5a97: lf_vprint at /home/lu/lf-zephyr-workspace/apps/Timer/src-gen/Timer/core/utils/util.c:151

0x400d5ab9: lf_print at /home/lu/lf-zephyr-workspace/apps/Timer/src-gen/Timer/core/utils/util.c:143

0x400d537e: lf_reactor_c_main at /home/lu/lf-zephyr-workspace/apps/Timer/src-gen/Timer/core/threaded/reactor_threaded.c:1190 (discriminator 2)

0x400d07a1: main at /home/lu/lf-zephyr-workspace/apps/Timer/src-gen/Timer/Timer.c:17

0x40081407: bg_thread_main at /home/lu/lf-zephyr-workspace/deps/zephyr/kernel/init.c:376

0x400d0857: z_thread_entry at /home/lu/lf-zephyr-workspace/deps/zephyr/lib/os/thread_entry.c:48

Here are the relevant lines from Timer/src-gen/Timer/core/threaded/reactor_threaded.c

1189        // Initialize start tag
1190        lf_print("Environment %u: ---- Intializing start tag", env->id);
1191        _lf_initialize_start_tag(env);

[erlingrj]

Thanks George. It makes sense that it wasn't the ctime call that was at fault, rather there is some other underlying issue. This is going to be challenging without a debugger. You could look at the memory map to see where the different memory is linked. Could this be a stack overflow or a out-of-memory error? Not sure. Would it be possible for you to obtain a debugger? If you are doing a project with this dev-kit I strongly recommend to have one. There are always some issues.

[lhstrh]

@georgedlu, were you able to able to pinpoint the issue using a debugger?

[erlingrj]

@georgedlu I spoke with another person that had issues with the ESP32 which were resolved by replacing calls to malloc with k_malloc and calloc with k_calloc. You could try this? I have defined a default prj.conf which is called prj_lf.conf which is code-generated into src-gen. There i select newlib as the C library. CONFIG_NEWLIB_LIBC=y, could it be that you are overriding this value with something else? Or maybe that we are looking at an out-of-memory error? Do you know how much heap that is allocated?

[erlingrj]

The other user reports that the issue is related to our use of newlib. Unfortunately, newlib was the only C library that I fully got to work with the LF runtime. The other user reports that simple Timer programs work with picolib, but the WIFI examples crash with exception.

I am afraid that we for now must conclude that we don't support ESP32 with our Zephyr port. It would be a nice challenge for anyone interested to get it to work, but I highly recommend doing this with a debugger so you can understand better the nature of the exceptions etc.

[erlingrj]

Yet another update here is that we have gotten picolibc to work with ESP32. There was an issue in what malloc and calloc returned if asked to allocate something of zero size. In picolib it returned NULL which was interpreted as an out-of-memory exception. I have fixed it in this PR: #2167

I should also add docs about ESP32 specifically since there is an issue with newlib and ESP32, but it works now if you use picolibc instead. It would be great to understand why there is an issue with newlib, but I do not have an ESP32 to test with