slow snd_rawmidi_drain() for VirMidi devcies

slow snd_rawmidi_drain() for VirMidi devcies

[Stefan Sauer]

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

Re: 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

Re: slow snd_rawmidi_drain() for VirMidi devcies

[Stefan Sauer]

-   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?

Stefan


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

Re: 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@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
> 
> 

Re: slow snd_rawmidi_drain() for VirMidi devcies

[Stefan Sauer]

From 6b97042bc91ebee267cbb05e6b937cbab5502f61 Mon Sep 17 00:00:00 2001
From: Stefan Sauer <ensonic@google.com>
Date: Wed, 5 Jan 2022 20:44:57 +0100
Subject: [PATCH] ALSA: seq: virmidi: Add a drain operation

If a driver does not supply a drain operation for outputs, a default code
path will execute msleep(50). Especially for a virtual midi device
this severely limits the throughput.

This implementation for the virtual midi driver simply flushes the output
workqueue.
---
 sound/core/seq/seq_virmidi.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
index 4abc38c70cae..1d708dc20443 100644
--- a/sound/core/seq/seq_virmidi.c
+++ b/sound/core/seq/seq_virmidi.c
@@ -262,6 +262,16 @@ static int snd_virmidi_output_close(struct
snd_rawmidi_substream *substream)
  return 0;
 }

+/*
+ * drain output work queue
+ */
+static void snd_virmidi_output_drain(struct snd_rawmidi_substream
*substream)
+{
+ struct snd_virmidi *vmidi = substream->runtime->private_data;
+
+ flush_work(&vmidi->output_work);
+}
+
 /*
  * subscribe callback - allow output to rawmidi device
  */
@@ -336,6 +346,7 @@ static const struct snd_rawmidi_ops
snd_virmidi_output_ops = {
  .open = snd_virmidi_output_open,
  .close = snd_virmidi_output_close,
  .trigger = snd_virmidi_output_trigger,
+ .drain = snd_virmidi_output_drain,
 };

 /*
-- 
2.34.1


Am Mi., 5. Jan. 2022 um 15:13 Uhr schrieb Takashi Iwai <tiwai@suse.de>:
>
> 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@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
> >
> >

Re: slow snd_rawmidi_drain() for VirMidi devcies

[Takashi Iwai]

On Wed, 05 Jan 2022 20:53:33 +0100,
Stefan Sauer wrote:
> 
> From 6b97042bc91ebee267cbb05e6b937cbab5502f61 Mon Sep 17 00:00:00 2001
> From: Stefan Sauer <ensonic@google.com>
> Date: Wed, 5 Jan 2022 20:44:57 +0100
> Subject: [PATCH] ALSA: seq: virmidi: Add a drain operation
> 
> If a driver does not supply a drain operation for outputs, a default code
> path will execute msleep(50). Especially for a virtual midi device
> this severely limits the throughput.
> 
> This implementation for the virtual midi driver simply flushes the output
> workqueue.

Your signed-off-by is missing.  Could you resubmit with it?


thanks,

Takashi

> ---
>  sound/core/seq/seq_virmidi.c | 11 +++++++++++
>  1 file changed, 11 insertions(+)
> 
> diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
> index 4abc38c70cae..1d708dc20443 100644
> --- a/sound/core/seq/seq_virmidi.c
> +++ b/sound/core/seq/seq_virmidi.c
> @@ -262,6 +262,16 @@ static int snd_virmidi_output_close(struct
> snd_rawmidi_substream *substream)
>   return 0;
>  }
>  
> +/*
> + * drain output work queue
> + */
> +static void snd_virmidi_output_drain(struct snd_rawmidi_substream *substream)
> +{
> + struct snd_virmidi *vmidi = substream->runtime->private_data;
> +
> + flush_work(&vmidi->output_work);
> +}
> +
>  /*
>   * subscribe callback - allow output to rawmidi device
>   */
> @@ -336,6 +346,7 @@ static const struct snd_rawmidi_ops snd_virmidi_output_ops
> = {
>   .open = snd_virmidi_output_open,
>   .close = snd_virmidi_output_close,
>   .trigger = snd_virmidi_output_trigger,
> + .drain = snd_virmidi_output_drain,
>  };
>  
>  /*
> --
> 2.34.1
> 
> Am Mi., 5. Jan. 2022 um 15:13 Uhr schrieb Takashi Iwai <tiwai@suse.de>:
> >
> > 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@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
> > >
> > >
> 
> 

[PATCH] ALSA: seq: virmidi: Add a drain operation

[Stefan Sauer]

If a driver does not supply a drain operation for outputs, a default code
path will execute msleep(50). Especially for a virtual midi device
this severely limmits the throughput.

This implementation for the virtual midi driver simply flushes the output
workqueue.

Signed-off-by: Stefan Sauer <st.kost@gmail.com>
---
 sound/core/seq/seq_virmidi.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
index 4abc38c70cae..f5cae49500c8 100644
--- a/sound/core/seq/seq_virmidi.c
+++ b/sound/core/seq/seq_virmidi.c
@@ -262,6 +262,16 @@ static int snd_virmidi_output_close(struct snd_rawmidi_substream *substream)
 	return 0;
 }
 
+/*
+ * drain output work queue
+ */
+static void snd_virmidi_output_drain(struct snd_rawmidi_substream *substream)
+{
+	struct snd_virmidi *vmidi = substream->runtime->private_data;
+
+	flush_work(&vmidi->output_work);
+}
+
 /*
  * subscribe callback - allow output to rawmidi device
  */
@@ -336,6 +346,7 @@ static const struct snd_rawmidi_ops snd_virmidi_output_ops = {
 	.open = snd_virmidi_output_open,
 	.close = snd_virmidi_output_close,
 	.trigger = snd_virmidi_output_trigger,
+	.drain = snd_virmidi_output_drain,
 };
 
 /*
-- 
2.34.1

Re: [PATCH] ALSA: seq: virmidi: Add a drain operation

[Geraldo Nascimento]

On Wed, Jan 05, 2022 at 09:47:17PM +0100, Stefan Sauer wrote:
> If a driver does not supply a drain operation for outputs, a default code
> path will execute msleep(50). Especially for a virtual midi device
> this severely limmits the throughput.
> 
> This implementation for the virtual midi driver simply flushes the output
> workqueue.
> 
> Signed-off-by: Stefan Sauer <st.kost@gmail.com>

Hi, Stefan,

Thanks for the patch!

However it seems you forgot to Cc: Takashi Iwai.

Cc:ing him now so he takes notice.

Thank you,
Geraldo Nascimento
> ---
>  sound/core/seq/seq_virmidi.c | 11 +++++++++++
>  1 file changed, 11 insertions(+)
> 
> diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
> index 4abc38c70cae..f5cae49500c8 100644
> --- a/sound/core/seq/seq_virmidi.c
> +++ b/sound/core/seq/seq_virmidi.c
> @@ -262,6 +262,16 @@ static int snd_virmidi_output_close(struct snd_rawmidi_substream *substream)
>  	return 0;
>  }
>  
> +/*
> + * drain output work queue
> + */
> +static void snd_virmidi_output_drain(struct snd_rawmidi_substream *substream)
> +{
> +	struct snd_virmidi *vmidi = substream->runtime->private_data;
> +
> +	flush_work(&vmidi->output_work);
> +}
> +
>  /*
>   * subscribe callback - allow output to rawmidi device
>   */
> @@ -336,6 +346,7 @@ static const struct snd_rawmidi_ops snd_virmidi_output_ops = {
>  	.open = snd_virmidi_output_open,
>  	.close = snd_virmidi_output_close,
>  	.trigger = snd_virmidi_output_trigger,
> +	.drain = snd_virmidi_output_drain,
>  };
>  
>  /*
> -- 
> 2.34.1
>