slow snd_rawmidi_drain() for VirMidi devcies

[Takashi Iwai]

On Wed, 05 Jan 2022 14:39:05 +0100,
Stefan Sauer wrote:
> 
> -   28,78%     0,00%  rawmidi_alsa  [snd_rawmidi]         [k]
> snd_rawmidi_drain_output
>    - snd_rawmidi_drain_output
>       - 26,59% msleep
>            schedule_timeout
>            schedule
>          + __schedule
>       + 2,13% schedule_timeout
> 
> Seems to be because of:
> https://github.com/torvalds/linux/blob/master/sound/core/rawmidi.c#L244
> if (substream->ops->drain)
>   substream->ops->drain(substream);
> else
>   msleep(50);
> 
> It see what fileops have no drain impl:
> https://github.com/torvalds/linux/blob/master/sound/core/rawmidi.c#L1708
> and I see
> https://github.com/torvalds/linux/blob/master/sound/core/seq/seq_virmidi.c#L329
> that define no drain op. Not which ones are actually used here :/
> 
> The docs confirm teh 50 ms wait though:
> https://github.com/torvalds/linux/blob/master/Documentation/sound/kernel-api/writing-an-alsa-driver.rst#drain-callback
> 
> would it make sense to have a dummy drain function for the seq_virmidi output
> ops?

Yes, a proper drain implementation is definitely better.
I guess just calling flush_work(&vmidi->output_work) there would
suffice.


thanks,

Takashi

> 
> Stefan
> 
> Am Di., 4. Jan. 2022 um 16:54 Uhr schrieb Takashi Iwai <tiwai at suse.de>:
> 
>     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
> 
>