[ISSUE #4697] Use Fluent Logging API to provide accurate, concise, and elegant logging #4698
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change | ||||
|---|---|---|---|---|---|---|
|
|
@@ -25,7 +25,6 @@ | |||||
| import org.apache.eventmesh.common.protocol.tcp.Subscription; | ||||||
| import org.apache.eventmesh.common.protocol.tcp.UserAgent; | ||||||
| import org.apache.eventmesh.common.utils.JsonUtils; | ||||||
|
|
||||||
| import org.apache.commons.lang3.ArrayUtils; | ||||||
| import org.apache.commons.lang3.StringUtils; | ||||||
|
|
@@ -39,7 +38,6 @@ | |||||
| import io.netty.handler.codec.MessageToByteEncoder; | ||||||
| import io.netty.handler.codec.ReplayingDecoder; | ||||||
|
|
||||||
| import com.fasterxml.jackson.core.JsonProcessingException; | ||||||
| import com.google.common.base.Preconditions; | ||||||
|
|
||||||
|
|
@@ -161,7 +159,7 @@ private Header parseHeader(ByteBuf in, int headerLength) throws JsonProcessingEx | |||||
| } | ||||||
| final byte[] headerData = new byte[headerLength]; | ||||||
| in.readBytes(headerData); | ||||||
| log.atDebug().log("Decode headerJson={}", deserializeBytes(headerData)); | ||||||
|
||||||
| log.atDebug().log("Decode headerJson={}", deserializeBytes(headerData)); | |
| log.atDebug().addArgument(() -> deserializeBytes(headerData)).log("Decode headerJson={}"); |
Since the purpose of your PR is to prevent expensive computations of disabled log statement arguments, you should use a lambda here.
Member
Author
There was a problem hiding this comment.
True🤣I tested it with the code below, and the timer shows that only Supplier could avoid executing formatMsg(). However the Fluent API said that For disabled log levels, the returned LoggingEventBuilder instance does nothing. Why is that?
Test code, ran under debug level:
......
long traceStart = System.currentTimeMillis();
log.trace("log.trace(). formatMsg() return value: {}", formatMsg("log.trace()", "executed"));
long traceEnd = System.currentTimeMillis();
long atTraceStart = System.currentTimeMillis();
log.atTrace().log("log.atTrace().log(). formatMsg() return value: {}", formatMsg("log.atTrace().log()", "executed"));
long atTraceEnd = System.currentTimeMillis();
long atTraceSupplierStart = System.currentTimeMillis();
log.atTrace().addArgument(() -> formatMsg("log.atTrace() Supplier", "executed")).log("log.atTrace().addArgument().log()");
long atTraceSupplierEnd = System.currentTimeMillis();
log.info("log.trace() cost: {}ms, log.atTrace().log() cost: {}ms, log.atTrace() Supplier cost: {}ms",
traceEnd - traceStart, atTraceEnd - atTraceStart, atTraceSupplierEnd - atTraceSupplierStart);
}
private String formatMsg(String name, String status) {
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
return name + "-" + status;
}
Output:
log.trace() cost: 1009ms, log.atTrace().log() cost: 1002ms, log.atTrace() Supplier cost: 0ms
addArgument is really inconvenient; it is less convenient than using ifDebugEnabled.
Contributor
There was a problem hiding this comment.
True🤣I tested it with the code below, and the timer shows that only Supplier could avoid executing
formatMsg(). However the Fluent API said thatFor disabled log levels, the returned LoggingEventBuilder instance does nothing. Why is that?
This is due to the order in which Java evaluates methods: it always evaluates the arguments of a method before the method itself. In this concrete example:
log.atDebug().log("Decode headerJson={}", deserializeBytes(headerData));Java will:
- Call
Logger#atDebug()and obtain aNOPLoggingEventBuilder, - Call
deserializeBytesand obtain a string, - Call
NOPLoggingEventBuilder#logwhich does nothing.
The Scala language has call-by-name arguments that are evaluated only if they are used. In Java everything is call-by-value and the arguments are computed even if they are not used.
Outdated
Contributor
There was a problem hiding this comment.
Suggested change
| log.atDebug().log("Decode bodyJson={}", deserializeBytes(bodyData)); | |
| log.atDebug().addArgument(() -> deserializeBytes(bodyData)).log("Decode bodyJson={}"); |
Same as above.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
File renamed without changes.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Since
log.info()already supports determining log level internally, why not use a more conciselog.info()here?Why not use the solution provided by @ppkarwasz in the discussion to modify LogUtils? Isn't this change smaller?
log.info()内部已经支持判断日志级别，为什么这里不直接使用更简洁的log.info()？Uh oh!
There was an error while loading. Please reload this page.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
There are many places where the usage of
ifDebugEnabledis a remnant from the log4j era, which can be replaced withlog.debug()from slf4j. However, in many cases, removing theifDebugEnableddirectly would result in a performance decrease.有不少地方的
ifDebugEnabled是log4j时代残留的用法，可以用slf4j的log.debug()代替。不过也有很多地方，直接去掉ifDebugEnabled的话，是会降低性能的。That requires obtaining the Fully Qualified Class Name (FQCN) of each class and passing it as a parameter to LogUtils, which is not a good approach for us.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
To be precise it is a remnant of the Log4j 1.x/JCL era. Since the release of SLF4J in 2005 these guards are not necessary. The Log4j 2.x API (2014) works the same way as SLF4J.
Probably my explanations were not clear. The FQCN to use is that of the
LogUtilsclass, i.e. "org.apache.eventmesh.common.utils.LogUtils". The logging backend will look into the stack for the class that calledLogUtils.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Regarding "better performance", the code here does not have the same situation as the example you provided.
Could you provide some examples to illustrate the performance decrease after removing the
ifDebugEnabledyou mentioned here?Also, I don't quite understand what you mean by "removing the
ifDebugEnabled". What is the relationship between log.debug() internal supporting for determining log level and "removing theifDebugEnabled"?The fact seems to be different.
关于“性能更好”，这里的代码不存在您所举例的情况。
能否列举一些情况说明一下您这句所说的性能降低的情况？
另外，我不太明白您说的“removing the
ifDebugEnabled”。log.debug()内部已经支持判断日志级别，这和“removing theifDebugEnabled”有什么关系？好像并非如此。
Uh oh!
There was an error while loading. Please reload this page.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@pandaapo
From:
To:
Even if the log level is set to "info", the latter will still invoke and execute toJSONString, whereas the former will not.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@Pil0tXia
So, you were referring to the situation you initially gave as an example, rather than the case of this line of reviewed code.
原来也是指最开始您所举例的情形，而非这行被review代码的情形。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
这里的性能会更好，应该还是部分特殊的情况（适用于能够懒加载的情况），既然LogUtils能解决日志代码行显示的问题，我觉得也可以采用LogUtils统一封装一下，这样在编码风格上也能有一定的统一。