坊间传闻,log4j对服务性能会造成不利影响,现从log4j的实现源码一探究竟。
一、从调用开始
打印日志时,接触最多的就是Logger类了。
从Logger实例的创建:
org.apache.log4j.Logger logger = Logger.getLogger("日志实例名");
到Logger实例的使用:
logger.trace("trace");
logger.info("info");
logger.error("error");
打印日志所需的一切功能都已具备,一切看起来如此简单,核心就是类Logger。
其实不然,Logger类只是提供了有限的几个方法:
其中核心方法之一:
static public Logger getLogger(String name) {
return LogManager.getLogger(name);
}
完全依赖类LogManager的实现。然后Logger类对trace()方法做了简单的支持。其他的核心方法,全部继承自其父类,也是log4j中的核心类org.apache.log4j.Category
。
而日志的打印,Category类的forceLog()方法提供了支持:
//This method creates a new logging event and logs the event
//without further checks.
protected void forcedLog(String fqcn, Priority level, Object message, Throwable t) {
callAppenders(new LoggingEvent(fqcn, this, level, message, t));
}
该方法依赖的callAppenders()是被认为是造成性能降低的罪魁祸首:
/**
* Call the appenders in the hierrachy starting at
* <code>this</code>. If no appenders could be found, emit a
* warning.
*
* <p>This method calls all the appenders inherited from the
* hierarchy circumventing any evaluation of whether to log or not
* to log the particular log request.
*
* @param event the event to log.
*/
public void callAppenders(LoggingEvent event) {
int writes = 0;
for (Category c = this; c != null; c = c.parent) {
// Protected against simultaneous call to addAppender, removeAppender,...
synchronized (c) {
if (c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if (!c.additive) {
break;
}
}
}
if (writes == 0) {
repository.emitNoAppenderWarning(this);
}
}
整个日志打印的方法调用流程如下:
这三个方法都是类Logger的实例方法。
二、锁的竞争
源码实现中看到了同步代码块,锁竞争的确会在一定程度上造成性能降低;通常服务的业务方法或多或少都会打印日志,这导致请求处理时间增加。
从实现代码中看到,每次打印日志,都会首先获取当前对象this
的内部锁(synchronized
机制),然后循环获取当前对象的parent
的锁。类Category持有一个类型为Category,名为parent的属性,用以保持对父级Logger的引用。
从逻辑上讲,如果对同一个锁的竞争越激烈,对性能造成的影响约大。但是通常在业务代码中,对于每一个业务服务类,我们都会使用如下的方式:
Logger logger = Logger.getLogger(CurrentServiceClassName.class);
来获取日志实例。由于日志实例不同,那么在callAppenders()方法的同步代码块中,synchronized(this)
的时候,竞争的不是同一个锁,对性能影响不大。
因此,只能“寄希望于”不同日志实例的parent
,如果各个不同的日志实例是同一个对象,那么,日志的打印就“可以”对性能造成很大影响了。下面从log4j日志系统的初始化过程来证明这一点。
二、log4j初始化
Category类
首先关注核心类Category,
public class Category implements AppenderAttachable {
//The parent of this category. All categories have at least one
// ancestor which is the root category.
// 当前logger的父级,所有的logger至少有一个祖先(根logger)
volatile protected Category parent;
}
以上我们已经了解到,日志实例在打印日志时,方法callAppenders()中会循环获取其parent的锁,这里的parent就是父级logger。那么parent字段是何时初始化呢 ?
正向查找太难,在没有文档资料参考的情况下,我们不知道log4j的初始化顺序是怎样的。那么不妨逆向去找,既然重点是parent字段,那么只要看parent的赋值操作,就可以一窥端倪:
发现在类Hierarchy
中,对parent做了赋值操作。
Hierarchy类
另一个核心类是Hierarchy,继承自接口LoggerRepository
。
正如其名字一样,LoggerRepository是所有logger的仓库,用于创建以及检索logger。LoggerRepository仓库中日志logger的关系取决于仓库本身,但是通常日志logger之间的关系是以名称决定的层级结构。除了创建方法之外,已经存在的日志logger可以在LoggerRepository中查询,此外LoggerRepository也可以作为日志logger相关事件的注册表。
Hierarchy作为LoggerRepository的子类,专门用来根据名字检索日志logger以及维护日志的层次结构。 通常用户不需要与Hierarchy类打交道。
日志logger之间的层次结构依赖于 Hierarchy的getLogger()
方法维护。这个层次结构中,子logger可以链接到他们的父级logger,但是父级logger不指向子logger。此外,日志logger可以以任何顺序初始化,甚至子孙logger可以在祖先logger之前初始化。
1. void updateParents(Logger)
以上是LoggerRepository类以及Hierarchy类的自说明文档。下面继续按照Category类中parent
赋值的线索。
Hierarchy类中方法updateParents(Logger)
对Category的parent属性做了赋值操作,这里的参数是Logger,因为Logger是Category的子类,也有parent属性:
final private void updateParents(Logger cat) {
String name = cat.name;
int length = name.length();
boolean parentFound = false;
// if name = "w.x.y.z", loop thourgh "w.x.y", "w.x" and "w", but not "w.x.y.z"
for (int i = name.lastIndexOf('.', length - 1); i >= 0;
i = name.lastIndexOf('.', i - 1)) {
String substr = name.substring(0, i);
//System.out.println("Updating parent : " + substr);
CategoryKey key = new CategoryKey(substr); // simple constructor
Object o = ht.get(key);
// Create a provision node for a future parent.
if (o == null) {
//System.out.println("No parent "+substr+" found. Creating ProvisionNode.");
ProvisionNode pn = new ProvisionNode(cat);
ht.put(key, pn);
} else if (o instanceof Category) {
parentFound = true;
cat.parent = (Category) o;
//System.out.println("Linking " + cat.name + " -> " + ((Category) o).name);
break; // no need to update the ancestors of the closest ancestor
} else if (o instanceof ProvisionNode) {
((ProvisionNode) o).addElement(cat);
} else {
Exception e = new IllegalStateException("unexpected object type " +
o.getClass() + " in ht.");
e.printStackTrace();
}
}
// If we could not find any existing parents, then link with root.
if (!parentFound)
cat.parent = root;
}
Hierarchy中,一个名为ht
的HashTable负责存储已将创建的全部节点,作为LoggerRepository的具体实现。
Hashtable ht;
该方法中,按照Logger的名字(name属性),以.
分割,从右向左依次循环,直到在ht
中找到类型为Category的节点,并作为当前logger的parent,如果没有找到,使用root
作为parent。这里的root是Hierarchy构造函数中传递的参数logger,由调用方决定。
正如注释所示,如果name = "w.x.y.z", 那么从 "w.x.y", "w.x" 以及 "w"依次去ht
中寻找类型为Category的节点作为parent。
2. Logger getLogger(String name, LoggerFactory factory)
继续线索,updateParents方法唯一被Hierarchy中的getLogger(String, LoggerFactory)
调用:
public Logger getLogger(String name, LoggerFactory factory) {
//System.out.println("getInstance("+name+") called.");
CategoryKey key = new CategoryKey(name);
// Synchronize to prevent write conflicts. Read conflicts (in
// getChainedLevel method) are possible only if variable
// assignments are non-atomic.
Logger logger;
synchronized (ht) {
Object o = ht.get(key);
if (o == null) {
logger = factory.makeNewLoggerInstance(name);
logger.setHierarchy(this);
ht.put(key, logger);
updateParents(logger);
return logger;
} else if (o instanceof Logger) {
return (Logger) o;
} else if (o instanceof ProvisionNode) {
//System.out.println("("+name+") ht.get(this) returned ProvisionNode");
logger = factory.makeNewLoggerInstance(name);
logger.setHierarchy(this);
ht.put(key, logger);
updateChildren((ProvisionNode) o, logger);
updateParents(logger);
return logger;
} else {
// It should be impossible to arrive here
return null; // but let's keep the compiler happy.
}
}
}
首先尝试从ht中取出同名的logger:
- 若不存在,使用工厂方法创建一个logger并加入ht,之后调用updateParents()更新logger的parent;
- 若存在,并且是Logger类型的,直接返回;
- 若是ProvisionNode类型,则根据名字name创建logger,加入ht,更新logger的parent。这里有一个额外的操作是更新该ProvisionNode下的所有子节点的parent为当前logger。
log4j支持子孙节点在祖先节点之前初始化的关键就是ProvisionNode。
在updateParents中,若从ht找不到name代表的父节点,则使用父节点名创建一个ProvisionNode,ProvisionNode维持一个Logger类型的列表,创建ProvisionNode时自动将logger加入列表,ProvisionNode称为logger的未来节点,在未来同名的Logger在getLogger()方法中创建时,会代替未来节点。updateParents方法总是能找到一个类型为Logger的父节点,根节点兜底。
在getLogger中,若name在ht已经作为一个ProvisionNode存在,则替换ht中同名ProvisionNode,更新当前logger父节点的同时,依赖ProvisionNode未来节点维持的列表,使用当前logger替换。
到这里已经解释了不同的logger为什么会有相同的parent了,层次机制主要由Hierarchy维持,层次越高,锁竞争越激烈。
如果一个jvm中只有一个Hierarchy结构,那么这种竞争更加激烈。
3. LogManager初始化
继续看getLogger()方法的调用者:
使用Logger类的静态方法getLogger()间接依赖Hierarchy的getLogger();
其他的使用都是与log4j的初始化相关。
通过逆向调用追踪,最终在LogManager
的static
代码块发现了Hierarchy getLogger()的调用。
在LogManager初始化时:
- 创建一个Hierarchy对象作为log4j的logger仓库;
- 在约定类路径位置寻找配置文件,输出URL;
- 根据配置文件的类型,选择DOMConfigurator或者PropertyConfigurator初始化日志系统;
[DOM,Property]Configurator初始化日志系统,其实是对logger仓库Hierarchy对象初始化。
这里我们只关注对Logger的初始化,以PropertyConfigurator为例,根据配置,若行以log4j.category.
或者log4j.logger.
开头,则调用Hierarchy对象的getLogger方法初始化配置的logger实例:
protected void parseCatsAndRenderers(Properties props, LoggerRepository hierarchy) {
// ...
loop props:
if key statswith CATEGORY_PREFIX or LOGGER_PREFIX:
Logger logger = hierarchy.getLogger(loggerName, loggerFactory);
//...
}
以上结合LogMamanger的getLogger方法,logger的创建在两个地方:
- 手动调用创建logger实例;
- 配置初始化时,会以
log4j.category.
或者log4j.logger.
开头的行,创建指定名字的logger。
LogManager的static代码块保证了同一个JVM中,只会初始化一次LogManager(若不存在人为加载并初始化LogManager的情况),从而保证一个JVM只有一个logger仓库Hierarchy对象。因此在所有的日志打印中,都会竞争日志层次结构中最顶层的logger对象锁。
三、总结
以下是log4j初始化过程中几个重要的类: