汀的知识碎片

4.0 统一的Java虚拟机日志接口

45 min read

第4章 统一的Java虚拟机日志接口

Java HotSpot虚拟机（VM）是一个特性和灵活性的宝库。命令行选项允许启用其实验性或诊断特性，并探索各种VM和垃圾回收活动。在HotSpot VM内部，有针对不同目的而构建的不同构建版本。主要版本是产品构建，针对性能进行了优化，用于生产环境。此外，还有调试构建，包括快速调试和慢调试变体。

启用了断言的快速调试构建（fast-debug build）提供了额外的调试能力，且性能开销极小，适合在需要一定诊断能力但又不显著影响性能的开发环境中使用。另一方面，慢调试构建（slow-debug build）包含全面的调试工具和检查，非常适合使用原生调试器进行深入分析，但需要付出显著的性能代价。

直到JDK 9，HotSpot VM的日志接口仍然支离破碎，缺乏统一性。开发者必须组合各种打印选项，才能以适当的时间戳和上下文获取详细的日志信息。本章将引导你了解这一功能的演进，重点关注JDK 9引入的统一日志系统，该系统在JDK 11和JDK 17中得到了进一步增强。

统一日志的必要性

Java HotSpot VM选项丰富，但缺乏统一的日志接口是一个显著的短板。需要各种命令行选项来获取特定的日志细节，这本来可以更清晰、更高效。以下是对这些选项的简要概述，说明了其复杂性（除了这里列出的之外，还有更多选项可用）：

  • 垃圾收集器（GC）事件时间戳：-XX:+PrintGCTimeStamps 或 -XX:+PrintGCDateStamps
  • GC事件详情：-XX:+PrintGCDetails
  • GC事件原因：-XX:+PrintGCCause
  • GC自适应性：-XX:+PrintAdaptiveSizePolicy
  • GC特定选项（例如，针对Garbage First [G1] GC）：-XX:+G1PrintHeapRegions
  • 编译级别：-XX:+PrintCompilation
  • 内联信息：-XX:+PrintInlining
  • 汇编代码：-XX:+PrintAssembly（需要 -XX:+UnlockDiagnosticVMOptions）
  • 类直方图：-XX:+PrintClassHistogram
  • 关于 java.util.concurrent 锁的信息：-XX:+PrintConcurrentLocks

记住每个选项并判断信息属于info、debug还是trace级别是很有挑战性的。因此，JDK 9中引入了 JDK增强提议（JEP）158：统一JVM日志1。随后是 JEP 271：统一GC日志2，它为GC活动提供了一个全面的日志框架。

统一与基础设施

Java HotSpot VM拥有统一的日志接口，为JVM的所有日志信息提供了熟悉的外观和方法。所有日志消息都使用标签进行表征。这样，你就可以根据需要调查的级别来请求信息级别，从”error”和”warning”日志到”info”、“trace”和”debug”级别。

要启用JVM日志，需要提供 -Xlog 选项。默认情况下（即未指定 -Xlog 时），仅将警告和错误记录到 stderr。因此，默认配置如下：

-Xlog:all=warning:stderr:uptime,level,tags

这里我们看到 all，它只是所有标签的别名。

统一日志系统是一个包罗万象的系统，为所有JVM日志提供一致的接口。它围绕四个主要组件构建：

  • 标签（Tags）：用于对日志消息进行分类，每条消息分配一个或多个标签。标签使得过滤和查找特定日志消息更加容易。一些预定义的标签包括 gc、compiler 和 threads。
  • 级别（Levels）：定义日志消息的严重性或重要性。共有六个级别：debug、error、info、off、trace 和 warning。
  • 装饰器（Decorators）：为日志消息提供额外的上下文，例如时间戳、进程ID等。
  • 输出（Outputs）：日志消息写入的目的地，例如 stdout、stderr 或文件。

性能指标

在JVM性能工程的背景下，统一日志系统为各种性能指标提供了宝贵的洞察。这些指标包括GC活动、即时（JIT）编译事件、系统资源使用情况等。通过监控这些指标，开发者可以识别潜在的性能问题，并预先采取必要措施来优化Java应用程序的性能。

统一日志系统中的标签

在统一日志系统中，标签对于区分和识别不同类型的日志消息至关重要。每个标签对应一个特定的系统区域或一种特定类型的操作。通过启用特定标签，用户可以定制日志输出，聚焦于感兴趣的领域。

日志标签

统一日志系统提供了大量标签来捕获细粒度的信息。例如，gc 用于垃圾回收，thread 用于线程操作，class 用于类加载，cpu 用于CPU相关事件，os 用于操作系统交互，以及更多，如下所列：

add, age, alloc, annotation, arguments, attach, barrier, biasedlocking, blocks, bot, breakpoint, 
bytecode, cds, census, class, classhisto, cleanup, codecache, compaction, compilation, condy, 
constantpool, constraints, container, coops, cpu, cset, data, datacreation, dcmd, decoder, 
defaultmethods, director, dump, dynamic, ergo, event, exceptions, exit, fingerprint, free, 
freelist, gc, handshake, hashtables, heap, humongous, ihop, iklass, indy, init, inlining, install, 
interpreter, itables, jfr, jit, jni, jvmci, jvmti, lambda, library, liveness, load, loader, 
logging, malloc, map, mark, marking, membername, memops, metadata, metaspace, methodcomparator, 
methodhandles, mirror, mmu, module, monitorinflation, monitormismatch, nestmates, nmethod, 
nmt, normalize, numa, objecttagging, obsolete, oldobject, oom, oopmap, oops, oopstorage, os, 
owner, pagesize, parser, patch, path, perf, periodic, phases, plab, placeholders, preorder, 
preview, promotion, protectiondomain, ptrqueue, purge, record, redefine, ref, refine, region, 
reloc, remset, resolve, safepoint, sampling, scavenge, sealed, setting, smr, stackbarrier, 
stackmap, stacktrace, stackwalk, start, startup, startuptime, state, stats, streaming, 
stringdedup, stringtable, subclass, survivor, suspend, sweep, symboltable, system, table, task, 
thread, throttle, time, timer, tlab, tracking, unload, unshareable, update, valuebasedclasses, 
verification, verify, vmmutex, vmoperation, vmthread, vtables, vtablestubs, workgang

指定 all 而不是标签组合，可以匹配所有标签组合。

如果你想运行应用程序并获取所有日志消息，可以使用 -Xlog 执行程序，这等效于 -Xlog:all。该选项会将所有消息记录到 stdout，级别设置为 info，而警告和错误则会发送到 stderr。

特定标签

默认情况下，使用 -Xlog 但不指定特定标签运行应用程序，会产生来自系统各个部分的大量日志消息。如果你想聚焦于特定区域，可以通过指定标签来实现。

例如，如果你对与垃圾回收、堆和压缩对象引用（compressed oops）相关的日志消息感兴趣，可以指定 gc 标签。在JDK 17中使用 -Xlog:gc* 选项运行应用程序，将产生与垃圾回收相关的日志消息：

$ java -Xlog:gc* LockLoops
[0.006s][info][gc] Using G1
[0.007s][info][gc,init] Version: 17.0.8+9-LTS-211 (release)
[0.007s][info][gc,init] CPUs: 16 total, 16 available 
...
[0.057s][info][gc,metaspace] Compressed class space mapped at: 0x0000000132000000
-0x0000000172000000, reserved size: 1073741824
[0.057s][info][gc,metaspace] Narrow klass base: 0x0000000131000000, Narrow klass shift: 0, Narrow 
klass range: 0x100000000

类似地，如果你的应用程序涉及大量多线程，你可能对 thread 标签感兴趣。使用 -Xlog:thread* 选项运行应用程序，将产生与线程操作相关的日志消息：

$ java -Xlog:thread* LockLoops
[0.019s][info][os,thread] Thread attached (tid: 7427, pthread id: 123145528827904).
[0.030s][info][os,thread] Thread "GC Thread#0" started (pthread id: 123145529888768, attributes: 
stacksize: 1024k, guardsize: 4k, detached).
...

识别缺失信息

在某些情况下，启用某个标签并不会产生预期的日志消息。例如，使用 -Xlog:monitorinflation* 运行应用程序可能输出很少，如下所示：

...
[11.301s][info][monitorinflation] deflated 1 monitors in 0.0000023 secs
[11.301s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=2, max=3
...

在这种情况下，你可能需要调整日志级别——我们将在下一节探讨这个主题。

深入探讨级别、输出和装饰器

让我们更仔细地查看可用的日志级别，检查装饰器的使用，并讨论重定向输出的方法。

级别

JVM的统一日志系统提供了各种日志级别，每个级别对应不同的详细程度。要了解这些级别，可以使用 -Xlog:help 命令，该命令提供所有可用选项的信息：

Available log levels:
 off, trace, debug, info, warning, error

这里：

  • off：禁用日志。
  • error：JVM内的关键问题。
  • warning：可能需要注意的潜在问题。
  • info：关于JVM操作的一般信息。
  • debug：对调试有用的详细信息。该级别提供了对JVM行为的深入洞察，通常用于排查特定问题。
  • trace：最详细的级别，提供极其详细的日志记录。Trace级别通常用于获取JVM操作最细粒度的洞察，尤其是在需要逐步详细记录事件时。

如我们之前的示例所示，如果未为某个标签指定具体的日志级别，默认日志级别设置为 info。当我们运行测试时，在默认的 info 日志级别下，monitorinflation 标签的信息非常少。我们可以显式将日志级别设置为 trace 以访问额外信息，如下所示：

$ java -Xlog:monitorinflation*=trace LockLoops

现在，输出日志包含了关于各种锁的详细信息，如以下日志摘录所示：

...
[3.073s][trace][monitorinflation      ] Checking in_use_list:
[3.073s][trace][monitorinflation      ] count=3, max=3
[3.073s][trace][monitorinflation      ] in_use_count=3 equals ck_in_use_count=3
[3.073s][trace][monitorinflation      ] in_use_max=3 equals ck_in_use_max=3
[3.073s][trace][monitorinflation      ] No errors found in in_use_list checks.
[3.073s][trace][monitorinflation      ] In-use monitor info:
[3.073s][trace][monitorinflation      ] (B -> is_busy, H -> has hash code, L -> lock status)

日志级别

在统一日志系统中，日志级别是分层次的。因此，将日志级别设置为 trace 将会包含所有更低级别（debug、info、warning、error）的消息。这确保了全面的日志输出，捕获了广泛的细节，如下面的日志所示：

[11.046s][trace][monitorinflation      ] deflate_monitor: object=0x000000070fe70a58, 
mark=0x00006000020e00d2, type='java.lang.Object'
[11.046s][debug][monitorinflation      ] deflated 1 monitors in 0.0000157 secs
[11.046s][debug][monitorinflation      ] end deflating: in_use_list stats: ceiling=11264, count=2, 
max=3
[11.046s][debug][monitorinflation      ] begin deflating: in_use_list stats: ceiling=11264, 
count=2, max=3
[11.046s][debug][monitorinflation      ] deflated 0 monitors in 0.0000004 secs
...

这种层次化的日志记录是JVM日志系统的一个关键方面，它允许根据你的需求进行灵活且详细的监控。

装饰器

装饰器是JVM日志的另一个关键方面。装饰器为日志消息添加额外的上下文，使其更具信息性。在命令行上指定 -Xlog:help 将显示以下装饰器：

可用的日志装饰器:
 time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis (um), timenanos (tn), 
uptimenanos (un), hostname (hn), pid (p), tid (ti), level (l), tags (tg)
 装饰器也可以指定为 'none' 表示无装饰.

这些装饰器在日志中提供特定信息。默认情况下，选中了 uptime、level 和 tags，这就是为什么我们在之前的示例中看到了这三个装饰器。然而，你可能有时希望使用不同的装饰器，例如：

  • pid (p)：进程ID。用于区分不同JVM实例的日志。
  • tid (ti)：线程ID。对于追踪特定线程的操作至关重要，有助于调试并发问题或特定线程的行为。
  • uptimemillis (um)：JVM运行时间（毫秒）。有助于将事件与应用程序操作的时间线关联起来，尤其是在性能监控中。

以下是如何添加装饰器的示例：

$ java -Xlog:gc*::uptimemillis,pid,tid LockLoops
[0.006s][32262][8707] Using G1
[0.008s][32262][8707] Version: 17.0.8+9-LTS-211 (release)
[0.008s][32262][8707] CPUs: 16 total, 16 available [0.023s][32033][9987] Memory: 16384M 
...
[0.057s][32262][8707] Compressed class space mapped at: 0x000000012a000000-0x000000016a000000, 
reserved size: 1073741824
[0.057s][32262][8707] Narrow klass base: 0x0000000129000000, Narrow klass shift: 0, Narrow klass 
range: 0x100000000

像 pid 和 tid 这样的装饰器在调试中特别有价值。当多个JVM同时运行时，pid 有助于识别生成日志的JVM实例。tid 在多线程应用程序中对于跟踪单个线程的行为至关重要，这对于诊断死锁或竞态条件等问题至关重要。

使用 uptime 或 uptimemillis 作为事件的时间参考，可以构建清晰的操作时间线。uptimemillis 在性能分析中至关重要，用于了解特定事件相对于应用程序启动时间发生的时间。类似地，hostname 在分布式系统中对于识别日志条目的源机器很有价值。

装饰器通过以下几种方式增强日志的可读性和分析能力：

  • 上下文清晰度：通过提供时间戳、进程ID和线程ID等额外细节，装饰器使日志自包含且更易于理解。
  • 过滤和搜索：借助相关的装饰器，可以更有效地过滤日志数据，从而更快地隔离问题。
  • 关联与因果分析：装饰器允许关联系统不同部分的事件，有助于根因分析和系统范围的性能优化。

总之，统一日志系统中的装饰器在增强JVM日志的调试和性能监控能力方面发挥着关键作用。它们添加了必要的上下文和清晰度，使日志数据对于开发者来说更具可操作性和洞察力。

输出

在JVM日志中，输出决定了日志信息的去向。JVM提供了控制日志输出的灵活性，允许用户将输出重定向到 stdout、stderr 或特定文件。默认行为是将所有警告和错误路由到 stderr，而所有 info、debug 和 trace 级别则定向到 stdout。然而，用户可以根据需要调整此行为。例如，用户可以指定一个特定文件来写入日志数据，这在需要稍后分析日志或 stdout/stderr 不方便或不可取时非常有用。

文件名可以作为参数传递给 -Xlog 命令，以将日志输出重定向到该文件。例如，假设你想要记录垃圾收集（gc）活动在 info 级别，并希望将这些日志写入 gclog.txt 文件。以下是针对 gc* 标签和级别设置为 info 的示例：

$ java -Xlog:gc*=info:file=gclog.txt LockLoops

在此示例中，所有关于垃圾收集过程在 info 级别的日志信息将被写入 gclog.txt 文件。对于任何标签或日志级别也可以这样做，为系统管理员和开发者提供了极大的灵活性。

你甚至可以将不同的日志级别定向到不同的输出，如下例所示：

$ java -Xlog:monitorinflation*=trace:file=lockinflation.txt -Xlog:gc*=info:file=gclog.txt 
LockLoops

在这种情况下，垃圾收集过程的 info 级别日志被写入 gclog.txt，而 monitorinflation 的 trace 级别日志被定向到 lockinflation.txt。这允许一种细粒度的方法来管理日志数据，并能够根据其详细程度对日志数据进行隔离，这在故障排除时可能非常有帮助。

NOTE

将日志定向到文件而不是 stdout/stderr 可能会带来性能影响，尤其是对于 I/O 密集型应用程序。写入文件可能更慢，并可能影响应用程序性能。为降低此风险，异步日志记录是一种有效的解决方案。我们将在本章稍后深入探讨异步日志记录。

理解并有效管理JVM日志中的输出，可以帮助你充分利用日志系统的灵活性和强大功能。此外，鉴于JVM不会自动处理日志轮转，管理大型日志文件对于长时间运行的应用程序至关重要。如果没有适当的日志管理，日志文件可能会显著增长，消耗磁盘空间并可能影响系统性能。通过外部工具或自定义脚本实现日志轮转，可以帮助控制日志文件大小并防止潜在问题。有效的日志输出管理不仅使应用程序调试和监控任务更易于管理，还能确保日志记录实践符合应用程序的性能和维护要求。

统一日志系统使用实践示例

为了展示统一日志系统的多功能性，我们首先了解如何配置它。全面掌握这个系统对于Java开发者来说至关重要，尤其是在高效的调试和性能优化方面。-Xlog 选项是该系统的核心组件，提供了极大的灵活性来定制特定需求。让我们通过不同场景来探索其用法：

  • 使用 -Xlog 选项配置日志系统：-Xlog 选项是一个强大的工具，用于配置日志系统。其灵活的语法 -Xlog:tags:output:decorators:level 允许你自定义记录什么、记录在哪里以及如何呈现。

  • 为特定标签启用日志记录：如果你想为 gc 和 compiler 标签启用 info 级别的日志记录，可以使用以下命令：

    $ java -Xlog:gc,compiler:info MyApp

  • 为不同标签指定不同级别：也可以为不同标签指定不同级别。例如，如果你希望 gc 日志在 info 级别，但 compiler 日志在 warning 级别，可以使用以下命令：

    $ java -Xlog:gc=info,compiler=warning MyApp

  • 记录到不同输出：默认情况下，日志写入 stdout。但你可以指定不同的输出，例如文件。例如：

    $ java -Xlog:gc:file=gc.log MyApp

    这将把所有 gc 日志写入 gc.log 文件。

  • 使用装饰器包含额外信息：你可以使用装饰器在日志消息中包含更多上下文。例如，要在 gc 日志中包含时间戳，可以使用以下命令：

    $ java -Xlog:gc*:file=gc.log:time MyApp

    这将把 gc 日志写入 gc.log，每条日志消息前缀带有时间戳。

  • 启用所有日志：为了进行全面的日志记录（在调试或详细分析时尤其有用），可以使用以下命令启用所有级别的所有日志消息：

    $ java -Xlog:all=trace MyApp

    此命令确保捕获来自JVM的每一条可能的日志消息，从 trace 到 error 级别。虽然这提供了JVM操作的完整图景，但可能会导致大量日志数据，因此应谨慎使用。

  • 禁用日志记录：如果你想关闭日志记录，可以使用以下命令：

    $ java -Xlog:off MyApp

基准测试与性能测试

统一日志系统在基准测试和性能测试场景中至关重要。通过深入分析日志，开发人员可以了解他们的应用程序在不同工作负载和配置下的表现。这些信息可用于对应用程序进行微调，以实现最佳性能。

例如，垃圾收集日志可以洞察应用程序的内存使用模式，从而指导调整堆大小和微调其他GC参数以提高效率。此外，其他类型的日志，如JIT编译日志、线程活动日志或前面讨论的监视器膨胀日志，也能提供有价值的信息。例如，JIT编译日志有助于识别性能关键方法³，而线程和监视器膨胀日志可用于诊断并发问题或线程利用效率低下。

除了在性能测试期间使用这些日志之外，将它们集成到回归测试框架中也至关重要。这可以确保新的更改或更新不会对应用程序性能产生不利影响。通过这种方式，持续集成流水线可以显著简化在持续交付环境中识别和解决性能瓶颈的过程。

然而，重要的是要注意，解释这些日志通常需要对JVM行为有细致的理解。例如，GC日志可能很复杂，需要对Java中的内存管理有深入了解。同样，解读JIT编译日志需要了解JVM如何优化代码执行。将日志分析与其他性能测试方法相结合，可以确保对应用程序性能进行全面评估。

工具与技术

由于可能涌入大量数据，分析JVM日志可能是一项复杂的工作。然而，借助专门的工具和技术，这项任务的复杂性大大降低。日志分析工具善于解析日志并以更易于管理和理解的格式呈现数据。这些工具可以过滤、搜索和聚合日志数据，使定位相关信息更加容易。同样，可视化工具可以帮助识别日志数据中的模式和趋势。它们可以将文本日志数据转换为图形表示，从而更容易发现异常或性能瓶颈。

此外，基于历史数据，机器学习技术可以预测未来的性能趋势。这种预测性分析对于主动的系统维护和优化至关重要。然而，有效使用这些技术需要大量的历史数据以及对数据科学原理的基本理解。

这些工具不仅在问题识别方面有重要作用，而且在操作响应中也扮演着角色，例如根据日志分析结果触发警报或自动操作。我们将在第5章“端到端Java性能优化：工程技术与JMH微基准测试”中学习性能技术。

注：³ 我们在第1章“Java的性能演变：语言与虚拟机”中已介绍过性能关键方法。

优化与管理统一日志系统

尽管统一日志系统是诊断和监控不可或缺的工具，但其使用需要仔细考虑，特别是对应用程序性能的影响。过多的日志记录可能导致性能下降，因为系统需要花费额外资源写入日志文件。此外，大量的日志记录会消耗大量磁盘空间，这在存储有限的环境中可能是一个问题。为帮助管理磁盘空间使用，可以根据需要压缩、轮转日志文件或将其移动到辅助存储。

因此，平衡详细日志信息的需求与潜在的性能影响至关重要。一种方法是在生产环境中调整日志级别，只包含最重要的消息。例如，在高流量场景中，将某些消息记录在错误和警告级别可能比将所有消息记录在信息、调试或跟踪级别更合适。

另一个考虑因素是日志消息的输出目标。在应用程序的开发阶段，建议将日志消息直接输出到 stdout（这也是日志系统的默认设置）。然而，在生产环境中，将日志消息写入文件可能更合适，以便之后可以存档并按需分析。

统一日志系统的一个高级特性是能够在运行时动态调整日志级别。这一功能对于实时应用程序的故障排除尤其有益。例如，你可能通常以标准日志记录运行应用程序以最大化性能。但在流量激增或观察到特定模式增加时，你可以临时更改日志标签级别以收集更多相关信息。一旦问题解决并恢复正常，无需重启应用程序即可恢复到原始日志级别。

这种动态日志功能通过 jcmd 工具实现，该工具允许向正在运行的JVM发送命令。例如，要将 gc* 标签的日志级别提高到 trace，并添加一些有用的修饰符，可以使用以下命令：

$ jcmd <pid> VM.log what=gc*=trace decorators=uptimemillis,tid,hostname

其中 <pid> 是正在运行的JVM的进程ID。执行此命令后，JVM将以trace级别记录所有垃圾收集活动，包括毫秒级的运行时间、线程ID和主机名修饰符。这为我们提供了全面的诊断信息。

要查看可配置选项的完整范围，可以使用以下命令：

$ jcmd <pid> help VM.log

尽管统一日志系统提供了丰富的信息，但明智地使用它至关重要。通过调整日志级别、选择合适的输出以及利用动态日志功能，你可以有效管理日志细节与系统性能之间的权衡。

异步日志记录与统一日志系统

Java统一日志系统的演进带来了另一个值得注意的高级（可选）特性：异步日志记录。与传统的同步日志记录（在某些条件下可能成为应用程序性能瓶颈）不同，异步日志记录将日志写入任务委托给一个单独的线程。日志条目被放置在一个临时缓冲区，然后传输到最终输出。这种方法最小化了日志记录对主应用程序线程的影响——这对于现代大规模、延迟敏感的应用程序至关重要。

异步日志记录的优势

  • 降低延迟：通过卸载日志记录活动，异步日志记录显著降低了应用程序处理中的延迟，确保关键操作不会被日志写入延迟。
  • 提高吞吐量：在I/O密集型环境中，异步日志记录通过并行处理日志活动来提高应用程序吞吐量，释放主应用程序以处理更多请求。
  • 负载下的稳定性：异步日志记录最显著的优势之一是即使在大量应用程序负载下也能保持稳定的性能。它有效减轻了日志记录导致的瓶颈风险，确保性能稳定且可预测。

在Java中实现异步日志记录

使用现有库和框架

Java提供了几个支持异步功能的健壮日志框架，例如Log4j2和Logback：

  • Log4j2⁴：Log4j2的异步日志记录器利用LMAX Disruptor（一个高性能线程间消息传递库）提供低延迟和高吞吐量的日志记录。其配置涉及在配置文件中指定 AsyncLogger，然后将日志事件定向到环形缓冲区，从而减少日志记录开销。
  • Logback⁵：在Logback中，可以通过 AsyncAppender 包装器启用异步日志记录，该包装器缓冲日志事件并将其分派到指定的附加器。配置包括用 AsyncAppender 包装现有附加器，并调整缓冲区大小和其他参数以平衡性能和资源使用。

在这两个框架中，配置异步日志记录器通常涉及XML或JSON配置文件，可以在其中定义各种参数，如缓冲区大小、阻塞行为和底层附加器。

链接：⁴ https://logging.apache.org/log4j/2.x/manual/async.html
⁵ https://logback.qos.ch/manual/appenders.html#AsyncAppender

自定义异步日志记录解决方案

在某些场景下，标准框架可能无法满足应用程序的特定需求。在这种情况下，开发自定义异步日志记录解决方案可能是合适的。自定义实现的关键考虑因素包括：

  • 线程安全：确保日志记录操作是线程安全的，以避免数据损坏或不一致。
  • 内存管理：在日志记录过程中高效管理内存，特别是在管理日志消息缓冲区时，以防止内存泄漏或高内存消耗。
  • 示例实现：一个基本的自定义异步日志记录器可能涉及生产者-消费者模式，其中主应用程序线程（生产者）将日志消息入队到共享缓冲区，而一个单独的日志记录线程（消费者）出队并处理这些消息。

与统一JVM日志的集成

  • 挑战与解决方案：对于JDK 17之前的JVM版本或在复杂的日志记录场景中，将外部异步日志记录框架与统一JVM日志系统集成需要仔细配置以确保兼容性和性能。这可能涉及设置JVM标志和参数，以正确地将日志消息路由到异步日志记录系统。
  • JDK 17及更高版本的原生支持：从JDK 17开始，统一日志系统原生支持异步日志记录。可以使用 -Xlog:async 选项启用，使JVM的内部日志记录能够异步处理，而不影响JVM本身的性能。

最佳实践与注意事项

管理日志背压

  • 挑战：在异步日志记录中，当日志消息生成速率超过处理和写入这些消息的能力时，就会发生背压。这可能导致性能下降或日志数据丢失。
  • 有界队列：在日志系统中实现有界队列有助于管理日志消息的累积。通过限制未处理消息的数量，这些队列防止内存过度使用。
  • 丢弃策略：当队列达到容量时，建立丢弃日志消息的策略可以防止系统过载。这可能涉及丢弃不太关键的日志消息或汇总消息内容。
  • 实际例子：一个高流量的Web应用程序可能会实现一个丢弃策略，在峰值负载期间优先记录错误日志而不是信息日志，以维持系统稳定性。

确保日志的可靠性

  • 关键性：日志系统的可靠性至关重要，特别是在应用程序崩溃或意外关闭时。在这些情况下丢失日志数据会阻碍故障排除，并影响合规性。
  • 预写日志：实现预写日志可确保即使在应用程序失败时日志数据也能得到保留。该技术在实际日志操作完成之前将日志数据写入持久化存储位置。
  • 优雅关闭程序：设计能够优雅处理关闭的日志系统，确保在应用程序完全停止前所有缓冲日志数据都被写出。
  • 应对不利条件的策略：在日志基础设施中引入冗余，以便即使主要日志机制失败也能捕获日志数据。这在多组件生成日志的分布式系统中尤为相关。

异步日志系统的性能调优

  • 调优以达最佳性能

    • 线程池大小：调整专门用于异步日志的线程数量至关重要。更多线程能够处理更高的日志量，但过多线程可能导致CPU开销过大。
    • 缓冲区容量：如果应用程序出现周期性的日志生成峰值，增大缓冲区大小有助于吸收这些峰值。
    • 处理间隔：日志从缓冲区刷新到输出的频率会影响性能和日志的实时性。调整此间隔有助于平衡CPU使用率和日志写入的即时性。

  • JDK 17 中异步日志的注意事项

    • 缓冲区大小调优：AsyncLogBufferSize 参数对于管理系统在刷新前能够处理的日志消息量至关重要。较大的缓冲区可以容纳更多日志消息，在日志生成峰值期间非常有益。然而，较大的缓冲区也需要更多内存。
    • 监控 JDK 17 的异步日志：使用新的异步日志功能，可能需要更新监控工具和技术，以跟踪新缓冲区的使用情况和日志系统的性能。

监控与指标

  • 缓冲区利用率：你可以使用日志框架的内部指标或自定义监控脚本来跟踪缓冲区使用情况。如果缓冲区利用率持续超过80%，则表明应增大其大小。
  • 队列长度：可以使用监控工具或日志框架API跟踪日志队列的长度。持续较长的队列需要更多日志线程或更大的缓冲区。
  • 写入延迟：测量日志消息创建与其最终写入操作之间的时间差可以揭示写入延迟。如果这些延迟持续较高，优化文件I/O操作或将日志分配到多个文件或磁盘可能有所帮助。
  • JVM工具与指标：像JVisualVM⁶和Java Mission Control (JMC)⁷等工具可以提供JVM性能的洞察，包括可能影响日志的方面，如线程活动或内存使用。

⁶ https://visualvm.github.io/
⁷ https://jdk.java.net/jmc/8/

理解 JDK 11 和 JDK 17 的增强

统一日志系统首次引入于JDK 9，并在后续JDK版本中经历了优化和增强。本节讨论JDK 11和JDK 17在统一日志方面的重要改进。

JDK 11

在JDK 11中，统一日志框架的一个显著改进是增加了在运行时动态配置日志的能力。这一增强通过jcmd工具实现，允许开发者向正在运行的JVM发送命令，包括调整日志级别的命令。这一创新极大地惠及了开发者，使他们能够根据诊断需求增加或减少日志记录，而无需重启JVM。

JDK 11还通过为Logger和LogManager引入新方法来改进java.util.logging。这些新增功能进一步增强了日志控制能力，为开发者在使用Java日志时提供了更细粒度和灵活性。

JDK 17

JDK 17在JVM的统一日志系统中原生支持了异步日志的改进。此外，JDK 17还带来了更广泛的、间接的改进，提升了日志系统的整体性能、安全性和稳定性。这些改进有助于统一日志的有效性，因为一个更稳定、更安全的系统总是有利于准确可靠的日志记录。

结论

在本章中，我们探讨了统一日志系统，展示了其实际用法，并概述了后续JDK版本中引入的增强功能。JVM中的统一日志系统为所有日志消息提供了一个单一、一致的接口。这种跨JVM的和谐性提高了可读性和可解析性，有效地消除了日志交错或混杂的问题。保留将日志重定向到文件的能力（这是JDK 9之前就已具备的功能）是保留早期日志机制有用性的关键部分。日志继续以人类可读格式呈现，默认情况下时间戳显示运行时间。

统一日志系统还提供了重要的增值特性。JDK 11中引入的动态日志允许开发者在运行时调整日志命令。结合统一日志系统提供的增强可见性和对应用程序过程的控制，开发者现在可以通过命令行输入指定所需的日志信息深度，从而提高调试和性能测试的效率。

从统一日志系统获取的信息可用于调整JVM参数以达到最佳性能。例如，笔者拥有自己的GC解析和绘图工具包，现在更加整合和简化，能够提供内存使用模式、暂停事件、堆利用率、暂停细节以及与收集器类型相关的各种其他模式的洞察。这些信息可用于调整堆大小、选择合适的垃圾收集器以及调优其他垃圾收集参数。

Java的新功能，如Project Loom和Z垃圾收集器（ZGC），对JVM性能有重要影响。可以通过统一日志系统监控这些功能，以了解它们对应用程序性能的影响。例如，ZGC日志可以提供GC暂停时间和内存回收效率的洞察。我们将在后续章节中了解更多关于这些功能的信息。

总之，JVM中的统一日志系统是开发者手中的一个强大工具。通过理解和利用该系统，开发者可以简化故障排除工作，更深入地洞察Java应用程序的行为和性能。跨不同JDK版本的持续增强使统一日志系统更加健壮和多功能，巩固了其作为Java开发者工具包中必不可少的工具的地位。

Footnotes

  1. https://openjdk.org/jeps/158 ↩

  2. https://openjdk.org/jeps/271 ↩