bigywater.tech
Java · 220

Java Logging Pipeline:从日志调用到输出端

日志调用到输出端之间有 logger、级别、handler、formatter 好几层。这篇用 java.util.logging 真实运行:看一条记录什么时候能被输出、被过滤的日志有多少成本、文件轮转的实际表现,以及几个容易踩的坑。

21.9 / 0.6 ns
被过滤的 fine 调用:字符串拼接 / Supplier
6890 → 3 个文件
写入字节数与 FileHandler(limit 2000、count 3)保留的文件
null
没有强引用的 logger,GC 后 getLevel() 的结果

logger 层级、级别与 handler

实测 · 本机执行输出
  新建 app.svc.db:getLevel() = null,getParent() = app.svc(app.svc 的 parent = ,根 logger 的名字是空串)
  根 handler=INFO、根 logger=INFO:记录 FINE 与 INFO → handler 收到 [INFO@app.svc.db:i1]
  只把 app.svc 设为 FINE(子 app.svc.db 继承):FINE 记录 → handler 收到 [](根 handler 的级别仍是 INFO)
  再把根 handler 设为 ALL:FINE、FINER → handler 收到 [FINE@app.svc.db:f3](FINER 在 FINE 之下,被 logger 级别挡掉)
  给 app.svc.db 再加一个 handler:一条 INFO → 自己的 handler [INFO@app.svc.db:i2],根 handler [INFO@app.svc.db:i2](沿父链向上传播,两个 handler 都收到)
  setUseParentHandlers(false):→ 自己的 handler [INFO@app.svc.db:i3],根 handler []
  isLoggable(FINE) = true,isLoggable(FINER) = false,getLevel() = null(未设置 = null,有效级别来自父)

被过滤的日志调用的成本

实测 · 本机执行输出
  级别 WARNING 下记录 FINE 2000 万次,字符串拼接 fine("value=" + i + …)           每次 21.9 ns
  级别 WARNING 下记录 FINE 2000 万次,Supplier  fine(() -> …)                每次 0.6 ns
  级别 WARNING 下记录 FINE 2000 万次,参数化  log(FINE, "{0} {1}", Object[])    每次 2.0 ns
  昂贵计算被调用的次数:Supplier 写法(被过滤)+ 拼接写法(被过滤)之后 expensive() 共被调用 1 次(只有拼接写法在日志被过滤时仍执行)

FileHandler 轮转

实测 · 本机执行输出
  app0.log         805 字节  首行 INFO line-177-xxxxxxxxxxxxxxxxxxxx
  app0.log.lck       0 字节  首行 -
  app1.log        2030 字节  首行 INFO line-119-xxxxxxxxxxxxxxxxxxxx
  app2.log        2025 字节  首行 INFO line-60-xxxxxxxxxxxxxxxxxxxx
  limit = 2000 字节、count = 3:写了 200 行(共 6890 字节);app0.log 是当前文件,app1、app2 是被轮转下来的更旧的文件;更早的内容已被删除(最早一行 line-0 还在吗:false)
  close() 之后目录里的文件:[app0.log, app1.log, app2.log]

弱引用、System.Logger 与格式

实测 · 本机执行输出
  setLevel(FINE) 之后立刻读取:weak.demo = FINE(这次读取又创建了新的引用)
  没有持有引用的 logger,GC 之后重新获取 getLevel():weak.demo2 = null;持有引用的 held.demo = FINE
  System.getLogger 的实现类 = sun.util.logging.internal.LoggingProviderImpl$JULWrapper,isLoggable(DEBUG) = false,isLoggable(INFO) = true
  给同名 JUL logger 设 FINE 并加 handler 后,System.Logger 的 DEBUG、TRACE 记录 → [FINE@sys.demo:via-system-logger](DEBUG→FINE,TRACE→FINER)
  SimpleFormatter 默认格式(时间 + 来源类名与方法名;没有来源类名时显示 logger 名)首行 = <时间> fmt
  设置 java.util.logging.SimpleFormatter.format 属性后,ConsoleHandler 的输出(写到 System.err):INFO|fmt2|hello(属性在 SimpleFormatter 第一次初始化时读取)

分步演示

日志管线
本步的对象

    本文用到的工具与边界

    • 本机 macOS 27 arm64 / OpenJDK(Temurin 17.0.20、Homebrew 21.0.12 与 27,每篇注明实际用的版本);用 javac 编译、java 直接运行,需要第三方库时用 Maven 解析依赖;计时用 System.nanoTime,数字每次运行会有小幅抖动。JDK 21.0.12,java.util.logging 与 System.Logger
    • 没有验证:Log4j2 与 Logback(它们的异步与 appender 机制不同)、AsyncHandler 的吞吐、多进程写同一个日志文件、logging.properties 配置文件的所有选项、日志框架桥接(SLF4J 到 JUL);纳秒级成本数字受 JIT 影响,只代表这台机器上的这次测量
    京ICP备2026067502号-1京公网安备11010502063487号