The warning message "AS-CONCURRENT-00001" is written to server.log many times.

[glassfishrobot]

User application submits a task to ManagedExecutorService or ManagedScheduledExecutorService.
Once the task processing time exceeds the "hung-after-seconds" value of ManagedExecutorService or ManagedScheduledExecutorService, a warning message "AS-CONCURRENT-00001" is written to server.log file repeatedly every minute until the task finishes.

When a lot of tasks do hang, a large amount of same "AS-CONCURRENT-00001" messages are written to server.log file.
In that case, there is a risk that other important messages are missed or lost by rotating the server.log file.

Therefore, I hope to change behavior so that the "AS-CONCURRENT-00001" message is written only once for each task when the task processing time exceeds the "hung-after-seconds".

I also hope to maintain compatibility by adding an additional property to ManagedExecutorService and ManagedScheduledExecutorService, so user can specify the behavior when the task processing time exceeds the "hung-after-seconds".

The "hung-after-seconds" value of ManagedExecutorService can be specified by the command below:

asadmin set resources.managed-executor-service.<jndi-name>.hung-after-seconds

Affected Versions

[4.1]

[glassfishrobot]

@glassfishrobot Commented
Reported by uno_kohei

[glassfishrobot]

@glassfishrobot Commented
uno_kohei said:
I propose a patch for fixing this bug.

This pach changes Managed(Scheduled)ExecutorService's behavior so that the "AS-CONCURRENT-00001" message is written only once for each task when the task processing time exceeds the "hung-after-seconds".

This patch requires another patch for "cu-javaee" project.
I'll create new issue for "cu-javaee" project, propose patch, and then link with each other.

Index: main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/ConcurrentRuntime.java
===================================================================
--- main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/ConcurrentRuntime.java	(Revision 64298)
+++ main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/ConcurrentRuntime.java	(Working Copy)
@@ -49,6 +49,7 @@
 import org.glassfish.concurrent.runtime.deployer.ManagedScheduledExecutorServiceConfig;
 import org.glassfish.concurrent.runtime.deployer.ManagedThreadFactoryConfig;
 import org.glassfish.enterprise.concurrent.*;
+import org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl.ManagedThread;
 import org.glassfish.hk2.api.PostConstruct;
 import org.glassfish.hk2.api.PreDestroy;
 import org.glassfish.internal.data.ApplicationRegistry;
@@ -189,7 +190,8 @@
 config.getTaskQueueCapacity(),
 createContextService(config.getJndiName() + "-contextservice",
         config.getContextInfo(), config.getContextInfoEnabled(), true),
-AbstractManagedExecutorService.RejectPolicy.ABORT);
+AbstractManagedExecutorService.RejectPolicy.ABORT,
+config.isLogHungThreadOnce());
         if (managedExecutorServiceMap == null) {
             managedExecutorServiceMap = new HashMap();
         }
@@ -231,7 +233,8 @@
 config.getThreadLifeTimeSeconds(),
 createContextService(config.getJndiName() + "-contextservice",
         config.getContextInfo(), config.getContextInfoEnabled(), true),
-AbstractManagedExecutorService.RejectPolicy.ABORT);
+AbstractManagedExecutorService.RejectPolicy.ABORT,
+config.isLogHungThreadOnce());
         if (managedScheduledExecutorServiceMap == null) {
             managedScheduledExecutorServiceMap = new HashMap();
         }
@@ -339,7 +342,8 @@
     0L,
     createContextService(name + "-contextservice",
             CONTEXT_INFO_CLASSLOADER, "true", false),
-    AbstractManagedExecutorService.RejectPolicy.ABORT);
+    AbstractManagedExecutorService.RejectPolicy.ABORT,
+    false);
             internalScheduler.scheduleAtFixedRate(new HungTasksLogger(), 1L, 1L, TimeUnit.MINUTES);
         }
     }
@@ -372,23 +376,35 @@
             }
             for (ManagedExecutorServiceImpl mes: executorServices) {
 Collection<AbstractManagedThread> hungThreads = mes.getHungThreads();
-logHungThreads(hungThreads, mes.getManagedThreadFactory(), mes.getName());
+logHungThreads(hungThreads, mes.isLogHungThreadOnce(), mes.getManagedThreadFactory(), mes.getName());
             }
             for (ManagedScheduledExecutorServiceImpl mses: scheduledExecutorServices) {
 Collection<AbstractManagedThread> hungThreads = mses.getHungThreads();
-logHungThreads(hungThreads, mses.getManagedThreadFactory(), mses.getName());
+logHungThreads(hungThreads, mses.isLogHungThreadOnce(), mses.getManagedThreadFactory(), mses.getName());
             }
         }

-        private void logHungThreads(Collection<AbstractManagedThread> hungThreads, ManagedThreadFactoryImpl mtf, String mesName) {
+        private void logHungThreads(Collection<AbstractManagedThread> hungThreads, boolean logHungThreadOnce, ManagedThreadFactoryImpl mtf, String mesName) {
             if (hungThreads != null) {
 for (AbstractManagedThread hungThread: hungThreads) {
-    Object[] params = {hungThread.getTaskIdentityName(),
-       hungThread.getName(),
-       hungThread.getTaskRunTime(System.currentTimeMillis()) / 1000,
-       mtf.getHungTaskThreshold() / 1000,
-       mesName};
-    logger.log(Level.WARNING, LogFacade.UNRESPONSIVE_TASK, params);
+    boolean loggable = true;
+    if(logHungThreadOnce && hungThread instanceof ManagedThread) {
+        ManagedThread mt = (ManagedThread) hungThread;
+        loggable = ! mt.isHungLogged();
+    }
+    if(loggable) {
+        Object[] params = {hungThread.getTaskIdentityName(),
+           hungThread.getName(),
+           hungThread.getTaskRunTime(System.currentTimeMillis()) / 1000,
+           mtf.getHungTaskThreshold() / 1000,
+           mesName};
+        logger.log(Level.WARNING, LogFacade.UNRESPONSIVE_TASK, params);
+
+        if(logHungThreadOnce && hungThread instanceof ManagedThread) {
+            ManagedThread mt = (ManagedThread) hungThread;
+            mt.setHungLogged(true);
+        }
+    }
 }
             }
         }
Index: main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/deployer/ManagedExecutorServiceConfig.java
===================================================================
--- main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/deployer/ManagedExecutorServiceConfig.java	(Revision 64298)
+++ main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/deployer/ManagedExecutorServiceConfig.java	(Working Copy)
@@ -55,6 +55,7 @@
     private int maximumPoolSize;
     private int taskQueueCapacity;
     private long threadLifeTimeSeconds;
+    private boolean logHungThreadOnce = true;

     public ManagedExecutorServiceConfig(ManagedExecutorService config) {
         super(config.getJndiName(), config.getContextInfo(), config.getContextInfoEnabled());
@@ -66,6 +67,9 @@
         maximumPoolSize = parseInt(config.getMaximumPoolSize(), Integer.MAX_VALUE);
         taskQueueCapacity = parseInt(config.getTaskQueueCapacity(), Integer.MAX_VALUE);
         threadLifeTimeSeconds = parseLong(config.getThreadLifetimeSeconds(), 0L);
+        if("repeat".equalsIgnoreCase(config.getPropertyValue("log-hung-thread-policy"))) {
+            logHungThreadOnce = false;
+        }
     }

     public int getHungAfterSeconds() {
@@ -100,6 +104,10 @@
         return threadLifeTimeSeconds;
     }

+    public boolean isLogHungThreadOnce() {
+        return logHungThreadOnce;
+    }
+
     @Override
     TYPE getType() {
         return TYPE.MANAGED_EXECUTOR_SERVICE;
Index: main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/deployer/ManagedScheduledExecutorServiceConfig.java
===================================================================
--- main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/deployer/ManagedScheduledExecutorServiceConfig.java	(Revision 64298)
+++ main/appserver/concurrent/concurrent-impl/src/main/java/org/glassfish/concurrent/runtime/deployer/ManagedScheduledExecutorServiceConfig.java	(Working Copy)
@@ -52,6 +52,7 @@
     private int corePoolSize;
     private long keepAliveSeconds;
     private long threadLifeTimeSeconds;
+    private boolean logHungThreadOnce = true;

     public ManagedScheduledExecutorServiceConfig(ManagedScheduledExecutorService config) {
         super(config.getJndiName(), config.getContextInfo(), config.getContextInfoEnabled());
@@ -61,6 +62,9 @@
         corePoolSize = parseInt(config.getCorePoolSize(), 0);
         keepAliveSeconds = parseLong(config.getKeepAliveSeconds(), 60);
         threadLifeTimeSeconds = parseLong(config.getThreadLifetimeSeconds(), 0L);
+        if("repeat".equalsIgnoreCase(config.getPropertyValue("log-hung-thread-policy"))) {
+            logHungThreadOnce = false;
+        }
     }

     public int getHungAfterSeconds() {
@@ -87,6 +91,10 @@
         return threadLifeTimeSeconds;
     }

+    public boolean isLogHungThreadOnce() {
+        return logHungThreadOnce;
+    }
+
     @Override
     public TYPE getType() {
         return TYPE.MANAGED_SCHEDULED_EXECUTOR_SERVICE;

If you want the previous behavior (before patch), set Managed(Scheduled)ExecutorService's additional property "log-hung-thread-policy" to "repeat".

asadmin set resources.managed-executor-service.<jndi-name>.property.log-hung-thread-policy=repeat
asadmin set resources.managed-scheduled-executor-service.<jndi-name>.property.log-hung-thread-policy=repeat

[glassfishrobot]

@glassfishrobot Commented
@YRutuja said:
Please provide a test case reproducing the problem.

[glassfishrobot]

@glassfishrobot Commented
This issue was imported from java.net JIRA GLASSFISH-21561

[glassfishrobot]

• Issue Imported From: https://github.com/javaee/glassfish/issues/21561
• Original Issue Raised By:@glassfishrobot
• Original Issue Assigned To: @YRutuja

[github-actions]

This issue has been marked as inactive and old and will be closed in 7 days if there is no further activity. If you want the issue to remain open please add a comment

[dmatej]

TODO: Cherrypick to 6.2.4 too

[dmatej]

The commit for 6.2.4 was: 0b114d5 ;)