Write poems in Java logs

工欲善其事, its prerequisite

Many programmers may forget how important it is to record the behavior of an application, and when encountering a concurrency bug caused by high stress in a multi-threaded environment, you can appreciate the importance of logging log.

Some people are happy to add the following sentence in the code:

Log.info ("Happy and carefree Logging");

He may not be aware of the importance of application logs in maintenance, tuning, and fault identification.
I think SLF4J is the best log API, mostly because it supports a great way to inject patterns:

Log.debug ("Found {} Records matching filter: ' {} '", records, filter);

Log4j, you can only do this:

Log.debug ("Found" + Records + "recordsmatching filter: '" + filter + "'");

This is not only more verbose and less readable, but string concatenation affects efficiency (when this level does not require output).

SLF4J introduced the {} injection feature, and the ToString method is not called or added with isdebugenabled because it avoids string concatenation every time.

SLF4J is an application of the appearance pattern, it is just a façade. Concrete implementation of the words I recommend Logback framework, has already done once advertising, rather than already very complete log4j. It has a lot of interesting features, and unlike log4j, it is still active in the development of the perfect.

Another tool to recommend is PERF4J:

PERF4J is to System.currenttimemillis () as log4j are to System.out.println ()

Just like log4j is a better alternative to SYSTEM.OUT.PRINTLN, perf4j is more of a substitute for System.currenttimemillis ().

I have introduced the perf4j in a project and observed its performance under high load conditions. Both administrators and business users were stunned by the beautiful graphics provided by this gadget.

We can view performance issues at any time. PERF4J should write a special article to say, now you can look at its developer guide.

There is also a Ceki Gülcü (creator of the LOG4J,SLF4J and Logback project) that provides a simple way for us to remove the dependency on commons-logging.

Don't forget the log level

Every time you add a line of logs, you'll think, what kind of log level should I use here? About 90% of programmers don't pay much attention to this problem, they use a level to log, usually not info is debug. Why?

The log framework has two major advantages over System.out: classification and level. Both allow you to selectively filter logs, permanent or just when troubleshooting errors.

• error has serious errors and must be dealt with immediately. This level of error is not tolerated by any system. For example: null pointer exception, database unavailable, critical path use case cannot continue execution.
• WARN will continue to follow the process, but it should be taken seriously. In fact, I would like to have two levels here: one is the obvious problem with the solution (for example, "Current data is not available, use cached data"), and the other is a potential problem and suggestion (such as "The program is running in development mode" or "The password of the management console is not secure"). Applications can tolerate this information, but they should be checked and repaired.
• What the DEBUG developers are concerned about. I'll talk about what kind of things should be recorded at this level.
• TRACE More detailed information is only used in the development phase. You may also need to focus on this information for a short period of time after the product goes live, but these logs are only temporary and should eventually be turned off. The difference between debug and trace is difficult to distinguish, but if you add a line of logs and then delete it after the development test, the log should be the trace level.

The list above is just a suggestion, you can record the log according to your own rules, but it is better to have some rules. My personal experience is: Do not log filtering at the level of the code, 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 the conditional statement of this infamous is*enabled. Some people like to add this before each log:

if (log.isdebugenabled ())    Log.debug ("Place for your commercial");

Personally, you should avoid adding this noisy thing to your code. Performance doesn't seem to be improving (especially after slf4j), it's more like premature optimization. And, you know, it's a little superfluous to do that? Rarely do you explicitly need this explicit judgment statement unless we prove that the construction log message itself costs too much. Otherwise, how to remember how to remember, let the log framework to worry about it.

Do you know what you're recording?

Every time you write down a line of logs, take a moment to see what you have printed in the log file. Read through your logs and find out where the anomalies are. First, at least avoid null pointer exceptions:

Log.debug ("Processing request with ID: {}", Request.getid ());

Have you confirmed that the request is not NULL?

The record set is also a big pit. If you use Hibernate to get a collection of domain objects from a database, you accidentally write this:

Log.debug ("Returning users: {}", users);

SLF4J only calls the ToString method when the statement does print, which is cool, of course. However, if the memory overflow, n+1 Select the problem, the thread starved to death, delayed initialization of the exception, log storage space ran out ... All of this is likely to happen.

The best way to do this is to only record the object's ID (or just the size of the collection). But collecting IDs requires calling the GetID method on each object, which is really not a simple thing in Java. Groovy has a great expansion operator (Users*.id), and in Java we can use the Commons Beanutils library to simulate the following:

Log.debug ("Returning user ids: {}", Collect (users, "id"));

The Collect method is probably the way to achieve this:

 Public Static Collection Collect (Collection Collection, String PropertyName) {    returnnew  Beantopropertyvaluetransformer (PropertyName));}

The last thing to say is that the ToString method may not be implemented correctly or used.

First, in order to log, it is very useful to create a ToString for each class, preferably with Tostringbuilder (but not the version of its reflection implementation).

Second, note the array and the atypical collection. The ToString implementation of arrays and some alternative collections may not have the ToString method of calling each element one by one. You can use the Arrays#deeptostring method provided by the JDK. Always check your own print logs to see if there is some information about the format exception.

Avoid side effects

Log printing generally does not have much effect on the performance of the program. Recently a friend of mine has run a system on some special platforms that throws Hibernate's Lazyinitializationexception exception. You may have guessed from this that when a session is connected, some log printing causes the collection of deferred initialization to be loaded. In this case, the log level is increased and the collection is no longer initialized. If you don't know the contextual information, how long will it take you to discover the bug.

Another side effect is how quickly the program runs. Quick answers to this question: if the log prints too much or does not use ToString and string concatenation correctly, log printing has 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 the thread to starve. That's the side effect! From my experience, the one-hour print hundred trillion is almost the limit.

Of course, this side effect is large if the business process is aborted due to a log printing exception. I often see people writing to avoid this:

Try {    log.trace ("id=" + request.getuser (). GetId () + "accesses" +catch( NullPointerException e) {}

This is a real code, but in order to make the world a little cleaner, please do not write this.

Description to be clear

Each log record will contain data and a description. Take a look at this example:

Log.debug ("message processed"); Log.debug (Message.getjmsmessageid ()); Log.debug ("message with ID ' {} ' Processed ", Message.getjmsmessageid ());

What kind of log do you prefer to see when troubleshooting errors in a strange system? Believe me, these examples are very common. There is also a reverse pattern:

if instanceof textmessage)     // ... Else     Log.warn (

Is it difficult to add message types, message IDs, and so on in this warning log? I know there's been a mistake, but what's wrong? What is contextual information?

The third negative example is the "Magic Log". A real example: a lot of programmers in the team know that after the 3 & numbers follow! Number followed by a #, followed by a pseudo-random number of logs means "message with ID XYZ received". No one wants to change the log, someone knocks on the keyboard, selects a unique "&&&!#" string, and he can quickly find the information he wants.

As a result, the entire log file looks like a large string of random characters. Some people can not help wondering if this is a Perl program.

The log file should be readable, legible, and self-descriptive. Do not use some magic numbers, record values, numbers, IDs, and their contexts. Record the data processed and what it means. What the recording program is doing. A good log should be a good document for the program code.

Did I mention that you don't print passwords and personal information? Believe that there are no such silly programmers.

Adjust your formatting

The log format is a useful tool that virtually adds valuable contextual information to the log. But you should figure out what information is included in your format. For example, it doesn't make sense to record a date in a log that is written every hour, because your log name already contains this information. Conversely, if you don't have a name for the thread, you won't be able to trace threads through the log when two threads are working in parallel--the logs are overlapping. In a single-threaded application, this is fine, but that's the past.

From my experience, the ideal log format should include (except, of course, the log information itself): The current time (no date, millisecond precision), log level, thread name, simple log name (without full name) and a message. This will be the case in the Logback:

class= "Ch.qos.logback.core.ConsoleAppender" >    <encoder>        <pattern>%d{hh:mm:ss. SSS}%-5level [%thread][%logger{0}]%m%n</pattern>    

Filenames, class names, and line numbers are not listed, although they look useful. I've also seen empty log records in the code:

Log.info ("");
Because the programmer thinks the line number is part of the log format, and he knows that if an empty log message appears in the 67 line of the file, it means that the user is authenticated. In addition, the record class name method name, or line number, has a significant impact on performance.

A more advanced feature of the log framework is the diagnostic context mapping (Mapped Diagnostic context). The MDC is just a local map of a thread. You can put any key-value pairs in this map, so that all of the log records for this thread can be taken from this map to the corresponding information as part of the output format.

Record the parameters and return values of a method

If you find a bug in the development phase, you will usually use the debugger to track the specific cause. Now suppose you don't want to use the debugger, for example, because the bug appeared in the user's environment a few days ago, you can get only a few logs. What can you find out?

If you follow the simple principle of printing the entry and exit parameters for each method, you do not need a debugger at all. Of course each method may access external systems, blocks, waits, and so on, which 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);     // lengthy printing operation    Log.debug ("Leaving PrintDocument (): {}", id);     return ID;}

Since you have recorded the logs at the beginning and end of the method, you can manually identify inefficient code, and even detect triggers that might cause deadlocks and starvation-you just have to look at the "Entering" and see if there is no "leaving". If the meaning of your method name is clear, clearing the log will be a pleasant thing. Again, it's easier to analyze anomalies because you know what you're doing at every step. There are many ways to record in the code, which can be done with AOP facets. This reduces the duplication of code, but using it with special care may result in the output of a large number of logs.

The most appropriate level for this type of log is Debug and trace. If you find that a method call is too frequent, logging its log can affect performance, just need to lower its log level, or delete the log directly (or the entire method call only one?). But the log is more than the less the better. Consider logging as a unit test, and your code should be filled with logs as if its unit tests were everywhere. There is no part of the system that does not require a log at all. Remember, sometimes you need to know if your system is working properly, and you can only view the logs that keep swiping.

Observing external systems

This advice is somewhat different from the previous one: if you are communicating with an external system, remember to record the outgoing and read data from 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 documenting the full message content, including the soap and HTTP headers of Apache CXF, was very effective during the integration and testing phases of the system.

This is expensive, and if it affects performance, you can only turn the log off. But then your system may run fast and hang quickly, and you can do nothing? When integrating with external systems, you can only be extra careful and ready to sacrifice a certain amount of overhead. If you're lucky enough, system integration is handled by the ESB, which is best when the bus logs requests and responses. You can refer to this log component of mule below.

Sometimes the amount of data exchanged with an external system determines that you cannot write down anything. On the other hand, in the test phase and early release, it's best to put everything in the log and prepare for sacrificing performance. This can be done by adjusting the log level. Take a look at the following tips:

// ... if (log.isdebugenabled ())    Log.debug ("processing IDs: {}", requestids); Else     Log.info (

If this logger is configured as 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 collection. You may ask me if I have forgotten the isinfoenabled condition, and look at the 2nd suggestion. It is also worth noting that the collection of IDs cannot be null. Although it is null to print normally under Debug, it is a large null pointer when configured as info. Remember the side effects mentioned in the 4th recommendation?

Correct logging of exceptions

First, do not log the exception, let the framework or container to do this. Of course there is an exception: if you throw an exception (RMI,EJB, etc.) from the remote service, the exception is serialized, ensuring that they return to the client (part of the API). Otherwise, the client receives a noclassdeffounderror or other quirky exception, not a real error message.

Exception logging is one of the most important responsibilities of logging, but many programmers tend to think of logging as a way to handle exceptions. They usually just return the default value (usually null,0 or an empty string), pretending nothing has happened. There are times when they record anomalies and then wrap them up and then throw them out:

Log.error ("IO exception", e); Throw New

This usually prints the stack information two times, because the place where the mycustomexception exception was caught is printed again. Log records, or wrap them up and throw them away, and don't use them at the same time, otherwise your logs will look confusing.

What if we really want to record the logs? For some reason (presumably not reading the API and documentation?) ), about half of the log records I think are wrong. To 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);//ALog.error (E, E);//BLog.error ("" + e);//CLog.error (E.tostring ());//DLog.error (E.getmessage ());//ELog.error (NULL, e);//FLog.error ("", e);//GLog.error ("{}", E);//HLog.error ("{}", E.getmessage ());//ILog.error ("Error reading configuration file:" + E);//JLog.error ("Error reading configuration file:" + e.getmessage ());//KLog.error ("Error reading configuration file", e);//L}

It's strange that only G and L (this is better) are right! A and B are compiled under SLF4J. However, the rest of the stack tracking information is discarded or printed 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. Do not write the exception information in, print the log after it will automatically come out, 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 interested in your log: we humans (regardless of whether you disagree with it, yard is also here), and the computer (usually the shell script written by the system administrator). The logs should be suitable for both users to understand. If someone looks behind you in the log of your program and sees this:

Then you certainly 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 gigabyte of logs per hour, no one or any graphical text editor can read them. This is when our old folks, grep,sed and awk, are on the pitch. If possible, the logs you log are best for people and computers to understand, do not format numbers, use a format that is easy to match, and so on. If this is not possible, print the data in two formats:

New Date (TTL), TTL); // Request TTL Set to:wed Apr 20:14:12 CEST (1272478452437) Final true true ); Log.info ("Importing took: {}ms ({})", Durationmillis, duration); //

The computer sees "Ms after 1970 epoch" as a time format that will thank you, and people are happy to see things like "1 days, 10 hours, 17 minutes, 36 seconds."

In short, the log can also be written as elegant as poetry, if you are willing to ponder.

Write poems in Java logs