java – Why is my thread blocked when it does no synchronization/locking

We have a tomcat 9.0.62 server that reliably locks up within 1-3hours. When we dump the thread states using jstack -F <PID> we see 359 threads in a BLOCKED state and 9 threads in a state of IN_NATIVE. Lots of available memory, lots of disk, low cpu usage. We have only seen this since we upgraded from OpenJDK 1.8.0u302 to 1.8.0u322 (on Solaris) (when we downgrade to u302 the problem goes away).

According to java documentation a state of BLOCKED means “waiting for a monitor lock”. What I don’t understand is how can an operation that does no synchronization be in a BLOCKED state? Here’s an example, blocked in Pattern.compile:

Thread t@1467: (state = BLOCKED)
- java.util.regex.Pattern.compile() @bci=144, line=1693 (Compiled frame)
 - java.util.regex.Pattern.<init>(java.lang.String, int) @bci=62, line=1352 (Compiled frame)
 - java.util.regex.Pattern.compile(java.lang.String) @bci=6, line=1028 (Compiled frame)
 - oracle.jdbc.driver.OracleStatement.<init>(oracle.jdbc.driver.PhysicalConnection, int, int, int, int) @bci=377, line=6198 (Compiled frame)
 - oracle.jdbc.driver.OraclePreparedStatement.<init>(oracle.jdbc.driver.PhysicalConnection, java.lang.String, int, int, int, int) @bci=9, line=1363 (Compiled frame)
 - oracle.jdbc.driver.T4CPreparedStatement.<init>(oracle.jdbc.driver.PhysicalConnection, java.lang.String, int, int) @bci=14, line=43 (Compiled frame)
 - oracle.jdbc.driver.T4CDriverExtension.allocatePreparedStatement(oracle.jdbc.driver.PhysicalConnection, java.lang.String, int, int) @bci=9, line=75 (Compiled frame)
 - oracle.jdbc.driver.PhysicalConnection.prepareStatementInternal(java.lang.String, int, int) @bci=120, line=1648 (Compiled frame)
 - oracle.jdbc.driver.PhysicalConnection.prepareStatement(java.lang.String, int, int) @bci=4, line=1606 (Compiled frame)
 - oracle.jdbc.driver.PhysicalConnection.prepareStatement(java.lang.String) @bci=4, line=1533 (Compiled frame)
 - com.zaxxer.hikari.pool.ProxyConnection.prepareStatement(java.lang.String) @bci=7, line=337 (Compiled frame)
 - com.zaxxer.hikari.pool.HikariProxyConnection.prepareStatement(java.lang.String) @bci=2 (Compiled frame)
 - org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection() @bci=4, line=37 (Compiled frame)
 - org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded() @bci=12, line=108 (Compiled frame)
 - org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection() @bci=5, line=138 (Compiled frame)
 - org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection() @bci=4, line=50 (Compiled frame)
 - org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.doPrepare() @bci=11, line=89 (Compiled frame)
 - org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement() @bci=47, line=176 (Compiled frame)
 - org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(java.lang.String, boolean, org.hibernate.ScrollMode) @bci=74, line=151 (Compiled frame)
 - org.hibernate.loader.Loader.prepareQueryStatement(java.lang.String, org.hibernate.engine.spi.QueryParameters, org.hibernate.dialect.pagination.LimitHandler, boolean, org.hibernate.engine.spi.SharedSessionContractImplementor) @bci=39, line=2127 (Compiled frame)
 - org.hibernate.loader.Loader.executeQueryStatement(java.lang.String, org.hibernate.engine.spi.QueryParameters, boolean, java.util.List, org.hibernate.engine.spi.SharedSessionContractImplementor) @bci=55, line=2059 (Compiled frame)
 - org.hibernate.loader.Loader.executeQueryStatement(org.hibernate.engine.spi.QueryParameters, boolean, java.util.List, org.hibernate.engine.spi.SharedSessionContractImplementor) @bci=10, line=2037 (Compiled frame)
 - org.hibernate.loader.Loader.doQuery(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters, boolean, org.hibernate.transform.ResultTransformer) @bci=44, line=956 (Compiled frame)
 - org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters, boolean, org.hibernate.transform.ResultTransformer) @bci=62, line=357 (Compiled frame)
 - org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters, boolean) @bci=5, line=327 (Compiled frame)
 - org.hibernate.loader.Loader.loadEntity(org.hibernate.engine.spi.SharedSessionContractImplementor, java.lang.Object, org.hibernate.type.Type, java.lang.Object, java.lang.String, java.io.Serializable, org.hibernate.persister.entity.EntityPersister, org.hibernate.LockOptions, java.lang.Boolean) @bci=116, line=2440 (Compiled frame)
 - org.hibernate.loader.entity.AbstractEntityLoader.load(org.hibernate.engine.spi.SharedSessionContractImplementor, java.lang.Object, java.lang.Object, java.io.Serializable, org.hibernate.LockOptions, java.lang.Boolean) @bci=22, line=77 (Compiled frame)
 - org.hibernate.loader.entity.AbstractEntityLoader.load(java.lang.Object, org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.LockOptions) @bci=7, line=66 (Compiled frame)
 - org.hibernate.persister.entity.AbstractEntityPersister.loadByUniqueKey(java.lang.String, java.lang.Object, org.hibernate.engine.spi.SharedSessionContractImplementor) @bci=11, line=2486 (Compiled frame)
 - org.hibernate.type.EntityType.loadByUniqueKey(java.lang.String, java.lang.String, java.lang.Object, org.hibernate.engine.spi.SharedSessionContractImplementor) @bci=90, line=756 (Compiled frame)
 - org.hibernate.type.EntityType.resolve(java.lang.Object, org.hibernate.engine.spi.SharedSessionContractImplementor, java.lang.Object, java.lang.Boolean) @bci=50, line=467 (Compiled frame)
 - org.hibernate.engine.internal.TwoPhaseLoad$EntityResolver.lambda$static$0(org.hibernate.type.EntityType, java.lang.Object, org.hibernate.engine.spi.SharedSessionContractImplementor, java.lang.Object, java.lang.Boolean) @bci=6, line=576 (Compiled frame)
 - org.hibernate.engine.internal.TwoPhaseLoad$EntityResolver$$Lambda$1426.resolve(org.hibernate.type.EntityType, java.lang.Object, org.hibernate.engine.spi.SharedSessionContractImplementor, java.lang.Object, java.lang.Boolean) @bci=7 (Compiled frame)
 - org.hibernate.engine.internal.TwoPhaseLoad.initializeEntityEntryLoadedState(java.lang.Object, org.hibernate.engine.spi.EntityEntry, org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.internal.TwoPhaseLoad$EntityResolver) @bci=348, line=221 (Compiled frame)
 - org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(java.lang.Object, boolean, org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.event.spi.PreLoadEvent, org.hibernate.engine.internal.TwoPhaseLoad$EntityResolver) @bci=48, line=156 (Compiled frame)
 - org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(java.lang.Object, boolean, org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.event.spi.PreLoadEvent) @bci=7, line=126 (Compiled frame)
 - org.hibernate.loader.Loader.initializeEntitiesAndCollections(java.util.List, java.lang.Object, org.hibernate.engine.spi.SharedSessionContractImplementor, boolean, java.util.List) @bci=171, line=1201 (Compiled frame)
 - org.hibernate.loader.Loader.doQuery(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters, boolean, org.hibernate.transform.ResultTransformer) @bci=102, line=979 (Compiled frame)
 - org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters, boolean, org.hibernate.transform.ResultTransformer) @bci=62, line=357 (Compiled frame)
 - org.hibernate.loader.Loader.doList(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters, org.hibernate.transform.ResultTransformer) @bci=38, line=2868 (Compiled frame)
 - org.hibernate.loader.Loader.doList(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters) @bci=4, line=2850 (Compiled frame)
 - org.hibernate.loader.Loader.listIgnoreQueryCache(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters) @bci=4, line=2682 (Compiled frame)
 - org.hibernate.loader.Loader.list(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters, java.util.Set, org.hibernate.type.Type[]) @bci=49, line=2677 (Compiled frame)
 - org.hibernate.loader.hql.QueryLoader.list(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters) @bci=19, line=540 (Compiled frame)
 - org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(org.hibernate.engine.spi.SharedSessionContractImplementor, org.hibernate.engine.spi.QueryParameters) @bci=179, line=400 (Compiled frame)
 - org.apache.log4j.Category.getEffectiveLevel() @bci=23, line=442 (Compiled frame)
 - org.apache.log4j.Category.isEnabledFor(org.apache.log4j.Priority) @bci=20, line=751 (Compiled frame)
 - org.jboss.logging.Log4jLogger.isEnabled(org.jboss.logging.Logger$Level) @bci=10, line=36 (Compiled frame)
 - org.jboss.logging.Logger.isTraceEnabled() @bci=4, line=98 (Compiled frame)
 - org.jboss.logging.DelegatingBasicLogger.isTraceEnabled() @bci=4, line=54 (Compiled frame)
 - org.hibernate.engine.query.spi.HQLQueryPlan.performList(org.hibernate.engine.spi.QueryParameters, org.hibernate.engine.spi.SharedSessionContractImplementor) @bci=3, line=195 (Compiled frame)
 - org.hibernate.internal.SessionImpl.list(java.lang.String, org.hibernate.engine.spi.QueryParameters) @bci=53, line=1454 (Compiled frame)
 - org.hibernate.query.internal.AbstractProducedQuery.doList() @bci=85, line=1649 (Compiled frame)
 - org.hibernate.query.internal.AbstractProducedQuery.list() @bci=5, line=1617 (Compiled frame)
 - org.hibernate.query.Query.getResultList() @bci=1, line=165 (Compiled frame)
...

UPDATE
I’ve checked the GC logs and I see this entry 4 seconds after the last log line emitted by any of my tomcat apps:

2022-05-19T00:57:45.782+0000: 2602.365: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 73400320 bytes, new threshold 15 (max 15)
- age   1:    9497240 bytes,    9497240 total
, 0.1257611 secs]
   [Parallel Time: 111.6 ms, GC Workers: 15]
      [GC Worker Start (ms): Min: 2602366.7, Avg: 2602366.8, Max: 2602366.9, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.4, Avg: 4.1, Max: 24.4, Diff: 22.9, Sum: 61.3]
      [Update RS (ms): Min: 6.9, Avg: 26.4, Max: 29.4, Diff: 22.5, Sum: 396.2]
         [Processed Buffers: Min: 4, Avg: 18.6, Max: 27, Diff: 23, Sum: 279]
      [Scan RS (ms): Min: 19.5, Avg: 20.2, Max: 20.9, Diff: 1.4, Sum: 303.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 60.2, Avg: 60.4, Max: 60.7, Diff: 0.6, Sum: 906.7]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2]
         [Termination Attempts: Min: 1, Avg: 194.5, Max: 260, Diff: 259, Sum: 2917]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 2.1]
      [GC Worker Total (ms): Min: 111.2, Avg: 111.4, Max: 111.5, Diff: 0.3, Sum: 1671.0]
      [GC Worker End (ms): Min: 2602478.1, Avg: 2602478.2, Max: 2602478.3, Diff: 0.2]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [String Dedup Fixup: 7.5 ms, GC Workers: 15]
      [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Table Fixup (ms): Min: 7.0, Avg: 7.2, Max: 7.4, Diff: 0.4, Sum: 108.1]
   [Clear CT: 0.6 ms]
   [Other: 6.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.4 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 2.9 ms]
   [Eden: 1098.0M(1098.0M)->0.0B(774.0M) Survivors: 20480.0K->77824.0K Heap: 3829.9M(6144.0M)->2788.9M(6144.0M)]
 [Times: user=1.78 sys=0.00, real=0.13 secs] 

What is missing there is a line like this which immediately follows every other GC entry in the log:

2022-05-19T00:57:42.081+0000: 2598.664: Total time for which application threads were stopped: 0.3016893 seconds, Stopping threads took: 0.0002452 seconds

The fact that this line is missing suggests to me that GC didn’t manage to resume the threads. Given that, I’m assuming this is a GC bug in OpenJDK 1.8.0u322.

These are the memory and GC related settings on our tomcat process:

-server 
-Xms2400m 
-Xmx6g 
-XX:+UseStringDeduplication 
-XX:CodeCacheMinimumFreeSpace=25m 
-XX:ReservedCodeCacheSize=200m 
-XX:-TieredCompilation 
-XX:MaxMetaspaceSize=1000m 
-XX:+UseG1GC 
-XX:MaxGCPauseMillis=200 
-Xloggc:gc.log.20220519_0014 
-verbose:gc 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintGCCause 
-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCApplicationConcurrentTime 
-XX:+PrintTenuringDistribution 
-XX:+UseGCLogFileRotation 
-XX:NumberOfGCLogFiles=20 
-XX:GCLogFileSize=50M 
-XX:+HeapDumpOnOutOfMemoryError 
-d64

Here is the first line of every thread’s stack trace: https://gist.github.com/davidmoten/c3b19afbfce981fec1f0722ec231f354. In that list you can see lots of innocuous calls that have no synchronization (which for me points to GC).

Leave a Comment