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

Some actual data below. TL;DR: all same order of magnitude, not worth any effort to "fix" this IMO.

void report4() {
    String aStr = "hello"
    double d = 0.00009
    
    long first = now()
    for (int i=0; i<1000; i++) {
        logWithClosure { "${aStr + "world"} $i $d ${methodCall(i)}" }
    }
    
    long second = now()

    for (int j=0; j<1000; j++) {
        logWithString "${aStr + "world"} $j $d ${methodCall(j)}"
    }
    
    long third = now()
    
    for (int k=0; k<1000; k++) {
        logWithEither "${aStr + "world"} $k $d ${methodCall(k)}"
    }
    
    long fourth = now()

    for (int l=0; l<1000; l++) {
        logWithEither { "${aStr + "world"} $l $d ${methodCall(l)}" }
    }
    
    long fifth = now()

    log.trace "Closure method = ${second-first} ms / 1000 calls"
    log.trace "String method = ${third-second} ms / 1000 calls"
    log.trace "Object(String) method = ${fourth-third} ms / 1000 calls"
    log.trace "Object(Closure) method = ${fifth-fourth} ms / 1000 calls"
}

String methodCall(i) {
    return "next is ${i+1}"
}

void logWithClosure(Closure message) {
    if (debugEnable) log.debug "${device.displayName} ${message()}"
}

void logWithString(String message) {
    if (debugEnable) log.debug "${device.displayName} $message"
}

void logWithEither(Object message) {
    if (debugEnable) {
        String text = (message instanceof Closure) ? message() : message
        log.debug "${device.displayName} ${text}"
    }
}

6 Likes

Did you run all with debug enabled?
Could you run the same code disabling debug?

It was run with debugEnable false, on a C8-Pro.

I'm not going to run it with debugEnable true.

This from the guy who probably knows what the "straw" might be.

1 Like

You did not test where the if (debugEnabled) is before the logging function is even called. Although according to what was posted above it should be nearly the same result as the "closure" method.

This seems like a waste of everyone’s time at this point, but what do I know :man_shrugging:.

1 Like

Well that would be like testing the performance of an if statement on a boolean variable...

1 Like

This topic is ridiculous. Off to the lounge!!

7 Likes

Well, OP, I don't think your topic is ridiculous. I'm glad to learn from Bruce and @hubitrep 's test that your genuine concern probably doesn't have any meaningful impact on hub peformance, something that I myself have wondered at times about logDebug(msg). Thanks for prompting discussion on it in a way that helps me learn more about development for this hub.

5 Likes

Thanks. After all the discussion, in the end it is a simple matter (in my opinion).
Be it considerable or small impact, there is a better way to do it, that uses less resources, and that doesn't cost more to implement, and to change existing code is a matter of search and replace. But anyone is free to disagree.

1 Like

Answering a question I had above, it seems the compiler is smart enough to detect this at compile time. So, I don't really think it's worth worrying about. If you aren't using string interpolation, it will produce just a String anyway, and if you are ... well, presumably you did it for a reason. :slight_smile:

    def s1 = 'test'
    def s2 = "test"
    def s3 = "${s1}"
    [s1, s2, s3].each {
        log.trace getObjectClassName(it)
    }

Log output, newest to oldest (screenshot): GStringImpl, String, String

4 Likes

And, an obvious point (maybe?):

If you have a line of code that only runs rarely (relatively, anyway), the savings from manual optimization isn't likely to be detectable.

However, if you have a tight loop or some other such situation where it's running hundreds or thousands of times in short order, it may well be worth manually optimizing your code (and more than just debug logging).

Good information to ponder and keep in mind--but most critical to consider in those (likely more) limited situations. :slight_smile:

3 Likes