tinyusb
tinyusb copied to clipboard
hathach
Missing iso packets in audio_test
Operating System
Linux
Board
esp32s3
Firmware
https://github.com/kaspernyhus/tinyusb/tree/audio_test_freertos/examples/device/audio_test_freertos
What happened ?
I made a freertos version of the audio_test example. Audio samples are coming through, but every other usb packet is missing data (see wireshark screenshots) 48kHz/16bit, 1 channel.
How to reproduce ?
clone my fork go to tinyusb/examples/device/audio_test_freertos make BOARD=espressif_s3_devkitc all flash
Debug Log
I (24) boot: ESP-IDF v5.0-dev-1867-g5faf116d26-dirty 2nd stage bootloader I (25) boot: compile time 21:20:35 I (25) boot: chip revision: 0 I (28) boot.esp32s3: Boot SPI Speed : 80MHz I (33) boot.esp32s3: SPI Mode : DIO I (38) boot.esp32s3: SPI Flash Size : 2MB I (43) boot: Enabling RNG early entropy source... I (48) boot: Partition Table: I (52) boot: ## Label Usage Type ST Offset Length I (59) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (66) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (74) boot: 2 factory factory app 00 00 00010000 00100000 I (81) boot: End of partition table I (86) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=08d28h ( 36136) map I (100) esp_image: segment 1: paddr=00018d50 vaddr=3fc922d0 size=02814h ( 10260) load I (105) esp_image: segment 2: paddr=0001b56c vaddr=40374000 size=04aach ( 19116) load I (115) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1ed68h (126312) map I (142) esp_image: segment 4: paddr=0003ed90 vaddr=40378aac size=09818h ( 38936) load I (151) esp_image: segment 5: paddr=000485b0 vaddr=50000000 size=00010h ( 16) load I (157) boot: Loaded app from partition at offset 0x10000 I (157) boot: Disabling RNG early entropy source... I (171) cpu_start: Pro cpu up. I (171) cpu_start: Starting app cpu, entry point is 0x40375254 I (0) cpu_start: App cpu up. I (185) cpu_start: Pro cpu start user code I (185) cpu_start: cpu freq: 160000000 Hz I (185) cpu_start: Application information: I (188) cpu_start: Project name: audio_test_freertos I (194) cpu_start: App version: 0.13.0-66-g6248f648 I (200) cpu_start: Compile time: Mar 7 2022 21:34:57 I (206) cpu_start: ELF file SHA256: ca7e3fa86253da6a... ELF file not found. You need to build & flash the project before running 'monitor', and the binary on the device must match the one in the build directory exactly. I (212) cpu_start: ESP-IDF: v5.0-dev-1867-g5faf116d26-dirty I (219) heap_init: Initializing. RAM available for dynamic allocation: I (227) heap_init: At 3FC96C88 len 00049378 (292 KiB): D/IRAM I (233) heap_init: At 3FCE0000 len 0000EE34 (59 KiB): STACK/DRAM I (240) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM I (246) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM I (253) spi_flash: detected chip: gd I (256) spi_flash: flash io: dio W (260) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (274) sleep: Configure to isolate all GPIO pins in sleep state I (280) sleep: Enable automatic switching of GPIO sleep configuration I (288) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU.
Screenshots
Hello, sorry for the possibly stupid question but is there any error in the functionality of this example? Anyway, for starting, stopping, etc. a few command messages from EP0 have to be transmitted. Have you found those in your wireshark? I saw only EP 0x81 (which is supposed to be so for data) in your pictures. Right now, i can not see any error!
Hello, No such thing as stupid questions here! I have filtered for EP1 messages 3.65.1 (bus 3, device 65, EP1). I believe EP 0x81 means an IN endpoint at EP1 for data, yes. What the pictures show is that for every second packet there is no data payload, only header bytes (176 bytes when full / 80 bytes with no data). There should be 96 bytes in the payload every 1ms, I believe. I cross checked with the same example on the pi pico, and there was indeed data in every packet. Does that make sense? Sorry for not being clear. Thanks
Ah now i am on track, thanks for the clarification. Indeed that seems weired, there should be a packet scheduled every ms. What puzzels me right now is that the saw-tooth-test signal looks without gaps. The audio_test example sends increasing values from 0 - 2^16-1. So in the first packet, there sould be numbers ranging from 0 - 47, in the second from 48 - 95, etc. If every second packet is missing, there sould be jumps of 48 in that signal. There "might" be jumps in your plot but i am not sure. Could you verify that? You may use the python scipts as well.
A second possibility is, that the saw-tooth signal needs double the time to reach the maximum of 2^16-1. If everything is ok, the saw-tooth should have a length of (2^16 / 48) / 1000 ~= 1.37 seconds. In your plot, that seems to be the case (2.7 + 1.37 = 4.07). Hence either there are jumps or wireshark is weired. ;) Let me know what you find!
Here I have decoded three concecutive packets containing data 2ms appart:
raw data packet 1 [f0fff1fff2fff3fff4fff5fff6fff7fff8fff9fffafffbfffcfffdfffeffffff00000100020003000400050006000700080009000a000b000c000d000e000f0010001100120013001400150016001700180019001a001b001c001d001e001f00]
raw data packet 2 [20002100220023002400250026002700280029002a002b002c002d002e002f0030003100320033003400350036003700380039003a003b003c003d003e003f0040004100420043004400450046004700480049004a004b004c004d004e004f00]
raw data packet 3 [50005100520053005400550056005700580059005a005b005c005d005e005f0060006100620063006400650066006700680069006a006b006c006d006e006f0070007100720073007400750076007700780079007a007b007c007d007e007f00]
timestamp: 15.361629, [65520, 65521, 65522, 65523, 65524, 65525, 65526, 65527, 65528, 65529, 65530, 65531, 65532, 65533, 65534, 65535, 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31]
timestamp: 15.363626, [32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79]
timestamp: 15.365626, [80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 122, 123, 124, 125, 126, 127]
so there are no gaps!
And the timing also seems correct: 1.365 seconds for one period
So the host somehow accepts a this halving of the bandwidth?
MicNode
Manufacturer: PaniRCorp
Serial Number: 123456
Speed: 12Mb/s (full)
Bus: 3
Address: 6
USB Version: 2.00
Device Class: ef(misc )
Device Subclass: 02
Device Protocol: 01
Maximum Default Endpoint Size: 64
Number of Configurations: 1
Vendor Id: cafe
Product Id: 4010
Revision Number: 1.00
Config Number: 1
Number of Interfaces: 2
Attributes: 80
MaxPower Needed: 100mA
Interface Number: 0
Name: snd-usb-audio
Alternate Number: 0
Class: 01(audio)
Sub Class: 01
Protocol: 20
Number of Endpoints: 0
Interface Number: 1
Name: snd-usb-audio
Alternate Number: 0
Class: 01(audio)
Sub Class: 02
Protocol: 20
Number of Endpoints: 0
Interface Number: 1
Name: snd-usb-audio
Alternate Number: 1
Class: 01(audio)
Sub Class: 02
Protocol: 20
Number of Endpoints: 1
Endpoint Address: 81
Direction: in
Attribute: 5
Type: Isoc
Max Packet Size: 96
Interval: 1ms
btw I also sniffed the usb traffic using an ellisys USB Explorer with same results as in wireshark :)
Interesting. However, we may not trust the time scale of audicity (maybe, i don't know audicity this well). It could be, that audicity just uses the information, that 48 kHz is the sample frequency. Can you test this another way? Can you schedule a recording lasting exactly 2 * 1.365 seconds? Not the corresponding amount of bytes but really in time. If the received signal has two saw-tooths also the timing is ok. If the bandwidth was halfed, only one saw-tooth should be received (half the bytes).
You may also measure the time it takes to acquire 2 * 2^16 samples, that should last 2 * 1.365 seconds.
Your decoded packets are 48 values each... every 2ms suggests the halfing of the bandwidth. I guess you will see only one saw-tooth. If you can confirm this, then we have an issue on the MCU (might be too slow in loading in data).
I'm not sure how I would do that. However I think you are correct in not trusting audacity! I tried to do a recording on my macbook using reaper and the results are very different indeed! Are we seeing the consequences of the missing packets here maybe?
To have a reference I made a recording of the original audio_test example on an rp2040.
Also I noticed audacity running more "smoothly" with the rp2040 plugged in, although there the waveforms look identical - 1.365 seconds
I had to reread your post earlier. I can confirm that the actual recording time is affected! I tried to time what should be 4 * saw-tooth ≈ 5.5seconds: the esp32s3 has 2 the pico has 4 !!
You may conduct this test by use of the python script in the audio test example. Set the duration to roughly 2.7 seconds.
Ok, then the MCU is too slow in loading the 48 samples or 96 bytes into the fifo and from the fifo into the usb buffer. Can you increase the clock frequency to speed the MCU up? Another possibility would be to reduce the workload in the example... but this would be a bit of work. One idea would be to trick the fifo into thinking something is contained in the fifo (by use of tu_fifo_advance_read_pointer()). Another one would be, to use a DMA to load data into the fifo.
recording time ≈5.5 in both cases, the left being esp32s3 and the right rp2040, both running versions of audio_test
Or the rtos intervenes somehow and keeps the MCU too busy.
I have been trying to look into this by using the trace option in the esp-idf and visualize using SEGGER SystemView. Looks like the interrupt handler _dcd_int_handler is only getting called every 2ms
Not sure this is of much value, but it shows the tud_task (second from the bottom) is scheduled to run with 2ms interval triggered by an interrupt (labeled "ETH_MAC" here for some reason)
I also notice the tud_task being interrupted by the same interrupt before finishing.
Ok that seems to be some configuration error regarding rtos. Performance is more than enough available ^^ and the USB protocol polls every ms but only every second triggers an interrupt. Unfortunately, i am not that experienced with freeRTOS. @hathach do you have an idea on this?
for the record I'm finding the same exact issues on the esp32s2 as the esp32s3
sorry guys, I am currently busy with other works and couldn't conduct any test and/or look into this. Though keep posting what you find, I will join in if I could spot anything suspicious
If it is indeed an rtos error, I'm not sure where to start looking. If we don't get the interrupt because the system is blocking, how can we test for that? Any ideas?
Die you try the example without rtos?On 3/14/22, 21:32 kaspernyhus @.***> wrote:
If it is indeed an rtos error, I'm not sure where to start looking. If we don't get the interrupt because the system is blocking, how can we test for that? Any ideas? —Reply to this email directly, view it on GitHub, or unsubscribe.Triage notifications on the go with GitHub Mobile for iOS or Android. You are receiving this because you commented.Message ID: @.***>
I'm not sure that I can use the esp32 without freertos? I think the second cpu can be configured to run without freertos, but I wouldn't know how to configure that using the tinyusb examples..
I have been digging around in the dcd_esp32sx.c file trying to identify possible bottlenecks.
In the interrupt handler _dcd_int_handler I have taken some timestamps to see if we got stuck somewhere - one at the top and one at the end:
__________________ name ______timestamp (us) ___ deltaT
I (8154) : 706: _dcd top 935207 1
I (8164) : 707: _dcd end 935213 6
I (8174) : 708: _dcd top 935222 9
I (8184) : 709: _dcd end 935226 4
I (8194) : 710: _dcd top 935237 11
I (8204) : 711: _dcd end 935244 7
I (8214) : 712: _dcd top 935272 28
I (8224) : 713: _dcd end 935274 2
I (8234) : 714: _dcd top 935276 2
I (8244) : 715: _dcd end 935278 2
I (8254) : 716: _dcd top 935279 1
I (8264) : 717: _dcd end 935285 6
I (8274) : 718: _dcd top 935621 336
I (8284) : 719: _dcd end 935623 2
I (8294) : 720: _dcd top 935627 4
I (8304) : 721: _dcd end 935629 2
I (8314) : 722: _dcd top 935631 2
I (8324) : 723: _dcd end 935637 6
I (8334) : 724: _dcd top 935682 45
I (8344) : 725: _dcd end 935689 7
I (8354) : 726: _dcd top 939841 4152
I (8364) : 727: _dcd end 939847 6
I (8374) : 728: _dcd top 939872 25
I (8384) : 729: _dcd end 939880 8
I (8394) : 730: _dcd top 941969 2089
I (8404) : 731: _dcd end 941975 6
I (8414) : 732: _dcd top 941992 17
I (8424) : 733: _dcd end 942000 8
I (8434) : 734: _dcd top 943969 1969
I (8444) : 735: _dcd end 943975 6
I (8454) : 736: _dcd top 943992 17
I (8464) : 737: _dcd end 944000 8
I (8474) : 738: _dcd top 945969 1969
I (8484) : 739: _dcd end 945975 6
I (8494) : 740: _dcd top 945992 17
I (8504) : 741: _dcd end 946000 8
I (8514) : 742: _dcd top 947969 1969
I (8524) : 743: _dcd end 947975 6
I (8534) : 744: _dcd top 947992 17
I (8544) : 745: _dcd end 948000 8
I (8554) : 746: _dcd top 949969 1969
I (8564) : 747: _dcd end 949975 6
I (8574) : 748: _dcd top 949992 17
I (8584) : 749: _dcd end 950000 8
I (8594) : 750: _dcd top 951969 1969
I (8604) : 751: _dcd end 951975 6
I (8614) : 752: _dcd top 951992 17
I (8624) : 753: _dcd end 952000 8
I (8634) : 754: _dcd top 953968 1968
I (8644) : 755: _dcd end 953975 7
I (8654) : 756: _dcd top 953992 17
I (8664) : 757: _dcd end 954000 8
I (8674) : 758: _dcd top 955968 1968
I (8684) : 759: _dcd end 955975 7
I (8694) : 760: _dcd top 955992 17
I (8704) : 761: _dcd end 956000 8
I (8714) : 762: _dcd top 957968 1968
I (8724) : 763: _dcd end 957975 7
I (8734) : 764: _dcd top 957991 16
I (8744) : 765: _dcd end 958000 9
I (8754) : 766: _dcd top 959968 1968
I (8764) : 767: _dcd end 959975 7
I (8774) : 768: _dcd top 959992 17
I (8784) : 769: _dcd end 960000 8
I (8794) : 770: _dcd top 961968 1968
I (8804) : 771: _dcd end 961975 7
I (8814) : 772: _dcd top 961991 16
I (8824) : 773: _dcd end 962000 9
I (8834) : 774: _dcd top 963968 1968
I (8844) : 775: _dcd end 963975 7
I (8854) : 776: _dcd top 963991 16
I (8864) : 777: _dcd end 964000 9
This is started right before the enumeration process ends and as soon as the iso IN data transfers start, we see the pattern with a ~2ms delay for every two calls. The delay must be happening outside of the _dcd_int_handler !
This might be showing that we lose an interrupt? And might suggest that it is not an rtos problem?
Could it be a missed clearing of an interrupt flag or something like that? In handle_epin_ints ?
/K
Can you somehow measure the CPU load? If it is very high the mcu might Hang in some buggy loop, if the load is low there might be a missing interrupt flag... The error might be in the dcd ISO related transfer functions...On 3/15/22, 21:41 kaspernyhus @.***> wrote:
I have been digging around in the dcd_esp32sx.c file trying to identify possible bottlenecks. In the interrupt handler _dcd_int_handler I taken some timestamps to see if we got stuck somewhere - one at the top and one at the end: __________________ name ______timestamp (us) ___ deltaT I (8154) : 706: _dcd top 935207 1 I (8164) : 707: _dcd end 935213 6 I (8174) : 708: _dcd top 935222 9 I (8184) : 709: _dcd end 935226 4 I (8194) : 710: _dcd top 935237 11 I (8204) : 711: _dcd end 935244 7 I (8214) : 712: _dcd top 935272 28 I (8224) : 713: _dcd end 935274 2 I (8234) : 714: _dcd top 935276 2 I (8244) : 715: _dcd end 935278 2 I (8254) : 716: _dcd top 935279 1 I (8264) : 717: _dcd end 935285 6 I (8274) : 718: _dcd top 935621 336 I (8284) : 719: _dcd end 935623 2 I (8294) : 720: _dcd top 935627 4 I (8304) : 721: _dcd end 935629 2 I (8314) : 722: _dcd top 935631 2 I (8324) : 723: _dcd end 935637 6 I (8334) : 724: _dcd top 935682 45 I (8344) : 725: _dcd end 935689 7 I (8354) : 726: _dcd top 939841 4152 I (8364) : 727: _dcd end 939847 6 I (8374) : 728: _dcd top 939872 25 I (8384) : 729: _dcd end 939880 8 I (8394) : 730: _dcd top 941969 2089 I (8404) : 731: _dcd end 941975 6 I (8414) : 732: _dcd top 941992 17 I (8424) : 733: _dcd end 942000 8 I (8434) : 734: _dcd top 943969 1969 I (8444) : 735: _dcd end 943975 6 I (8454) : 736: _dcd top 943992 17 I (8464) : 737: _dcd end 944000 8 I (8474) : 738: _dcd top 945969 1969 I (8484) : 739: _dcd end 945975 6 I (8494) : 740: _dcd top 945992 17 I (8504) : 741: _dcd end 946000 8 I (8514) : 742: _dcd top 947969 1969 I (8524) : 743: _dcd end 947975 6 I (8534) : 744: _dcd top 947992 17 I (8544) : 745: _dcd end 948000 8 I (8554) : 746: _dcd top 949969 1969 I (8564) : 747: _dcd end 949975 6 I (8574) : 748: _dcd top 949992 17 I (8584) : 749: _dcd end 950000 8 I (8594) : 750: _dcd top 951969 1969 I (8604) : 751: _dcd end 951975 6 I (8614) : 752: _dcd top 951992 17 I (8624) : 753: _dcd end 952000 8 I (8634) : 754: _dcd top 953968 1968 I (8644) : 755: _dcd end 953975 7 I (8654) : 756: _dcd top 953992 17 I (8664) : 757: _dcd end 954000 8 I (8674) : 758: _dcd top 955968 1968 I (8684) : 759: _dcd end 955975 7 I (8694) : 760: _dcd top 955992 17 I (8704) : 761: _dcd end 956000 8 I (8714) : 762: _dcd top 957968 1968 I (8724) : 763: _dcd end 957975 7 I (8734) : 764: _dcd top 957991 16 I (8744) : 765: _dcd end 958000 9 I (8754) : 766: _dcd top 959968 1968 I (8764) : 767: _dcd end 959975 7 I (8774) : 768: _dcd top 959992 17 I (8784) : 769: _dcd end 960000 8 I (8794) : 770: _dcd top 961968 1968 I (8804) : 771: _dcd end 961975 7 I (8814) : 772: _dcd top 961991 16 I (8824) : 773: _dcd end 962000 9 I (8834) : 774: _dcd top 963968 1968 I (8844) : 775: _dcd end 963975 7 I (8854) : 776: _dcd top 963991 16 I (8864) : 777: _dcd end 964000 9
This is started right before the enumeration process ends and as soon as the iso IN data transfers start, we see the pattern with a ~2ms delay. The delay is happening outside of the _dcd_int_hnadler ! This might be showing that we lose an interrupt? And might suggest that it is not an rtos problem? Could it be a missed clearing of an interrupt flag or something like that? In handle_epin_ints ? /K —Reply to this email directly, view it on GitHub, or unsubscribe.Triage notifications on the go with GitHub Mobile for iOS or Android. You are receiving this because you commented.Message ID: @.***>
Can you profile how long the write functions for loading the data into the buffers last?On 3/15/22, 21:41 kaspernyhus @.***> wrote:
I have been digging around in the dcd_esp32sx.c file trying to identify possible bottlenecks. In the interrupt handler _dcd_int_handler I taken some timestamps to see if we got stuck somewhere - one at the top and one at the end: __________________ name ______timestamp (us) ___ deltaT I (8154) : 706: _dcd top 935207 1 I (8164) : 707: _dcd end 935213 6 I (8174) : 708: _dcd top 935222 9 I (8184) : 709: _dcd end 935226 4 I (8194) : 710: _dcd top 935237 11 I (8204) : 711: _dcd end 935244 7 I (8214) : 712: _dcd top 935272 28 I (8224) : 713: _dcd end 935274 2 I (8234) : 714: _dcd top 935276 2 I (8244) : 715: _dcd end 935278 2 I (8254) : 716: _dcd top 935279 1 I (8264) : 717: _dcd end 935285 6 I (8274) : 718: _dcd top 935621 336 I (8284) : 719: _dcd end 935623 2 I (8294) : 720: _dcd top 935627 4 I (8304) : 721: _dcd end 935629 2 I (8314) : 722: _dcd top 935631 2 I (8324) : 723: _dcd end 935637 6 I (8334) : 724: _dcd top 935682 45 I (8344) : 725: _dcd end 935689 7 I (8354) : 726: _dcd top 939841 4152 I (8364) : 727: _dcd end 939847 6 I (8374) : 728: _dcd top 939872 25 I (8384) : 729: _dcd end 939880 8 I (8394) : 730: _dcd top 941969 2089 I (8404) : 731: _dcd end 941975 6 I (8414) : 732: _dcd top 941992 17 I (8424) : 733: _dcd end 942000 8 I (8434) : 734: _dcd top 943969 1969 I (8444) : 735: _dcd end 943975 6 I (8454) : 736: _dcd top 943992 17 I (8464) : 737: _dcd end 944000 8 I (8474) : 738: _dcd top 945969 1969 I (8484) : 739: _dcd end 945975 6 I (8494) : 740: _dcd top 945992 17 I (8504) : 741: _dcd end 946000 8 I (8514) : 742: _dcd top 947969 1969 I (8524) : 743: _dcd end 947975 6 I (8534) : 744: _dcd top 947992 17 I (8544) : 745: _dcd end 948000 8 I (8554) : 746: _dcd top 949969 1969 I (8564) : 747: _dcd end 949975 6 I (8574) : 748: _dcd top 949992 17 I (8584) : 749: _dcd end 950000 8 I (8594) : 750: _dcd top 951969 1969 I (8604) : 751: _dcd end 951975 6 I (8614) : 752: _dcd top 951992 17 I (8624) : 753: _dcd end 952000 8 I (8634) : 754: _dcd top 953968 1968 I (8644) : 755: _dcd end 953975 7 I (8654) : 756: _dcd top 953992 17 I (8664) : 757: _dcd end 954000 8 I (8674) : 758: _dcd top 955968 1968 I (8684) : 759: _dcd end 955975 7 I (8694) : 760: _dcd top 955992 17 I (8704) : 761: _dcd end 956000 8 I (8714) : 762: _dcd top 957968 1968 I (8724) : 763: _dcd end 957975 7 I (8734) : 764: _dcd top 957991 16 I (8744) : 765: _dcd end 958000 9 I (8754) : 766: _dcd top 959968 1968 I (8764) : 767: _dcd end 959975 7 I (8774) : 768: _dcd top 959992 17 I (8784) : 769: _dcd end 960000 8 I (8794) : 770: _dcd top 961968 1968 I (8804) : 771: _dcd end 961975 7 I (8814) : 772: _dcd top 961991 16 I (8824) : 773: _dcd end 962000 9 I (8834) : 774: _dcd top 963968 1968 I (8844) : 775: _dcd end 963975 7 I (8854) : 776: _dcd top 963991 16 I (8864) : 777: _dcd end 964000 9
This is started right before the enumeration process ends and as soon as the iso IN data transfers start, we see the pattern with a ~2ms delay. The delay is happening outside of the _dcd_int_hnadler ! This might be showing that we lose an interrupt? And might suggest that it is not an rtos problem? Could it be a missed clearing of an interrupt flag or something like that? In handle_epin_ints ? /K —Reply to this email directly, view it on GitHub, or unsubscribe.Triage notifications on the go with GitHub Mobile for iOS or Android. You are receiving this because you commented.Message ID: @.***>
Mh i see... @HiFiPhile have you any experience with rtos and uac?
I didn't use RTOS on SAME70 & LPC4322. I doubt there is some issue in esp-idf since personally I'm not impressed by it's robustness. (5-6 issues submitted in 2 weeks and more minor glitches)
Can you somehow measure the CPU load? If it is very high the mcu might Hang in some buggy loop, if the load is low there might be a missing interrupt flag... The error might be in the dcd ISO related transfer functions...>
My tracing shows that the cpu running the tud_task is mostly idle - the other cpu has only systicks. So cpu load is assumed to be quite low, right?
Can you profile how long the write functions for loading the data into the buffers last?>
tud_audio_write ?
Can you profile how long the write functions for loading the data into the buffers last?>
tud_audio_write?
I have measured the time between handle_epin_ints() and data filling in the buffer（dcd_edpt_xfer），It's much less than 1ms
Could you monitor the corresponding interrupt enable registers sucht that you can say if it gets disabled at some point? Maybe by placing a breakpoint which hits when the register flag gets changed?
I'm sorry, I didn't find at https://www.espressif.com/sites/default/files/documentation/esp32-s3_technical_reference_manual_en.pdf relevant introduction of the usb register, but I did an experiment, in the hid device 1ms to send out a data, is can produce the corresponding interrupt signal ,I wonder if it has something to do with endpoint initialization or configuration, but I don't know how to verify this
Look info the device controler driver file tinyusb/src/portable/espressif/esp32sx/dcd_esp32sx.c. The registers are set within dcd_edpt_open().Check if the registers are correctly set for the ISO endpoint!On 3/21/22, 06:38 LiTongXue98 @.***> wrote:
I'm sorry, I didn't find at https://www.espressif.com/sites/default/files/documentation/esp32-s3_technical_reference_manual_en.pdf relevant introduction of the usb register, but I did an experiment, in the hid device 1ms to send out a data, is can produce the corresponding interrupt signal ,I wonder if it has something to do with endpoint initialization or configuration, but I don't know how to verify this —Reply to this email directly, view it on GitHub, or unsubscribe.Triage notifications on the go with GitHub Mobile for iOS or Android. You are receiving this because you commented.Message ID: @.***>
I'm very eager to help bugfix this, but I'm also not at all sure what to look for.
Here is a probing of the USB0.gintsts register when it enters the _dcd_int_handler in dcd_esp32sx.c
static void _dcd_int_handler(void* arg)
{
(void) arg;
uint8_t const rhport = 0;
const uint32_t int_msk = USB0.gintmsk;
const uint32_t int_status = USB0.gintsts & int_msk;
(...)
I (3246) : USB0.gintsts: 0x00040020 47
I (3256) : USB0.gintsts: 0x00008038 1248
I (3256) : USB0.gintsts: 0x00000030 15
I (3266) : USB0.gintsts: 0x00080020 2
I (3266) : USB0.gintsts: 0x00040020 18
I (3276) : USB0.gintsts: 0x00040020 34
I (3276) : USB0.gintsts: 0x00000030 18
I (3286) : USB0.gintsts: 0x00000030 3
I (3286) : USB0.gintsts: 0x00080020 2
I (3296) : USB0.gintsts: 0x00108030 406
I (3296) : USB0.gintsts: 0x00000030 15
I (3306) : USB0.gintsts: 0x00080020 2
I (3306) : USB0.gintsts: 0x00040028 92
I (3316) : USB0.gintsts: 0x00000030 57
I (3316) : USB0.gintsts: 0x00000030 15
I (3326) : USB0.gintsts: 0x00080020 3
I (3326) : USB0.gintsts: 0x00040020 13
I (3336) : USB0.gintsts: 0x00040020 39
I (3336) : USB0.gintsts: 0x00000030 18
I (3336) : USB0.gintsts: 0x00000030 2
I (3346) : USB0.gintsts: 0x00080020 2
I (3346) : USB0.gintsts: 0x00000030 562
I (3356) : USB0.gintsts: 0x00000030 15
I (3356) : USB0.gintsts: 0x00080020 2
I (3366) : USB0.gintsts: 0x00040020 48
I (3366) : USB0.gintsts: 0x00148028 4219
I (3376) : USB0.gintsts: 0x00040020 31
I (3376) : USB0.gintsts: 0x00148028 2097
I (3386) : USB0.gintsts: 0x00040020 20
I (3386) : USB0.gintsts: 0x00148028 1980
I (3396) : USB0.gintsts: 0x00040020 20
I (3396) : USB0.gintsts: 0x00148028 1980
I (3406) : USB0.gintsts: 0x00040020 20
I (3406) : USB0.gintsts: 0x00148028 1980
I (3416) : USB0.gintsts: 0x00040020 20
I (3416) : USB0.gintsts: 0x00148028 1980
I (3426) : USB0.gintsts: 0x00040020 20
I (3426) : USB0.gintsts: 0x00148028 1980
I (3436) : USB0.gintsts: 0x00040020 20
I (3436) : USB0.gintsts: 0x00148028 1980
the rightmost row is time passed in us since the call above.
For whatever reason different bit are indeed set in the 0x0014 Interrupt Register of the usb_dev_t USB0 struct
Well, according to the manual on page 602, the interrupt for the IN EP is always set (bit 18). Unfortunately, the manual does not tell the meaning of the other bits. Can you also check for the masking register USB_GINTSTS_REG and SB_GLBLINTRMSK. In this registers you can check if the interrupt was masked out. Furthermore, please check USB_DAINT_REG to check the number of the EP interrupt and finally the corresponding USB_DIEPINTn_REG for the interrupt source. These should indicate the endpoint 0x81 i guess.
Yes, this part of the documentation leaves a bit to be desired.
Here is another run:
I (7981) : -------------------------------------------------
I (7991) : USB0.gintsts : 0x00040020 22
I (7991) : USB0.gintmsk : 0x208C3C16 1
I (8001) : int_status : 0x00040000 2
I (8011) : daint : 0x00000001 1
I (8011) : daintmsk : 0x00010003 2
I (8021) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8021) : dsts : 0x0042C106 1
I (8031) : -------------------------------------------------
I (8041) : USB0.gintsts : 0x00040020 29
I (8041) : USB0.gintmsk : 0x208C3C16 1
I (8051) : int_status : 0x00040000 1
I (8051) : daint : 0x00000001 2
I (8061) : daintmsk : 0x00010003 1
I (8061) : USB0.in_ep_reg[1].diepint: 0x00000080 2
I (8071) : dsts : 0x0042C106 1
I (8081) : -------------------------------------------------
I (8081) : USB0.gintsts : 0x00000030 51
I (8091) : USB0.gintmsk : 0x208C3C16 2
I (8091) : int_status : 0x00000010 1
I (8101) : daint : 0x00000000 1
I (8111) : daintmsk : 0x00010003 2
I (8111) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8121) : dsts : 0x0042C106 2
I (8121) : -------------------------------------------------
I (8131) : USB0.gintsts : 0x00000030 4
I (8141) : USB0.gintmsk : 0x208C3C16 1
I (8141) : int_status : 0x00000010 2
I (8151) : daint : 0x00000000 1
I (8151) : daintmsk : 0x00010003 2
I (8161) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8161) : dsts : 0x0042C106 2
I (8171) : -------------------------------------------------
I (8181) : USB0.gintsts : 0x00080020 4
I (8181) : USB0.gintmsk : 0x208C3C16 1
I (8191) : int_status : 0x00080000 1
I (8191) : daint : 0x00010000 2
I (8201) : daintmsk : 0x00010003 1
I (8211) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8211) : dsts : 0x0042C106 2
I (8221) : -------------------------------------------------
I (8221) : USB0.gintsts : 0x00008030 400
I (8231) : USB0.gintmsk : 0x208C3C16 2
I (8241) : int_status : 0x00000010 1
I (8241) : daint : 0x00000000 1
I (8251) : daintmsk : 0x00010003 2
I (8251) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8261) : dsts : 0x0042C106 2
I (8261) : -------------------------------------------------
I (8271) : USB0.gintsts : 0x00000030 4
I (8281) : USB0.gintmsk : 0x208C3C16 1
I (8281) : int_status : 0x00000010 2
I (8291) : daint : 0x00000000 1
I (8291) : daintmsk : 0x00010003 2
I (8301) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8311) : dsts : 0x0042C106 1
I (8311) : -------------------------------------------------
I (8321) : USB0.gintsts : 0x00080020 5
I (8321) : USB0.gintmsk : 0x208C3C16 1
I (8331) : int_status : 0x00080000 1
I (8341) : daint : 0x00010000 2
I (8341) : daintmsk : 0x00010003 1
I (8351) : USB0.in_ep_reg[1].diepint: 0x00000080 2
I (8351) : dsts : 0x0042C106 1
I (8361) : -------------------------------------------------
I (8361) : USB0.gintsts : 0x00040020 55
I (8371) : USB0.gintmsk : 0x208C3C16 2
I (8381) : int_status : 0x00040000 1
I (8381) : daint : 0x00000001 2
I (8391) : daintmsk : 0x00010003 1
I (8391) : USB0.in_ep_reg[1].diepint: 0x00000080 2
I (8401) : dsts : 0x0042C106 1
I (8411) : -------------------------------------------------
I (8411) : USB0.gintsts : 0x00148028 4053
I (8421) : USB0.gintmsk : 0x208C3C16 2
I (8421) : int_status : 0x00040000 1
I (8431) : daint : 0x00000002 1
I (8441) : daintmsk : 0x00010003 2
I (8441) : USB0.in_ep_reg[1].diepint: 0x00000081 1
I (8451) : dsts : 0x0042C606 2
I (8451) : -------------------------------------------------
I (8461) : USB0.gintsts : 0x00040020 41
I (8471) : USB0.gintmsk : 0x208C3C16 1
I (8471) : int_status : 0x00040000 2
I (8481) : daint : 0x00000002 1
I (8481) : daintmsk : 0x00010003 2
I (8491) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8491) : dsts : 0x0042C606 1
I (8501) : -------------------------------------------------
I (8511) : USB0.gintsts : 0x00148028 2006
I (8511) : USB0.gintmsk : 0x208C3C16 2
I (8521) : int_status : 0x00040000 1
I (8521) : daint : 0x00000002 2
I (8531) : daintmsk : 0x00010003 1
I (8541) : USB0.in_ep_reg[1].diepint: 0x00000081 1
I (8541) : dsts : 0x0042C806 2
I (8551) : -------------------------------------------------
I (8551) : USB0.gintsts : 0x00040020 32
I (8561) : USB0.gintmsk : 0x208C3C16 2
I (8571) : int_status : 0x00040000 1
I (8571) : daint : 0x00000002 1
I (8581) : daintmsk : 0x00010003 2
I (8581) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8591) : dsts : 0x0042C806 1
I (8591) : -------------------------------------------------
I (8601) : USB0.gintsts : 0x00148028 1951
I (8611) : USB0.gintmsk : 0x208C3C16 2
I (8611) : int_status : 0x00040000 1
I (8621) : daint : 0x00000002 2
I (8621) : daintmsk : 0x00010003 1
I (8631) : USB0.in_ep_reg[1].diepint: 0x00000081 1
I (8641) : dsts : 0x0042CA06 2
I (8641) : -------------------------------------------------
I (8651) : USB0.gintsts : 0x00040020 32
I (8651) : USB0.gintmsk : 0x208C3C16 2
I (8661) : int_status : 0x00040000 1
I (8671) : daint : 0x00000002 1
I (8671) : daintmsk : 0x00010003 2
I (8681) : USB0.in_ep_reg[1].diepint: 0x00000080 1
I (8681) : dsts : 0x0042CA06 2
I (8691) : -------------------------------------------------
I (8701) : USB0.gintsts : 0x00148028 1950
I (8701) : USB0.gintmsk : 0x208C3C16 2
I (8711) : int_status : 0x00040000 1
I (8711) : daint : 0x00000002 2
I (8721) : daintmsk : 0x00010003 1
I (8721) : USB0.in_ep_reg[1].diepint: 0x00000081 1
I (8731) : dsts : 0x0042CC06 2
I (8741) : -------------------------------------------------
So,
- when the 2ms delay starts
USB0.in_ep_reg[1].diepintis oscillating between 0x80/0x81 - what does that mean?? - the masking register
gintmskdoesn't change. - the 0x0818 Device All Endpoints Interrupt Register
daintis 0x2 = EP1 - the 0x0808 Device Status Register (Read Only)
dstsis changing
I haven't been able to locate the global int mask. Here is the USB struct defined in usb_struct.h:
typedef struct usb_reg {
volatile uint32_t gotgctl; // 0x0000 OTG Control and Status Register
volatile uint32_t gotgint; // 0x0004 OTG Interrupt Register
volatile uint32_t gahbcfg; // 0x0008 AHB Configuration Register
volatile uint32_t gusbcfg; // 0x000c USB Configuration Register
volatile uint32_t grstctl; // 0x0010 Reset Register
volatile uint32_t gintsts; // 0x0014 Interrupt Register
volatile uint32_t gintmsk; // 0x0018 Interrupt Mask Register
volatile uint32_t grxstsr; // 0x001c Receive Status Debug Read Register
volatile uint32_t grxstsp; // 0x0020 Receive Status Read/Pop Register
volatile uint32_t grxfsiz; // 0x0024 Receive FIFO Size Register
volatile uint32_t gnptxfsiz; // 0x0028 Non-periodic Transmit FIFO Size Register
volatile uint32_t gnptxsts; // 0x002c Non-periodic Transmit FIFO/Queue Status Register
uint32_t reserved_0x0030_0x0040[4]; // 0x0030 to 0x0040
volatile uint32_t gsnpsid; // 0x0040 Synopsys ID Register
volatile uint32_t ghwcfg1; // 0x0044 User Hardware Configuration 1 Register
volatile uint32_t ghwcfg2; // 0x0048 User Hardware Configuration 2 Register
volatile uint32_t ghwcfg3; // 0x004c User Hardware Configuration 3 Register
volatile uint32_t ghwcfg4; // 0x0050 User Hardware Configuration 4 Register
uint32_t reserved_0x0054_0x005c[2]; // 0x0054 to 0x005c
volatile uint32_t gdfifocfg; // 0x005c Global DFIFO Configuration Register
uint32_t reserved_0x0060_0x0100[40]; // 0x0060 to 0x0100
volatile uint32_t hptxfsiz; // 0x0100 Host Periodic Transmit FIFO Size Register
volatile uint32_t dieptxf[4]; // 0x0104 to 0x0114 Device IN Endpoint Transmit FIFO Size Register i
uint32_t reserved_0x0114_0x0140[11]; // 0x0114 to 0x0140
uint32_t reserved_0x0140_0x0400[176]; // 0x0140 to 0x0400
/**
* Host mode registers offsets from 0x0400 to 0x07FF
*/
volatile uint32_t hcfg; // 0x0400 Host Configuration Register
volatile uint32_t hfir; // 0x0404 Host Frame Interval Register
volatile uint32_t hfnum; // 0x0408 Host Frame Number/Frame Remaining Register
uint32_t reserved0x40C; // 0x040c Reserved
volatile uint32_t hptxsts; // 0x0410 Host Periodic Transmit FIFO/ Queue Status Register
volatile uint32_t haint; // 0x0414 Host All Channels Interrupt Register
volatile uint32_t haintmsk; // 0x0418 Host All Channels Interrupt Mask Register
volatile uint32_t hflbaddr; // 0x041c Host Frame List Base Address Register
uint32_t reserved0x0420_0x0440[8]; // 0x0420 to 0x0440
volatile uint32_t hprt; // 0x0440 Host Port Control and Status Register
uint32_t reserved_0x0444_0x0500[47]; // 0x0444 to 0x0500
//Skip over the host channel registers
volatile uint32_t host_chan_regs[128]; // 0x0500 to 0x0700
uint32_t reserved_0x0700_0x0800[64]; // 0x0700 to 0x0800
/**
* Device mode registers offsets from
*/
volatile uint32_t dcfg; // 0x0800 Device Configuration Register
volatile uint32_t dctl; // 0x0804 Device Control Register
volatile uint32_t dsts; // 0x0808 Device Status Register (Read Only)
uint32_t reserved0x80c; // 0x080c
volatile uint32_t diepmsk; // 0x0810 Device IN Endpoint Common Interrupt Mask Register
volatile uint32_t doepmsk; // 0x0814 Device OUT Endpoint Common Interrupt Mask Register
volatile uint32_t daint; // 0x0818 Device All Endpoints Interrupt Register
volatile uint32_t daintmsk; // 0x081c Device All Endpoints Interrupt Mask Register
uint32_t reserved_0x0820_0x0828[2]; // 0x0820 to 0x0828
volatile uint32_t dvbusdis; // 0x0828 Device VBUS discharge Register
volatile uint32_t dvbuspulse; // 0x082c Device VBUS Pulse Register
volatile uint32_t dthrctl; // 0x0830 Device Thresholding control register (Read/Write)
volatile uint32_t dtknqr4_fifoemptymsk; // 0x0834 Device IN Endpoint FIFO Empty Interrupt Mask register
uint32_t reserved_0x0838_0x0900[50]; // 0x0838 to 0x0900
// Input Endpoints
usb_in_endpoint_t in_ep_reg[USB_IN_EP_NUM]; // 0x0900 to 0x09e0 IN EP registers
uint32_t reserved_0x09e0_0x0b00[72]; // 0x09e0 to 0x0b00
// Output Endpoints
usb_out_endpoint_t out_ep_reg[USB_OUT_EP_NUM]; // 0x0b00 to 0x0be0 OUT EP registers
uint32_t reserved_0x0be0_0x0d00[72]; // 0x0be0 to 0x0d00
uint32_t reserved_0x0d00_0x0e00[64]; // 0x0d00 to 0x0e00
/**
* Power Control and direct FIFO access
*/
uint32_t pcgctrl; // 0x0e00 Power and Clock Gating Control Register
uint32_t reserved_0x0e04; // 0x0e04
uint8_t reserved8[0x1000 - 0xe08]; // 0x0d00 to 0x1000
uint32_t fifo[16][0x400]; // 0x1000 to 0x2000 Device EP i/Host Channel i FIFO
uint8_t reserved0x11000[0x20000 - 0x11000];
uint32_t dbg_fifo[0x20000]; // 0x2000 to 0x22000 Direct Access to Data FIFO RAM for Debugging
} usb_dev_t;
extern usb_dev_t USB0;
Is this essentially a job for Espressif to fix, since it seems to be quite deep down in the handling of interrupts?
when the 2ms delay starts USB0.in_ep_reg[1].diepint is oscillating between 0x80/0x81 - what does that mean??
I guess the interrupt flag is not cleared. The error may be in the function handle_epin_ints() as there these flags are cleared. Or this function does not get called every second time?!
Is this essentially a job for Espressif to fix, since it seems to be quite deep down in the handling of interrupts?
I guess yes, the device controler dcd_esp32sx.c was also written by Espressif Systems.