Tips for reducing slow execution and lag time?

[davidt]

I have used Keyboard Maestro to create a faux operating system that runs on my mum's TV. Using a Stream Deck, she can now watch films, play music, make phone calls, by pressing one of the 10 buttons on the SD. I've got it working pretty well, but there's a lag (almost 2 seconds) on all the actions and I want to figure out how to make the code more efficient. I'm on an M1 32GB, the delay is around 2seconds.

Screenshot

I've looked in the forum and am finding mixed results that I'm not sure apply to my case. I'm wondering if you guys could help with some consolidated tips on how to optimize my workflow?

Amount of Macros

• There are around 10 "top level" macros that get called by the Stream Deck.
• Under the hood there's an additional 50 macros that get called in the background.
• I can't say for sure but I think the nesting of macros calling other macros might go 5-7 levels deep at times.
• Despite this, my Keyboard Maestro Macros.plist is only 300kb

BACKGROUND
Reason for all this over-complexity is to make the front-end feel like a TV experience as possible, meaning everything happens fullscreen, never shows the OS interface, jumps between opening videos in VLC, music in Spotify, Facetime calls, webpages in Chrome.
Consider this is for someone with Dementia, so in between each "scene change" I have assistive full-screen messaging and voice feedback.
Lastly, it's entirely controllable with the Stream Deck, no mouse or keyboard needed.

That's a bit to explain why I've ended up with a total of 62 macros instead of simply 10.

Some optimising I've done already:
For example I have around 5 txt files being written/read by bash/applescripts (things like generating a list of all files in the Films folder). In the early days I started out by reading/writing these text files each time a macro was called, but have since optimised it by putting a great part of that functionality into scheduled macros that get called once a day, leaving a skinnier portion of the code to be executed each time "Play a random Film" gets called. This improved execution time. Now I'm wondering what else I could look into.

Bash + Applescripts
I have several Bash and Applescripts.
Some of are checking app statuses, like tell application "Spotify" if player state is playing then return "playing" else return "not playing" end if end tell which I believe adds time. I've disabled some of these and replaced them with an annoyingly complex system of manually-created variables that I got the system to manage. However this has increased the amount of IF statements and calculations needed.

• How does KM's native IF statements compare with checking app statuses via applescript?

DEBUG SUBROUTINE
I also have Debug subroutine that gets called pretty much from every single macro, multiple times, appending new lines to a log file. Inside it is this bash script:

Debug BASH

#!/bin/bash
# Config
LOG_DIR="$KMVAR_Config_HomePath/Engine/KM"
LOG_FILE="$LOG_DIR/debug.log"
MAX_SIZE=1048576  # 1MB in bytes
BACKUP_COUNT=50    # Number of old logs to keep
short_user="${KMVAR_Config_User:0:1}"
Debug_ExecutingMacro=$KMVAR_Debug_ExecutingMacro

# Function to rotate logs
rotate_log() {
    # Shift old logs
    for i in $(seq $((BACKUP_COUNT-1)) -1 0); do
        if [ -f "${LOG_FILE}.$i" ]; then
            mv "${LOG_FILE}.$i" "${LOG_FILE}.$((i+1))"
        fi
    done
    # Move current log to .0
    mv "$LOG_FILE" "${LOG_FILE}.0"
    touch "$LOG_FILE"
}

# Check file size and rotate if needed
if [ -f "$LOG_FILE" ]; then
    size=$(stat -f%z "$LOG_FILE")
    if [ $size -gt $MAX_SIZE ]; then
        rotate_log
    fi
fi

# previous time:
debug_timestampLast="${KMVAR_debug_timestampLast:-0}"

# current time:
debug_timestampString="$(/usr/local/opt/coreutils/libexec/gnubin/date '+%y/%m/%d %H:%M:%S.%3N')"
debug_timestamp="$(/usr/local/opt/coreutils/libexec/gnubin/date '+%s.%3N')"

# calc time passed (with check for first run)
if [ -z "$debug_timestampLast" ]; then
    time_diff="0.000"
else
    time_diff=$(echo "$debug_timestamp - $debug_timestampLast" | bc)
fi

# Update the debug_timestampLast variable
osascript <<EOF
tell application "Keyboard Maestro Engine"
    setvariable "debug_timestampLast" to "$debug_timestamp"
end tell
EOF

# Append new log entry (using standard ASCII characters)
echo "__________
[$short_user],	$debug_timestampString,	delay: $time_diff,	[$Debug_ExecutingMacro],
$KMVAR_mylocal_txt
" >> "$LOG_FILE"

I tried disabling this macro (by adding a Return action at the top, because actually disabling it didn't prevent it from being executed) and it sped up performance by quite a bit. However I'd like to keep it for debugging purposes. Is there anything in there that is particularly memory-intensive? Timestamps? Formatting?
Any tips on how to store logs for debugging purposes without cramming the memory? I find them super hard to read, hence the additional formatting and variables.

(To be honest, in writing this part of this post, I just figured out that this Debugger is indeed the biggest culprit in my workflow. I'll keep the rest of the post as is, just because I'd still like to understand)

Some other questions that come to mind

• Is reading/writing to internal variables more efficient than text files?
• I have an additional 15 text and log files being written (no reading) for logging purposes by various bash/applescripts. Is appending single lines to a text file a memory-chugger or is it minimal?
• Disabled actions inside an active Macro: do they add to memory?
• Does having [2 Macros calling 1 Subroutine with a bash script] weigh more than [2 Macros each with its own copy of the same identical bash script]?

Any other tips, or links that I should read, feel free!

Many thanks

[griffman]

@davidt

Any tips on how to store logs for debugging purposes without cramming the memory? I find them super hard to read, hence the additional formatting and variables.

Just one thought on the debug logs: You have log rotation and log writing in the same script. I would think it'd be a lot more efficient to move the rotation code to another macro, and just put that macro on a periodic timer (2x a day or whatever). That'd move 50% of your debug code into something that doesn't have to run multiple times per macro call, leaving just the time calc and log writing.

I have no idea if it'd actually help, but it sure seems like it should.

-rob.

[davidt]

Actually yes that's a good idea, thank you I'll try that.

[kevinb]

That sounds like an admirably ambitious and worthwhile project!

I could offer tentative answers about some of your interesting theoretical questions but instead I should just let those who can respond authoritatively do so. I think it's safe to say that optimisation outside the key area that you identified would provide only marginal improvements (despite, for instance, how slow Applescript is known to be).

[peternlewis]

Step one when resolving any issue of performance is to instrument it so that you can see where the delay is happening.

Use the SECONDS function to get a fractional number of seconds which will allow you to log specific times.

Try to eliminate the possibility that the lag is happening between the pressing of the button and the starting of the macro - a lot happens from Steam Deck button press to macro start, and while it should be virtually instantaneous, there is a lot going on that might have issues.

That said, the screen shot you show shows a Global Macro Palette trigger, so it is not immediately clear to me how the macros are triggered.

Anyway, once you can eliminate that as the source of the delays, then you can use the Log action and the SECONDS function (via the Calculate token) to log specific times. Create two of them in a row to verify that the actions are executing at roughly 0.001 seconds.

2024-12-31 10:45:35 Log: A 345110.841118
2024-12-31 10:45:35 Log: B 345110.841955

At that point you can be confident that the Log action itself, and the interaction delay, are not issues.

Then find what is.

[davidt]

@peternlewis

Try to eliminate the possibility that the lag is happening between the pressing of the button and the starting of the macro - a lot happens from Steam Deck button press to macro start, and while it should be virtually instantaneous, there is a lot going on that might have issues.

That said, the screen shot you show shows a Global Macro Palette trigger, so it is not immediately clear to me how the macros are triggered.

Yes exactly, I set up the global macro palette specifically to eliminate the Stream Deck from the suspects' list. I was surprised there was very little difference in lag time!

@peternlewis

Create two of them in a wrote to verify that the actions are executing at roughly 0.001 seconds.

Ah that's a good tip, hadn't thought of doing it so explicitly.
What I do have however is multiple calls to the Debug() subroutine within the same Macro, for example 1 before the IF statement, and 1 after. But to your point I should probably not use the Debug() routine just to calculate time elapsed, and instead just call the........... oh hang on..........

@peternlewis

image756×156 19.6 KB

I didn't know about log as an action! lol That's the whole reason i created my own Debug logging subroutine. I thought I was limited to Alert and Display Text this whole time.
OK this might really help, thank you.

EDIT: looking into it further and testing it out, it seems writing to an external file is still more efficient than using the KM's default log. Still, it's what i should use for quick time calculations like this.

[peternlewis]

@davidt

EDIT: looking into it further and testing it out, it seems writing to an external file is still more efficient than using the KM's default log. Still, it's what i should use for quick time calculations like this.

Log is fine for short amounts of text, but like all actions it executes at about 1000 actions/s, and the log itself has buffering to allow it to avoid reporting multiple identical log commands, so there will be a lag on that (but the SECONDS function will record the time accurately regardless of when it shows up in the log file).

[Nige_S]

@davidt

How does KM's native IF statements compare with checking app statuses via applescript?

The If statements in both will be practically instantaneous. It does take time to initiate an AS environment to perform the AS in, but that's only 10s of milliseconds (~70ms on my old Intel iMac).

But those 10s can add up, so you want to avoid repeated AS actions -- don't do:

...when you can do:

The same goes for any shell/Python/etc scripts. So yes, your debug subroutine is costing you time on every invocation (those file system checks for log rotation aren't helping, either).

But the main determinant on how long an AS takes to run is how long it takes for the apps you are targeting to return a result for each command in your script. Sometimes those results take time because what seems trivial is actually a lot of work, other times because the framework itself is (relatively) slow, eg System Events.

Other points in brief:

• Is reading/writing to internal variables more efficient than text files?

Much more efficient!

I have an additional 15 text and log files being written (no reading) for logging purposes by various bash/applescripts. Is appending single lines to a text file a memory-chugger or is it minimal?

Memory isn't the issue -- it's the CPU time required to instantiate those script environments (I/O time will be negligible too if all you are doing is writing and you aren't including all those unnecessary "rotation" checks every call).

Ditch all those external calls, use the native "Append Text to a File" action instead.

@davidt

Disabled actions inside an active Macro: do they add to memory?

Again, memory isn't the issue. And while disabled actions still "cost" -- those parts of the plist are still read in and evaluated when the macro instantiates a new instance -- that cost will be negligible compared to everything else going on.

Does having [2 Macros calling 1 Subroutine with a bash script] weigh more than [2 Macros each with its own copy of the same identical bash script]?

You're shuffling deckchairs at this point (and it'll depend on whether that sub is always or rarely called, what parameters are being passed, etc). From an ongoing maintenance perspective it'll be better to go the subroutine route. But for execution speed, better to do away with the bash script entirely if you can!

Any other tips, or links that I should read, feel free!

Simplify and combine. Every KM action takes at least 1ms so delete, or avoid execution by branching, actions you don't need and do multiple operations in a single action where possible -- better to combine multiple text tokens in a single "Append to File" action then to do multiple "Append"s.

Don't shell out if you can do something with simple KM actions -- but be aware of when using the shell will be faster. Appending a line to a log -- use a KM action. Getting a directory listing for a prompt -- the shell is faster than a "For Each: Append to list" over a folder contents Collection.

Metrics. You won't know where to concentrate your efforts if you don't have numbers! This:

...takes less than 1/10th of a second to list 600 files for me. Better, IMO, to concentrate optimisation efforts elsewhere...

Feel (going directly against the above ). If it feels slow it is slow, regardless of the metrics. Start optimising those parts of the workflow -- and don't dismiss a simple "Progress" dialog, things feel faster when there's an indicator to show that something is happening.

One thing you haven't mentioned is how you are triggering your macros from your SD buttons. It would be worth checking that the delay isn't there -- a simple button-triggered "Beep" macro would be enough.

[kevinb]

@Nige_S

The If statements in both will be practically instantaneous.

I have previously^[1] noted that switch seemed to be much faster than if. It might be worth seeing if^[2] that claim holds up within the context of this macro, @davidt.

Also... I wonder whether it might be worthwhile trying compiled Applescripts.

---

1. How to toggle 2 actions (not simple menu items)? - #4 by kevinb ↩︎

2. / switch ↩︎

[Nige_S]

@kevinb

I have previously[1] noted that switch seemed to be much faster than if.

In KM, a "Switch/Case" should be faster than nested "If"s -- one action vs many and a macro only executes (at most) one action per millisecond.

For me, 1,000 repeats of a 5-Case Switch that always matches the last Case takes ~3 seconds. The equivalent nested If takes ~12s. Matching on the first case/if takes ~2s or ~3s respectively.

So while there is a difference between the two you'll need to be doing a lot of branching for your choice to make much impact. I'd worry more about nested "If"s counting towards the maximum number of concurrently executing macros.

@kevinb

Also... I wonder whether it might be worthwhile trying compiled Applescripts.

Pre-compiling apparently makes little difference. You still have to instantiate the environment they'll run in, so if there is a difference it'll only become noticeable with the longer scripts.

[kevinb]

@Nige_S

Pre-compiling apparently makes little difference. You still have to instantiate the environment they'll run in, so if there is a difference it'll only become noticeable with the longer scripts.

Yet in the topic "Does a pre-compiled AppleScript run faster?", there is this:

@noisneil

As I understand it, improvements in speed may be most noticeable for shorter scripts, as most of the lag is in the initialization.

I really don't know and was just thinking back to "saving as an app" within Script Editor.

[kevinb]

@Nige_S

For me, 1,000 repeats of a 5-Case Switch that always matches the last Case takes ~3 seconds. The equivalent nested If takes ~12s. Matching on the first case/if takes ~2s or ~3s respectively.

My bare-bones tests just now, matching on the first (and only) condition, indicate that switch / case takes about 3/4 of the time that if does, but if that's the case^[1], I can't imagine the difference being significant in practice unless it's another situation in which the concern may be that actions are too fast rather than too slow.

---

1. or in case that's the if ↩︎

[Nige_S]

@kevinb

My bare-bones tests just now, matching on the first (and only) condition, indicate that switch / case takes about 3/4 of the time that if does

At the risk of labouring the point...

At best, an executing instance will execute 1 action per millisecond (many actions will take longer, of course).

This takes 3ms

...so is three actions per loop:

evaluate repeat
evaluate switch
set variable
evaluate repeat
evaluate switch
set variable
...

It makes little difference how many cases there are, nor how far down the list of cases the match is.

This takes 4ms

...so is four actions per loop, and I'm assuming it goes:

evaluate repeat
evaluate if
execute "execute the following actions"
set variable
evaluate repeat
evaluate if
execute "execute the following actions"
set variable

...and it doesn't matter if it evaluates the "execute..." or "otherwise..." branch.

But this, where Local_test is set to 1 and so the 5th nested "If" is true:

...takes 12ms -- 12 actions per loop! And if we go through them:

evaluate repeat
evaluate 1st nested if
execute "otherwise..."
   evaluate 2nd nested if
   execute "otherwise..."
      evaluate 3rd nested if
      execute "otherwise..."
         evaluate 4th nested if
         execute "otherwise..."
            evaluate 5th nested if
            execute "execute..."
            set variable
evaluate repeat
evaluate 1st nested if
etc...

Count the lines and, from evaluate repeat to set variable there are indeed 12 actions.

For nested "If"s it does matter how quickly true is reached -- make the above so the first "If" is true and we're back to 4ms since the nested "If"s are never executed.

Takeaways...

1. If you can use Switch/Case, do so. It's faster for even a single decision
2. If you use nested "If"s, try to arrange your logic so the most frequently encountered trues are checked early in the sequence
3. Ignore the above whenever it makes sense to do so -- in particular, don't try to jam a round mental model of your macro into a square "optimal" hole. In most real world macros these tweaks will make little difference and you'll waste far more time trying to make sense of what you've done when you next come to edit the macro!

While thinking about all the above is fun and could be useful in edge cases, there's usually bigger fish to fry first when optimising.

[Nige_S]

@kevinb

Yet in the topic "Does a pre-compiled AppleScript run faster?", there is this:

@noisneil

As I understand it, improvements in speed may be most noticeable for shorter scripts, as most of the lag is in the initialization.

As I understand it, there's two parts to this:

1. Initialisation of the AS environment
2. Compilation of the script that is then run in that environment

Initialisation of the environment should be relatively constant, and is out of our control. Compilation time will vary depending on the size of the script, and the proportion of the KM action's execution time that is spent on compilation will also depend on how long the AS takes to execute.

IMO (and I haven't tested properly), for the vast majority of scripts the time saved by pre-compiling will be negligible compared to the total execution time of the action -- and is often negated by the extra time you have to spend in the first place and when editing later.

But @noisneil looked into this a lot more, and might chime in later.

[kevinb]

Our findings and conclusions are in agreement, then.

The often overlooked switch should always be considered when ifs start to accumulate in one place. The most obvious benefit is increased readability.

[noisneil]

FWIW...

On my old i9, I noticed some slight speed advantages when using pre-compiled scripts, particularly for UI interaction, which, for some tasks in Logic Pro, made a big enough difference to me to warrant their use.

However, since upgrading to an M4 Max, I can't perceive any added latency, so I've completely stopped using them and gone back to text scripts.