-
Notifications
You must be signed in to change notification settings - Fork 641
[ISSUE #4697] Use Fluent Logging API to provide accurate, concise, and elegant logging #4698
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Conversation
3f16894 to
19d129d
Compare
987e33b to
9f1e5d3
Compare
ppkarwasz
left a comment
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.
Due to the order of evaluation of Java method arguments, in both the following statements the deserializeBytes method will be called even if DEBUG is disabled:
| final byte[] headerData = new byte[headerLength]; | ||
| in.readBytes(headerData); | ||
| LogUtils.debug(log, "Decode headerJson={}", deserializeBytes(headerData)); | ||
| log.atDebug().log("Decode headerJson={}", deserializeBytes(headerData)); |
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.
| 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.
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.
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.
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.
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.
| final byte[] bodyData = new byte[bodyLength]; | ||
| in.readBytes(bodyData); | ||
| LogUtils.debug(log, "Decode bodyJson={}", deserializeBytes(bodyData)); | ||
| log.atDebug().log("Decode bodyJson={}", deserializeBytes(bodyData)); |
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.
| log.atDebug().log("Decode bodyJson={}", deserializeBytes(bodyData)); | |
| log.atDebug().addArgument(() -> deserializeBytes(bodyData)).log("Decode bodyJson={}"); |
Same as above.
| } | ||
|
|
||
| LogUtils.info(log, "[WatchFileManager] start close"); | ||
| log.atInfo().log("[WatchFileManager] start close"); |
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?
private static final String FQCN = LogUtils.class.getName():
public static void trace(Logger logger, Marker marker, String msg, Object arg) {
final LoggingEventBuilder builder = logger.atTrace();
if (builder instanceof CallerBoundaryAware) {
((CallerBoundaryAware) builder).setCallerBoundary(FQCN);
}
builder.addMarker(marker).log(msg, arg);
}
- 既然
log.info()内部已经支持判断日志级别,为什么这里不直接使用更简洁的log.info()? - 为什么不采用讨论中 ppkarwasz 提供的这种方案修改下LogUtils,这样改动不是更小吗?
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.
- Better performance:
The additional
isDebugEnabled()check beforelog.debug()is performed in order to avoid invoking the methods referenced in themessagefield, thus improving logging performance. For example:log.debug("formatted msg: {}", formatMsg(rawMsg));Even when the log level is set to
info, theformatMsg(rawMsg)method will still be called and return a result before being passed as an argument tolog.debug(). This takes time.
- Scenarios where Fluent Logging API is unnecessary:
Only the scenario mentioned in the Background Knowledge section require the use of Fluent Logging API. For example, in the case of the changes in
Codecclass L224, where no object parameters are passed or existing objects are referenced, there is no additional performance overhead, and there is no need to pre-evaluate log levels. Thelog.debug()usage can be directly applied.
There are many places where the usage of ifDebugEnabled is a remnant from the log4j era, which can be replaced with log.debug() from slf4j. However, in many cases, removing the ifDebugEnabled directly 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.
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.
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.
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.
Probably my explanations were not clear. The FQCN to use is that of the LogUtils class, i.e. "org.apache.eventmesh.common.utils.LogUtils". The logging backend will look into the stack for the class that called LogUtils.
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.
Better performance
Regarding "better performance", the code here does not have the same situation as the example you provided.
However, in many cases, removing the
ifDebugEnableddirectly would result in a performance decrease.
Could you provide some examples to illustrate the performance decrease after removing the ifDebugEnabled you 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 the ifDebugEnabled"?
That requires obtaining the Fully Qualified Class Name (FQCN) of each class and passing it as a parameter to LogUtils
The fact seems to be different.
However, in many cases, removing the
ifDebugEnableddirectly would result in a performance decrease.
关于“性能更好”,这里的代码不存在您所举例的情况。
However, in many cases, removing the
ifDebugEnableddirectly would result in a performance decrease.
能否列举一些情况说明一下您这句所说的性能降低的情况?
另外,我不太明白您说的“removing the ifDebugEnabled”。log.debug()内部已经支持判断日志级别,这和“removing the ifDebugEnabled”有什么关系?
That requires obtaining the Fully Qualified Class Name (FQCN) of each class and passing it as a parameter to LogUtils
好像并非如此。
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.
removing the
ifDebugEnabled
From:
if (log.isDebugEnabled()) {
log.debug("Encoder pkg={}", JsonUtils.toJSONString(pkg));
}To:
log.debug("Encoder pkg={}", JsonUtils.toJSONString(pkg));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统一封装一下,这样在编码风格上也能有一定的统一。
|
Thanks @ppkarwasz @pandaapo , let's use LogUtils. More elegant than the public static void debug(Logger logger, String format, Supplier<?> objectSupplier) {
final LoggingEventBuilder builder = logger.atDebug();
if (builder instanceof CallerBoundaryAware) {
((CallerBoundaryAware) builder).setCallerBoundary(FQCN);
}
builder.addArgument(objectSupplier).log(format);
} |
This reverts commit 9c23c8b.
The `LogUtils` class is not useful because: * it wraps every logger call in `isLevelEnabled`. These are not necessary since the arguments to the logger calls are simple variables and not computationally complex expressions, * currently it breaks location detection of the logger calls, which will always show `LogUtils` as origin, * it prevents the project from using source code rewrite tools like [`rewrite-logging-frameworks`](https://github.com/openrewrite/rewrite-logging-frameworks). This commit adds deprecates the class for removal in the next major version and adds Error Prone's `@InlineMe` annotations, to help users automatically rewrite code based on `LogUtils`.
This task patches the codebase based on Error Prone suggestions (cf. [patching](https://errorprone.info/docs/patching), without adding Error Prone to the main compile task. It is a simplified version of the `gradle-errorprone-plugin` (cf. [installing](https://errorprone.info/docs/installation) and only works on a clean tree using JDK 11. Use as: ./gradlew clean errorPronePatch errorPronePatchTest
This commit contains exclusively code changes performed by Error Prone and rewrites all the callsites to `LogUtils` to use the `Logger` object directly.
This reverts commit e78fcef.
# Conflicts: # eventmesh-common/src/main/java/org/apache/eventmesh/common/utils/LogUtils.java
# Conflicts: # eventmesh-sdks/eventmesh-sdk-java/src/main/java/org/apache/eventmesh/client/tcp/common/TcpClient.java
|
I have streamlined There are 9 instances where the logger with time-consuming methods as parameters is replaced with LogUtil's Supplier. You can search for All other usages have been replaced with regular Slf4j usage and no further work is required. Besides, I have Replaced isXXXXEnabled to normal use, Renamed messageLogger to static final MESSAGE_LOGGER, and ran spotlessApply. ErrorProne task may be used in a future refactor, so I retained it. |
ppkarwasz
left a comment
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.
Looks good to me.
ErrorProne task may be used in a future refactor, so I retained it.
Those tasks are a fast hack I introduced for a one-shot job. For longer usage I would recommend using the gradle-errorprone-plugin instead.
If you integrate the plugin into your build (it probably requires a separate discussion and a new PR), it can detect quite a lot of bug patterns (cf. complete list). At Apache Logging Services we use both Spotbugs and Error Prone, they complement each other.
build.gradle
Outdated
| .exclude('**/org/apache/eventmesh/connector/jdbc/antlr**') | ||
|
|
||
| configurations { | ||
| errorprone.extendsFrom(annotationProcessor) |
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.
For all integration code related to Error Prone, I suggest not adding code that is currently not used.
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.
👌, then we can search for errorprone in Github PRs for reference.
| @Slf4j | ||
| public class AbstractTCPServer extends AbstractRemotingServer { | ||
|
|
||
| private static final Logger MESSAGE_LOGGER = LoggerFactory.getLogger(EventMeshConstants.MESSAGE); |
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.
Can this field be kept in TcpDispatcher?
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.
A static member in subclasses is not supported util JDK16.
|
|
||
| public <T> Response publish(T message) { | ||
| LogUtils.info(log, "Publish message ", message.toString()); | ||
| LogUtil.info(log, "Publish message ", message::toString); |
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 is no placeholder {}, After processed by builder. addArgument (message::toString). log("xxx"), how will the return value of message::toString be output?
没有占位符{},经过builder.addArgument(sendResult::toString).log(xxx);处理后,message::toString返回值会如何被输出?
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.
The supplier can be processed correctly:
However, due to an incorrect modification, the supplier parameter does not have a place to be filled:
I will correct similar usages. @scwlkq Please have a check.
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.
All fixed in 56b3d16.
| @Override | ||
| public void onSuccess(SendResult sendResult) { | ||
| LogUtils.debug(log, sendResult.toString()); | ||
| LogUtil.debug(log, "", sendResult::toString); |
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.
These parameters are passed to builder.addArgument(sendResult::toString).log(""), how will the return value of sendResult::toString be output after processing?
这样的参数,经过builder.addArgument(sendResult::toString).log("")处理后,sendResult::toString的返回值会如何被输出?
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.
Adding a builder.addArgument(objectSupplier).log(); will output null, so I added a {} in abc67ce.
| if (committableOffsets.hasPending()) { | ||
| log.debug("{} There are currently {} pending messages spread across {} source partitions whose offsets will not be committed. " | ||
| + "The source partition with the most pending messages is {}, with {} pending messages", | ||
| + "The source partition with the most pending messages is {}, with {} pending messages", |
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.
Bring a situation unrelated to the purpose of this PR to the attention of the community: the automatic modification of this format seems to create a burden of constant modification, such as this line starting with no indentation, then adding indentation, and now removing indentation again.
一个和本PR目标无关的情况,提出来让社区注意一下:这种格式的自动修改,似乎带来一种改来改去的情况,比如这一行开始没有缩进,然后加上了缩进,现在移除了缩进。
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.
Our community has always preferred using 1TAB instead of 2TAB, and my IDEA's default newline indentation is also 1TAB. This time, spotless mainly formatted the code for lark and wecom connector.
It appears that the checkstyle XML file in the "style" directory does not enforce 1TAB indentation for line breaks, but spotless does.
This reverts commit 3e4dc11.
pandaapo
left a comment
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.
The changes in this PR are already OK for me. However, in light of the mention of 'uniform encapsulation' in this comment #4698 (comment), there's one thing for @xwm1992 to note: The encapsulation of LogUtil has been minimized, now only encapsulating cases that require delayed execution, while directly using the native API for other situations (to ensure efficiency).
这个PR的修改对我来说已经OK了。鉴于这条评论#4698 (comment) 中提到了“统一封装”,现在有一点需要您 @xwm1992 注意:LogUtil的封装改成了最小化的,只封装需要延迟执行的情况,其他情况直接使用原生api(保证效率)。
# Conflicts: # eventmesh-common/src/main/java/org/apache/eventmesh/common/file/WatchFileTask.java # eventmesh-common/src/main/java/org/apache/eventmesh/common/protocol/tcp/codec/Codec.java
|
Conflicts resolved. @pandaapo May you please approve? Thanks. |
I am waiting for @xwm1992 's response to this situation. #4698 (review) |
xwm1992
left a comment
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.
LGTM
…se, and elegant logging (apache#4698) * upgrade log4j and slf4j * recommanded example * add known dependencies * remove log4j-to-slf4j * Revert "recommanded example" This reverts commit 3c52810. * Deprecate `LogUtils` for removal The `LogUtils` class is not useful because: * it wraps every logger call in `isLevelEnabled`. These are not necessary since the arguments to the logger calls are simple variables and not computationally complex expressions, * currently it breaks location detection of the logger calls, which will always show `LogUtils` as origin, * it prevents the project from using source code rewrite tools like [`rewrite-logging-frameworks`](https://github.com/openrewrite/rewrite-logging-frameworks). This commit adds deprecates the class for removal in the next major version and adds Error Prone's `@InlineMe` annotations, to help users automatically rewrite code based on `LogUtils`. * Add minimal `errorPronePatch` task This task patches the codebase based on Error Prone suggestions (cf. [patching](https://errorprone.info/docs/patching), without adding Error Prone to the main compile task. It is a simplified version of the `gradle-errorprone-plugin` (cf. [installing](https://errorprone.info/docs/installation) and only works on a clean tree using JDK 11. Use as: ./gradlew clean errorPronePatch errorPronePatchTest * Rewrite `LogUtils` call sites This commit contains exclusively code changes performed by Error Prone and rewrites all the callsites to `LogUtils` to use the `Logger` object directly. * add suppliers * Revert "Rewrite `LogUtils` call sites" This reverts commit 1dc6bf4. * Replace the time-consuming method parms with the supplier usage of LogUtil * Execute errorProne scripts and remove blank line by IDEA optimize import * Remove non-supplier methods in LogUtils * Remove unused trace and error log level * Rename LogUtils to LogUtil to save space * Fix checkstyle * Replace isXXXXEnabled to normal use * Rename messageLogger to static final MESSAGE_LOGGER * Fix all checkstyle warnings * run spotlessApply * Fix JDK11 Javadoc task failed * Add {} and fix javadoc task * Revert "Add minimal `errorPronePatch` task" This reverts commit 0407bda. * Turn back to surpress javadoc only on JDK8 * Fix logging lack param * Merge branch 'master' into pil0txia_enhance_4697 --------- Co-authored-by: Piotr P. Karwasz <[email protected]>



Fixes #4697.
Background Knowledge
Disscussion: apache/logging-log4j2#2133
The additional
isDebugEnabled()check beforelog.debug()is performed in order to avoid invoking the methods referenced in themessagefield, thus improving logging performance. For example:Even when the log level is set to
info, theformatMsg(rawMsg)method will still be called and return a result before being passed as an argument tolog.debug(). This takes time.Solution Selection
Since slf4j does not support passing arguments through the Supplier introduced in log4j 2.13.0 (discussed in qos-ch/slf4j#70, no need to read though), so the Supplier is encapsulated into LogUtils to invoke the passed Supplier lazily, thereby avoiding unnecessary method execution time.
The Fluent Logging API since slf4j 2.0.0 is used to provide accurate caller location (such as its line number) instead of
LogUtilsitself.Scenarios where LogUtils is unnecessary
Only the scenario mentioned in the Background Knowledge section require the use of Fluent Logging API. For example, in the case of the changes in
Codecclass L226, where no object parameters are passed or existing objects are referenced, there is no additional performance overhead, and there is no need to pre-evaluate log levels. The simplest usage of slf4j can be directly applied.Why not use original Fluent Logging API and its Supplier
I think the encapsulated LogUtils is simpler than the original Fluent Logging API.
LogUtils:
The original Fluent Logging API:
or:
Follow-up tasks
@scwlkq will submit a PR for the unified modification of log output statements.
LogUtils will be renamed to LogUtil to save space.
Documentation