周六的早晨8点,应用出现了大面积的登录超时问题。

作为一款日活15W、用户量700W+的应用,这是致命的问题。

唯一的安慰是——好在今天是周末,加班的公司才会使用。虽然如此,客服、产品的电话也被打爆了。

初步怀疑,问题与前一天晚上的更新有关,运维的同事回滚了更新,应用全部回滚完毕,然而,问题依然没有解决,服务依然不可用。

运维开始束手无策,9点钟的时候,基本所有的开发teamleader都过来了,加上架构部的,十几号人开始分析问题,客服、运营、产品们忙着安慰客户,发公告。总监、副总裁都过来了,看着一群开发忙来忙去的找问题。

我们最先怀疑的是后端的基础系统故障(历史经验,这一块出问题的可能性比较大),mongo, mysql,  redis, memcache, rabbitmq一个个排查,它们的表现都正常:群集读写的压力都很小,请求处理时间短。

在排除了以上系统的问题之后,我们把怀疑的对象对准了一个Http服务,这是一个古老的服务,使用oauth 1.0 ,底层的http不能指定超时(而新的服务都是使用async-http实现,有超时设置),屏蔽服务后,问题依然存在。

后续的分析,集中在内部服务接口的请求上。通过vpn直接请求内部接口,测了几个在网关层请求都超时的服务,它们的返回都正常,最终将问题锁定在了网关层的服务。

网关层服务是一个轻量级的服务,它的主要职责是两件事:(1)鉴权(移动端、ERP)(2)路由(按业务),理论上这个服务不应该出现问题,不管它,先dump内存看看。

将网关层应用的内存dump下来后,发现了问题: 

"qtp1056944384-232" prio=10 tid=0x00007f54900d0800 nid=0x63b3 waiting for monitor entry [0x00007f54492d0000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:205)
	- waiting to lock <0x00000007e81c4830> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:368)

 总计有200多个log4j的线程在等待锁"0x00000007e81c4830",而这把锁被谁持有呢?通过搜索,找到以下dump信息:

"qtp1056944384-218" prio=10 tid=0x00007f54800bb800 nid=0x63a5 runnable [0x00007f544a0de000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketOutputStream.socketWrite0(Native Method)
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:141)
	at net.logstash.log4j.SocketAppender.append(SocketAppender.java:190)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	- locked <0x00000007e8210868> (a net.logstash.log4j.SocketAppender)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	- locked <0x00000007e81c4830> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:368)

 第218号线程持有了锁"0x00000007e81c4830",然后其它log4j的线程都在等待这把锁的释放。可以看到,这把锁的持有者,一个关键字“logstash.log4j”,因此初步诊断和最近添加的elk有关。elk 即 Logstash+ElasticSearch+Kibana4,它是架构部近期引入的一个实时日志分析系统,最近的调整是:log4j.rootLogger 参数,添加了实时将日志打到logstash,而logstash在早晨8点的时候日志片段如下:

WARNING: [logstash-elk_0_47-16997-7944] [gc][young][2284683][25218] duration [1.1s], collections [1]/[1.8s], total [1.1s]/[12.2m], memory [1gb]->[915.1mb]/[3.9gb], all_pools {[young] [269.4mb]->[6.4mb]/[532.5mb]}{[survivor] [50.3mb]->[50.3mb]/[66.5mb]}{[old] [742.8mb]->[858.4mb]/[3.3gb]}
{:timestamp=>"2015-12-12T08:01:00.606000+0800", :message=>"retrying failed action with response code: 503", :level=>:warn}
{:timestamp=>"2015-12-12T08:01:00.636000+0800", :message=>"retrying failed action with response code: 503", :level=>:warn}
{:timestamp=>"2015-12-12T08:01:00.637000+0800", :message=>"retrying failed action with response code: 503", :level=>:warn}
{:timestamp=>"2015-12-12T08:01:00.637000+0800", :message=>"retrying failed action with response code: 503", :level=>:warn}

 logstash出现了大量的503,查看elasticsearch的日志片段:

[2015-12-12 08:00:00,244][INFO ][cluster.metadata         ] [Iron Man] [logstash-2015.12.12] creating index, cause [auto(bulk api)], templates [logstash], shards [5]/[0], mappings [_default_]
[2015-12-12 08:00:00,285][INFO ][cluster.metadata         ] [Iron Man] [app-logs-2015.12.12] creating index, cause [auto(bulk api)], templates [], shards [5]/[0], mappings []
[2015-12-12 08:00:18,053][WARN ][cluster.routing.allocation.decider] [Iron Man] high disk watermark [10%] exceeded on [o-oE92qNSyyoqbzUoRTS7Q][Iron Man] free: 34.5gb[7%], shards will be relocated away from this node
[2015-12-12 08:00:48,053][WARN ][cluster.routing.allocation.decider] [Iron Man] high disk watermark [10%] exceeded on [o-oE92qNSyyoqbzUoRTS7Q][Iron Man] free: 34.5gb[7%], shards will be relocated away from this node
[2015-12-12 08:00:48,054][INFO ][cluster.routing.allocation.decider] [Iron Man] high disk watermark exceeded on one or more nodes, rerouting shards
[2015-12-12 08:01:18,087][WARN ][cluster.routing.allocation.decider] [Iron Man] high disk watermark [10%] exceeded on [o-oE92qNSyyoqbzUoRTS7Q][Iron Man] free: 34.5gb[7%], shards will be relocated away from this node
[2015-12-12 08:01:48,054][WARN ][cluster.routing.allocation.decider] [Iron Man] high disk watermark [10%] exceeded on [o-oE92qNSyyoqbzUoRTS7Q][Iron Man] free: 34.5gb[7%], shards will be relocated away from this node
[2015-12-12 08:02:18,054][WARN ][cluster.routing.allocation.decider] [Iron Man] high disk watermark [10%] exceeded on [o-oE92qNSyyoqbzUoRTS7Q][Iron Man] free: 34.5gb[7%], shards will be relocated away from this node
[2015-12-12 08:02:18,054][INFO ][cluster.routing.allocation.decider] [Iron Man] high disk watermark exceeded on one or more nodes, rerouting shards
[2015-12-12 08:02:48,054][WARN ][cluster.routing.allocation.decider] [Iron Man] high disk watermark [10%] exceeded on [o-oE92qNSyyoqbzUoRTS7Q][Iron Man] free: 34.5gb[7%], shards will be relocated away from this node
[2015-12-12 08:03:18,054][WARN ][cluster.routing.allocation.decider] [Iron Man] high disk watermark [10%] exceeded on [o-oE92qNSyyoqbzUoRTS7Q][Iron Man] free: 34.7gb[7%], shards will be relocated away from this node
[2015-12-12 08:03:18,055][INFO ][cluster.routing.allocation.decider] [Iron Man] high disk watermark exceeded on one or more nodes, rerouting shards

运维的同事说,elk是单节点,而此时,elasticsearch由于磁盘空间不够,出现了服务不可用(没有添加预警),logstash阻塞。logstash阻塞,导致网关服务整个集群不可用。

初步的处理是,停用logstash同步写,同时将生产环境日志临时调整为fatal(为了减少日志量)。

为什么log4j会出现几百个线程等待一个锁的问题呢?后面笔者分析的log4j的Category.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);
    }
  }

log4j版本1.x中,使用的是古老的synchronized(this),所有线程共用一个Category,而它通过log4j.properties指定。 同一个Category下的线程打log时,需要进行全局同步,因此它的效率会很低,log4j 1.x版不适合高并发的场景。

为了杜绝这样的问题,后续需要吸取教训:

1. 尽量减少不必要的日志,在成熟的接口上,关闭日志输出,这样有利于提高效率。

2. 替换底层log的实现类,不再使用log4j 1.x,使用logback(推荐)或者新的log4j 2.x版本。

最后,附带两篇关于log4j 1.x中,日志系统死锁的分析(我们最开始怀疑是这个问题):

https://bz.apache.org/bugzilla/show_bug.cgi?id=50213

http://javaeesupportpatterns.blogspot.com/2012/09/log4j-thread-deadlock-case-study.html

 

posted @ 2015-12-12 17:23 素轩 阅读(6305) 评论(0) 推荐(3) 编辑
摘要: 何谓反射机制JAVA反射机制是在运行状态中,对于任意一个类,都能够知道这个类的所有属性和方法;对于任意一个对象,都能够调用它的任意一个方法;这种动态获取的信息以及动态调用对象的方法的功能称为java语言的反射机制。 阅读全文
posted @ 2015-11-26 00:06 素轩 阅读(164) 评论(0) 推荐(0) 编辑
摘要: 作者简介Dong Lea任职于纽约州立大学奥斯威戈分校(State University of New York at Oswego),他发布了第一个广泛使用的java collections框架实现,他实现了java.concurrent.*(JDK5开始至今)。论文译文开始:论文摘要本论文介绍一... 阅读全文
posted @ 2015-11-17 00:08 素轩 阅读(4915) 评论(1) 推荐(0) 编辑
摘要: 在泛型编程时,使用部分限定的形参时,和的使用场景容易混淆,PECS原则可以帮助我们很好记住它们:生产者(Producer)使用extends,消费者(Consumer)使用super。留下一段代码加深印象(来自JDK 8 Collections.copy()源码)/** * Copies a... 阅读全文
posted @ 2015-11-16 23:48 素轩 阅读(5560) 评论(0) 推荐(1) 编辑
摘要: Executor框架集对线程调度进行了封装,将任务提交和任务执行解耦。它提供了线程生命周期调度的所有方法,大大简化了线程调度和同步的门槛。Executor框架集的核心类图如下:从上往下,可以很清晰的看出框架集的各个类,以及它们之间的关系:Executor,是一个可以提交可执行(Runnable)任务... 阅读全文
posted @ 2015-11-08 23:54 素轩 阅读(3380) 评论(0) 推荐(1) 编辑
摘要: 1. 复制集(Replica sets)模式时,其会使用下面的local数据库local.system.replset 用于复制集配置对象存储 (通过shell下的rs.conf()或直接查询)local.oplog.rs 一个capped collection集合.可在命令行下使用--oplogS... 阅读全文
posted @ 2015-11-08 23:53 素轩 阅读(4437) 评论(0) 推荐(0) 编辑
摘要: 移相器(Phaser)内有2个重要状态,分别是phase和party。phase就是阶段,初值为0,当所有的线程执行完本轮任务,同时开始下一轮任务时,意味着当前阶段已结束,进入到下一阶段,phase的值自动加1。party就是线程,party=4就意味着Phaser对象当前管理着4个线程。Phase... 阅读全文
posted @ 2015-11-08 23:52 素轩 阅读(552) 评论(0) 推荐(0) 编辑
摘要: Semaphore 直译是信号量,它的功能比较好理解,就是通过构造函数设定一个数量的许可,然后通过 acquire 方法获得许可,release 方法释放许可。它还有 tryAcquire 和 acquireUninterruptibly 方法,可以根据自己的需要选择。以下是模拟一个连接池,控制同一... 阅读全文
posted @ 2015-11-08 23:51 素轩 阅读(274) 评论(0) 推荐(0) 编辑
摘要: 闭锁是一种同步器 ( Synchronizer ),它可以延迟线程的进度直到线程到达终止状态,CountDownLatch是一个灵活的闭锁实现:1)允许一个或多个线程等待一个事件集的发生,闭锁的状态包括一个计数器,初始化为一个正数,用来实现需要等待的事件数。2)countDown对计数器做减操作,表... 阅读全文
posted @ 2015-11-08 23:50 素轩 阅读(1272) 评论(0) 推荐(1) 编辑
摘要: CyclicBarrier 直译过来叫循环栅栏,它主要的方法就是一个:await()。await() 方法没被调用一次,计数便会减少1,并阻塞住当前线程。当计数减至0时,阻塞解除,所有在此 CyclicBarrier 上面阻塞的线程开始运行。在这之后,如果再次调用 await() 方法,计数就又会变... 阅读全文
posted @ 2015-11-08 23:50 素轩 阅读(291) 评论(0) 推荐(0) 编辑
点击右上角即可分享
微信分享提示