Time to play is too long
captaincurrie opened this issue · 15 comments
🔧 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?
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!
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.
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.
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
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?
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
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'
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.
<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.
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.
Playback, for me, is delayed until the command completes.
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?
>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?
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?
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.