If you want to do things well, you must first sharpen your tools.
Many programmers may forget how important it is to record the behavior of applications. When encountering concurrent bugs caused by high pressure in multi-threaded environments, you can understand the importance of recording logs.
Some people were very happy to add this sentence to the code:
log.info("Happy and carefree logging");
He may not even realize the importance of application logs in maintenance, tuning and fault identification. I think slf4j is the best logging API, mainly because it supports a great way to inject schema:
log.debug("Found {} records matching filter: '{}'", records, filter);
For log4j, you can only do this:
log.debug("Found " + records + " recordsmatching filter: '" + filter + "'");
This writing is not only more wordy and poor readability, but also has a string splicing that affects efficiency (when this level does not require output).
slf4j introduces the {} injection feature, and since string splicing is avoided every time, the toString method will not be called, and there is no need to add isDebugEnabled. slf4j is an application of appearance mode, it is just a facade. For specific implementation, I recommend the logback framework. I have already advertised it once before, instead of the already complete log4j. It has many interesting features. Unlike log4j, it is still under active development and improvement.
Another tool to recommend is perf4j:
Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()
Just like log4j is a better alternative to System.out.println, perf4j is more like a replacement for System.currentTimeMillis(). I've introduced perf4j in a project and observed how it performs under high loads. Administrators and business users are both stunned by the beautiful charts provided by this gadget. We can view performance issues at any time. perf4j should be a special article to talk about. Now, you can first look at its developer guide. There is also a Ceki Gülcü (creator of log4j, slf4j and logback project) that provides an easy way for us to remove dependencies on commons-logging.
Don't forget the log level
Every time you want to add a line of logs, you will think, which log level should be used here? About 90% of programmers do not pay much attention to this issue. They use one level to record logs, usually either INFO or DEBUG. Why?
The log framework has two major advantages compared to System.out: classification and level. Both allow you to selectively filter logs, permanently or just when troubleshooting errors.
ERROR: A serious error occurred and must be dealt with immediately. This level of error is intolerable to any system. For example: null pointer exception, database is unavailable, and the use cases of critical paths cannot continue to be executed.
WARN: The subsequent process will continue, but it should be taken seriously. Actually, I hope there are two levels here: one is the obvious problem with the solution (such as "the current data is not available, using cached data"), and the other is the potential problem and suggestions (such as "the program runs in development mode" or "the password of the management console is not secure enough". Applications can tolerate this information, but they should be checked and fixed.
DEBUG: What developers are concerned about. Later I will talk about what things should be recorded at this level.
TRACE: More detailed information, only used in the development stage. You may still need to pay attention to this information within a short period of time after the product is launched, but these log records are only temporary and should be turned off eventually. It is difficult to distinguish the difference between DEBUG and TRACE, but if you add a line of logs and delete it after the development and testing, the log should be at the TRACE level.
The list above is just a suggestion, you can log according to your own rules, but it is best to have certain rules. My personal experience is: don’t filter logs at the code level, but use the correct log level to quickly filter out the desired information, which can save you a lot of time.
The last thing to say is this infamous is*Enabled conditional statement. Some people like to add this before each log:
if(log.isDebugEnabled()) log.debug("Place for your commercial");Personally, I think that you should avoid adding this messy thing to the code. The performance doesn't seem to be much improved (especially after using slf4j), which is more like a premature optimization. Also, don’t you find it a bit redundant? Rarely, this explicit judgment statement is explicitly needed unless we prove that constructing log messages itself is too expensive. Otherwise, you can remember as much as you should and let the log framework worry about this.
Do you know what you are recording?
Every time you write a line of logs, take a moment to see what you are printing in the log file. Read your log and find out where the exception is. First, at least avoid null pointer exceptions:
log.debug("Processing request with id: {}", request.getId());
Have you confirmed that request is not null?
Recording collections are also a big pit. If you use Hibernate to obtain a collection of domain objects from the database, you accidentally write it like this: log.debug("Returning users: {}", users);
slf4j will only call the toString method when this statement is indeed printed, of course this is cool. However, if memory overflows, N+1 selection problems, thread starves to death, delayed initialization exception, log storage space runs out... all these may happen. The best way is to record only the ID of the object (or only the size of the collection). However, collecting IDs requires calling the getId method for each object, which is really not an easy task in Java. Groovy has a great expansion operator (users*.id). In Java we can use the Commons Beanutils library to simulate:
log.debug("Returning user ids: {}", collect(users, "id"));
This is probably how collect method is implemented:
public static Collection collect(Collection collection, String propertyName) { return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));}Finally, the toString method may not be implemented correctly or used.
First, in order to log, there are many ways to create a toString for each class. It is best to use ToStringBuilder to generate (but not the version of its reflection implementation).
Second, pay attention to arrays and atypical sets. The toString implementation of arrays and some alternative collections may not call the toString method of each element one by one. The Arrays#deepToString method provided by JDK can be used. Check the logs you printed on yourself to see if there is any information about the format exception.
Avoid side effects
Log printing generally does not have much impact on the performance of the program. Recently, a friend of mine threw a Hibernate LazyInitializationException exception on a system running on some special platforms. As you may have guessed from this, some log prints that result in delayed initialization collections being loaded when the session is connected. In this case, if the log level is increased, the collection will no longer be initialized. If you don't know this context information, how long will it take you to discover this bug.
Another side effect is that it affects the running speed of the program. A quick answer to this question: If the logs are printed too much or the toString and string splicing are not used correctly, the log printing will have a negative impact on performance. How big can it be? Well, I've seen a program restart every 15 minutes because too many logs cause threads to starve to death. This is the side effect! From my experience, printing a hundred megabytes in one hour is almost the upper limit.
Of course, if the business process is aborted due to log printing exceptions, this side effect will be great. I often see people writing this to avoid this:
try { log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())} catch(NullPointerException e) {}This is a real piece of code, but in order to make the world more purified, please don't write it like this.
Describe clearly
Each log record contains data and description. Take a look at this example:
log.debug("Message processed");log.debug(message.getJMSMessageID());log.debug("Message with id '{}' processed", message.getJMSMessageID()); When troubleshooting errors in an unfamiliar system, what kind of log do you prefer to see? Trust me, these examples are common. There is also a negative mode:
if(message instanceof TextMessage)
//...
else
log.warn("Unknown message type");
Is it difficult to add message types, message IDs, etc. to this warning log? I know that an error occurred, but what is it? What is the context information?
The third negative example is "Magic Log". A real example: Many programmers on the team know that 3 ≥ numbers follow! The number followed by a # number, followed by a pseudo-random number log means "the message with ID XYZ has been received". No one wants to change this log. If someone typed the keyboard and selected a unique "&&&!#" string, he would quickly find the information he wanted.
The result is that the entire log file looks like a large string of random characters. Some people can't help but wonder if this is a perl program.
Log files should be readable, clear, and self-described. Don't use magic numbers, record values, numbers, IDs and their context. Record the processed data and its meaning. Record what the program is doing. A good log should be a good document of the program code.
Have I mentioned not to print a password and have personal information? I believe there is no such a stupid programmer.
Adjust your format
Log format is a very useful tool, which invisibly adds valuable context information to the log. But you should think clearly about what kind of information is included in your format. For example, it is meaningless to record dates in logs written every hourly cycle, because your log name already contains this information. On the contrary, if you do not record the thread name, when two threads work in parallel, you will not be able to track the threads through the logs - the logs have overlapped together. In a single-threaded application, it's OK to do this, but that's already a thing of the past.
From my experience, the ideal log format should include (except the log information itself, of course): current time (no date, millisecond precision), log level, thread name, simple log name (not with full name), and messages. In logback it will look like this:
<appender name="STDOUT"> <encoder> <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern> </encoder></appender>File names, class names, line numbers, don't need to be listed, although they seem useful. I've also seen empty logging in the code:
log.info(""); because the programmer believes that the line number will be part of the log format, and he knows that if the empty log message appears on line 67 of the file, it means that the user has been authenticated. Not only that, recording class name method names, or line numbers have a great impact on performance.
A more advanced feature of the logging framework is the Mapped Diagnostic Context. MDC is just a map that is local to thread. You can put any key-value pairs into this map, so that all log records of this thread can obtain corresponding information from this map as part of the output format.
Record the parameters and return values of the method
If you find a bug in the development stage, you usually use a debugger to track the specific reason. Now let's say you won't use the debugger anymore. For example, because this bug appeared in the user's environment a few days ago, all you can get is a few logs. What can you find out from this?
If you follow the simple principle of printing in and out parameters for each method, you don't need a debugger at all. Of course, each method may access external systems, block, wait, etc., and these should be taken into account. Just refer to the following format:
public String printDocument(Document doc, Mode mode) { log.debug("Entering printDocument(doc={}, mode={})", doc, mode); String id = ...; //Lengthy printing operation log.debug("Leaving printDocument(): {}", id); return id;}Since you log the logs at the beginning and end of the method, you can manually find inefficient codes, and even detect causes that may cause deadlocks and hunger - you just need to see if there is no "Leaving" after "Entering". If the meaning of your method name is clear, it will be a pleasant thing to clear the log. Similarly, analyzing exceptions is easier because you know what you are doing at each step. If there are many methods to record in the code, you can use AOP sections to complete it. This reduces duplicate code, but you need to be very careful when using it, and if you are not careful, it may lead to a large amount of log output.
The most suitable levels for this kind of log are DEBUG and TRACE. If you find that a method is called too frequently and recording its log may affect performance, you just need to lower its log level, or delete the log directly (or only one of the entire method calls?) However, too many logs are better than fewer ones. Think of logging as unit tests, your code should be covered with logs just as its unit tests are everywhere. No part of the system requires no logs at all. Remember, sometimes you need to know whether your system is working properly, and you can only view the logs that are constantly flooding the screen.
Observe external systems
This suggestion is a bit different from the previous one: If you are communicating with an external system, remember to record the outgoing and reading data of your system. System integration is a chore, and diagnosing problems between two applications (imagine different companies, environments, technical teams) is especially difficult. Recently we found that recording complete message content, including Apache CXF's SOAP and HTTP headers, is very effective during the integration and testing phase of the system.
This is expensive, and if it affects performance, you can only turn off the log. But in this way, your system may run very quickly and hang quickly, so you can't do anything about it? When integrating with external systems, you can only be extra careful and be prepared to sacrifice some overhead. If you are lucky enough and the system integration is handled by the ESB, it is best to record the request and response on the bus. You can refer to this log component of Mule.
Sometimes the amount of data exchanged with external systems determines that it is impossible for you to write down everything. On the other hand, it is best to keep everything in the log during the testing phase and early release stages and be prepared to sacrifice performance. This can be done by adjusting the log level. Take a look at the following tips:
Collection<Integer> requestIds = //...if(log.isDebugEnabled()) log.debug("Processing ids: {}", requestIds);else log.info("Processing ids size: {}", requestIds.size()); If this logger is configured to the DEBUG level, it prints the complete collection of request IDs. If it is configured to print INFO information, it will only output the size of the set. You may ask me if I forgot the isInfoEnabled condition, please see the second suggestion. Another thing worth noting here is that the set of IDs cannot be null. Although it can print normally under DEBUG as NULL, it is a large null pointer when configured as INFO. Remember the side effects mentioned in the 4th suggestion?
Correct logging exceptions
First, don't log exceptions, let the framework or container do this. Of course there is an exception: if you throw exceptions (RMI, EJB, etc.) from a remote service, the exceptions are serialized to ensure that they can be returned to the client (part of the API). Otherwise, the client will receive a NoClassDefFoundError or other weird exception instead of a real error message.
Exception recording is one of the most important responsibilities of logging, but many programmers tend to use logging as a way to handle exceptions. They usually just return the default value (usually null, 0 or empty string), and pretend nothing happened. Sometimes, they will first record the exception, then wrap the exception and then throw it out:
log.error("IO exception", e); throw new CustomException(e);This way, the stack information will usually be printed twice, because the places where the MyCustomException exception are caught will be printed again. Log records, or wrap it and throw it out, do not use it at the same time, otherwise your logs will look confusing.
What if we really want to log? For some reason (presumably not reading APIs and documentation?), about half of the logging I think is wrong. Do a small test, which of the following log statements can correctly print null pointer exceptions?
try { Integer x = null; ++x;} catch (Exception e) { log.error(e); //A log.error(e, e); //B log.error("" + e); //C log.error(e.toString()); //D log.error(e.getMessage()); //E log.error(null, e); //F log.error("", e); //G log.error("{}", e); //H log.error("{}", e.getMessage()); //I log.error("Error reading configuration file: " + e); //J log.error("Error reading configuration file: " + e.getMessage()); //K log.error("Error reading configuration file", e); //L}It's strange that only G and L (this is better) are right! A and B are not compiled under slf4j at all. Others will throw away the stack trace information or print incorrect information. For example, E does not print anything because the null pointer exception itself does not provide any exception information and the stack information is not printed out. Remember, the first parameter is usually text information, about the error itself. Don't write exception information in it. It will automatically come out after printing the log, in front of the stack information. But if you want to print this, of course you have to pass the exception to the second parameter.
Logs should be readable and easy to parse
Now there are two groups of users who are interested in your logs: we humans (whether you agree or not, the coders are here), and computers (usually shell scripts written by system administrators). Logs should be suitable for both users to understand. If someone looks at your program's log behind you and sees this:
Then you definitely didn't follow my advice. Logs should be as easy to read and understand as code.
On the other hand, if your program generates half a GB of logs every hour, no one or any graphical text editor can finish them. At this time, our old guys, grep, sed and awk, came when they came on the field. If possible, it is best for the logs you record to make it clear to both the computer. Do not format numbers, use some formats that make regular matchable, etc. If it is not possible, print the data in two formats:
log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);log.info("Importing took: {}ms ({})", durationMillis, duration);//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)Computers see "ms after 1970 epoch" such a time format will thank you, while people are happy to see something like "1 day 10 hours 17 minutes 36 seconds".
In short, the journal can also be written as elegant as a poem, if you are willing to think about it.
The above is a collection of information on the Java log adjustment output format. Friends who are interested can refer to it.