Time to play is too long

[captaincurrie]

🔧 Feature request 🔧

Time-to-play needs to be instant for alda play to be useful in development

Description

I just installed alda 2.2.1, and i get delays like this

<time alda play -c "flute: o5 c8 < b16 a g f e d c2"
Playing...

real    0m2.491s
user    0m6.335s
sys 0m0.396s

Anyway to get this closer to 0?

[daveyarwood]

Hi @captaincurrie, I can provide some information here:

I agree that time-to-play needs to be as close as possible to 0 to be useful in development. The alda CLI itself (a Go program) is very fast in that regard, but the alda-player process (a Kotlin program with a built-in MIDI synthesizer and sequencer) is slower to start because it's running on the JVM.

To address the slow JVM start, I've set it up so that Alda does most of its work in the alda client (Go) and only the playback part in the alda-player process (Kotlin). alda-player processes are ephemeral and started automatically by the alda CLI as needed.

The important thing to note here is that the very first time you run any alda command (including alda, alda play, alda --help, etc.) after a long period of inactivity, it will take a few seconds before you hear anything because player processes are starting. But then after that, Alda has a pool of available player processes that it can use for all subsequent alda commands, so if you continue to run alda play commands after that, the playback is instantaneous. The player processes eventually shut themselves down after a period of inactivity where you haven't run alda in a while.

One thing you can do here if you really want to completely remove the slow "cold starts" is to set up a cron job to periodically run alda (with no arguments), say once every 10 minutes, just to ensure that there are always player processes available. The trade-off is that these processes are always running in the background and consuming memory, but depending on your needs, it might be worth it.

Personally, I tend to just run alda with no arguments whenever I know that I'm about to play something with Alda. That kicks off the spawning of player processes. Then, by the time I'm finished typing my real command, e.g. alda play -f some-score.alda, the playback is instantaneous.

I hope this helps. Let me know if you have any other questions/thoughts/ideas, as this subject is interesting to me!

[captaincurrie]

Thanks for the detailed reply and all your work on Alda over the years.

What you described does not seem to be taking place in my environment. I have alda isntalled from the AUR on ArchLinux, but that shouldn't matter.

I get the same play times on every invokation. For example,

> for x in $(seq 5); do time alda play -c 'piano: c e g'; done
Playing...

real    0m2.500s
user    0m6.103s
sys     0m0.536s
Playing...

real    0m3.680s
user    0m7.238s
sys     0m0.458s
Playing...

real    0m5.699s
user    0m7.647s
sys     0m0.525s
Playing...

real    0m7.640s
user    0m7.614s
sys 0m0.463s
Playing...

real    0m3.768s
user    0m7.114s
sys     0m0.559s

did i misunderstand something?

In fact the invokation times are increasing.

[daveyarwood]

When you run an alda play command, the CLI returns immediately after starting playback (i.e. sending messages to a player process, starting player processses if needed), and then the playback continues "in the background" in the player process. So if you run a tight loop like that, it's going to be sending the messages faster than player processes can be spawned, so there will be a lot of delays.

[captaincurrie]

I don't understand. Adding a 4 second sleep between invokation i still get big delays.

<for x in $(seq 5); do time alda play -c 'piano: c e g'; sleep 4; done
Playing...
6.100u 0.619s 2.689r     alda play -c piano: c e g
Playing...
6.040u 0.437s 2.551r     alda play -c piano: c e g
Playing...
6.829u 1.711s 5.060r     alda play -c piano: c e g
Playing...
7.024u 1.891s 5.444r     alda play -c piano: c e g
Playing...
7.202u 2.046s 6.851r     alda play -c piano: c e g

[daveyarwood]

Hmm, that's interesting. Out of curiosity, what is the output of alda version? And is there any difference if you increase the sleep, say to 10 seconds?

[captaincurrie]

No

<alda version
alda 2.2.1

<for x in $(seq 4); do time alda play -c 'piano: c e g'; sleep 10; done
Playing...
6.033u 0.376s 2.358r     alda play -c piano: c e g
Playing...
6.906u 0.450s 3.800r     alda play -c piano: c e g
Playing...
6.340u 0.347s 2.608r     alda play -c piano: c e g
Playing...
6.073u 0.353s 2.322r     alda play -c piano: c e g

[daveyarwood]

Ah, OK. I think I see the confusion. Playback is actually instantaneous, but it takes a couple seconds after that to spawn an additional player process for next time.

You can see a little more of what's going on if you run at a higher verbosity level, e.g. alda -v 2 play -c 'piano: c e g'

[daveyarwood]

There is an undocumented environment variable flag that you can set, ALDA_DISABLE_SPAWNING, that will disable the player spawning, and you can see that the alda play command completes in close to 0 seconds if you do that.

(Important note: I ran alda without arguments first and then ran alda ps until it showed at least one player process in the "ready" state.)

$ alda
alda: a text-based language for music composition

Website: https://alda.io
GitHub: https://github.com/alda-lang/alda
Slack: https://slack.alda.io

Usage:
  alda [command]

Available Commands:
  doctor      Run health checks to determine if Alda can run correctly
  export      Evaluate Alda source code and export to another format
  help        Help about any command
  instruments Display the list of available instruments
  parse       Display the result of parsing Alda source code
  play        Evaluate and play Alda source code
  ps          List background processes
  repl        Start an Alda REPL client/server
  shutdown    Shut down background processes
  stop        Stop playback
  telemetry   Enable or disable telemetry
  update      Update to the latest version of Alda
  version     Print Alda version information

Flags:
  -h, --help            help for alda
  -v, --verbosity int   verbosity level (0-3) (default 1)

Use "alda [command] --help" for more information about a command.
$ alda ps
id  port    state   expiry  type
$ alda ps
id  port    state   expiry  type
bbg 35721   starting    7 minutes from now  player
gla 36281   starting    8 minutes from now  player
urk 35081   starting    9 minutes from now  player
$ alda ps
id  port    state   expiry  type
bbg 35721   starting    7 minutes from now  player
gla 36281   starting    8 minutes from now  player
urk 35081   starting    9 minutes from now  player
$ alda ps
id  port    state   expiry  type
bbg 35721   ready   7 minutes from now  player
gla 36281   ready   8 minutes from now  player
urk 35081   ready   9 minutes from now  player
$ time ALDA_DISABLE_SPAWNING=yes alda -v 2 play -c 'piano: c e g'
Dec  8 21:48:06 INF parser/parser.go:1105 > Parsed input. filepath= took="62.997µs"
Dec  8 21:48:06 INF system/process_management.go:527 > Skipping filling the player pool. ALDA_DISABLE_SPAWNING=yes
Dec  8 21:48:06 INF cmd/play.go:222 > Constructed score. took="20.393µs" updates=4
Dec  8 21:48:06 INF cmd/play.go:284 > Sending messages to players. action=play players=[{"Expiry":1670554557382,"ID":"bbg","Port":35721,"State":"ready"}]
Dec  8 21:48:06 INF cmd/play.go:306 > Sent OSC messages to player. player={"Expiry":1670554557382,"ID":"bbg","Port":35721,"State":"ready"}
Playing...

real    0m0.178s
user    0m0.029s
sys 0m0.017s
$ alda ps
id  port    state   expiry  type
bbg 35721   active  7 minutes from now  player
gla 36281   ready   7 minutes from now  player
urk 35081   ready   8 minutes from now  player

But note that this will only work until you run out of player processes, because it isn't spawning new ones. If you wanted, you could get around that by having some kind of cron job, or even just a second terminal running a loop of the alda command with no arguments to ensure that the player process pool gets refilled.

[captaincurrie]

<time alda play -c 'piano: c e g'
Playing...
6.285u 0.420s 2.475r     alda play -c piano: c e g

<alda ps
id  port    state   expiry  type
csw 36321   active  8 minutes from now  player
irj 45613   active  6 minutes from now  player
oxr 37205   ready   4 minutes from now  player
uak 44045   ready   5 minutes from now  player
uqt 36399   starting    7 minutes from now  player

<export ALDA_DISABLE_SPAWNING=yes
<time alda play -c 'piano: c e g'
Playing...
2.076u 0.146s 1.500r     alda play -c piano: c e g

It does help, cuts the play time almost in half. But its still more then a second on my machine. 2017 Macbook Air.

You seem to get good times thou.

[daveyarwood]

The point I'd like to emphasize here is that you shouldn't be hearing the playback delayed, even though the command might take a few seconds to complete. There might be a delay while player processes are spawned, but that should be happening after playback starts.

[captaincurrie]

Playback, for me, is delayed until the command completes.

[daveyarwood]

Hmm, that doesn't track with my understanding of how the Alda CLI works.

Can you try it with -v 3 and see if it helps you understand where the delay is?

[captaincurrie]

>alda ps
id  port    state   expiry  type
fkf 39047   ready   8 minutes from now  player
irw 33813   ready   9 minutes from now  player
uxp 40249   ready   8 minutes from now  player

>alda play -v 3 -c 'piano: c e g'
Dec  9 09:43:20 DBG alda.io/client/cmd/telemetry.go:249 > Sending telemetry request. json="{\"arch\":\"amd64\",\"command\":\"play\",\"os\":\"linux\",\"version\":\"2.2.1\"}"
Dec  9 09:43:20 DBG alda.io/client/parser/scanner.go:284 > Adding token. token="[1:1] name | `piano` | <nil>"
Dec  9 09:43:20 DBG alda.io/client/parser/scanner.go:284 > Adding token. token="[1:6] colon | `:` | <nil>"
Dec  9 09:43:20 DBG alda.io/client/parser/scanner.go:284 > Adding token. token="[1:8] note letter | `c` | 99"
Dec  9 09:43:20 DBG alda.io/client/parser/scanner.go:284 > Adding token. token="[1:10] note letter | `e` | 101"
Dec  9 09:43:20 DBG alda.io/client/parser/scanner.go:284 > Adding token. token="[1:12] note letter | `g` | 103"
Dec  9 09:43:20 INF alda.io/client/parser/parser.go:1105 > Parsed input. filepath= took=1.779572ms
Dec  9 09:43:20 DBG alda.io/client/model/note.go:142 > Adding note. AudibleDuration=450 Duration=500 MidiNote=60 Offset=0
Dec  9 09:43:20 DBG alda.io/client/model/note.go:142 > Adding note. AudibleDuration=450 Duration=500 MidiNote=64 Offset=500
Dec  9 09:43:20 DBG alda.io/client/model/note.go:142 > Adding note. AudibleDuration=450 Duration=500 MidiNote=67 Offset=1000
Dec  9 09:43:20 INF alda.io/client/cmd/play.go:222 > Constructed score. took="396.903µs" updates=4
Dec  9 09:43:20 DBG alda.io/client/system/process_management.go:299 > Waiting for player to respond to ping. port=39047
Dec  9 09:43:21 DBG alda.io/client/system/process_management.go:299 > Waiting for player to respond to ping. port=39047
Dec  9 09:43:22 DBG alda.io/client/cmd/telemetry.go:269 > Telemetry sent. body="{\"message\":\"Telemetry recorded.\"}" status=201
Dec  9 09:43:22 INF alda.io/client/cmd/play.go:284 > Sending messages to players. action=play players=[{"Expiry":1670597505199,"ID":"fkf","Port":39047,"ReadError":null,"State":"ready"}]
Dec  9 09:43:22 DBG alda.io/client/transmitter/transmitter.go:58 > Applying transmission option to=
Dec  9 09:43:22 DBG alda.io/client/transmitter/transmitter.go:48 > Applying transmission option from=
Dec  9 09:43:22 DBG alda.io/client/transmitter/transmitter.go:109 > Applying transmission option oneOff=true
Dec  9 09:43:22 DBG alda.io/client/transmitter/osc.go:217 > Transmission options applied. ctx="&transmitter.TransmissionContext{from:\"\", to:\"\", fromIndex:0, toIndex:3, syncOffsets:map[*model.Part]float64(nil), oneOff:true, loadOnly:false}"
Dec  9 09:43:22 DBG alda.io/client/transmitter/osc.go:420 > Sending OSC bundle. bundle={"Bundles":null,"Messages":[{"Address":"/track/1/midi/patch","Arguments":[0,0]},{"Address":"/system/tempo","Arguments":[0,120]},{"Address":"/track/1/midi/volume","Arguments":[0,100]},{"Address":"/track/1/midi/panning","Arguments":[0,64]},{"Address":"/track/1/midi/note","Arguments":[0,60,500,450,69]},{"Address":"/track/1/midi/note","Arguments":[500,64,500,450,69]},{"Address":"/track/1/midi/note","Arguments":[1000,67,500,450,69]},{"Address":"/system/play","Arguments":null},{"Address":"/system/shutdown","Arguments":[11450]}],"Timetag":{"MinValue":1}}
Dec  9 09:43:23 DBG alda.io/client/system/process_management.go:497 > Spawning players. availablePlayers=2 desiredAvailablePlayers=3 playersToStart=1
Dec  9 09:43:23 INF alda.io/client/system/process_management.go:452 > Spawned player process.
Dec  9 09:43:23 INF alda.io/client/cmd/play.go:306 > Sent OSC messages to player. player={"Expiry":1670597505199,"ID":"fkf","Port":39047,"ReadError":null,"State":"ready"}
Playing...
Dec  9 09:43:23 DBG alda.io/client/cmd/root.go:53 > Waiting for background activity to complete. activity="clean up renamed executables"
Dec  9 09:43:23 DBG alda.io/client/cmd/root.go:53 > Waiting for background activity to complete. activity="send telemetry"
Dec  9 09:43:23 DBG alda.io/client/cmd/root.go:53 > Waiting for background activity to complete. activity="fill the player pool"

Nothing jumps out at me. Perhaps it could be a delay in whatever system is being used to play. Perhaps its because i use pipewire?

[daveyarwood]

It looks like the delay might be between these log messages:

Dec  9 09:43:20 DBG alda.io/client/system/process_management.go:299 > Waiting for player to respond to ping. port=39047
Dec  9 09:43:21 DBG alda.io/client/system/process_management.go:299 > Waiting for player to respond to ping. port=39047
Dec  9 09:43:22 INF alda.io/client/cmd/play.go:284 > Sending messages to players. action=play players=[{"Expiry":1670597505199,"ID":"fkf","Port":39047,"ReadError":null,"State":"ready"}]

Interestingly, it looks like it timed out waiting for the ping the first time (initiated :20) and it had to retry again (:21), before finally getting a ping response and proceeding to send the message (:22).

I'm not sure, off hand, why the player process wouldn't respond quickly to the ping message. I do see in the alda ps output above that that player process was already in the "ready" state, so I would expect it to respond quickly. :thinking:

Some kind of networking issue, maybe?

[captaincurrie]

Sounds like it. Don't know what else it could be. Must be on my end. I'll close the issue, let you know if anything comes up.