Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG]Messages that have been sent will be displayed later. #366

Open
masahirokakishita opened this issue Jul 22, 2024 · 35 comments
Open

[BUG]Messages that have been sent will be displayed later. #366

masahirokakishita opened this issue Jul 22, 2024 · 35 comments
Assignees
Labels
bug 🐞 Something isn't working

Comments

@masahirokakishita
Copy link
Collaborator

Describe the bug
ProtoZoA has an echo back program.
Messages that have been sent will be displayed later.

To Reproduce
Install the enclosed zoa_loop.uf2 on protoZoA.

zoa_loop.uf2.zip

This program echoes back the UMP messages it receives.
The zoa_loop don't store messages inside of protoZoA.

Launch one console.

midi endpoint send-message 0x40123456 0x00000000 -p 0 -c 125000 -i
You should see a message that says midi.exe sent 125,000 messages.
After that in the same console

midi endpoint monitor --verbose
Incoming messages will begin to be displayed.

Expected behavior
In this case, since the messages have already been sent and some time has passed, we assume that the messages will not be displayed.

Installer Name or Version
dev-preview-6/Windows.MIDI.Services.App.SDK.Runtime.-.Developer.Preview.6.1.0.24194.2233-arm64.exe
dev-preview-6/Windows.MIDI.Services.Console.-.Developer.Preview.6.1.0.24194.2233-arm64.exe
dev-preview-6/Windows.MIDI.Services.In-Box.Service.-.Developer.Preview.6.1.0.24194.2233-arm64.exe
240713-USBMidi2-Arm64-TESTSIGNED

Desktop (please complete the following information):
Snapdragon 3GHz Windows 11 Pro
Build 26100.ge_release.240331-1435

@masahirokakishita masahirokakishita added the bug 🐞 Something isn't working label Jul 22, 2024
@Psychlist1972
Copy link
Contributor

How much time had passed before you open the new monitor? Are you seeing the end of the messages echoed back?

When you send messages, they go into an outbound queue. Once queued, the client returns quickly. meanwhile, the service processes that queue and sends them to the USB driver.

@AmeNote-Michael
Copy link
Collaborator

Actually @Psychlist1972 I think I might know what is going on here - of course need to verify. @garydan42 would love your opinion.

If using midi console app to sending a chunk of data, it "opens" driver to send data and closes shortly after. During the time open to send, the ContinuousReader will read the data from the USB device.

Now that we have multiple UMP messages in a single USB message, there is a chance that the USB driver is "closed" before the last message sent is looped back. The data is sitting in ProtoZOA message queue to send but nothing is grabbing. Although it is true that ProtoZOA does not store a lot of data in USB In (out from device) queue, it does have some.

When the USB device is subsequently "opened" for monitor later, the Continuous Reader is started again and this small queued information is read. I will look later in week if ProtoZOA driver can "flush" buffers when closed, but I do not think this currently happens.

Also, is it possible that USB Stacks queue up some information?

@masahirokakishita
Copy link
Collaborator Author

How much time had passed before you open the new monitor?
I wait one minutes or more longer.

Are you seeing the end of the messages echoed back?
Yes, sending was finished.

image

@Psychlist1972
Copy link
Contributor

How much time had passed before you open the new monitor?
I wait one minutes or more longer.

Are you seeing the end of the messages echoed back?
Yes, sending was finished.

image

Sorry, I was unclear. I mean, the messages you saw in the new console monitor window, were they the last messages sent, or were they earlier messages?

@Psychlist1972
Copy link
Contributor

Actually @Psychlist1972 I think I might know what is going on here - of course need to verify. @garydan42 would love your opinion.

If using midi console app to sending a chunk of data, it "opens" driver to send data and closes shortly after. During the time open to send, the ContinuousReader will read the data from the USB device.

Now that we have multiple UMP messages in a single USB message, there is a chance that the USB driver is "closed" before the last message sent is looped back. The data is sitting in ProtoZOA message queue to send but nothing is grabbing. Although it is true that ProtoZOA does not store a lot of data in USB In (out from device) queue, it does have some.

When the USB device is subsequently "opened" for monitor later, the Continuous Reader is started again and this small queued information is read. I will look later in week if ProtoZOA driver can "flush" buffers when closed, but I do not think this currently happens.

Also, is it possible that USB Stacks queue up some information?

If this is a MIDI 2.0 device, UMP-native, there's a persistent connection open from the service to the device to capture metadata. So this doesn't sound quite right.

You can see that with midi enum sessions

Pete

@masahirokakishita
Copy link
Collaborator Author

I'm sorry, my explanation is poor and it's hard to understand the issue.
So I made a video.
The device is zoa_loop.uf2.
I only use one console and type two commands.

midi endpoint send-message 0x40123456 0x00000000 -p 0 -c 125000 -i
midi endpoint monitor --verbose

In the video, the following commands are inserted during the wait:

midi enum sessions

366.mov

@Psychlist1972
Copy link
Contributor

Thanks @masahirokakishita . I thought maybe it was just a few messages, but that's essentially every message. The video certainly helped me see that.

@Psychlist1972
Copy link
Contributor

One other strange thing here is that midisrv should have had an option session to the protozoa. It keeps a connection open to all devices which report a native data format of UMP because they can send metadata at any time.

That doesn't explain the main issue, but this is a secondary issue I see here.

@AmeNote-Michael any idea what is happening here? Is this on the protozoa? I'll need to grab that firmware and try it out myself to see what's happening on the service side.

@Psychlist1972
Copy link
Contributor

For example: This is what I see with the Montage and with the Iridium connected, even though no client is using them.

image

@AmeNote-Michael
Copy link
Collaborator

@masahirokakishita @Psychlist1972 I think what is happening here is that the command to send data to ProtoZOA is still working on it. To verify this, I made a large transfer, but not as large as above example. Here is what I observed:

Test case 1:

  1. midi endpoint send-message 0x20903c7f -p 0 -c 12500 -i
  2. midi endpoint monitor --verbose

I observe a bunch of messages being received in monitor.

Test case 2:

  1. midi endpoint send-message 0x20903c7f -p 0 -c 12500 -i
  2. Wait about 45 seconds
  3. midi endpoint monitor --verbose

In this case I observe NO messages in monitor.

This leads me to believe that even though the console app indicates messages are sent, they are still being physically processed through to the device. When you run monitor quick enough, you are seeing the tail end of the transfer.

@Psychlist1972
Copy link
Contributor

@masahirokakishita @Psychlist1972 I think what is happening here is that the command to send data to ProtoZOA is still working on it. To verify this, I made a large transfer, but not as large as above example. Here is what I observed:

Test case 1:

  1. midi endpoint send-message 0x20903c7f -p 0 -c 12500 -i
  2. midi endpoint monitor --verbose

I observe a bunch of messages being received in monitor.

Test case 2:

  1. midi endpoint send-message 0x20903c7f -p 0 -c 12500 -i
  2. Wait about 45 seconds
  3. midi endpoint monitor --verbose

In this case I observe NO messages in monitor.

This leads me to believe that even though the console app indicates messages are sent, they are still being physically processed through to the device. When you run monitor quick enough, you are seeing the tail end of the transfer.

You are correct in that "sent" messages are queued. There's an x-proc buffer between the client and the service. The client returns immediately once messages are queued. I thought I had included that information in this issue, but it was in a different issue.

However, there were something like 80k messages received in that monitor session before the video stops. That's not right. They should have all been received by then, unless the loopback in the protozoa is extremely slow, which did not appear to be the case.

And then there's the fact that protozoa doesn't show up in the midisrv sessions. There's something else strange going on -- perhaps multiple things.

@AmeNote-Michael
Copy link
Collaborator

Note, I have confirmed this by observing on the USB protocol analyzer. So the messages appearing on the analyzer, if the midi endpoint monitor is started before USB streaming is complete, then data shows up on the monitor. If midi endpoint monitor is started after the USB streaming is complete, then no data shows up on the monitor.

What is interesting is the duration between USB packets sent - the USB Out transactions seemed to be spaced 14 ms apart for some reason. That is a lot - is this a driver issue? I do not think it is a throughput issues. Maybe a ProtoZOA issue.

Will continue to investigate on Thursday.

@Psychlist1972
Copy link
Contributor

Most of the incoming messages arrive in around 5 microseconds from the previous one, but every maybe 10th one is like 12 milliseconds. But even then, everything should have been sent to the protozoa within a few seconds at most so I'm at a bit of a loss as to where the massive time difference is coming from. Rewatching the video, there were > 95,000 of the 125,000 messages that came in after that 45 second or so wait.

But if there's a 14ms delta between each packet going to the Protozoa, that could do it.

Mostly I want to make sure we're debugging a MIDI Services issue here, not a protozoa issue.

@MusicMaker
Copy link

MusicMaker commented Jul 26, 2024

FWIW, Sending many message to a low performance MCU can easily cause messages to drop or other weird things to happen. it really depends on how the MCU (RP2040 here) receives and send USB messages. Take for example a USB to DIN interface and loop back via the DIN cable, then play a MIDI file with lots of MIDI data, many USB interface drop messages, that could easily be the case echoing using UMP/USB. The only device doing this with DIN fine via SUB, for me, is a focusrite audio interface with MIDI DIN. Try to send messages with delays in between an observer again ? Add an option to add a delay between a set of UMP packets ?

@AmeNote-Michael
Copy link
Collaborator

@masahirokakishita can you please share the source code for the zoa_loop.uf2 application. I would like to look at if it is a ProtoZOA issue or driver issue in the slow loopback and would like to understand your code for loopback.

@m-komo
Copy link
Collaborator

m-komo commented Jul 30, 2024

I just measured the time to complete the transfer with the attached ProtoZOA firmware.
It took about 4 minutes to complete sending and receiving all 125,000 messages.

image
image

@Psychlist1972
Copy link
Contributor

@m-komo that is much slower than I would expect for a native UMP device. Can you share the source with @AmeNote-Michael ?

Thanks

@m-komo
Copy link
Collaborator

m-komo commented Jul 30, 2024

@Psychlist1972

I just measured the time to complete the transfer with the attached ProtoZOA firmware.

Sorry, it was unclear.
"the attached ProtoZOA firmware" means the firmware attached by Kakishita-san at the first post.

In short, this one.
https://github.com/user-attachments/files/16326655/zoa_loop.uf2.zip

@masahirokakishita
Copy link
Collaborator Author

I gave the zoa_loop source code to Michael directry.
The core part of the program is shown below.
After sending the source code, I realized that
the part where I use printf to write to Serial is probably what's causing the slowness.

   while (true) {
       tud_task();
       if(read_midi_interface_selected()==1){
           if((umpCount = tud_midi_ump_read(0,UMPpacket,16))){
               printf("UMP  %d :",umpCount);
               for(uint8_t i=0; i<umpCount; i++){
                   printf("%08x ",UMPpacket[i]);
                   if(i%2==1) printf("\n");
               }
               n=0;
               cnt=0;
               while((n!=umpCount) && (cnt<4)){
                   n=tud_midi_ump_write(0,UMPpacket,umpCount);
                   cnt++;
               }
           }
      }

I think that somewhere in Windows, the UMP is being cached and continues to be sent.
I assumed that the transmission would end when the midi.exe application was closed.

@AmeNote-Michael
Copy link
Collaborator

AmeNote-Michael commented Jul 31, 2024 via email

@Psychlist1972
Copy link
Contributor

Psychlist1972 commented Jul 31, 2024

I think that somewhere in Windows, the UMP is being cached and continues to be sent. I assumed that the transmission would end when the midi.exe application was closed.

There are several buffers involved.

When transmitting MIDI data, the client application puts all the messages it can on the outgoing buffer that the service reads. This is quite fast, and a client will finish (typically) long before the messages are all sent to the device. This is by design so we block as little as possible and allow the client to get on with its business.

Then the service will process the messages. Depending on what needs to be done to them, there are a few other buffers before we get to the xproc for the USB driver

  • Scheduler queue. If the messages have a timestamp in the future, they are put on a scheduler queue, which is effectively another buffer.
  • Translation. If the messages need to be translated from UMP to MIDI 1.0 data format then there's a buffer that is part of how libmidi2 works. Usually, this gets processed quickly, especially in the case of UMP -> byte format, but it's there.

After that, there's the xproc queue/buffer that goes from the service to the MIDI 2.0 USB driver. In the case of the MIDI 1.0 class driver or vendor MIDI 1.0 drivers, there's no buffer, just an ioctl.

@masahirokakishita
Copy link
Collaborator Author

I understand that this phenomenon was not a bug, but was caused by protoZOA's slow reception of UMP messages.
No problems occurred when I removed the printf from the program as follows:

   while (true) {
       tud_task();
       if(read_midi_interface_selected()==1){
           if((umpCount = tud_midi_ump_read(0,UMPpacket,16))){
               n=0;
               cnt=0;
               while((n!=umpCount) && (cnt<4)){
                   n=tud_midi_ump_write(0,UMPpacket,umpCount);
                   cnt++;
               }
           }
      }

@masahirokakishita
Copy link
Collaborator Author

I have a question.
If the device does not receive UMP and is a send-only device, when will the buffer be cleared?
Install zoa_noreceive.uf2.

zoa_noreceive.uf2.zip

The device is programmed as follows (I know this is an extreme example):

    while (true) {
        tud_task(); 
    }

Open Task Manager > Memory
Check In Used,

Repeat the following for this device about 10 times:

midi endpoint send-message 0x40123456 0x00000000 -p 0 -c 125000 -i

I attached the video.
You can see that memory is gradually consumed.
Using Memory started at 5.0GB and ended at 6.1GB.
It may not be a problem in practice?

366_2.mov

@Psychlist1972
Copy link
Contributor

@masahirokakishita

Do you have a new .uf2 without the printf? @garydan42 was doing some testing direct to the new driver and protozoa and noticed the same speed issues. We wanted to verify it's the firmware and not something else.

@Psychlist1972
Copy link
Contributor

@masahirokakishita

I wouldn't expect that much memory to be used if the device is sending to Windows with nothing clearing the queues.

If this is a MIDI 2.0 device, the protocol negotiation code will be reading the incoming buffers looking for protocol information, so the buffers will be read.

If this is a MIDI 1.0 device, there's no protocol negotiation, so the buffers will be filled. However, the buffer size is either 1x or 2x PAGE_SIZE . You should not see anything close to a couple GB used.

I see you are sending messages which aren't being read. A new client gets created each time, but when you close the console, that client will be destroyed. Did you happen to see which process had increased memory?

@AmeNote-Michael
Copy link
Collaborator

@masahirokakishita @m-komo this issue has more to do with the loopback software being used in ProtoZOA than driver issue. This ProtoZOA loopback removes any printf statements inside tight loop to loopback MIDI2 data - and has proven to process USB MIDI 2 messages at rates of 40k to 50k with full speed USB.

TBD if there is still an issue because we all feel that when USB driver is closed, all transfers regardless of state should cancel - not sure where messages a
UUT_USB_MIDI_ECHO_NO_PRINTF.uf2.zip
re being queued, especially since the ProtoZOA has limited memory to queue messages.

Please retest with this loopback code for ProtoZOA.

@masahirokakishita
Copy link
Collaborator Author

I'm sorry to be late. Thank you for creating the program.
It's good. This program is a UMP message loopback program and does not do printf.

I have a question about UUT_USB_MIDI_ECHO_NO_PRINTF.uf2.
When this device is connected for the first time, the USBMIDI2 driver is loaded.
Also, if you try to update the driver, a list of drivers is displayed as shown below.

image

Is this possible due to the way the USB descriptor is written?

@masahirokakishita
Copy link
Collaborator Author

Memory not being freed issue, I can't find out which process is using memory.
In the Performance view of Task manager, the memory usage is increasing as shown in the video.
However, when I look in the Processes of Task manager or Process Explorer, I cannot find the process that is increasing the memory usage.
Is there any way to check?

@Psychlist1972
Copy link
Contributor

Memory not being freed issue, I can't find out which process is using memory. In the Performance view of Task manager, the memory usage is increasing as shown in the video. However, when I look in the Processes of Task manager or Process Explorer, I cannot find the process that is increasing the memory usage. Is there any way to check?

If you don't see the committed memory being tied to a specific process, then it is most likely the USB MIDI 2 Driver which is increasing memory usage.

Memory-mapped files for communication between the service and driver should show up in the MidiSrv process.
Memory-mapped files for communication between the application and the service show up in the client process, as I recall.

Folks often recommend RAMMap, but it doesn't offer much more than what Task Manager does when it comes to drivers.
https://learn.microsoft.com/sysinternals/downloads/rammap
(RAMmap takes a while to start up. It may look locked up, but it is not.)

Some tools will let you report memory usage by pool tag. Here's the USB MIDI Driver's tag:

image

Here's a tool found via StackOverflow. I haven't used it myself.
https://www.osronline.com/article.cfm%5earticle=98.htm

Tagging @AmeNote-Michael in case there's a memory leak in the driver.

@Psychlist1972
Copy link
Contributor

I'm sorry to be late. Thank you for creating the program. It's good. This program is a UMP message loopback program and does not do printf.

I have a question about UUT_USB_MIDI_ECHO_NO_PRINTF.uf2. When this device is connected for the first time, the USBMIDI2 driver is loaded. Also, if you try to update the driver, a list of drivers is displayed as shown below.

image

Is this possible due to the way the USB descriptor is written?

IIRC, ProtoZOA's VID/PID is still hard-coded in the INF so it will behave a bit differently than other devices when it comes to driver selection.

@masahirokakishita
Copy link
Collaborator Author

Let me state my problem again. I am using RAMmap to dump the memory map.

  1. Install zoa_noreceive.uf2 to ProtoZoA

  2. The memory map at this point is as follows: Nonpaged Pool is 480M.
    p1

  3. Open the console and run the following command five times.

midi endpoint send-message 0x40123456 0x00000000 -p 0 -c 125000 -i

  1. Check the memory map, the Nonpaged Pool has been increased, 2.159G.

p2

  1. Run the following command five times.

midi endpoint send-message 0x40123456 0x00000000 -p 0 -c 125000 -i

  1. Check the memory map, the Nonpaged Pool has been increased, 4.242G.

p3

I don't know when and how to free up the Nonpaged Pool.

@Psychlist1972
Copy link
Contributor

Gary found some cleanup that wasn't happening in the service when a device was disconnected. We'll need to see if that addresses this specific problem.

@AmeNote-Michael
Copy link
Collaborator

@Psychlist1972 can this issue be closed. Combined improvements in service plus the update to ProtoZOA not using printf?

@Psychlist1972
Copy link
Contributor

@Psychlist1972 can this issue be closed. Combined improvements in service plus the update to ProtoZOA not using printf?

@masahirokakishita can you try with today's DP7 release and the updated ProtoZoa code, and let us know if this issue is resolved? Thanks.

@sat-okada
Copy link
Collaborator

I comment on behalf of @masahirokakishita .

Checking with DP7, this issue is not solved.

1.Install zoa_noreceive.uf2 on ProtoZoA

Memory map in initial state
Image

  1. Execute the following commands 10 times
    midi endpoint send-message 0x40123456 0x00000000 -p 0 -c 125000 -i

Memory map
Image

Nonpaged pool has increased to 1,280,260K.

No further operations have been performed.
After 10 minutes, Nonpaged pool was 1,287,296K and did not seem to be decreasing.
After 30 minutes, it had decreased to 512,676K.
Memory release appears to be slow.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug 🐞 Something isn't working
Projects
Status: No status
Development

No branches or pull requests

6 participants