调用链耗时统计工具Profiler

代码实现

引入了Profiler用于打印日志调用耗时，包括Profiler和ProfilerEntry两个类

package org.apache.james.mailbox.profiler;

/**
 * 耗时统计工具
 *
 * @since 2021-01-20
 */
public class Profiler {

    private static final ThreadLocal<ProfilerEntry> entryStack = new ThreadLocal();

    public Profiler() {
    }

    public static void start() {
        start(null);
    }

    public static void start(String message) {
        entryStack.set(new ProfilerEntry(message, null, null));
    }

    public static void enter(String message) {
        ProfilerEntry currentEntry = getCurrentEntry();
        if (currentEntry != null) {
            currentEntry.enterSubEntry(message);
        }

    }

    public static void release() {
        ProfilerEntry currentEntry = getCurrentEntry();
        if (currentEntry != null) {
            currentEntry.release();
        }

    }

    public static String dump() {
        return dump("", "");
    }

    public static String dump(String prefix1, String prefix2) {
        ProfilerEntry entry = entryStack.get();
        return entry != null ? entry.toString(prefix1, prefix2) : "";
    }

    private static ProfilerEntry getCurrentEntry() {
        ProfilerEntry subEntry = entryStack.get();
        ProfilerEntry entry = null;
        if (subEntry != null) {
            do {
                entry = subEntry;
                subEntry = subEntry.getUnreleasedEntry();
            } while (subEntry != null);
        }

        return entry;
    }
}

package org.apache.james.mailbox.profiler;

import java.text.MessageFormat;
import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;

import org.apache.commons.lang3.StringUtils;

/**
 * 耗时统计工具
 *
 * @since 2021-01-20
 */
public final class ProfilerEntry {
    private final List<ProfilerEntry> subEntries = new ArrayList(4);

    private final Object message;

    private final ProfilerEntry parentEntry;

    private final ProfilerEntry firstEntry;

    private final long baseTime;

    private final long startTime;

    private long endTime;

    ProfilerEntry(Object message, ProfilerEntry parentEntry, ProfilerEntry firstEntry) {
        this.message = message;
        this.startTime = System.currentTimeMillis();
        this.parentEntry = parentEntry;
        this.firstEntry = null != firstEntry ? firstEntry : this;
        this.baseTime = firstEntry == null ? 0L : firstEntry.startTime;
    }

    public String getMessage() {
        String messageString = null;
        if (this.message instanceof String) {
            messageString = (String) this.message;
        }

        return (String) StringUtils.defaultIfEmpty(messageString, (CharSequence) null);
    }

    public long getStartTime() {
        return this.baseTime > 0L ? this.startTime - this.baseTime : 0L;
    }

    public long getDuration() {
        return this.endTime < this.startTime ? -1L : this.endTime - this.startTime;
    }

    public long getDurationOfSelf() {
        long duration = this.getDuration();
        if (duration < 0L) {
            return -1L;
        } else if (this.subEntries.isEmpty()) {
            return duration;
        } else {
            ProfilerEntry entry;
            for (Iterator var3 = this.subEntries.iterator(); var3.hasNext(); duration -= entry.getDuration()) {
                entry = (ProfilerEntry) var3.next();
            }

            return duration < 0L ? -1L : duration;
        }
    }

    public double getPercentage() {
        double parentDuration = 0.0D;
        double duration = (double) this.getDuration();
        if (this.parentEntry != null && this.parentEntry.isReleased()) {
            parentDuration = (double) this.parentEntry.getDuration();
        }

        return duration > 0.0D && parentDuration > 0.0D ? duration / parentDuration : 0.0D;
    }

    public double getPercentageOfAll() {
        double firstDuration = 0.0D;
        double duration = (double) this.getDuration();
        if (this.firstEntry != null && this.firstEntry.isReleased()) {
            firstDuration = (double) this.firstEntry.getDuration();
        }

        return duration > 0.0D && firstDuration > 0.0D ? duration / firstDuration : 0.0D;
    }

    public void release() {
        this.endTime = System.currentTimeMillis();
    }

    public boolean isReleased() {
        return this.endTime > 0L;
    }

    public void enterSubEntry(Object message) {
        ProfilerEntry subEntry = new ProfilerEntry(message, this, this.firstEntry);
        this.subEntries.add(subEntry);
    }

    public ProfilerEntry getUnreleasedEntry() {
        ProfilerEntry subEntry = null;
        if (!this.subEntries.isEmpty()) {
            subEntry = this.subEntries.get(this.subEntries.size() - 1);
            if (subEntry.isReleased()) {
                subEntry = null;
            }
        }

        return subEntry;
    }

    @Override
    public String toString() {
        return this.toString("", "");
    }

    public String toString(String prefix1, String prefix2) {
        StringBuffer buffer = new StringBuffer();
        this.toString(buffer, prefix1, prefix2);
        return buffer.toString();
    }

    private void toString(StringBuffer buffer, String prefix1, String prefix2) {
        buffer.append(prefix1);
        String message = this.getMessage();
        long startTime = this.getStartTime();
        long duration = this.getDuration();
        long durationOfSelf = this.getDurationOfSelf();
        double percent = this.getPercentage();
        double percentOfAll = this.getPercentageOfAll();
        Object[] params = new Object[] {message, startTime, duration, durationOfSelf, percent, percentOfAll};
        StringBuffer pattern = new StringBuffer("{1,number} ");
        if (this.isReleased()) {
            pattern.append("[{2,number}ms");
            if (durationOfSelf > 0L && durationOfSelf != duration) {
                pattern.append(" ({3,number}ms)");
            }

            if (percent > 0.0D) {
                pattern.append(", {4,number,##%}");
            }

            if (percentOfAll > 0.0D) {
                pattern.append(", {5,number,##%}");
            }

            pattern.append("]");
        } else {
            pattern.append("[UNRELEASED]");
        }

        if (message != null) {
            pattern.append(" - {0}");
        }

        buffer.append(MessageFormat.format(pattern.toString(), params));

        for (int i = 0; i < this.subEntries.size(); ++i) {
            ProfilerEntry subEntry = (ProfilerEntry) this.subEntries.get(i);
            buffer.append('\n');
            if (i == this.subEntries.size() - 1) {
                subEntry.toString(buffer, prefix2 + "`---", prefix2 + "    ");
            } else if (i == 0) {
                subEntry.toString(buffer, prefix2 + "+---", prefix2 + "|   ");
            } else {
                subEntry.toString(buffer, prefix2 + "+---", prefix2 + "|   ");
            }
        }

    }
}

使用方法

样例

package demo;

import lombok.extern.slf4j.Slf4j;
import profiler.Profiler;


@Slf4j
public class ProfilerDemo {
    public static void main(String[] args) throws InterruptedException {
        Profiler.start("ProfilerDemo");
        Profiler.enter("Enter sayHello");
        ProfilerDemo.sayHello();
        Profiler.release();

        Profiler.enter("Enter sayHello2");
        ProfilerDemo.sayHello2();
        Profiler.release();
        Profiler.release();

        System.out.println(Profiler.dump());
    }

    public static void sayHello() throws InterruptedException {
        Profiler.enter("Enter sayHello");
        Thread.sleep(500);
        ProfilerDemo.sayHello2();
        Profiler.release();
    }

    public static void sayHello2() throws InterruptedException {
        Profiler.enter("Enter sayHello2");
        Thread.sleep(500);
        ProfilerDemo.sayHello3();
        Profiler.release();

    }

    public static void sayHello3() throws InterruptedException {
        Profiler.enter("Enter sayHello3");
        Thread.sleep(500);
        Profiler.release();

    }

}

结果如下

0 [2,546ms, 100%] - ProfilerDemo
+---0 [1,534ms, 60%, 60%] - Enter sayHello
|   `---0 [1,534ms (512ms), 100%, 60%] - Enter sayHello
|       `---512 [1,022ms (515ms), 67%, 40%] - Enter sayHello2
|           `---1,027 [507ms, 50%, 20%] - Enter sayHello3
`---1,534 [1,012ms, 40%, 40%] - Enter sayHello2
    `---1,534 [1,012ms (507ms), 100%, 40%] - Enter sayHello2
        `---2,041 [505ms, 50%, 20%] - Enter sayHello3

使用说明

1、通过Profiler.start("ProfilerDemo");开启日志链

2、调用过程中使用，如下组合，成对调用，否则不成链

Profiler.enter("xxx");
Profiler.release();

3、最后通过Profiler.release();结束全部调用

4、通过日志打印，调用Profiler.dump()方法打出调用耗时链

注意点

• 成对使用Profiler.enter("xxx");和Profiler.release();
• 可以嵌套使用
• 需要在同一线程中使用，因为底层使用了ThreadLocal来统计
• 可以在上层方法调用Profiler.enter，在后续的调用类中Profiler.release();