ctag-tbd icon indicating copy to clipboard operation
ctag-tbd copied to clipboard

httpd_txrx errors, timeouts

Open hampa opened this issue 2 years ago • 8 comments

I have this issue where the web interface frequently timeouts.

I've tried to disable the Process loop of my module so it doesn't consume much CPU but the timeouts are still there.

Perhaps I'm running out of memory, I have some wavetables in const float[] arrays.

I (0) cpu_start: App cpu up. I (1015) spiram: SPI SRAM memory test OK I (1023) cpu_start: Pro cpu start user code I (1023) cpu_start: cpu freq: 240000000 I (1023) cpu_start: Application information: I (1026) cpu_start: Project name: ctag-tbd I (1031) cpu_start: App version: 0.9.21-14-g5d73a30-dirty I (1038) cpu_start: Compile time: Jun 20 2022 22:16:24 I (1044) cpu_start: ELF file SHA256: 61544a7abb127c22... I (1050) cpu_start: ESP-IDF: v4.4.1 I (1055) heap_init: Initializing. RAM available for dynamic allocation: I (1062) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (1068) heap_init: At 3FFC7940 len 000186C0 (97 KiB): DRAM I (1074) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (1081) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (1087) heap_init: At 40099C4C len 000063B4 (24 KiB): IRAM I (1094) spiram: Adding pool of 4095K of external SPI memory to heap allocator I (1102) spi_flash: detected chip: gd I (1106) spi_flash: flash io: qio I (1112) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (5116) fs: Initializing SPIFFS I (5316) fs: Partition size: total: 2884241, used: 365205 I (5316) SPModel: Trying to read config file I (5646) Control: Initializing control! I (5646) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:2 I (5646) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:2 I (5736) CAL: Check calibration request I (5736) WM8978: Init I (5736) WM8978: Soft reset successfull I (5736) WM8978: Init finished I (5736) WM8978: Initializing CODEC I2S I (5746) gpio: GPIO[0]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (5756) I2S: APLL expected frequency is 22579200 Hz, real frequency is 22579193 Hz I (5756) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=4 I (5766) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=4 I (5776) I2S: I2S0, MCLK output by GPIO0 I (5776) Network: Starting with ssid ctag-tbd, pwd , mdns ctag-tbd, ip 192.178.3.1, is ap I (5836) wifi:wifi driver task: 3ffd3a00, prio:23, stack:3584, core=0 I (5836) system_api: Base MAC address is not set I (5836) system_api: read default base MAC address from EFUSE I (5846) wifi:wifi firmware version: 63017e0 I (5846) wifi:wifi certification version: v7.0 I (5846) wifi:config NVS flash: enabled I (5856) wifi:config nano formating: disabled I (5856) wifi:Init data frame dynamic rx buffer num: 32 I (5856) wifi:Init management frame dynamic rx buffer num: 32 I (5866) wifi:Init management short buffer num: 32 I (5866) wifi:Init dynamic tx buffer num: 32 I (5876) wifi:Init tx cache buffer num: 32 I (5876) wifi:Init static rx buffer size: 1600 I (5886) wifi:Init static rx buffer num: 10 I (5886) wifi:Init dynamic rx buffer num: 32 I (5896) wifi_init: tcpip mbox: 32 I (5896) wifi_init: udp mbox: 6 I (5896) wifi_init: tcp mbox: 6 I (5906) wifi_init: tcp tx win: 5744 I (5906) wifi_init: tcp rx win: 5744 I (5916) wifi_init: tcp mss: 1440 I (5916) wifi_init: WiFi IRAM OP enabled I (5916) wifi_init: WiFi RX IRAM OP enabled I (5926) wifi:Set ps type: 0 I (5926) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 I (6016) wifi:mode : softAP (f0:08:d1:69:cd:2d) I (6016) wifi:Total power save buffer number: 16 I (6016) wifi:Init max length of beacon: 752/752 I (6026) wifi:Init max length of beacon: 752/752 I (6026) Network: Disabling wifi power save mode I (6036) wifi:Set ps type: 0 I (6036) esp-rest: Starting HTTP Server I (9496) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<255,255>, prof:1 I (9506) wifi:station: 60:03:08:92:c1:10 join, AID=1, bgn, 20 I (9506) Network: station 60:03:08:92:c1:10 join, AID=1 I (9526) esp_netif_lwip: DHCP server assigned IP to a station, IP is: 192.168.4.2 W (93276) httpd_txrx: httpd_sock_err: error in recv : 104 W (100766) httpd_txrx: httpd_sock_err: error in send : 104 W (100766) httpd_txrx: httpd_sock_err: error in recv : 104 W (135836) httpd_txrx: httpd_sock_err: error in recv : 104 W (198976) httpd_txrx: httpd_sock_err: error in send : 104

hampa avatar Jun 21 '22 02:06 hampa

Which esp idf version do you use?

ctag-fh-kiel avatar Jun 21 '22 06:06 ctag-fh-kiel

bash-3.2$ idf.py --version ESP-IDF v4.4.1

On 21 Jun 2022, at 10:51 AM, Robert Manzke @.***> wrote:

Which esp idf version do you use?

— Reply to this email directly, view it on GitHub https://github.com/ctag-fh-kiel/ctag-tbd/issues/63#issuecomment-1161333295, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAD6T4PQLGHDSUOCWU75EKTVQFQ63ANCNFSM5ZKWOR2A. You are receiving this because you authored the thread.

hampa avatar Jun 21 '22 08:06 hampa

TBD firmware is tested only with release 4.1 other idf releases can cause all kinds of issues, also potentially this one...

ctag-fh-kiel avatar Jun 21 '22 09:06 ctag-fh-kiel

Hi - if you look here, you should be able to implement a bypass solution for the "idf.py monitor" issue you had, with keeping IDF version 4.1: https://github.com/espressif/esptool/issues/540 I can't test this, because I don't have MacOS, but the point seemingly is to find a solution for the missing/wrong Port-Symbol as mentioned by the error-text as: "dlsym(RTLD_DEFAULT, kIOMasterPortDefault): symbol not found"

Visuelle-Musik avatar Jun 21 '22 10:06 Visuelle-Musik

Another bypass solution may be to use esptool instead of idf.py and combine it with a monitor-option like described here: https://github.com/espressif/esptool/issues/284 I am using esptool.py a lot and it works perfectly fine for me, but I have not tried out miniterm.py in combination yet. The miniterm-application that came with "pip install pyserial" is working like this on Windows, though:

C:\Users\Mathias>pyserial-miniterm COM3 115200 --- Miniterm on COM3 115200,8,N,1 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ␛[0;32mI (5480) fs: Initializing SPIFFS␛[0m ␛[0;32mI (5680) fs: Partition size: total: 2884241, used: 1002996␛[0m ␛[0;32mI (5680) SSD1306: OLED configured successfully␛[0m ␛[0;32mI (9750) SPModel: Trying to read config file␛[0m ␛[0;32mI (10060) Control: Initializing control!␛[0m ␛[0;32mI (10060) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:2 ␛[0m ␛[0;32mI (10060) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:2 ␛[0m ␛[0;32mI (10120) CAL: Check calibration request␛[0m ␛[0;32mI (10120) WM8974: Init␛[0m ␛[0;32mI (10220) WM8974: Init finished␛[0m ␛[0;32mI (10220) WM8974: Initializing CODEC I2S␛[0m ␛[0;32mI (10220) gpio: GPIO[0]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 ␛[0m ␛[0;32mI (10220) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=4␛[0m ␛[0;32mI (10230) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=4␛[0m ␛[0;32mI (10250) I2S: APLL: Req RATE: 44�b␂�����rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199.625000, diva: 1, divb: 0␛[0m

In other word: apart from some odd characters due to a wrong character-set in the windows-shell (I guess), it's working fine!

And most of all: there should be no problems with any IDF-version (affecting building the TBD firmware) here, because this terminal-application is independant of IDF. (Reading serial data coming in from the specified PORT).

Visuelle-Musik avatar Jun 22 '22 00:06 Visuelle-Musik

I'm potentially going to build a TBD soon :) Is ESP-IDF 4.1 really a requirement? It seems that the Gitpod dockerfile itself uses 4.4, as does the devcontainer configuration.

jypma avatar Jun 24 '22 07:06 jypma

Seems like I used too much memory in the data and BSS sections, I removed a const float[] in my class and it seems to have made it better.

4.4 seems to work fine otherwise, I haven't encountered any issues so far.

What is the best strategy for managing and keeping track of the memory? I'm using "idf.py size" to check.

Total sizes: Used static DRAM: 96572 bytes ( 84164 remain, 53.4% used) .data size: 15084 bytes .bss size: 81488 bytes Used static IRAM: 105546 bytes ( 25526 remain, 80.5% used) .text size: 104519 bytes .vectors size: 1027 bytes Used Flash size : 1186107 bytes .text : 900295 bytes .rodata : 285556 bytes Total image size: 1306737 bytes (.bin may be padded larger)

hampa avatar Jun 27 '22 05:06 hampa

Yes, the heap/static memory usage of IDF changes with every version. I found that in higher versions than 4.1, IDF uses in fact significantly more memory. This disallows some plugins in TBD to load successfully, as they are allocated dynamically. ESP32 has unfortunately a scattered memory layout (not linearly addressable large blocks) which further complicates things. I have not tried further with higher than 4.1 releases because debugging is very tedious. idf.py size is one way to check, but it shows only the static memory use. Another thing you have to do is to load all plugins and all plugin combinations (stereo and mono/mono) and see with idf.py monitor if heap allocation for that plugin (combination) was successful. Each plugin is allocated as a smart pointer (unique_ptr<ctagSoundProcessor>) from the ctagSoundProcessor factory class, i.e. using heap.

Good luck, let us know how far you get ;)

ctag-fh-kiel avatar Jun 27 '22 06:06 ctag-fh-kiel

May be fixed with 1.0.0 and move to IDF 5.1.1

ctag-fh-kiel avatar Nov 21 '23 14:11 ctag-fh-kiel