slow snd_rawmidi_drain() for VirMidi devcies

[Takashi Iwai]

On Sat, 01 Jan 2022 12:49:13 +0100,
Stefan Sauer wrote:
> 
> hi,
> 
> I've tried to link BitwigStudio to the webapp cables.gl over virmidi.
> Unfortunately Bitwig Studio only supports rawmidi. What I discovered is
> that there is a strange slowness when sending data to virmidi caused
> by snd_rawmidi_drain().
> 
> I've posted two tiny, self-contained c apps to:
> https://gist.github.com/ensonic/c7588b87fa6c1fa94a8f753b1e0aa394
> See some examples below. 2 observations:
> * snd_rawmidi_type() is *not* reporting virmidi as VIRTUAL
> * snd_rawmidi_drain() takes about 60ms! on virtual vs. less that 0.1 ms on
> usb midi (I checked all my hw midi and the worst was avg=1ms on physical
> midi image unitor8)
> 
> When comparing the implementations:
> https://github.com/alsa-project/alsa-lib/blob/master/src/rawmidi/rawmidi_virt.c#L173
> https://github.com/alsa-project/alsa-lib/blob/master/src/rawmidi/rawmidi_hw.c#L164
> I see that the hw one results in an IOCTL which I can see when striking the
> code and I wonder if this is the root cause? Why is rawmidi_virt.c not used
> for virmidi?
> >From poking at snd_rawmidi_open_conf() I have not yet figured where this is
> decided ....
> 
> Stefan
> 
> > amidi -l
> Dir Device    Name
> IO  hw:0,0,0  Scarlett 18i20 USB MIDI 1
> IO  hw:3,0,0  nanoKEY2 nanoKEY2 _ KEYBOARD
> IO  hw:5,0,0  nanoKONTROL nanoKONTROL _ SLIDE
> IO  hw:10,0    Virtual Raw MIDI (16 subdevices)
> IO  hw:11,0    Virtual Raw MIDI (16 subdevices)
> 
> # using direct i/o to virmidi - all good
> > ./rawmidi_oss /dev/midi11 0
> Using device '/dev/midi11' without draining
> write took min=  0.0015 ms, avg=  0.0016 ms, max=  0.0110 ms
> > ./rawmidi_oss /dev/midi11 1
> Using device '/dev/midi11' with draining
> write took min=  0.0015 ms, avg=  0.0017 ms, max=  0.0101 ms
> drain took min=  0.0001 ms, avg=  0.0001 ms, max=  0.0008 ms
> 
> # using snd_rawmidi to virmidi - slow drain operations
> > ./rawmidi_alsa hw:11,0 0
> Using device 'hw:11,0' without draining
> SND_RAWMIDI_TYPE_HW
> write took min=  0.0010 ms, avg=  0.0011 ms, max=  0.0056 ms
> > ./rawmidi_alsa hw:11,0 1
> Using device 'hw:11,0' with draining
> SND_RAWMIDI_TYPE_HW
> write took min=  0.0016 ms, avg=  0.0040 ms, max=  0.0077 ms
> drain took min= 55.9951 ms, avg= 60.4330 ms, max= 64.0653 ms
> 
> # using snd_rawmidi to usb hw - all good
> > ./rawmidi_alsa hw:3,0 0
> Using device 'hw:3,0' without draining
> SND_RAWMIDI_TYPE_HW
> write took min=  0.0012 ms, avg=  0.0015 ms, max=  0.0121 ms
> > ./rawmidi_alsa hw:3,0 1
> Using device 'hw:3,0' with draining
> SND_RAWMIDI_TYPE_HW
> write took min=  0.0024 ms, avg=  0.0032 ms, max=  0.0110 ms
> drain took min=  0.0293 ms, avg=  0.0636 ms, max=  0.2277 ms

This kind of thing needs profiling.  You can try perf or whatever
available, and identify which call takes long.  My wild guess is
something about snd_seq_sync_output_queue(), maybe poll syscall takes
unexpected long.


thanks,

Takashi