阿里云服务器trojan_浅析JAVA日志中的几则性能实践与原理解释

阿里梅导游

本文通过几个技术点来说明日志记录过程中的性能实践，计算机世界的性能往往遵循冰山规则，即你所看到的，程序员能感知到的，只是其中的一小部分，冰山之下隐藏着很多细节。

前言

记录程序的过程是将需要记录的内容写入磁盘文件的过程。类似于生活中的物流场景，就像一卡车的货物通过一套运输系统运送到目的地的过程，但在这个物流系统中，我们往往不需要完成装箱、登机、运输、卸货等整套流程，而只需要在包裹准备好后交给专业的物流公司。对于我们今天要描述的日志场景，日志内容是需要发货的货物，日志框架是物流公司，目的地是磁盘（或其他日志收集服务器）上的文件。在 Java 语言系统中，有很好的日志处理的日志框架 log4j 和 jul（Java Util），它们为我们隐藏了日志的技术细节，程序员只需要使用这个工具类就可以高效地完成业务日志记录，如下面的代码所示：

Logger logger = LogFactory.getLogger("PoweredByEDAS");
String product = "EDAS";logger.info("This is powered by product: " + product);

本文意在通过几个技术点来说明日志过程中的性能实践，计算机领域的性能往往遵循冰山的规则，即你所看到的和程序员能感知到的只是其中的一小部分，冰山下隐藏着很多细节， 如下图所示

自

简单说明上图：当程序员按照业务代码的方式输出日志内容时，日志的目的地是磁盘，在日志内容最终烧录到磁盘之前，需要经过日志框架、JVM、Linux 文件系统等层层。这就像一个物流过程，其中有多个停靠点，有些停靠点可能需要转移。交通中使用的整个交通系统（汽车、司机、道路等）是图中绘制的“对数通道”。根据这个图，我们还给出了系统优化的思路，即避免通道拥塞，减少可见的业务开销，避免无形的系统开销。

避免通道拥塞

在交通系统中，避免拥堵有两个主要思路：1） 尝试控制交通流量，以及 2） 优化整个交通系统（修建更多道路、增加更多信息技术等）。在日志输出场景下，程序员主要可以控制业务日志的内容和日志策略的配置，相当一部分能力取决于底层基础设施的性能。对于程序员可以控制的东西，我们尝试优化;对于我们无法控制的事情，我们尝试解耦。这是我们在本章中将详细阐述的主要思想。

减少业务输出的内容

直观地说，日志内容越大，它对整个系统的压力就越大。为了量化差异，我们执行了以下测试比较：首先，我们只将不同的日志大小写入内存。在第二组中，我们将不同的日志大小写入磁盘文件。

我们使用 Log4j 写入内存，它的作用是在做日志的正式输出时，只统计输出的日志，这是一种可以在一定程度上衡量简单日志框架处理效率的测试方法。

<Appenders>  <CountingNoOp name="NoOp">  CountingNoOp>Appenders>

在下图所示的测试结果中，我们可以看到，即使没有刷写，写入吞吐量也会随着内容的大小而显著降低

在另一组测试中，我们将不同日志大小的内容写入一个文件中，然后进行类似的对比，从实验结果中，我们可以得出两个简单的结论：

与仅写入内存的吞吐量相比，两者之间的吞吐量差异会随着日志内容的增加而增大。

同时，随着输出内容量的增加，在磁盘场景下呈现明显的下降趋势，并随着内容的增加逐渐趋于平缓。

具体结果如下所示：

这

上图中的测试数据是我们从速度约为 400MB/s 的 IO 设备中获得的数据;在 IO 未满的情况下，增加写入次数仍会增加整体写入量，但一旦达到设备瓶颈。继续写入将导致写入累积。

但是，这两组数据可以得出相同的结论，即较大的日志文本内容只会导致更糟糕的处理时间。类比生活中的运输场景，如果我们想运输非常大量的货物，那么我们的卡车需要有更多的空间，更强的动力，运输速度也会更慢。同时，超重货物会存在动力不平衡、轮胎爆胎等风险。为了提高运输的效率和健康，必须尽量避免运输超大货物。从我们的日志场景出发，过大的日志也会对系统产生不同程度的 CPU、内存、I/O 和其他资源的影响。

降低系统输出

压缩输出：

在获取日志输出时，大多数程序员都有直接使用 Class 对象的习惯，请参阅以下代码片段：

package com.alibabacloud.edas.demo;
public class PoweredByEdas {  private static Logger logger = LogFactory.getLogger(        ProweredByEdas.class);
    public void execute() {        String product = "EDAS";         logger.info("Prowered by " + product);    }}

当输出日志时，如果是 class，则默认输出会对应对应的 FQCN，即 com.. edas.demo。

其实我们可以使用 re- 方法进行压缩，比如用 %{5} 或者 %c{5} 压缩后，输出时会被压缩成 C.A.E.D.，平均对数会减少 19 个字符。

// 使用默认 [%logger] 进行输出2023-11-11 16:14:36.790 INFO [com.alibabacloud.edas.demo.PoweredByEdas] Prowered by EDAS 
// 使用默认 [%logger{5}] 进行输出2023-11-11 16:24:44.879 INFO [c.a.e.d.PoweredByEdas] Prowered by EDAS

但是，这种日志处理由于字符串的切分和拦截会消耗一定量的 CPU，如果是计算密集型业务（当 CPU 使用率已经很高时），不建议用于生产。

压缩异常输出

这

当我们在线系统出现问题或故障时，异常信息的记录是进行故障排除的重要依据，其全面性往往直接影响问题的解决效率，但是异常信息记录过多往往很容易掩盖真正有用的信息。当我们把系统中抛出的异常拆开时，不难看出，在整个堆栈信息中，往往只有几行信息可以帮助我们排查问题，如下图所示：

根据笔者自身的经验，在直接打印出 之前，我们可以尝试重新迭代 堆栈，并在输出前重新排列信息

在堆栈顶部保留几帧：堆栈的顶部往往包含最关键的信息，而且是犯罪的第一个现场，他信息的完整性尤为重要。

保留服务堆栈帧：在 Java 语言中，您将遵循为业务代码提供单独包名称的做法，我们可以使用包名称来筛选和保留堆栈帧。

全栈信息的采样和打印：可以根据具体的业务情况来确定，而全栈信息需要随机输出的原因是有时你可能会追踪一些系统级的 bug，或者想了解它的一些机制。全栈信息的输出有助于跟踪问题的根本原因。

压缩异常不仅可以带来性能提升，还可以节省大量的存储空间，这里感兴趣的同学可以进一步参考上一篇文章：“.

解耦通道依赖关系

如果说上面说的减少是为了减少货物的运载量，那么对渠道的优化思路就是优化运输的整体效率;从应用程序的角度来看，通道优化与系统运行时的状态和所用框架的实现有很大关系，这意味着很大一部分内容不受程序员的控制。对于非受控部分，我们的想法是尽可能地解耦底层实现，具体的想法是两个：

在写入日志内容时，异步缓冲区用于解耦从业务代码到通道（从日志记录框架到 JVM 再到操作系统）的瓶颈。

当文件内容放在磁盘上时，将大文件拆分成小文件，以尽可能解耦硬件层面的瓶颈。

如下图所示：

使用异步日志

由于异步方式是业务代码先将日志内容放入缓冲区中，然后通过特殊线程异步烧录到文件系统中，因此可以最大程度地保证业务的吞吐量不受底层框架的影响。但是，是否所有日志都适合异步策略，需要根据业务场景来区分：如果常规业务日志遇到 log drop 的场景，对业务的影响可能不会太大，但有些场景必须与数据严格一致，比如 Log，因为一条日志代表着一条完整的业务消息的投递， 并且必须与业务状态的返回严格一致，在这种情况下，异步模式不是一个好的选择;在 Log4j 中，他还提供了两种方式，一种是细粒度的级别配置，另一种是全局配置;下图显示了这三种策略对性能吞吐量的影响

对上图进行简要解读：第一，同步写入的性能是所有场景下最低的，这与我们常规的理解是一致的;另一方面，TPS（蓝色直方图）可以随 的增加而增加，但只能持平。这与我们的传统理解有点不同，带着这个疑问，让我们更深入地挖掘。

以下是 的配置方法，框架提供了更多的参数来做更精细的控制，核心参数解读如下：

<Async name="Async">  <AppenderRef ref="RollingRandomAccessFile"/>  <shutdownTimeout>500shutdownTimeout>  <bufferSize>1024bufferSize>  <blocking>trueblocking>Async>

简单解读一下设计意图：框架会先提供一个系统缓冲区来缓存需要写入的内容，但是当缓冲区满了时，框架也提供了两种策略供你选择，第一种是直接丢弃，第二种是等待，但具体的等待时间还是可以配置的。
相比 ，它也更易于使用，你只需要设置启动参数 -.=org... log4j.core.async. 即可全局开启异步日志记录。同样，缓冲区大小将有一个设置，默认为 256K。当超过缓冲区大小时，可以使用丢弃策略。您可以通过配置 -.= 和 -.=INFO 参数来指定要丢弃的日志级别。
值得一提的是，使用了带有 LMAX 的高性能队列，这也是为什么与单线程吞吐量和多线程并发相比，它具有更好性能的关键。与阻塞队列相比，LMAX 可以随线程数扩展的主要原因有三个：首先，它解决了伪共享问题;其次，无锁队列设计只需要 CAS 的开销。最后，重要的是要明确比较是此日志场景中队列的性能。
<dependency>   <groupId>com.lmaxgroupId>   <artifactId>disruptorartifactId>dependency>

和 Log4j 一样，也有类似的策略，这里就不细说怎么使用了，但是在下表中，我们总结了各种策略的优缺点，希望能帮到你选择模型的时候
异步
同步日志
性能
最佳的
更好
更好
穷
易于使用
易于使用，只需 jvm 参数 -.=org...log4j.core.async
配置复杂，需要多个配置
配置复杂，需要多个配置
易于使用
内存压力
较大
较大
较大
较小
日志是否会丢失
当进程退出或 IO 无法跟上时
当进程退出或 IO 无法跟上时
当进程退出或 IO 无法跟上时
没有
兼容性
异常
异常
异常
没有
是否受磁盘已满或受限 I/O 的影响
丢弃时，它不受影响
丢弃时，它不受影响
丢弃时，它不受影响
冲击
配置说明 1
指定 false
指定 false
指定 false
指定 true
配置说明 2
设置丢弃策略 -.= 和 -.=INFO
设置丢弃策略 -.= 和 -.=INFO
设置 Drop ：true
没有
使用滚动日志
对于操作系统来说，相比于大文件，从系统资源的角度来看，大文件往往意味着更多的内存占用、更多的 I/O 操作、更苛刻的磁盘空间、更多的总线带宽等，而当任何一方的资源出现瓶颈时，也会带来更多的 CPU 使用率，给系统带来更高的负载。除了从上述资源角度带来更好的优化空间外，小文件还提供了更多的运维管理便利，比如使用更小的磁盘、尽快归档、尽快清理磁盘空间等等。
在生产实践中，正确使用滚动日志是一项非常重要的实践，以下示例是 log4j 中的一个配置片段，它配置为以天为单位滚动日志文件，大小为 100MB，最多为 5 个文件
<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/app.log"                                 filePattern="powered_by/edas-%d{MM-dd-yyyy}-%i.log">    <PatternLayout>        <Pattern>${commonPattern}Pattern>    PatternLayout>    <Policies>        <TimeBasedTriggeringPolicy />        <SizeBasedTriggeringPolicy size="100 MB"/>    Policies>    <DefaultRolloverStrategy>        <max>5max>    DefaultRolloverStrategy>RollingRandomAccessFile>

减少可见的业务费用
可见的业务费用就像运输中的货物，我们期望货物在最终目的使用;也就是说，在可以装车之前，必须确保可以装车，并在装车前确定要运输。在日志输出的场景中，我们也将其分为两部分：
在执行之前确定输出（避免构建复杂的日志参数）。
在一些需要记录详细日志内容的场景下，往往需要根据上下文中的某些参数获取全量信息（例如查询数据库），这意味着调用开销很大。()".确认对应的日志级别满足要求后，打开对应的查询，参考以下代码：
// 不推荐log.debug("Powered by {}", getProductInfoByCode("EDAS"));
// 推荐if (log.isDebugEnabled()) {    log.debug("Powered by {}", getProductInfoByCode("EDAS"));}

虽然上面的逻辑很简单，原理也简单易懂，但是我们很多客户因为这样的代码太多而性能下降的情况也不在少数，一个很典型的例子就是大对象的 JSON 序列化，原因是代码经常在日常迭代的项目实现中没有标准化， 缺少代码过程会导致恶化。
在拼接之前确定输出（使用参数占位符）。
与上述情况类似，这种做法简单而有效。使用参数占位符有两个好处。首先，它更容易编写，而且比直接连接字符串对句子的完整性和可读性更友好。其次，由于它生成内容的延迟，它可以保证在需要实际输出时填充内容，这几乎节省了大量的开销。下面是代码的示例：
String product = "EDAS";//推荐log.debug("Powered by {}", product);
//不推荐log.debug("Powered by " + product);

但是，有些同学心中可能会有一个疑惑：如果日志级别是 “DEBUG”，岂不是会带来相同（或更差）的性能开销？带着这种担忧，我们使用 log4j 框架做了一个有针对性的测试，测试效果如下图所示：

上图中的测试结果可以得出以下两个结论：1）当输出字符较短时，字符串拼接比占位符快，因为占位符方式需要执行占位符扫描和替换过程。2） 但是随着输出字符越来越大，占位符反过来比字符串连接更快，而更长的字符串更快。原因是对于长字符的输出，日志框架会有针对性地进行优化。在 中，它使用缓存并重用对象，无需每次都为大对象构建一个大对象。另一方面，字符串连接每次都会创建一个新对象。
避免看不见的系统开销
继续类比到货物运输的场景，无形的系统开销就像是整车资产的折旧，路况和驾驶员驾驶习惯造成的综合油耗。在计算机软件中，我们经常把系统开销讲成是主要资源（计算、内存、磁盘、网络等）的开销，在本文中，我们主要从内存和计算两个角度进行阐述
避免冗余内存资源（免费）。
“Free” 也称为 “No GC”，即不生成 GC;这是一种新的内存优化技术，旨在减轻垃圾回收 （GC） 的压力，其实现原则很简单：通过重用对象来避免不必要的对象创建。这可以通过在线程中放置需要重用的对象来实现，也可以通过重用它们来避免创建不必要的字符串对象。通过这两种技术避免 GC 的开销，它可以显著降低延迟。官方性能测试结果对比如下：

需要注意的是，在传统的 J2EE Web 应用程序的情况下，会有热加载需求，并且由于 Free 会缓存大量 large in ，这可能会导致程序热加载时潜在的内存泄漏。因此，当检测到 J2EE Web 应用程序时，默认情况下会禁用此技术。如果您想强制打开它，您可以添加 -..到启动参数 =true -...=true。
避免冗余的计算资源（避免元信息打印）。
这
日志输出时打印元数据信息是指输出内容时程序的输出和相关代码信息，包括类名、文件名、方法名、行号等。以获取行号为例，下图展示了在不同日志框架中使用行号和不使用行号的性能差异。该图清楚地显示了在执行行号输出时几乎所有框架的性能都急剧下降：

我们的问题是：为什么？例如，在计算时，可以通过构建一个 来获取堆栈，然后反转同名类所在的堆栈帧，然后获取它。光是听这个过程不是很感人吗？有兴趣的同学可以查看对应的代码，如下：
    public StackTraceElement calcLocation(final String fqcnOfLogger) {        if (fqcnOfLogger == null) {            return null;        }        // LOG4J2-1029 new Throwable().getStackTrace is faster than Thread.currentThread().getStackTrace().        final StackTraceElement[] stackTrace = new Throwable().getStackTrace();        boolean found = false;        for (int i = 0; i < stackTrace.length; i++) {            final String className = stackTrace[i].getClassName();            if (fqcnOfLogger.equals(className)) {
                found = true;                continue;            }            if (found && !fqcnOfLogger.equals(className)) {                return stackTrace[i];            }        }        return null;    }

总结
本文试图提供一些来自 EDAS 团队客户服务流程的 JAVA 日志。受限于作者本人的知识，可能无法一一列举所有影响性能的因素，如果您有任何其他额外补充，请留言与我们沟通。您也可以加入定渠《云微服务应用管理最佳实践 - EDAS （1）】与我们交流。此外，EDAS 还提供了运行时调整日志配置的能力。
参考链接
自由：
Log4j 配置：
配置：
EDAS 运行日志动态调整：
10 行代码将日志存储减少 80%：
欢迎加入 [阿里云开发者公众号] 读者群
这是“阿里云开发者”公众号读者的交流空间
在这里你可以讨论技巧和做法，我们也会定期发布团体福利和活动~