How to log Garbage Collector (GC) information with WSO2 products

WSO2 products are well known for their performance (WSO2 ESB is the worlds fastest open source ESB). You can even fine tune the performance of WSO2 ESB with the help of the following documentation.

https://docs.wso2.org/display/ESB481/Performance+Tuning

Sometimes when you are developing your enterprise system with WSO2 products, you may need to write several custom code which can be used as extensions to the existing WSO2 products. As an example, you may write a class mediator to transform your message. In these kind of scenarios, you may need to tune up the WSO2 server further. In such a scenario, we can use the JVM level parameters to optimize the WSO2 server.

WSO2 servers are running on top of the JVM and we can use Java Garbage Collector (GC) to tune up the memory usage. Most of the JVM related parameters are included in the startup script file resides in CARBON_HOME\bin\wso2server.sh location.

If you need to print the GC level parameters from the WSO2 server log file for fine tuning the memory usage, you can use this script file to specify the GC options. Here is a sample section of the wso2server.sh file with the GC logging options included.

    $JAVACMD \

    -Xbootclasspath/a:”$CARBON_XBOOTCLASSPATH” \

    -Xms256m -Xmx1024m -XX:MaxPermSize=256m \

    -XX:+PrintGC \

    -XX:+PrintGCDetails \

    -XX:+HeapDumpOnOutOfMemoryError \

    -XX:HeapDumpPath=”$CARBON_HOME/repository/logs/heap-dump.hprof” \

If you start the server with the above parameters in the startup script, you can see the GC logging in the wso2carbon.log file as below.

[GC [PSYoungGen: 66048K->2771K(76800K)] 66048K->2779K(251904K), 0.0087670 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

[GC [PSYoungGen: 68792K->2281K(76800K)] 68800K->2297K(251904K), 0.0048210 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

[GC [PSYoungGen: 68328K->2296K(76800K)] 68344K->2312K(251904K), 0.0045700 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

[GC [PSYoungGen: 68344K->6375K(142848K)] 68360K->6399K(317952K), 0.0104050 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

[GC [PSYoungGen: 138471K->10730K(142848K)] 138495K->19636K(317952K), 0.0237340 secs] [Times: user=0.06 sys=0.02, real=0.03 secs]

[GC [PSYoungGen: 142826K->16873K(275456K)] 151732K->28565K(450560K), 0.0254950 secs] [Times: user=0.06 sys=0.02, real=0.03 secs]

[2014-06-17 16:34:26,747]  INFO – CarbonCoreActivator Starting WSO2 Carbon…

[2014-06-17 16:34:26,750]  INFO – CarbonCoreActivator Operating System : Mac OS X 10.9.3, x86_64

[2014-06-17 16:34:26,750]  INFO – CarbonCoreActivator Java Home        : /Library/Java/JavaVirtualMachines/jdk1.7.0_51.jdk/Contents/Home/jre

[2014-06-17 16:34:26,750]  INFO – CarbonCoreActivator Java Version     : 1.7.0_51

[2014-06-17 16:34:26,750]  INFO – CarbonCoreActivator Java VM          : Java HotSpot(TM) 64-Bit Server VM 24.51-b03,Oracle Corporation

[2014-06-17 16:34:26,751]  INFO – CarbonCoreActivator Carbon Home      : /Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0

[2014-06-17 16:34:26,751]  INFO – CarbonCoreActivator Java Temp Dir    : /Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/tmp

[2014-06-17 16:34:26,751]  INFO – CarbonCoreActivator User             : chanaka-mac, si-null, America/New_York

[2014-06-17 16:34:26,850]  WARN – ValidationResultPrinter The default keystore (wso2carbon.jks) is currently being used. To maximize security when deploying to a production environment, configure a new keystore with a unique password in the production server profile.

[2014-06-17 16:34:26,862]  INFO – AgentHolder Agent created !

[2014-06-17 16:34:26,901]  INFO – AgentDS Successfully deployed Agent Client

[GC [PSYoungGen: 275433K->22522K(281088K)] 287125K->63756K(456192K), 0.0684670 secs] [Times: user=0.17 sys=0.06, real=0.07 secs]

[2014-06-17 16:34:29,981]  INFO – EmbeddedRegistryService Configured Registry in 80ms

[2014-06-17 16:34:30,020]  INFO – EmbeddedRegistryService Connected to mount at wso2sharedregistry in 1ms

[2014-06-17 16:34:30,287]  INFO – EmbeddedRegistryService Connected to mount at wso2sharedregistry in 1ms

[2014-06-17 16:34:30,310]  INFO – RegistryCoreServiceComponent Registry Mode    : READ-WRITE

[GC [PSYoungGen: 281082K->42490K(277504K)] 322316K->98228K(452608K), 0.0657550 secs] [Times: user=0.12 sys=0.03, real=0.06 secs]

[2014-06-17 16:34:31,794]  INFO – UserStoreMgtDSComponent Carbon UserStoreMgtDSComponent activated successfully.

[GC [PSYoungGen: 277498K->42003K(277504K)] 333236K->110149K(452608K), 0.0442770 secs] [Times: user=0.10 sys=0.01, real=0.05 secs]

[GC [PSYoungGen: 277011K->29878K(288768K)] 345157K->108388K(463872K), 0.0407510 secs] [Times: user=0.08 sys=0.01, real=0.04 secs]

[GC [PSYoungGen: 256182K->31730K(258048K)] 334692K->110993K(433152K), 0.0176340 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

[GC [PSYoungGen: 258034K->32431K(287232K)] 337297K->111779K(462336K), 0.0217120 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

[GC [PSYoungGen: 259247K->31258K(286720K)] 338595K->110630K(461824K), 0.0202040 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

[GC [PSYoungGen: 258074K->32458K(288768K)] 337446K->111859K(463872K), 0.0170430 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

[GC [PSYoungGen: 262346K->33068K(288256K)] 341747K->112493K(463360K), 0.0172840 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

[GC [PSYoungGen: 262956K->32229K(290304K)] 342381K->111695K(465408K), 0.0168820 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

[GC [PSYoungGen: 265701K->33600K(289792K)] 345167K->113082K(464896K), 0.0172510 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

[GC [PSYoungGen: 267072K->32988K(292352K)] 346554K->112494K(467456K), 0.0179370 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

[2014-06-17 16:34:38,888]  INFO – TaglibUriRule TLD skipped. URI: http://tiles.apache.org/tags-tiles is already defined

[GC [PSYoungGen: 270556K->12544K(292352K)] 350062K->92081K(467456K), 0.0130250 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

[2014-06-17 16:34:40,022]  INFO – ClusterBuilder Clustering has been disabled

[2014-06-17 16:34:40,921]  INFO – LandingPageWebappDeployer Deployed product landing page webapp: StandardEngine[Catalina].StandardHost[localhost].StandardContext[/home]

[2014-06-17 16:34:40,922]  INFO – UserStoreConfigurationDeployer User Store Configuration Deployer initiated.

[2014-06-17 16:34:40,983]  INFO – PassThroughHttpSSLSender Initializing Pass-through HTTP/S Sender…

[2014-06-17 16:34:41,010]  INFO – ClientConnFactoryBuilder HTTPS Loading Identity Keystore from : repository/resources/security/wso2carbon.jks

[2014-06-17 16:34:41,022]  INFO – ClientConnFactoryBuilder HTTPS Loading Trust Keystore from : repository/resources/security/client-truststore.jks

[2014-06-17 16:34:41,082]  INFO – PassThroughHttpSSLSender Pass-through HTTPS Sender started…

[2014-06-17 16:34:41,083]  INFO – PassThroughHttpSender Initializing Pass-through HTTP/S Sender…

[2014-06-17 16:34:41,086]  INFO – PassThroughHttpSender Pass-through HTTP Sender started…

[GC [PSYoungGen: 250112K->6275K(293376K)] 329649K->86451K(468480K), 0.0130880 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]

[2014-06-17 16:34:41,228]  INFO – DeploymentInterceptor Deploying Axis2 service: echo {super-tenant}

[2014-06-17 16:34:41,459]  INFO – DeploymentEngine Deploying Web service: Echo.aar – file:/Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/repository/deployment/server/axis2services/Echo.aar

[2014-06-17 16:34:41,746]  INFO – DeploymentInterceptor Deploying Axis2 service: echo {super-tenant}

[2014-06-17 16:34:41,971]  INFO – DeploymentInterceptor Deploying Axis2 service: Version {super-tenant}

[2014-06-17 16:34:42,010]  INFO – DeploymentEngine Deploying Web service: Version.aar – file:/Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/repository/deployment/server/axis2services/Version.aar

[2014-06-17 16:34:42,083]  INFO – DeploymentInterceptor Deploying Axis2 service: Version {super-tenant}

[2014-06-17 16:34:42,212]  INFO – PassThroughHttpSSLListener Initializing Pass-through HTTP/S Listener…

[2014-06-17 16:34:42,238]  INFO – PassThroughHttpListener Initializing Pass-through HTTP/S Listener…

[2014-06-17 16:34:42,452]  INFO – ModuleDeployer Deploying module: addressing-1.6.1-wso2v10 – file:/Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/repository/deployment/client/modules/addressing-1.6.1-wso2v10.mar

[2014-06-17 16:34:42,457]  INFO – ModuleDeployer Deploying module: rampart-1.6.1-wso2v8 – file:/Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/repository/deployment/client/modules/rampart-1.6.1-wso2v8.mar

[2014-06-17 16:34:42,465]  INFO – TCPTransportSender TCP Sender started

[2014-06-17 16:34:43,569]  INFO – DeploymentEngine Deploying Web service: org.wso2.carbon.message.processor –

[2014-06-17 16:34:43,579]  INFO – DeploymentEngine Deploying Web service: org.wso2.carbon.message.store –

[GC [PSYoungGen: 244355K->20195K(258560K)] 324531K->102591K(433664K), 0.0250600 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]

[2014-06-17 16:34:44,523]  INFO – DeploymentInterceptor Deploying Axis2 service: wso2carbon-sts {super-tenant}

[2014-06-17 16:34:44,646]  INFO – DeploymentEngine Deploying Web service: org.wso2.carbon.sts –

[2014-06-17 16:34:44,859]  INFO – DeploymentEngine Deploying Web service: org.wso2.carbon.tryit –

[2014-06-17 16:34:45,173]  INFO – CarbonServerManager Repository       : /Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/repository/deployment/server/

[2014-06-17 16:34:46,869]  INFO – PermissionUpdater Permission cache updated for tenant -1234

[2014-06-17 16:34:47,015]  INFO – ServiceBusInitializer Starting ESB…

[2014-06-17 16:34:47,099]  INFO – ServiceBusInitializer Initializing Apache Synapse…

[2014-06-17 16:34:47,104]  INFO – SynapseControllerFactory Using Synapse home : /Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/.

[2014-06-17 16:34:47,104]  INFO – SynapseControllerFactory Using synapse.xml location : /Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/././repository/deployment/server/synapse-configs/default

[2014-06-17 16:34:47,104]  INFO – SynapseControllerFactory Using server name : localhost

[2014-06-17 16:34:47,108]  INFO – SynapseControllerFactory The timeout handler will run every : 15s

[2014-06-17 16:34:47,119]  INFO – Axis2SynapseController Initializing Synapse at : Tue Jun 17 16:34:47 EDT 2014

[2014-06-17 16:34:47,134]  INFO – CarbonSynapseController Loading the mediation configuration from the file system

[2014-06-17 16:34:47,138]  INFO – MultiXMLConfigurationBuilder Building synapse configuration from the synapse artifact repository at : ././repository/deployment/server/synapse-configs/default

[2014-06-17 16:34:47,139]  INFO – XMLConfigurationBuilder Generating the Synapse configuration model by parsing the XML configuration

[2014-06-17 16:34:47,182]  INFO – SynapseImportFactory Successfully created Synapse Import: googlespreadsheet

[2014-06-17 16:34:47,279]  INFO – MessageStoreFactory Successfully added Message Store configuration of : [SampleStore].

[2014-06-17 16:34:47,286]  INFO – SynapseConfigurationBuilder Loaded Synapse configuration from the artifact repository at : ././repository/deployment/server/synapse-configs/default

[2014-06-17 16:34:47,288]  INFO – Axis2SynapseController Loading mediator extensions…

[2014-06-17 16:34:47,403]  INFO – LibraryArtifactDeployer Synapse Library named ‘{org.wso2.carbon.connectors}googlespreadsheet’ has been deployed from file : /Users/chanaka-mac/Documents/wso2/wso2esb-4.8.0/repository/deployment/server/synapse-libs/googlespreadsheet-connector-1.0.0.zip

[2014-06-17 16:34:47,403]  INFO – Axis2SynapseController Deploying the Synapse service…

[2014-06-17 16:34:47,422]  INFO – Axis2SynapseController Deploying Proxy services…

[2014-06-17 16:34:47,423]  INFO – ProxyService Building Axis service for Proxy service : ToJSON

[2014-06-17 16:34:47,425]  INFO – ProxyService Adding service ToJSON to the Axis2 configuration

[2014-06-17 16:34:47,430]  INFO – DeploymentInterceptor Deploying Axis2 service: ToJSON {super-tenant}

[2014-06-17 16:34:47,513]  INFO – ProxyService Successfully created the Axis2 service for Proxy service : ToJSON

[2014-06-17 16:34:47,513]  INFO – Axis2SynapseController Deployed Proxy service : ToJSON

[2014-06-17 16:34:47,514]  INFO – ProxyService Building Axis service for Proxy service : MessageExpirationProxy

[2014-06-17 16:34:47,514]  INFO – ProxyService Adding service MessageExpirationProxy to the Axis2 configuration

[2014-06-17 16:34:47,522]  INFO – DeploymentInterceptor Deploying Axis2 service: MessageExpirationProxy {super-tenant}

[2014-06-17 16:34:47,601]  INFO – ProxyService Successfully created the Axis2 service for Proxy service : MessageExpirationProxy

[2014-06-17 16:34:47,602]  INFO – Axis2SynapseController Deployed Proxy service : MessageExpirationProxy

[2014-06-17 16:34:47,602]  INFO – ProxyService Building Axis service for Proxy service : SampleProxy

[2014-06-17 16:34:47,602]  INFO – ProxyService Adding service SampleProxy to the Axis2 configuration

[2014-06-17 16:34:47,607]  INFO – DeploymentInterceptor Deploying Axis2 service: SampleProxy {super-tenant}

[2014-06-17 16:34:47,697]  INFO – ProxyService Successfully created the Axis2 service for Proxy service : SampleProxy

[2014-06-17 16:34:47,697]  INFO – Axis2SynapseController Deployed Proxy service : SampleProxy

[2014-06-17 16:34:47,697]  INFO – Axis2SynapseController Deploying EventSources…

[2014-06-17 16:34:47,709]  INFO – InMemoryStore Initialized Store [SampleStore]…

[2014-06-17 16:34:47,709]  INFO – API Initializing API: SampleAPI

[2014-06-17 16:34:47,710]  INFO – ServerManager Server ready for processing…

[2014-06-17 16:34:47,984]  INFO – RuleEngineConfigDS Successfully registered the Rule Config service

[GC [PSYoungGen: 258275K->19130K(294400K)] 340671K->117346K(469504K), 0.0427350 secs] [Times: user=0.11 sys=0.01, real=0.04 secs]

[2014-06-17 16:34:49,698]  INFO – PassThroughHttpSSLListener Starting Pass-through HTTPS Listener…

[2014-06-17 16:34:49,710]  INFO – PassThroughHttpSSLListener Pass-through HTTPS Listener started on 0:0:0:0:0:0:0:0:8244

[2014-06-17 16:34:49,711]  INFO – PassThroughHttpListener Starting Pass-through HTTP Listener…

[2014-06-17 16:34:49,712]  INFO – PassThroughHttpListener Pass-through HTTP Listener started on 0:0:0:0:0:0:0:0:8281

[2014-06-17 16:34:49,715]  INFO – NioSelectorPool Using a shared selector for servlet write/read

[2014-06-17 16:34:50,074]  INFO – NioSelectorPool Using a shared selector for servlet write/read

[2014-06-17 16:34:50,112]  INFO – RegistryEventingServiceComponent Successfully Initialized Eventing on Registry

[GC [PSYoungGen: 122601K->7374K(292352K)] 220817K->119091K(467456K), 0.0306650 secs] [Times: user=0.07 sys=0.01, real=0.03 secs]

[Full GC [PSYoungGen: 7374K->0K(292352K)] [ParOldGen: 111717K->92241K(175104K)] 119091K->92241K(467456K) [PSPermGen: 54805K->54784K(110080K)], 0.5673070 secs] [Times: user=1.61 sys=0.01, real=0.57 secs]

[2014-06-17 16:34:50,780]  INFO – JMXServerManager JMX Service URL  : service:jmx:rmi://localhost:11112/jndi/rmi://localhost:10000/jmxrmi

[2014-06-17 16:34:50,780]  INFO – StartupFinalizerServiceComponent Server           :  WSO2 Enterprise Service Bus-4.8.0

[2014-06-17 16:34:50,781]  INFO – StartupFinalizerServiceComponent WSO2 Carbon started in 31 sec

[2014-06-17 16:34:51,234]  INFO – CarbonUIServiceComponent Mgt Console URL  : https://155.199.241.116:9444/carbon/

[GC [PSYoungGen: 240640K->17977K(292864K)] 332881K->110226K(467968K), 0.0183980 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]

You can find more information about GC parameters from the below post.

https://blog.codecentric.de/en/2014/01/useful-jvm-flags-part-8-gc-logging/

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s