High CPU overhead in JMX operations when many rolled log files exist

Environment

• Red Hat JBoss Enterprise Application Platform
  • 6.3.x
  • 6.4.x
  • 7.0.x

Issue

• JMX operations in EAP 6 are slower and consuming more CPU, depending on the size of log directory i.e. value set for ${jboss.server.log.dir}. Below thread is taking time to complete:

For Windows:

   java.lang.Thread.State: RUNNABLE
        at java.io.WinNTFileSystem.checkAccess(Native Method)
        at java.io.File.canRead(File.java:768)
        at org.jboss.as.logging.LoggingResource$AllowedFilesFilter.accept(LoggingResource.java:274)
        at java.io.File.listFiles(File.java:1291)
        at org.jboss.as.logging.LoggingResource.findFiles(LoggingResource.java:217)
        at org.jboss.as.logging.LoggingResource.getChildrenNames(LoggingResource.java:147)
        at org.jboss.as.logging.LoggingResource.hasReadableFile(LoggingResource.java:203)
        at org.jboss.as.logging.LoggingResource.getChild(LoggingResource.java:98)
        at org.jboss.as.controller.OperationContextImpl.getAuthorizationResource(OperationContextImpl.java:1405)
        at org.jboss.as.controller.OperationContextImpl.getBasicAuthorizationResponse(OperationContextImpl.java:1362)
        at org.jboss.as.controller.OperationContextImpl.authorize(OperationContextImpl.java:1281)
        at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:646)
        at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:632)
        at org.jboss.as.controller.operations.global.ReadResourceDescriptionHandler$ReadResourceDescriptionAccessControlContext.addParentResource(ReadResourceDescriptionHandler.java:786)

For Unix:

   java.lang.Thread.State: RUNNABLE
	at java.io.UnixFileSystem.checkAccess(Native Method)
	at java.io.File.canRead(File.java:768)
	at org.jboss.as.logging.LoggingResource$AllowedFilesFilter.accept(LoggingResource.java:274)
	at java.io.File.listFiles(File.java:1291)
	at org.jboss.as.logging.LoggingResource.findFiles(LoggingResource.java:217)
	at org.jboss.as.logging.LoggingResource.getChildrenNames(LoggingResource.java:147)
	at org.jboss.as.logging.LoggingResource.hasReadableFile(LoggingResource.java:203)
	at org.jboss.as.logging.LoggingResource.requireChild(LoggingResource.java:109)
	at org.jboss.as.controller.OperationContextImpl.requireChild(OperationContextImpl.java:992)
	at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:671)
	at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:632)

Resolution

• As preventive measure, keep the size of log directory of EAP as small as possible. Keep cleaning the log directory for older rolled log files.
• Upgrade to EAP 7.1.0+ for logging improvements to this

Root Cause

• On startup while loading all subsystem, EAP load all the file handlers mentioned in the logging subsystem.
• While doing so, it search for the files mentioned in the file handler and load it. To do so a filter is applied which traverse through all the files present in the log directory at that moment and find the file. This loop depends on the number of files present in the log directory.
• Content from issues.jboss.org is not included.WFCORE-1503

Diagnostic Steps

Please take the thread dumps and check for the following :
For Unix:

java.lang.Thread.State: RUNNABLE
	at java.io.UnixFileSystem.checkAccess(Native Method)
	at java.io.File.canRead(File.java:768)
	at org.jboss.as.logging.LoggingResource$AllowedFilesFilter.accept(LoggingResource.java:274)
	at java.io.File.listFiles(File.java:1291)
	at org.jboss.as.logging.LoggingResource.findFiles(LoggingResource.java:217)
	at org.jboss.as.logging.LoggingResource.getChildrenNames(LoggingResource.java:147)
	at org.jboss.as.logging.LoggingResource.hasReadableFile(LoggingResource.java:203)
	at org.jboss.as.logging.LoggingResource.requireChild(LoggingResource.java:109)
	at org.jboss.as.controller.OperationContextImpl.requireChild(OperationContextImpl.java:992)
	at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:671)
	at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:632)
	at 

For Windows:

java.lang.Thread.State: RUNNABLE
        at java.io.WinNTFileSystem.checkAccess(Native Method)
        at java.io.File.canRead(File.java:768)
        at org.jboss.as.logging.LoggingResource$AllowedFilesFilter.accept(LoggingResource.java:274)
        at java.io.File.listFiles(File.java:1291)
        at org.jboss.as.logging.LoggingResource.findFiles(LoggingResource.java:217)
        at org.jboss.as.logging.LoggingResource.getChildrenNames(LoggingResource.java:147)
        at org.jboss.as.logging.LoggingResource.hasReadableFile(LoggingResource.java:203)
        at org.jboss.as.logging.LoggingResource.getChild(LoggingResource.java:98)
        at org.jboss.as.controller.OperationContextImpl.getAuthorizationResource(OperationContextImpl.java:1405)
        at org.jboss.as.controller.OperationContextImpl.getBasicAuthorizationResponse(OperationContextImpl.java:1362)
        at org.jboss.as.controller.OperationContextImpl.authorize(OperationContextImpl.java:1281)
        at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:646)
        at org.jboss.as.controller.OperationContextImpl.readResourceFromRoot(OperationContextImpl.java:632)

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.