更新总结

回顾一下

大约一周前，更新过一次线上，上了分享相册终端页，第二天新鲜事入口一打开，从早上开始就一直开始挂机器，起初认为是压力问题，后来加机器到了快晚上7点的时候，几乎大面积的挂掉，没办法，只能回滚。通过分析，发现是压力测试不到位，因为压力测试不够真实，不够真实是因为数据不够随机，导致缓存为服务减少了压力。

第二天亮哥写了一个足够随机的取数据算法，把算法移植到压测代码上后，进行压测，大概也是夜里7点左右进行，第一次压测不到5分钟就挂了，从现象上看是内存耗尽，FGC频繁。第二次压测大概进行了20分钟左右，又挂了。挂了代表压测足够真实。通过监控工具jconsole发现old区域的曲线一直在往上涨，涨到一定的时候，就挂了。第三次压测大概也进行了20分钟，也挂了，挂了的原因是亮哥无意间用Jstack抓了一个栈，曲线和第二次相似，自己百思不得其解。因为有GC，理论上不会让它一直只涨不跌的。初步认为是什么地方内存发生了泄漏。

第三天就在我还在纠结于内存泄漏这个问题的时候，亮哥从昨晚的堆栈log里找到了答案，堆栈里充满了大量的ReentrantLock，这东西看似不起眼的，有Lock但是栈里却没有Blocked，都被人忽略了。但是跟进代码里一看这把lock锁住了四部对DB的操作，3次查询一次插入。亮哥对我说先把lock干掉，这把锁有问题，代码不能这样写。

 

@Override
 public void save(ShareMap shareMap, int userId) {
        lock.lock();
        if (findMapId(shareMap.getShareId(), shareMap.getReferId(), userId) == 0){
            shareMap.setMapId(idSequenceDAO.nextId(IdSequenceDAO.SHARE_ID));
            shareMap.setId(idSequenceDAO.nextId(IdSequenceDAO.SHARE_MAP_ID));
            shareMapDAO.insert(shareMap, userId);
        }
        lock.unlock();
  }

 因为这把锁在并发量大的时候，完全可以造成无数的线程在这里造成一个临时性的Blocked。为了证明这个问题，我们进行了再一次的压测。这次我们压测从周五下午开始，刚开始一台机器，从监控曲线上看，old区域的内存一直在增加，直到它达到自己的最大内存时，突然一根直线下来降到最大内存的百分之30左右，看到这根曲线我就知道服务正常了。为了达到前一天夜里时候的压测压力，又加了一台机器的流量进行。这次压测我们的代码坚持到了周一我手动把压测服务给杀掉了。通过这次压测，几乎可以确认就是这把lock导致的线上服务大规模的瘫痪。

 

第一次压测学到的东西：
1、Lock的范围，粒度，以及该不该使用Lock。虽然说这把Lock加上是为了保证下面insert里的某些东西的唯一性，但是为一个概率很小的可能性事件消耗了线上服务的质量，真不值得。

2、服务器挂掉的原因，服务堵了，服务虽然没有Block，但是大大降低了并发效率，导致服务消耗了大量的内存在等待线程排队，使old区域的内存只涨不跌，直到挂掉。

3、知道JVM里面内存分布，内存的分代，知道了什么事FGC，什么是YGC。FGC对服务的影响。

 

 

压测成功了，我兴致满满的提测了，测试通过后，就急于更新线上的服务，在我觉得更完了，没事的时候，服务又挂了，这次几乎是一台接一台的挂掉，这次我傻了，心想优化了代码死的还更惨，一头雾水的我真不知掉咋办。想想压测白做了？我承认我当时很低落。低落的不敢看一眼流量图，这让我产生了一种挫败感。

 

那天夜里我在临近一台机器快要挂掉的时候，用Jstack抓了一个线程堆栈的log，接着回滚线上，然后在抓了一个老版本的jstack log 。

 

第二天早上一来，我试着对比了两个log。发现新代码的log里充满着大量的findShareMap方法，在往上看就是

 

com.mysql.jdbc.util.ReadAheadInputStream。我统计了一下com.mysql.jdbc.util.ReadAheadInputStream的行数发现岂有400多行，再对比了一下老代码中的com.mysql.jdbc.util.ReadAheadInputStream，发现才25，我觉得这是一个线索，顺着这条线索我统计了一下findShareMap的方法，发现岂有惊人的1100多行。给我第一感觉就是在等待查表，我看了看代码，发现那条语句就是直接调用DAO的，没有任何其他逻辑，于是我查了查表中的索引，发现这条SQL的查询语句条件居然不是一个索引。我想初步的原因可能已经找到，但是我觉得这仍然不能解释为什么新鲜事路口不开放挂的比上次还快，还恐怖。带着这个疑问，先让DB给我把索引加上了之后，我又进行了一次压测，这次测得不是翻页，而是分享，我用了线上一台机器上的流量直接切到测试机。然后我也没监控了，直接查看log中的findShareMap，这时几乎都在10以下。我觉得问题应该解决了。应该就是少了一个索引导致的线上挂掉。但是这次我仍然不是非常肯定，最后更新一台一台的上去。更一台观察一台，直到所有的都更完。夜里观察了一下高峰的压力。很明显进流量大了很多。由此就解决了我心中的疑问，新鲜事虽然没放开路口，但是仍然有人从列表入口进入查看分享相册。随着分享传播越来越多。量也越来越大。从而不开新鲜事口也可以让线上服务挂掉。

 

        com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
        - locked <0x00002aab08030860> (a com.mysql.jdbc.util.ReadAheadInputStream)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2452)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2906)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2895)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3438)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1951)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2101)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2554)
        - locked <0x00002aab08030a40> (a java.lang.Object)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1761)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1912)
        - locked <0x00002aab08030a40> (a java.lang.Object)
        at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
        at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:648)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:591)
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:641)
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:670)
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:678)
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:710)
        at net.paoding.rose.jade.provider.jdbc.JdbcImpl.query(JdbcImpl.java:63)
        at net.paoding.rose.jade.provider.jdbc.JdbcDataAccess.select(JdbcDataAccess.java:79)
        at net.paoding.rose.jade.core.SQLThreadLocalWrapper.select(SQLThreadLocalWrapper.java:48)
        at net.paoding.rose.jade.core.SelectOperation.execute(SelectOperation.java:66)
        at net.paoding.rose.jade.core.JadeDaoInvocationHandler.invoke(JadeDaoInvocationHandler.java:128)
        at $Proxy45.findShareMap(Unknown Source)
        at com.renren.app.share.biz.impl.ShareMapBizImpl.findShareMap(ShareMapBizImpl.java:75)

 

第二次压测学到的东西：

1、心态，遇到问题一定要冷静，淡定。这样才能分析原因。

2、Jstack的使用，分析。

3、线上挂掉的原因总结，查问题的思路

4、更新前先做好策略，应对突发情况。

评论

1 楼 aa87963014 2013-08-28  

我也遇到了 com.mysql.jdbc.util.ReadAheadInputStream.read 这个问题
无解,和数据量有关,就算单条sql 不是查询 而是update 也会出现这种问题

至于你前面的lock,本来是没什么问题
但是就是因为lock的内容阻塞了 导致其他线程无法访问锁.

而且lz并没有真正的解决这个问题.