| //// |
| Licensed to the Apache Software Foundation (ASF) under one or more |
| contributor license agreements. See the NOTICE file distributed with |
| this work for additional information regarding copyright ownership. |
| The ASF licenses this file to You under the Apache License, Version 2.0 |
| (the "License"); you may not use this file except in compliance with |
| the License. You may obtain a copy of the License at |
| |
| https://www.apache.org/licenses/LICENSE-2.0 |
| |
| Unless required by applicable law or agreed to in writing, software |
| distributed under the License is distributed on an "AS IS" BASIS, |
| WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| See the License for the specific language governing permissions and |
| limitations under the License. |
| //// |
| = Log4j 2 API |
| |
| == Log Builder |
| |
| Log4j has traditionally been used with logging statements like |
| [source,java] |
| ---- |
| logger.error("Unable to process request due to {}", code, exception); |
| ---- |
| |
| This has resulted in some confusion as to whether the exception should be a parameter to the message or |
| if Log4j should handle it as a throwable. In order to make logging clearer a builder pattern has been |
| added to the API. Using the builder syntax the above would be handled as: |
| [source,java] |
| ---- |
| logger.atError().withThrowable(exception).log("Unable to process request due to {}", code); |
| ---- |
| |
| With this syntax it is clear that the exception is to be treated as a Throwable by Log4j. |
| |
| The Logger class now returns a LogBuilder when any of the atTrace, atDebug, atInfo, atWarn, atError, |
| atFatal, always, or atLevel(Level) methods are called. The logBuilder then allows a Marker, Throwable, |
| and/or location to be added to the event before it is logged. A call to the log method always causes the |
| log event to be finalized and sent. |
| |
| A logging statement with a Marker, Throwable, and location would look like: |
| [source,java] |
| ---- |
| logger.atInfo().withMarker(marker).withLocation().withThrowable(exception).log("Login for user {} failed", userId); |
| ---- |
| Providing the location method on the LogBuilder provides two distinct advantages: |
| |
| 1. Logging wrappers can use it to provide the location information to be used by Log4j.</li> |
| 2. The overhead of capturing location information when using the location method with no |
| parameters is much better than having to calculate the location information when it is needed. Log4j |
| can simply ask for the stack trace entry at a fixed index instead of having to walk the stack trace |
| to determine the calling class. Of course, if the location information will not be used by the layout |
| this will result in slower performance.</li> |
| |
| === Location Performance |
| |
| The table below shows some of the results from the FileAppenderBenchmark and FileAppenderWithLocationBenchmark |
| classes in the log4j-perf project when configured to use 4 threads. The results show that lazily including |
| the location information is about 8 times slower than not including location information. While using the |
| withLocation method of LogBuilder is about 3 times faster than lazily calculating the location information |
| it is still about 2.5 times slower than not including location information. |
| |
| The tests were run on a 2018 MacBook Pro with a 2.9 GHz Intel Core i9 processor with 6 cores, 32 GB of memory |
| and 1 TB of SSD storage on Java 11 using Log4j 2.13.0 and Logback 1.2.3. |
| image:../images/LocationPerf.png[Location Performance] |
| |
| |=== |
| |Test|Print Location Info|No Location Info Printed |
| |
| |Log4j2 File| 191,509.724 ± 11339.978 ops/s| 1,407,329.130 ± 22595.997 ops/s |
| |Log4j2 Log Builder withLocation()|469,200.684 ± 50025.985 ops/s|577,127.463 ± 11464.342 ops/s |
| |Logback File|159,116.538 ± 1884.969 ops/s|1,240,438.384 ± 76619.873 ops/s |
| |=== |
| As expected, when using LogBuilder with a call to the withLocation() method logging is much faster when |
| location information is used in the output but significantly slower when it is not. |
| |
| Note: Running the tests at various times provides varying results. Although some results have been as much |
| as 10% higher all results are generally affected similarly so the comparisons between them stay the same. |