Optimize some hotspots

[christophsturm]

Don't build huge debug strings unless we have to.

[sqrrm]

utACK

... but would be better with braces for the log code blocks

[christophsturm]

I did it without braces because the log command is always just one statement, and its already very verbose. do you think i should change it?

[sqrrm]

I have seen a few bugs already due to code blocks without braces. Don't know if java or this project or why, but I now prefer them for all if statements for bisq.

[christophsturm]

ok. I'll change it.

[freimair]

need to check if the isDebugEnabled() call isn't done by log.debug("{}", a) anyways.

[freimair]

I have been in the believe that this is exactly what log.debug("{}", a) does before the string is assembled?

[chimp1984]

I think as well that the expression is only executed if log level matches. the static string does not has much cost

[freimair]

I would instead suggest:

Suggested change

	log.debug("<< Received networkEnvelope of type: {}", networkEnvelope.getClass().getSimpleName());

[christophsturm]

ok that will still do the networkEnvelope.getClass().getSimpleName() call but that's probably not expensive.

[chimp1984]

As far I understand it does it only at debug log level

[sqrrm]

It looks like it will have to do that call to getSimpleName() but not build the string at debug log level. I think that's an acceptable balance so I change my opinion and would go with what @freimair suggests.

[christophsturm]

i already changed it to his suggestion

[christophsturm]

@sqrrm @freimair pls review again

[chimp1984]

We should use the {} syntax instead of +

[christophsturm]

good point but it has no perfomance implications in that case. maybe + is even faster if we already checked for isDebugEnabled?

[chimp1984]

I think as well that the expression is only executed if log level matches. the static string does not has much cost

[chimp1984]

As far I understand it does it only at debug log level

[christophsturm]

@chimp1984 i think all your feedback is already implemented in later commits.

[sqrrm]

utACK

[freimair]

I just played around with numbers a bit and there came a surprising result. But please take these results with a pinch of salt (there might be some caching involved).

• log.isDebugEnabled() = false
• I placed a breakpoint in `Connection.java:763'
• used the [Evaluate]-Tool of IntelliJ to execute:

long start = System.nanoTime();
for(int i = 0; i < 1000; i++)
	log.debug("size=" + size + "object=" + Utilities.toTruncatedString(proto, 100));
System.err.println((System.nanoTime()-start)/1000);
start = System.nanoTime();
for(int i = 0; i < 1000; i++)
	log.debug("size={}; object={}", size, Utilities.toTruncatedString(proto, 100));
System.err.println((System.nanoTime()-start)/1000);
start = System.nanoTime();
for(int i = 0; i < 1000; i++)
   if (log.isDebugEnabled())
       log.debug("size={}; object={}", size, Utilities.toTruncatedString(proto, 100));
System.err.println((System.nanoTime()-start)/1000);

and

long start = System.nanoTime();
for(int i = 0; i < 1000; i++)
    log.debug("size=" + size);
System.err.println((System.nanoTime()-start)/1000);
start = System.nanoTime();
for(int i = 0; i < 1000; i++)
    log.debug("size={}", size);
System.err.println((System.nanoTime()-start)/1000);
start = System.nanoTime();
for(int i = 0; i < 1000; i++)
   if (log.isDebugEnabled())
       log.debug("size={}", size);
System.err.println((System.nanoTime()-start)/1000);

and

long start = System.nanoTime();
for(int i = 0; i < 1000; i++)
    log.debug("classname=" + this.getClass().getSimpleName());
System.err.println((System.nanoTime()-start)/1000);
start = System.nanoTime();
for(int i = 0; i < 1000; i++)
    log.debug("classname={}", this.getClass().getSimpleName());
System.err.println((System.nanoTime()-start)/1000);
start = System.nanoTime();
for(int i = 0; i < 1000; i++)
	if(log.isDebugEnabled())
    	log.debug("classname={}", this.getClass().getSimpleName());
System.err.println((System.nanoTime()-start)/1000);

• and here comes the somewhat surprising result:

What bothers me is that this kind of behavior would render any logging framework useless. Is there something I overlooked?

[sqrrm]

@freimair interesting, I guess Utilities.toTruncatedString is slow and it's worth the check to not run it.

[freimair]

of course. What bothers me is, to be more exact, is that there is no difference whether one uses "+" or "{}".

I recall that at least one logging framework implementation did show a massive performance improvement with using "{}" over "+" back in the days. Apparently not this one...

[sqrrm]

I think there would be a difference if you had more than one concatenated argument, I think it's worse than linear but can't remember where I saw that.

[freimair]

... being the idea of "{}" to only be assembled when the logging priority is actually enabled. In this case it looks like the string is concatenated either way.

[sqrrm]

I stepped through the log code in the debugger and I didn't see it concatenate it when not logging debug.

[christophsturm]

I think {} is for objects that have an expensive toString method. the parameters of the log call will always be evaluated, but the toString will only be called when the string is actually assembled.
btw in kotlin logging you can just do log.debug { "a"+ "b"} maybe theres a logging lib for java with a similar syntax.

[christophsturm]

if (log.isDebugEnabled()) log.debug("....") is very error prone when you start changing log levels and forget to do it in both places. I have seen it :))