日志调用到输出端之间有 logger、级别、handler、formatter 好几层。这篇用 java.util.logging 真实运行:看一条记录什么时候能被输出、被过滤的日志有多少成本、文件轮转的实际表现,以及几个容易踩的坑。
新建 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 次(只有拼接写法在日志被过滤时仍执行)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]
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 第一次初始化时读取)