preface

Coincidentally, these days I am reading a book, called “Java System performance Optimization Combat”, written by Li Jiazhi, in the code review chapter mentioned a log output problem, let’s take a look at how we originally output information, as follows.

private static  Logger logger = LoggerFactory.getLogger(FileManageApplication.class);

public static void main(String[] args) {
	logger.info("Log Output {}".1);
}
Copy the code

The first argument is a formatting template, “{}” is a placeholder, and the second argument is that the type can be Object… Arguments, replace the “{}” of the first argument with the data in the array.

2021years01month07day19:5209:INFO main (FileManageApplication.java:35)- Log output 1Copy the code

However, he does not recommend using this method, because there is a time consuming process in the logging framework to replace the placeholder “{}” with the target variable. Considering that the info method may be called frequently, which may affect performance, he recommends direct concatenation, with the following code:

public static void main(String[] args) {
	User user  =getUser();
	logger.info("Username :"+user.getUserName());
}
Copy the code

This seems to have some truth, but this morning I saw an article on the official account, which also mentioned this problem (a big V), which said: “Do not do String concatenation, it will produce a lot of String objects, occupy space, affect performance.”

what???

And he gives a counter example, as follows:

logger.debug("Processing trade with id: " + id + " symbol: " + symbol);
Copy the code

And there is a positive example, as follows:

logger.debug("Processing trade with id:[{}] and symbol : [{}] ", id, symbol)
Copy the code

In addition, this format is more readable and more helpful for troubleshooting problems.

So, in the end, what do we do?

Below we still take a look at the test.

A little time

Using splicing

public class Main {
    private static Logger logger = LoggerFactory.getLogger(Main.class);
    public static void main(String[] args) {
        long startTimer = System.currentTimeMillis();
        for (int i = 0; i < 200000; i++) {
            logger.info("i="+i); } System.out.println(System.currentTimeMillis()-startTimer); }}Copy the code

Run 10 times and the result is as follows, with an average of 512.2.

534, 510, 486, 518, 495, 505, 526, 507, 511, 530Copy the code

Using a template

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Main {
    private static Logger logger = LoggerFactory.getLogger(Main.class);
    public static void main(String[] args) {
        long startTimer = System.currentTimeMillis();
        for (int i = 0; i < 200000; i++) {
            logger.info("i={}",i); } System.out.println(System.currentTimeMillis()-startTimer); }}Copy the code

Run 10 times and the result is as follows, with an average of 642.9.

654,648,599,624,678,660,643,656,583,684
Copy the code

It is true, as stated in the book, that the process of replacing “{}” is time-consuming.

The system.out.println () comparison is not used here, because it is too slow, because internal locking is involved.

Memory usage comparison

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import javax.swing.*;
import java.awt.event.ActionEvent;
import java.awt.event.ActionListener;

public class Main extends JFrame {
    private static Logger logger = LoggerFactory.getLogger(Main.class);

    public Main(a) {
        this.setSize(300.300);
        this.setVisible(true);
        this.setDefaultCloseOperation(EXIT_ON_CLOSE);

        JButton jButton = new JButton("Start");
        jButton.addActionListener(new ActionListener() {
            public void actionPerformed(ActionEvent e) {
                for (int i = 0; i < 1000000; i++) {
                    logger.info("i={}",i);
// logger.info("i="+ i);}}});this.add(jButton);
    }

    public static void main(String[] args) {
        newMain(); }}Copy the code

Template method

After clicking the button and waiting for the output to complete, the memory stayed at 112,764KB.

After GC, it drops to 13,484KB.

Stitching way

After clicking the button and waiting for the output to complete, the memory stayed at 128,014KB, a difference of 15,250KB.

Down to 17,777KB after GC.

In this comparison, the splicing way to occupy higher memory, also in line with the public number said.

conclusion

Obviously all win, so can only look at their own needs, in addition, such as Tomcat source code, the use of the splicing method….

There is in alibaba Java development manual so said….