3

查询 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+ BLOCKED 线程之一的跟踪

***"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驱动或者连接池配置问题？

4

1 回答 1

1

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

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

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

于 2019-12-02T07:23:28.090 回答