[OPINION] Almost all community drivers and apps don't implement logs properly, wasting hub's CPU and Memory

đź’¬ Lounge
, ,
1

Built-in drivers and apps might have the same problem. Since their code is not open, only staff could confirm, @mike.maxwell @gopher.ny @bobbyD

This is how drivers and apps are normally implementing logging

logDebug "current state.deviceProfile=${state.deviceProfile}, settings.forcedProfile=${settings?.forcedProfile}, getProfileKey()=${getProfileKey(settings?.forcedProfile)}"

void logDebug(String msg) {
    if (settings?.logEnable) {
        log.debug "${device.displayName} ${msg}"
    }
}

This might look ok at a first glance, but there is a performance penalty with this approach.

When logDebug is invoked with the dynamic String parameter, there are several CPU costly operations required to create the final String, that will be then passed onto the method as a calculated static string (new object).

String concatenation per se is already a relatively costly operation for CPU and memory.
In the example above, there are multiple interpolation operations, some requiring calls to other methods that will calculate the concatenation values. Method invocation is also a CPU costly operation, not to mention what they do inside them.

EDIT: Besides the initial CPU usage, a string with 4 interpolations like the one above, results in 5 new String objects allocated in memory, those will later require some more CPU work from the Garbage Collector to be cleaned.

What are all these CPU cycles and memory used for?
Most of the time: NOTHING!

Since the debug will be disabled, the process/thread won't get inside the if statement!
So all the calculations and interpolations will create a final string that most of the times IS NOT USED AT ALL.

This might sound unimportant, but we must remember that the hub's CPU is not as powerful as a PC or Smartphone. Even if it was, we'd still be wasting some of it's power for nothing!
Also when you have hundreds of devices and apps, this adds up and might become a relevant performance penalty.

So, how would it be the proper way to implement logs then?

I do it this way, if you know another, please share!

Add an if statement before each log method invocation, at least for debug and trace (if available). Info, warning and error would normally be logged anyway and don't even have a toggle, so they don't need the if.

if (logEnable) logDebug "${costly.operation.here}"

EDIT: @JustinL proposed some interesting alternatives below, closures seem to be the sweet spot. No if statement needed, and the message is only interpolated when it will actually be used.

BTW, I'm talking about logs here, but of course, this is a programming best practice that can be applied anywhere were there is a similar mechanism.

Also, there is another problem that affects logging and most of the times all strings in a driver/app: The indiscriminate use of double quotes!

EDIT: There is no need for this, as @bertabcd1234 tested, the compiler does that optimization already.

In Groovy, single-quoted strings are treated as static strings and do not support variable interpolation, making them slightly more efficient for simple strings without variables. Using single quotes can help avoid unnecessary parsing overhead associated with double-quoted strings, which do allow for interpolation and escape sequences.

So, double quotes should be used only where necessary, do not double quote static strings.

1 Like
2

Most hub code does things the way you suggest, though certain apps do their own thing. The examples in the HubitatPublic repo are representative, generally.

I'd also wager the compiler can convert double quoted strings to String and not GString at compile time if there is no interpolation involved (seems this would be apparent if the value is a string literal), though I don't know the inner workings and can't really imagine this adding up to anything in actual apps or drivers even if it's a GString.

What changes to your hub CPU statistics (e.g., /hub/advanced/cpu5min) have you noticed since modifying your code?

3

It just seems to me that as far as code repetition goes, that if (logEnable) line is going to be repeated all throughout the code for every log sent.

That would normally be a case where you would want to put all those repeated IFs into the single method as good practice for reusing code.

I do see your point, you can save a method call and passing a string every time when logging is turned off, but since it is actually passing a reference to the string, is it really that costly?

"Passing a String to a method in Groovy, as with other object types, involves passing the reference to the String object, not a copy of the entire String content. This means the cost is generally minimal and not a significant performance concern in most applications."

Edit: I guess you also save creating the string at all, and many log statements do use interpolation to build a string instead of using a string literal, so there is that.

Edit2: I do have some custom apps and drivers that are still heavy on debug statements, so I think I will heed your advice.

Find and Replace all can be a pretty quick fix for the code:

Find: logDebug("
Replace: if (settings?.debugMode) logDebug("

2 Likes
4

The use of methods does open up the option for using library code to handle this including the definition of the preference settings. That doesn't consider performance, just a reason I like the approach.

5

It's sort of a strong claim that logging is "hurting the hub's CPU". We've been at this for quite some time, and have not seen any evidence of this. What is your evidence?

2 Likes
6

It is only a reference to the string if it is a static string (single quoted), if it is a dynamic string, it has to be calculated for each call, since it could be different every time. In the latter case, the parameter value is calculated prior to the method call, and the resulting string (new object) is passed to the method.

A simple example

printNumber(4 + 7)

void printNumber(num) {
    if (logEnabled) {
        print("Number is: ${num}" )
    }
}

The sum will be executed and a new space in memory will be allocated to store the result (11) regardless of what happens inside the method call.

7

It is hard to measure, isn't it?
Regardless of the actual impact, creating lots strings using concatenations, sometimes involving method calls or calculations, to end up not using the result for anything, certainly is not helping to save CPU cycles.

8

This is mostly all well above my head as a non-programmer.

But I’m also curious how the OP determined that “almost all” community developed code suffers from this purported flaw, as the title of this thread claims.

There’s a lot of apps and drivers out there and I wonder how many the OP personally reviewed before determining that it could impact “almost all” of them.

9

Correct. But a claim without evidence doesn't hold much water... Nice theory, code hygiene is always a good thing, but poor code is not necessarily code that is "hurting the hub's CPU" to any meaningful extent.

4 Likes
10

At least we agree on something :slight_smile:

I forgot to mention in my initial post that there is another avoidable cost with the proposed best practice.

When a dynamic string with 5 arguments is resolved, apart from the calculations and CPU cycles to create it, 6 string objects are allocated in memory. After use (or not!) those will still have to be cleaned up by the garbage collector at some point.

11

Guilty as charged and comically unrepentant. Sure, I could optimize every log line like it’s a microcontroller’s last breath, but as someone who’s written in C/C++, I’ve already made peace with far worse sins: interpreted languages, garbage collection, and people who think YAML is a good idea.

If my logs burn a few extra CPU cycles on a box running 200MHz slower than my watch, so be it, my time’s worth more than the hub’s.

7 Likes
12

As for me, I don't like to waste any resource unnecessarily.
I think that putting an if statement before each logDebug call wouldn't add too much to the total time of driver/app code writing.
You do it once, it runs millions of times, what is not worth about it?

13

I just looked through most of the custom code I have from the community, and OP is right, I cannot find an example of it NOT being done the way it is described yet. That leads me to also believe that most code calls the debug method this way, just from random samples I have looked at.

It certainly has an impact to constantly create string objects that are never used, and then just left behind to be cleaned up by garbage collector. How much of an impact this actually has is the question....

2 Likes
14

A question of how many angels can dance on the head of a pin. Good luck!

3 Likes
15

I think of it more like the paradox of the heap. What is the next piece of added functionality/complexity that causes the need for a higher-powered hub? Note I am all for more functionality and another hub.

16

Thank you for clarifying that. I’m sure it’s possible or even likely it’s a widespread practice.

Nonetheless it does seem like the OP is making rather strong claims about both the severity of the impact as well as how widespread it is, without any data to back up such claims.

ETA: just to be clear, I’m not equating an absence of evidence as evidence of absence. It’s just that it’s on the person making the claim to provide evidence for it if they expect anyone else to believe them.

17

I'd bet $ that it isn't logging...

6 Likes
18

I understand you would like everyone to please follow this theoretically-valid practice with additional friction and no visible benefit

The second law of thermodynamics: sorry, no can do.

19

I used to write code in your approved fashion.

Over time, my coding 'got infected' by other's styles. This became significant as I became the maintainer of rather large Apps written by others: HubConnect and Hubitat Package Manager.

HubConnect uses your approved method, HPM does not. My latest App ( Sprinkler Schedule Manager) is using the "standard style". It looks better, that's all I have... that it's visually appealing to reduce the code from ~18 chars to ~7. It allows my eyes to treat "IF" as code logic, the stuff I read. My eyes can skip over "logDebug" so much easier.

2 Likes
20

Guilty as charged.

ChatGPT's take for thought....

Yes, you’re exactly right — Option 1 favors readability and developer convenience, while Option 2 avoids unnecessary work when logging is disabled, especially if constructing the log message involves costly operations (like method calls or string interpolations).

:white_check_mark: Option 3: Lazy Evaluation with Closure

You can strike a better balance using closures (lambdas) for lazy evaluation:

void logDebug(Closure msg) {
    if (logEnable) {
        log.debug "${device.displayName} ${msg()}"
    }
}

Then you call it like this:

logDebug { "current state.deviceProfile=${state.deviceProfile}, settings.forcedProfile=${settings?.forcedProfile}, getProfileKey()=${getProfileKey(settings?.forcedProfile)}" }

:white_check_mark: Benefits of Option 3

  • Performance: The string interpolation and method calls in the closure are only evaluated if logEnable is true.
  • Developer-friendly: It preserves the readability of Option 1, without needing to wrap every log call in a conditional.
  • No performance hit: Behaves like Option 2 when logging is off, because the closure isn’t invoked.

:white_check_mark: Optional Variant: Support Both String and Closure

You can even make logDebug more flexible by supporting both a String and a Closure:

void logDebug(Object msg) {
    if (logEnable) {
        def text = (msg instanceof Closure) ? msg() : msg
        log.debug "${device.displayName} ${text}"
    }
}

Then you can call it either way:

logDebug "This is a simple message"
logDebug { "Complex message with ${expensiveCall()}" }

This is a clean, idiomatic Groovy solution with minimal trade-offs.

4 Likes