MIDI plugin latency through Sushi

Elk Audio OS Sushi
1

Hello there,

It is been several weeks that I am trying to do this: running a MIDI plugin with Sushi without sensible latency.

For a start, I have no latency using aconnect between a MIDI keyboard and synth, connected via USB to the Raspberry PI.
aconnect 16 20

For the next step, I have tried the Transposer SUSHI internal plugin, and I have more than 1 second of latency, which is not normal. I have same kind of latency using midish.
I connect a keyboard to SUSHI, and SUSHI to a synth via aconnect.
aconnect 16 128:0
aconnect 128:1 20:0

I am on Raspberry Pi 4 with Hifiberry hat, and Elk OS 64 bit.

It may be some setting to adjust, but I do not know where.

In advance, thank you.

2

Hi Teu. That sounds odd. Midi turnaround latency in Sushi should be comparable to audio latency. Have you tried running Sushi with the –log-level=debug option and looked at the log file in /tmp/sushi.log ? Iirc that should give you timestamps for both incoming and outgoing midi and you should be able to see if there is a significant delay there.
Though if you’re experiencing the same delay with midish (which I’m not familiar with) that could suggest something in Alsa rather that Sushi.

Happy hacking!

3

Hi Gustav !

Thank you for your answer. I had the same analysis concerning ALSA, but I do not know what happens, because sound plugins work fine (OBXD for instance). In order to understand, I give you what I have set so far, and the log.

  1. First, SUSHI config file, then SUSHI service systemd file :
    more ~/config_files/config_play_through.json

     {
     "host_config" : {
         "samplerate" : 48000,
         "tempo_sync" : "internal",
         "playing_mode" : "stopped"
     },
     "tracks" : [
         {
             "name" : "main",
             "mode" : "stereo",
             "inputs" : [ ],
             "outputs" : [ ],
             "plugins" : [
                 {
                     "uid" : "sushi.testing.transposer",
                     "name" : "transposer",
                     "type"   : "internal"
                 }
             ]
         }
     ],
     "midi" : {
         "track_connections": [
             {
                 "port": 0,
                 "channel": 0,
                 "track": "main",
                 "raw_midi": false
             }
         ],
         "track_out_connections": [
             {
                 "port": 0,
                 "channel": 0,
                 "track": "main"
             }
         ]
     }
 }

more /lib/systemd/system/sushi.service

[Unit]
Description=sushi starting service
After=load-drivers.service
ConditionPathExists=/dev/rtdm/audio_rtdm

[Service]
Type=simple
RemainAfterExit=yes
WorkingDirectory=/udata/
Environment=LD_LIBRARY_PATH=/usr/xenomai/lib
ExecStart=/usr/bin/sushi -r -c /home/mind/config_files/config_play_through.json --log-level=debug
User=mind

[Install]
WantedBy=multi-user.target

1. I start monitoring MIDI in and out with aseqdump (129) :

mind@elk-pi:~$ aseqdump | while IFS= read -r line; do printf '%s:%s:%s.%s %s\n' "$(date +%H)" "$(date +%M)" "$(date +%S)" "$(date +%3N)" "$line"; done &
[1] 358

mind@elk-pi:~$ aconnect 20 129
mind@elk-pi:~$ 20:05:15.404 Waiting for data at port 129:0. Press Ctrl+C to end.
20:05:15.418 Source Event Ch Data
20:05:15.431 0:1 Port subscribed 20:0 -> 129:0

aconnect 128:1 129
mind@elk-pi:~$ 20:05:31.846 0:1 Port subscribed 128:1 -> 129:0

2. I played 3 different notes on the USB MIDI keyboard (I display only the first note on/off). Sent via 20, received via 128:1. Below the log thanks to aseqdump.

20:05:43.910  20:0   Note on                 0, note 48, velocity 112
20:05:44.042  20:0   Note off                0, note 48, velocity 0
20:05:45.370 128:1   Note on                 0, note 48, velocity 112
20:05:45.501 128:1   Note off                0, note 48, velocity 0

3. I looked at the SUSHI log.

mind@elk-pi:~$ more /tmp/sushi.log

[2021-11-10 20:04:22.117] [warning] #############################
[2021-11-10 20:04:22.117] [warning]    Started Sushi Logger!
[2021-11-10 20:04:22.117] [warning] #############################
[2021-11-10 20:04:22.290] [info] [main] Setting up Xenomai RASPA frontend
[2021-11-10 20:04:22.297] [info] [jsonconfig] Setting engine sample rate to 48000.0
[2021-11-10 20:04:22.298] [info] [jsonconfig] Setting engine playing mode to stopped
[2021-11-10 20:04:22.298] [info] [jsonconfig] Setting engine tempo sync mode to internal
[2021-11-10 20:04:22.298] [debug] [engine] Succesfully registered processor main.
[2021-11-10 20:04:22.298] [info] [engine] Track main successfully added to engine
[2021-11-10 20:04:22.298] [debug] [jsonconfig] Successfully added track "main" to the engine
[2021-11-10 20:04:22.299] [debug] [engine] Succesfully registered processor transposer.
[2021-11-10 20:04:22.299] [debug] [jsonconfig] Successfully added Plugin "transposer" to Chain "main"
[2021-11-10 20:04:22.299] [debug] [jsonconfig] Successfully added Track main to the engine
[2021-11-10 20:04:22.299] [info] [jsonconfig] Successfully configured engine with tracks in JSON config file "/home/mind/config_files/config_play_through.json"
[2021-11-10 20:04:22.299] [info] [midi dispatcher] Connected MIDI port "0" to track ID "0"
[2021-11-10 20:04:22.299] [info] [midi dispatcher] Connected MIDI from track ID "0" to port "0" with channel 0
[2021-11-10 20:04:22.299] [info] [jsonconfig] Config file does not have CV/Gate definitions
[2021-11-10 20:04:22.299] [info] [jsonconfig] Config file does not have any Event definitions
[2021-11-10 20:04:22.301] [debug] [controller] get_tracks called
[2021-11-10 20:04:22.301] [debug] [controller] get_processor_parameters called with processor 0
[2021-11-10 20:04:22.301] [debug] [controller] get_processor_id called with processor main
[2021-11-10 20:04:22.301] [debug] [controller] get_parameter_id called with processor 0 and parameter gain
[2021-11-10 20:04:22.301] [info] [osc frontend] Added osc callback /parameter/main/gain
[2021-11-10 20:04:22.301] [debug] [controller] get_processor_id called with processor main
[2021-11-10 20:04:22.301] [debug] [controller] get_parameter_id called with processor 0 and parameter pan
[2021-11-10 20:04:22.301] [info] [osc frontend] Added osc callback /parameter/main/pan
[2021-11-10 20:04:22.301] [debug] [controller] get_track_processors called for track: 0
[2021-11-10 20:04:22.301] [debug] [controller] get_processor_parameters called with processor 1
[2021-11-10 20:04:22.305] [debug] [controller] get_processor_id called with processor transposer
[2021-11-10 20:04:22.305] [debug] [controller] get_parameter_id called with processor 1 and parameter transpose
[2021-11-10 20:04:22.305] [info] [osc frontend] Added osc callback /parameter/transposer/transpose
[2021-11-10 20:04:22.305] [debug] [controller] get_processor_id called with processor transposer
[2021-11-10 20:04:22.305] [info] [osc frontend] Added osc callback /bypass/transposer
[2021-11-10 20:04:22.305] [debug] [controller] get_processor_id called with processor main
[2021-11-10 20:04:22.305] [info] [osc frontend] Added osc callback /keyboard_event/main
[2021-11-10 20:04:22.305] [info] [jsonconfig] Config file does not have OSC mapping definitions
[2021-11-10 20:04:22.317] [info] [alsamidi] Created Alsa Midi port listen:in
[2021-11-10 20:04:22.318] [info] [alsamidi] Created Alsa Midi port read:out
[2021-11-10 20:04:22.397] [info] [main] Starting gRPC server with address: [::]:51051
[2021-11-10 20:05:43.898] [debug] [alsamidi] Received midi message: [90 30 70 0], port0, timestamp: 76337813
[2021-11-10 20:05:43.899] [debug] [midi dispatcher] Dispatching midi [90 30 70 0], timestamp: 77796889
[2021-11-10 20:05:44.030] [debug] [alsamidi] Received midi message: [80 30 0 0], port0, timestamp: 76469819
[2021-11-10 20:05:44.031] [debug] [midi dispatcher] Dispatching midi [80 30 0 0], timestamp: 77928556

4. Analysis. Only the first note on/off appears in the log, with max 1ms delay between Received and Dispatching. Therefore, the problem seems to be between Sushi Dispatching (43.899/44.031) and aconnect 128:1 129 (45.370/45.501).

I can share other relevant settings as you like, and maybe an example with midish could help comparing.

Note : Unplugging the HDMI screen improved the ability to connect via SSH. Unplugging the QWERTY keyboard did not improve anything.

Thank you again in advance !

1 Like
4

Thank you for investigating and getting the logs Teu. This issue popped up internally as well this week, so thanks for finding it. Our initial analys points towards there being something wrong in how Sushi sets the alsa timing for outgoing midi messages. Midi events should ideally be delayed just enough to compensate for audio interface and DAC latency, but somehows it schedules messages much later.

If you are able build Sushi yourself, we found a workaround by having the Alsa frontend send messages with no delay. Change line 237 of sushi/src/control_frontends/alsa_midi_frontend.cpp from:
snd_seq_real_time_t ev_time = _to_alsa_time(timestamp);
to
snd_seq_real_time_t ev_time = {0,0};

We’ll keep digging into it when we have time and will update you if we find anything.

1 Like