Skip to main content

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.
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/
Labels:

Comments

Post a Comment

Popular posts from this blog

WSO2 ESB tuning performance with threads

I have written several blog posts explaining the internal behavior of the ESB and the threads created inside ESB. With this post, I am talking about the effect of threads in the WSO2 ESB and how to tune up threads for optimal performance. You can refer [1] and [2] to understand the threads created within the ESB. [1] http://soatutorials.blogspot.com/2015/05/understanding-threads-created-in-wso2.html [2] http://wso2.com/library/articles/2012/03/importance-performance-wso2-esb-handles-nonobvious/ Within this blog post, I am discussing about the "worker threads" which are used for processing the data within the WSO2 ESB. There are 2 types of worker threads created when you start sending the requests to the server 1) Server Worker/Client Worker Threads 2) Mediator Worker (Synapse-Worker) Threads Server Worker/Client Worker Threads These set of threads will be used to process all the requests/responses coming to the ESB server. ServerWorker Threads will be used to pr
4 comments
Read more

How puppet works in your IT infrstructure

What is Puppet? Puppet is IT automation software that helps system administrators manage infrastructure throughout its lifecycle, from provisioning and configuration to orchestration and reporting. Using Puppet, you can easily automate repetitive tasks, quickly deploy critical applications, and proactively manage change, scaling from 10s of servers to 1000s, on-premise or in the cloud. How the puppet works? It works like this..Puppet agent is a daemon that runs on all the client servers(the servers where you require some configuration, or the servers which are going to be managed using puppet.) All the clients which are to be managed will have puppet agent installed on them, and are called nodes in puppet. Puppet Master: This machine contains all the configuration for different hosts. Puppet master will run as a daemon on this master server. Puppet Agent: This is the daemon that will run on all the servers, which are to be managed using p
7 comments
Read more

How to configure timeouts in WSO2 ESB to get rid of client timeout errors

WSO2 ESB has defined some configuration parameters which controls the timeout of a particular request which is going out of ESB. In a particular  scneario, your client sends a request to ESB, and then ESB sends a request to another endpoint to serve the request. CLIENT->WSO2 ESB->BACKEND The reason for clients getting timeout is that ESB timeout is larger than client's timeout. This can be solved by either increasing the timeout at client side or by decreasing the timeout in ESB side. In any of the case, you can control the timeout in ESB using the below properties. 1) Global timeout defined in synapse.properties (ESB_HOME\repository\conf\) file. This will decide the maximum time that a callback is waiting in the ESB for a response for a particular request. If ESB does not get any response from Back End, it will drop the message and clears out the call back. This is a global level parameter which affects all the endpoints configured in ESB. synapse.global_timeout_inte
3 comments
Read more