From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from alsa0.perex.cz (alsa0.perex.cz [77.48.224.243]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.lore.kernel.org (Postfix) with ESMTPS id 85606C433EF for ; Wed, 5 Jan 2022 14:14:47 +0000 (UTC) Received: from alsa1.perex.cz (alsa1.perex.cz [207.180.221.201]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by alsa0.perex.cz (Postfix) with ESMTPS id 724E31908; Wed, 5 Jan 2022 15:13:55 +0100 (CET) DKIM-Filter: OpenDKIM Filter v2.11.0 alsa0.perex.cz 724E31908 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=alsa-project.org; s=default; t=1641392085; bh=CccutYUHBbdgq2XTy76jLP+WE0Q7inQcrnF7f3LVFdI=; h=Date:From:To:Subject:In-Reply-To:References:Cc:List-Id: List-Unsubscribe:List-Archive:List-Post:List-Help:List-Subscribe: From; b=dF6KjXsxybVKJaNc+blFvBZsNb9uUNJez/gL4PnydxA5xOrn7XrjbSDzaQdjhLDtl qCHA7lMquBsBcBxPXa+/prPAuTgYxww9a1W3P7F0kHNpLo13hL/O3uywfnNgTZDGyt b6Tvif0l3VNTKO3gNlMhCTZVUt1nC1MANi0YoNIg= Received: from alsa1.perex.cz (localhost.localdomain [127.0.0.1]) by alsa1.perex.cz (Postfix) with ESMTP id EE035F801D8; Wed, 5 Jan 2022 15:13:54 +0100 (CET) Received: by alsa1.perex.cz (Postfix, from userid 50401) id D5779F8007E; Wed, 5 Jan 2022 15:13:53 +0100 (CET) Received: from smtp-out1.suse.de (smtp-out1.suse.de [195.135.220.28]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by alsa1.perex.cz (Postfix) with ESMTPS id 024EAF8007E for ; Wed, 5 Jan 2022 15:13:47 +0100 (CET) DKIM-Filter: OpenDKIM Filter v2.11.0 alsa1.perex.cz 024EAF8007E Authentication-Results: alsa1.perex.cz; dkim=pass (1024-bit key) header.d=suse.de header.i=@suse.de header.b="SIF5Boag"; dkim=permerror (0-bit key) header.d=suse.de header.i=@suse.de header.b="1DmjC+ez" Received: from relay2.suse.de (relay2.suse.de [149.44.160.134]) by smtp-out1.suse.de (Postfix) with ESMTP id 38DF8210F8; Wed, 5 Jan 2022 14:13:47 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.de; s=susede2_rsa; t=1641392027; h=from:from:reply-to:date:date:message-id:message-id:to:to:cc:cc: mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=ox5tYzMQtKTOGwhlzmzLIoDhdG9OZXr9oK4OGLN9kG8=; b=SIF5BoagLyD+tatgKxJdjmc5Xc7s8i0+9yTvl7vmRj7u57iNCVyqCQi7hyPTqXVXehOeCy z3db/JTDXMiAqvTokQ+yismwkhOqrufuaJEcFJ2P8pUuiOHTSaTUjB9sqKUSbWFsJGWA4r KIKR5QuCFS/ERhyuscfLeMKaCgdXJ5U= DKIM-Signature: v=1; a=ed25519-sha256; c=relaxed/relaxed; d=suse.de; s=susede2_ed25519; t=1641392027; h=from:from:reply-to:date:date:message-id:message-id:to:to:cc:cc: mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=ox5tYzMQtKTOGwhlzmzLIoDhdG9OZXr9oK4OGLN9kG8=; b=1DmjC+ez33P8C1LuCqIWUjOe+z7u+jZPoHJWzHEql9PMTJIkiCdXT5oRrtyboQumpgrD7i eI5sRVJThE3Gz7Dg== Received: from alsa1.suse.de (alsa1.suse.de [10.160.4.42]) by relay2.suse.de (Postfix) with ESMTP id 332B3A3B98; Wed, 5 Jan 2022 14:13:47 +0000 (UTC) Date: Wed, 05 Jan 2022 15:13:47 +0100 Message-ID: From: Takashi Iwai To: Stefan Sauer Subject: Re: slow snd_rawmidi_drain() for VirMidi devcies In-Reply-To: References: User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI/1.14.6 (Maruoka) FLIM/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL/10.8 Emacs/25.3 (x86_64-suse-linux-gnu) MULE/6.0 (HANACHIRUSATO) MIME-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka") Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Cc: alsa-devel@alsa-project.org X-BeenThere: alsa-devel@alsa-project.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: "Alsa-devel mailing list for ALSA developers - http://www.alsa-project.org" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: alsa-devel-bounces@alsa-project.org Sender: "Alsa-devel" 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 : > > 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 > >