Time to play is too long about alda

[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. 🤔

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.