Java 在 String.toUpperCase() 上阻塞线程

Question

其中一个线程在查询Oracle数据库时被锁定超过3秒。这会在访问 Oracle 数据库时导致许多线程阻塞，从而导致线程数量突然增加和应用程序无响应。我正在使用 Tomcat 8.5，Tomcat 连接池，Java 8。阻塞线程的跟踪：

***"http-nio-80-exec-433" #4207 daemon prio=5 os_prio=0 tid=0x00007fd9d8042000 nid=0x503b runnable [0x00007fd839f04000]
   java.lang.Thread.State: RUNNABLE
    at java.util.Hashtable.get(Hashtable.java:363)
    - locked <0x000000070193caa0> (a java.util.Hashtable)
    at java.lang.ConditionalSpecialCasing.lookUpTable(ConditionalSpecialCasing.java:151)
    at java.lang.ConditionalSpecialCasing.toUpperCaseEx(ConditionalSpecialCasing.java:123)
    at java.lang.String.toUpperCase(String.java:2775)
    at java.lang.String.toUpperCase(String.java:2833)
    at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1638)
    at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:4401)
    at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:4482)
    - locked <0x000000074cd7d868> (a oracle.jdbc.driver.T4CConnection)
    at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:6272)
    at sun.reflect.GeneratedMethodAccessor400.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:210)
    at com.sun.proxy.$Proxy637.executeQuery(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor400.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
    at com.sun.proxy.$Proxy637.executeQuery(Unknown Source)
    at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
    at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
    at org.hibernate.loader.Loader.doQuery(Loader.java:802)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
    at org.hibernate.loader.Loader.doList(Loader.java:2533)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
    at org.hibernate.loader.Loader.list(Loader.java:2271)***

这是 10 多个阻塞线程之一的跟踪

***"http-nio-80-exec-271" #2777 daemon prio=5 os_prio=0 tid=0x00007fd9c8941800 nid=0x19c3 waiting for monitor entry [0x00007fd8356ca000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.util.Hashtable.get(Hashtable.java:363)
    - waiting to lock <0x000000070193caa0> (a java.util.Hashtable)
    at java.lang.ConditionalSpecialCasing.lookUpTable(ConditionalSpecialCasing.java:151)
    at java.lang.ConditionalSpecialCasing.toUpperCaseEx(ConditionalSpecialCasing.java:123)
    at java.lang.String.toUpperCase(String.java:2775)
    at java.lang.String.toUpperCase(String.java:2833)
    at oracle.jdbc.driver.CharCommonAccessor.init(CharCommonAccessor.java:164)
    at oracle.jdbc.driver.VarcharAccessor.<init>(VarcharAccessor.java:88)
    at oracle.jdbc.driver.T4CVarcharAccessor.<init>(T4CVarcharAccessor.java:108)
    at oracle.jdbc.driver.T4CTTIdcb.fillupAccessors(T4CTTIdcb.java:431)
    at oracle.jdbc.driver.T4CTTIdcb.receiveCommon(T4CTTIdcb.java:209)
    at oracle.jdbc.driver.T4CTTIdcb.receive(T4CTTIdcb.java:145)
    at oracle.jdbc.driver.T4C8Oall.readDCB(T4C8Oall.java:963)
    at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:447)
    at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:235)
    at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:543)
    at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:239)
    at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:1246)
    at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1500)
    at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1717)
    at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:4401)
    at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:4482)
    - locked <0x000000074d203f60> (a oracle.jdbc.driver.T4CConnection)
    at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:6272)
    at sun.reflect.GeneratedMethodAccessor400.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:210)
    at com.sun.proxy.$Proxy637.executeQuery(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor400.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
    at com.sun.proxy.$Proxy637.executeQuery(Unknown Source)
    at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)***

我不知道为什么 toUpperCase() 会锁定某些东西（据我所知，它是某个 Integer 对象被锁定）30 多秒，但这每天会发生多次。线程转储分析器没有在转储中发现任何死锁。 Tomcat 查询阻塞线程 http-nio-80-exec-433 的池日志需要 5 分钟才能完成。

这可能是jvm、内存或其他问题？比如jdbc驱动或者连接池配置问题？

Answer 1

问题似乎与代码无关。我们有 10GB 大小的 catalina.out 日志文件，以及 4 个 bash 脚本，每五分钟分析一次该文件的特定错误，并且由于文件很大，每个这样的分析（主要是 tail/wc 命令）花了 3-4 分钟。我不知道 catalina.out 是否被锁定，但是 "tail" 和 "wc" 命令的 CPU 用法非常重要。不过，内存使用量并没有显着增加。

手动滚动catalina.out后，问题解决了。管理员的任务是找出 logrotate 失败的原因。

更新：该问题在更高负载（>50 个用户）下不断出现，因此经过一些测试，区域设置从 "lt" 更改为 "en"。与修复另一个 MyFaces 缓存错误一起，Tomcat 的响应时间减少了 10-20 倍，并且可以使用应用程序的并发用户数量增加了 >10 倍。

Java 在 String.toUpperCase() 上阻塞线程

Java blocked thread on String.toUpperCase()

java

multithreading

database-connection

jdbc

blocked-threads