A series of introduction

This is a new series summarizing my ideas and experiences about observation systems over the past year. According to my observation, most Internet companies, the importance of this piece is seriously insufficient, the company will not hire an observer. Observation has always been a common shortcoming. This series hopes to share my practice and concept of observability and give you some inspiration and experience.

I hope to see systems observation engineers become standard in companies in the future. The more people know how to observe, the more they understand the nature of the problem. An observable system can help everyone grow.

This series will be sequenced through three observables: logs, links, and monitoring.

Read it carefully and you will learn something.

directory

  1. The function of logs.
  2. Mechanism of logs.
  3. The correct posture for hitting the log.
  4. Log performance problems.

Functions of Logs

Logging is the closest part of the application to recording the flow, the details of the exception, and the context in which it occurred.

The problem with logs is that they are atomic, and there is no real connection between each log. So we need to artificially bury some things in the log such as link ids, user ids, IP, order ids, RPC caller names, etc., and string them together to make sense.

Mechanism of Logs

What is the log facade

Logging Facade, Facade here actually means interface, similar to Java interface, namely a set of APIS, which basically does not contain any concrete implementation.

Slf4j(Simple Logging Facade for Java), the most popular one in Java, is a set of Logging Facade, which is generally implemented with Logback and Log4j2.

The structure of the logging framework

Logging frameworks generally include the following functions:

  1. Interface for connecting logs. Can also not docking, their own implementation of a similar set. For example, Skywalking itself developed a simple set: logging-Skywalking
  2. Format logs. Let the user customize the format of the output, as well as implementation of %timestamp, %thread, etc.
  3. Output logs. Generally speaking, there areSystem.outKafka, ElasticSearch, etc.

Log performance problems

Because the log facade looks so simple and light, many people mistakenly think that logging is a low-cost thing. In fact, logging itself is a very expensive operation, producing many more strings in the process.

Here’s a little experiment to see how much more memory the logging framework uses to output strings (Logback 1.2.3) :

@SneakyThrows
public void test(a) {
    // If you don't want to watch the experiment, you can just watch the end
    ThreadMXBean threadMXBean = (ThreadMXBean) ManagementFactory.getThreadMXBean();
    long threadId = Thread.currentThread().getId();

    / / tip, through the com. Sun. Management ThreadMXBean. GetThreadAllocatedBytes () to obtain the memory to the thread are applying for.
    // Initialize thread memory
    long threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);
    long lastBytes = threadAllocatedBytes;

    // Sout itself generates a certain amount of memory, in this case 144 bytes
    System.out.println(threadAllocatedBytes - lastBytes);
    threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);

    // Output :144. The memory generated by sout above
    System.out.println(threadAllocatedBytes - lastBytes);
    lastBytes = threadAllocatedBytes;

    // 48 bytes are generated. 40 bytes are the fixed overhead of the String itself, and 8 bytes are for the String itself.
    // Due to the memory alignment policy, both 1 and 4 characters are 8 bytes
    String msg = String.valueOf("* * * *");
    
    threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);
    
    // Output: 192. Minus the cost of sout once, 144, the MSG string itself is 48 bytes.
    System.out.println(threadAllocatedBytes - lastBytes);
    lastBytes = threadAllocatedBytes;

    // Log to console
    / / output format for [% p] [% d {MM - dd yyyy - HH: MM: ss. The SSS}] [% X {trace. Type}] [% X {trace. Id}] [% X {trace. Extra}] [% t] [% logger {50}] % m % n
    log.info(msg);

    threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);
    
    // Output: 3440. Excluding the 144 bytes generated by sout, the log itself produces 3296bytes, or about 3.2k
    System.out.println(threadAllocatedBytes - lastBytes);
}
Copy the code

Conclusion: The memory overhead of logging (calling to the console) is 3296bytes, which is 68 times as much as the user String itself (in terms of the String object), or 412 times as much as the String itself. This is not very scientific, of course, because the log format itself has a fixed overhead, and multiples may decrease as user strings grow.

More surprisingly, if you add a line number to the log (format %line), how much memory will be generated for each log output?

8960 Bytes

It is worth mentioning that the all-asynchronous, Garbage Free mode is enabled with Log4j2, and in the case of no line numbers, the logging overhead is 0. It’s log base 4j2.

The line number problem

First, how does the logging framework know which class is logging?

The answer is simple, because we tell it:

private static final Logger log = LoggerFactory.getLogger(XyzService.class);
Copy the code

In each logger we actively pass in a class.

Where did that line number come from?

In the case of Logback, if you ask for an output line number in the log format, the LineOfCallerConverter is triggered.

public class LineOfCallerConverter extends ClassicConverter {

    public String convert(ILoggingEvent le) {
        StackTraceElement[] cda = le.getCallerData();
        if(cda ! =null && cda.length > 0) {
            return Integer.toString(cda[0].getLineNumber());
        } else {
            returnCallerData.NA; }}}Copy the code

New Throwable().getStackTrace(), and select the corresponding class in the stack based on the class name passed in:

public static StackTraceElement[] extract(Throwable t, String fqnOfInvokingClass, final int maxDepth, List<String> frameworkPackageList) { if (t == null) { return null; } StackTraceElement[] steArray = t.getStackTrace(); StackTraceElement[] callerDataArray; int found = LINE_NA; for (int i = 0; i < steArray.length; i++) { if (isInFrameworkSpace(steArray[i].getClassName(), fqnOfInvokingClass, frameworkPackageList)) { // the caller is assumed to be the next stack frame, hence the +1. found = i + 1; } else { if (found ! = LINE_NA) { break; }}}Copy the code

That is, every time a log is logged, an exception is thrown behind it and a stack climb is notoriously expensive.

Combined with the memory flame map to see, do not open line number:

Open line number:

As you can see, when the line numbers are not opened, the memory usage is 90% calendar.getDisplayName (). After you turn on the line numbers, it’s only 28%. That means 221% more memory overhead. And that’s not even counting the CPU overhead, which is actually quite high.

To sum up, the line is not open line number.

Incidentally, the memory flame graph is collected by the divine async-profiler project with the command /profiler.sh -e alloc -t -d 30 -f result.html $pid.

Blocking threads

Either Logback or Log4j2 can block the user thread. For example, when the output source is system.out, because the same lock is to be acquired, there is a lot of congestion when there is a lot of competition.

Note whether asynchronous mode is enabled when the user thread outputs logs.

The correct posture for hitting the log

Choose the framework

Select Log4j2, not Logback. Log4j2 has GC Free mode, which can greatly reduce memory requirments and reduce GC caused by log output. There will be a detailed article on how to do this later, and it will give us some ideas for writing code.

Enable Garbage Gree mode

Many chose the right framework, but didn’t turn on full asynchronous mode, which means nothing.

System.setProperty(“log4j2.contextSelector”, contextSelector); “org.apache.logging.log4j.core.async.AsyncLoggerContextSelector”);

// Do not set the size of asynchronous cache to too large. If the log content is large, it is easy to OOM. The default System. 4096 setProperty (” log4j2 asyncLoggerRingBufferSize “, “2048”);

/ / to prevent blocking user threads, not in the log bail System. SetProperty (” log4j2. AsyncQueueFullPolicy “, “Discard”); System.setProperty(“AsyncLogger.SynchronizeEnqueueWhenQueueFull”, “false”);

Log configuration:


      
<Configuration status="WARN" monitorInterval="30">

    <Appenders>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <! -- Output log format -->
            <PatternLayout>
                <Pattern>${pattern}</Pattern>
            </PatternLayout>
        </Console>

        <! -- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
        <RandomAccessFile name="RandomAccessFile" fileName="${jojo:logging.file.path}" immediateFlush="false" append="false">
            <PatternLayout>
                <Pattern>${pattern}</Pattern>
            </PatternLayout>
        </RandomAccessFile>
    </Appenders>
    <Loggers>
        <Logger name="root" level="info" includeLocation="false">
            <AppenderRef ref="RandomAccessFile"/>
            <! -- To turn off the output to the console, type "RandomAccessFile" here, preferably via configuration. -->
            <AppenderRef ref="${isAppenderToStdout}"/>
        </Logger>
    </Loggers>
</Configuration>
Copy the code

See log4J-asynchronous Loggers for low-latency Logging and log4J-garbage-free Steady State Logging

Select the output source

Better to output to a file, disk IO is more reliable and stable than Kafka, UDP, HTTP, etc.

I don’t need to output to the console, just PASS.

The end of the

This article concludes with an overview of logging, performance overhead, and proper logging posture. If anything is unclear, feel free to comment below, and I’ll fill it in. This series is determined to achieve enough of the full enough, meaningful.

Like 100, move on to the next episode.