生产环境典型问题实录第二期

• 往期回顾
  • 第一期 ： https://mp.weixin.qq.com/s/Vm7-k2pbpdkw2ZWFzl0-Hg

案例六：方法体内部创建线程池

"pool-2494-thread-1" prio=10 tid=0x00007f885014c800 nid=0xc06d waiting on condition [0x00007f86d20fe000]   java.lang.Thread.State: WAITING (parking)at sun.misc.Unsafe.park(Native Method)- parking to wait for   (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)at java.lang.Thread.run(Thread.java:745)   Locked ownable synchronizers:- None

• 线程名称pool-2494-thread-1透露出来的信息是这已经是第2494个线程池，每个线程池里只有1个线程。
• WAITING表示这个线程池的任务队列为空，所以阻塞在LinkedBlockingQueue.take方法上。
• 线程池数量已经到2000多个，基本上可以说明这个线程池是在方法内部创建的；线程数量是1，大概率是调用的Executors.newSingleThreadExecutor; 阻塞在LinkedBlockingQueue.take上，说明这个线程池用完后没有关闭。
• 总结：不建议在方法内部创建私有的线程池，这个等同于在方法内部创建线程，并发量高的时候，线程数会暴增，可能出现OOM:Unable to create new thread，而且大量的线程并不会带来性能的提高，相反由于上下文切换反而会带来性能损耗，就好比只有两个核酸检测人员（两核），你排成2000条队（2000个线程），并不能提高核酸检测效率，还会由于2000条队列的调度拖慢效率。

案例七：慎用反射

反射调用是一个较慢的操作，通过Class.forName进行反射调用时，会调用ClassLoader.loadClass，这是一个synchronized的方法，在并发量大时，会出现严重性能瓶颈。

    final Class<?> loadClass(Module module, String name) {        synchronized (getClassLoadingLock(name)) {            // First, check if the class has already been loaded            Class<?> c = findLoadedClass(name);            if (c == null) {                c = findClass(module.getName(), name);            }            if (c != null && c.getModule() == module) {                return c;            } else {                return null;            }        }    }

我们常用的两个框架logback和hibernate也是反射的重度使用者。

• logback在输出日志时如果要输出jar包名称，会调用PackageDataCalculation进行反射调用，建议关闭此特性。
  • 参考 https://jira.qos.ch/browse/LOGBACK-730

"qtp1747988071-86163" prio=10 tid=0x00007f8bd809d800 nid=0x193e7 waiting for monitor entry [0x00007f8b2bd7a000]   java.lang.Thread.State: BLOCKED (on object monitor)at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:390)- waiting to lock  (a org.eclipse.jetty.webapp.WebAppClassLoader)at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:383)at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:207)

• 通过hibernate写hql时，hibernate需要大量使用反射来将数据库表、字段与PO、属性进行反射调用，在hibernate3.X版本中有严重性能问题，hibernate5.X做了优化。
  • 参考 https://hibernate.atlassian.net/browse/HHH-4959

"qtp1884473012-36570" prio=10 tid=0x00007ff7d8323000 nid=0x134a waiting for monitor entry [0x00007ff7275b2000]   java.lang.Thread.State: BLOCKED (on object monitor)at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:390)- waiting to lock  (a org.eclipse.jetty.webapp.WebAppClassLoader)at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:383)at org.hibernate.util.ReflectHelper.classForName(ReflectHelper.java:95)at org.hibernate.impl.SessionFactoryImpl.getImplementors(SessionFactoryImpl.java:683)at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1543)at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283)

• 总结 ： 反射调用时在评估一下调用次数，超过一定量会引起系统锁竞争爆发，大量线程Block。

案例八：线程池需考虑任务队列大小和拒绝策略

在使用线程池时，会使用阻塞队列BlockingQueue做为其任务队列。

• ArrayBlockingQueue必须设置其固定大小，有使用者误以为其capacity类似于ArrayList的initialCapacity,其实不然。ArrayBlockingQueue是固定大小的，不是像ArrayList会动态扩容。
• BlockingQueue及其子类应该都是固定大小的，不排除有些自定义的BlockingQueue可以动态扩容。
• BlockingQueue的容量大小（capacity）要考虑内存占用和任务的消费速度，既要避免内存占用过多导致OOM，也要考虑队列容量过小导致系统阻塞。

"qtp1975260912-1059" - Thread t@1059   java.lang.Thread.State: WAITINGat sun.misc.Unsafe.park(Native Method)- parking to wait for  (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)at java.util.concurrent.locks.LockSupport.park(Unknown Source)at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)at java.util.concurrent.LinkedBlockingQueue.put(Unknown Source)at com.thunisoft.summer.component.ssoserver.asyn.LogRecordWriterImpl.writeLog(LogRecordWriterImpl.java:49)

• 线程池的拒绝策略不要选择DiscardPolicy。DiscardPolicy不会更新Future的任务状态，导致后续调用Future.get会无限阻塞。
  • 推荐使用AbortPolicy或者给Future.get设置超时时间。
  • 参考 https://mp.weixin.qq.com/s/2VEGYqIHhlG7l-9CZUP9qg

案例九：读写锁，需考虑写锁的耗时

java提供了读写锁ReentrantReadWriteLock,读锁与读锁之间互相不阻塞，读锁与写锁、写锁与写锁之间阻塞，因此在使用写锁时要考虑写锁的阻塞耗时，尽量不要超过1秒，避免写锁阻塞时间过长，导致系统无响应。

Thread 102250: (state = BLOCKED) - java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise) - java.lang.Object.wait() @bci=2, line=485 (Compiled frame) - EDU.oswego.cs.dl.util.concurrent.WriterPreferenceReadWriteLock$ReaderLock.acquire() @bci=34 (Compiled frame) - com.thunisoft.summer.util.cache.AbstractCacheImpl.readLock() @bci=7, line=34 (Compiled frame) - com.thunisoft.summer.component.config.sysConfig.SysConfigCache$$EnhancerByCGLIB$$9bf9c44$$FastClassByCGLIB$$ec264ca4.invoke(int, java.lang.Object, java.lang.Object[]) @bci=723 (Compiled frame)

案例十：不要用System.out.println

System.out 用的是PrintStream，其println源码如下：

public void println(boolean x) {    synchronized (this) {        print(x);        newLine();    }}

可以看到println为synchonzied方法，当并发较大或者往控制台输出信息过多时，其方法就阻塞住。

• 总结
  • 不要显式调用System.out。注：sonar可以检查出来。
  • 使用logback时，生产环境不要使用ConsoleAppender，其内部就是System.out

  "qtp1349006843-290" - Thread t@290   java.lang.Thread.State: BLOCKEDat java.io.PrintStream.write(PrintStream.java:429)- waiting to lock  (a XXX.server.module.log.TASPrintStream) owned by     "qtp1349006843-36" t@36at XXX.server.module.log.TASPrintStream.write(TASPrintStream.java:55)at java.io.FilterOutputStream.write(FilterOutputStream.java:80)at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:36)at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:135)at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194)at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219)at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)