10 + Points why to separate Backoffice from Frontend

I came upon the idea of writing this while i was checking on the side effects of some Business Cases of our Backoffice, running in the same JVM with our Front-End. The first hint i got (and this is where CI – continous integration shows its benefits) was after integrating my Jmeter Load Tests in Hudson, our CI System. By doing this, i radically changed the behaviour of the system. The data was getting filled to the database right after deployment, and not manually (therefore using a deterministic behaviour)

After having had one of the automatic tests failed, i turned first to the response times. I was suprised to see the radical increase of response times from one build to the other. Expecting a response times under 500 ms, i was getting 20 seconds back:

JMeter Hudson - Response Times

JMeter Hudson - Response Times

I needed to look deeper into the problem, so the first thing (the one that i always do) was to launch VisualVM and check on the status of JVM, which looked something like this:

Visual VM - Full Heap - Full GC

Visual VM - Full Heap - Full GC

And this is how the memory footprint looked like:

Visual VM - Full Heap - Memory Footprint

Visual VM - Full Heap - Memory Footprint

There it was. My JVM was getting filled, therefore going into Full Garbage Collections (hence the CPU spikes in the image above). Doing a simple “jmap -histo pid | grep pattern” i could see a lot of objects that belonged to our Backoffice.

Doing a heap dump, i discovered that the parent of all this object was a scheduled timer, that was going through a list of entries in the database, doing some operations at the end, but transferring all of them first local (so filling the heap with objects needed for calculation and other operations)

It was not the first time i had seen this ( i had seen it before, but after manually starting a Backoffice operation, which was pretty much working in the same way: going to the database, and transferring all objects local), so i decided to take a deeper look, and decide if having a Backoffice and Frontend together in the same JVM / Machine is a good idea after all. After doing some brainstorming for a couple of hours, i came up with about 10 points why it is not a good idea.

10 + Points why to separate Backoffice from Frontend

  1. Queries – Long running queries need resources. In order to go to database, you need a connection. In order to get a connection you need a thread. You will get both of them from a pool (http thread pool and jdbc connection pool) While one or two connections may not sound critic, if you have a support department employing more than a couple of Backoffice users, you will “steal” expensive resources which may be well used by the Frontend at peak times.
  2. CPU - If you are doing local calculations on sets of data retrieved from the database, you need CPU, specially if you are working with highly complex mathematical functions, or (and) with large sets of data. Again, doing this a couple of times ( once for each Backoffice user) may well steal CPU power, that may be used at peak (but also normal) times by your front-end. Take this very serious, we are talking JVM here. We need CPU for finding objects, working with them, cleaning them up. You do not want to give your CPU away to your Backoffice while your front-end has to eventually wait
  3. Result sets – Sometimes you do computations either on the database side (taking off the burden of computing on the application side) or local (taking the burden off the database) According to expected result sets, and your business needs of course, one may use one or the other method. Yet, chosing without predicting can be fatal. Transfering large quantities of objects from the database to the application server for doing the calculation, can easily fill up the Heap, specially if you are using JPA in a domain driven design application. Not only that the shared heap will be filled with objects that the front-end does not need, but you may well find yourself in a FULL GC situation, just because you do not have enough space anymore to accomodate objects from your result set. Full GC’s will immediately translate into huge response times on the user side (see images above). Are you willing to risk that?
    On the other side, Garbage Collection will last a lot longer, depending on the object tree. Although you work well with your front-end, not having leaks, you have to risk response times because of unneeded Garbage Collection
  4. Optimum debugging of memory problems – Have you ever tried dumping a filled heap of 8 GB size? Have you tried loading it into a Heap Analyzer??? If you did, than you know by now that this is a no go. And even if you’d work with a smaller heap, detecting memory leaks is much easier once you get fast to the root references. You will definitely achieve this by running your Backoffice in a separate JVM. It will be much easier to separate objects belonging to one application or the other (cause there will be only one)
  5. Memory leaks do not cause operation disruption
    Any memory leak will translate – sooner or later – into Full Garbage Collections and eventually OOM (much feared out of memory) Any business case that you have not tested, or that you are not aware of can cause something like this. Before going to the roots of the problem, and solving it by modifying the code, you will need to restart your application server, hence restart your front-end server. Are you willing to be “not available”?
    Running the Backoffice into a separate JVM will allow you to: 

    • Restart Backoffice JVM
    • Online redeploy of  newer, fixed versions of software
  6. JDBC statement caching
    As most of you probably know, JDBC allows configuring the number of statements to be cached / jdbc connection. As i am aware of, the algorithm chosen for managing the cache is LRU. Now, running the Backoffice and front-end in the same JVM, may well dismiss critical cached statements of a connection, just because your Backoffice business case needs a lot of statements to be run. Although it is not an effect that you see in the day to day operation, you will notice it in a OLTP system. Guaranteed!
  7. SQL Debugging
    Running the Backoffice in the same JVM, over the same JDBC connection will make isolating Backoffice queries almost impossible to acchieve. I am referring to the Oracle trace files, or views (v$sql, v$sqlarea, etc.), which will show you a bunch of statements running over the same connection, same user, etc. Having the possibility of filtering after hostname or even better, username, will save you a lot of time. You can do that either by using a second jdbc connection pool, configured with another user, or by running the Backoffice in a separate JVM, separate application server
  8. Custom tuning for busines needs
    Configuring your Backoffice into another JVM will allow you to fine tune things like: 

    • heap size
    • garbage collection strategy
    • jdbc settings (validation,timeout,statement caching)
    • thread pool
    • etc.

    The fine tuning for Backoffice will almost never meet the needs of front-end

  9. Sampling, profiling
    No need to point this out. Having a single application to profile (or sample) makes things much easier, and faster to detect and fix.
  10. High availability
    I was pointed about this one by Niels, one of my collegues. If your production environment is configured using the “staging” principle, where shutting down means actually moving over, you will then need to double the requirements on Heap, both for your front end and back end. Now, imagine you have a 16 GB server, with a configured heap size of 8GB for both Frontend and Backoffice. In order to create the stage system, and to have them both running, 16 GB will therefore not be enough, not anymore ( you need to double the resources). Moving the Backoffice to another server, and another JVM will allow you to “stage” gracefully.

I will get back to this list whenever i feel like adding another point. I would be happy to see  your comments.

Cheers,

Alex

Categories: Uncategorized

Glassfish – JDBC Connection Validation explained

Advanced properties are not being called “advanced” for nothing. Playing with some parameters hoping that it will improve some behaviour, without really knowing all underlying effects can have really bad side effects.

I came across the topic of connection validation while studying a very confusing error, with a very low level of reproducing. Actually, if i think it over, we were not able to reproduce it again once we restarted the application server (that was still before adding the connection validation)

So, let’s go to the roots, and have a sound understanding of what Connection Validation can do for us.

The error we were receiving showed us that the database was closing the connection, as soon as we were trying to do something over it.

Associate with Thread:

Thread-1;|RAR5031:System Exception javax.resource.spi.LocalTransactionException: Closed Connection

Trust me, there isn’t too much information out there regarding this. On the Oracle side, you will get something like this in the trace files:

ORA-600 [12333] – The error may have a number of different root causes. For example, a multi-threaded Client-side application sent an OCI call out of order, or the data in the network buffer may have been overwritten.
Since there are many potential causes of this error, it is essential to have a reproducible testcase to correctly diagnose the underlying cause.

Nice, isn’t it ?:)

Since we were working in a distributed environment, with many application servers and one single database, each application server had a pool of some 200 dedicated connections to the database. Depending on the server where the user was landing, this problem could be happening after one or after 1000 transactions. Since the jdbc connections are served from the pool, there is no guarantee that the same connection will be used by the same thread over and over again ( of course, you are able to set the advanced property “Associate with Thread”, but that brings some side effects, which are outside the topic discussed here)

At first i (after having a fresh read about the PGA and SGA on shared vs dedicated Oracle connections the previous night) supposed that the problem could be because of the number of sessions, and somehow because of the change we did a couple of days ago, when we decided to switch off the ASSM in Oracle. I thought that because we forgot setting some manual values for the SGA,  a problem like this could happen, where too many connections could cause such a behaviour. So i decided to follow the well known “divide et impera”, by gradually reducing the number of connections on each of the application servers, and trying to reproduce the error on the application server in cause.

Since we were working with a cluster of 6 Glassfish Application Servers, we started with the last one.

  1. Reducing the number of connections in the pool
    When trying to reproduce the problem, it occured to me that it was not only still happening, but it was happening more often. So reducing the number of connections increased the rate of reproducing…interesting
  2. Reducing the number of connections up to the last application server
    After doing this for all servers, and reproducing the problem on all servers, i was now running with a number of 20 connections / pool / application server. Clearly, there was no SGA problem on the Database side.
  3. Faulty JDBC Connections
    After carefully reviewing the log output of the error, reasearching the internet, and discussing this with our DBA, we soon came to the conclusion that the problem was being caused by a faulty jdbc connection. This can happen because of several causes, leading to some inconsistency on JDBC level, for example  a connection that is trying to access a cursor that it still thinks it owns, but does no longer, network problems, etc. The main point here is that a JDBC connection CAN go corrupt. And if it does, there is nobody (when using the default configuration) to check on it and heal/remove it.

So, we isolated the problem up to the point that we knew that some of the connections were going corrupt. Since we cannot control which jdbc connection goes to which thread, the probability of the faulty connection to be used is pretty much the same as for any other connection to be used: HIGH

Solution

Connection Validation: Validation Method – Table

Armed with the information that JDBC connection can be corrupted, we needed a solution for a cleaning process. So i came across JDBC Connection Validation. Basically, this was designed with a purpose, and that is to make sure that faulty connections are being used as less as possible before being removed from the pool.

Unfortunately, there is not too much information out there on the topic, and if there is, none of it is really “complete”. After starting on Jagadish’s Blog, i was soon on the right track of configuring the connection validation. The idea is as following:

  1. Before using a connection from the pool, a test query is sent over the connection to the database. The table to be queried is chosen by you
  2. If the connection is faulty, it will be removed from the pool, and the next one will be used (removal of the connection will not add a new one instead – only in the case that the pool is empty)
  3. As long as the connections are faulty, each of the connections will be tested the same way as in step 2.
  4. Once the last connection has been marked as faulty, a fresh new connection will be added to the pool

In the worse case scenario, dealing with 200 faulty connections, you would go over 200 connections to run a statement, which of course, brings a lot of overhead. Therefore, you can always enable the following parameter:

Connection Validation – On Any Failure: Close all connections

By doing this, whenever a connection validation fails, all remaining connections, regardless of their state (valid or corrupt, we cannot know until we do a check) will be DROPPED. Now, don’t jump on setting this immediately. Of course this comes at some cost, specially if you have prepared your Glassfish Server for Production by following some of the awesome hints described here: http://weblogs.java.net/blog/sdo/archive/2007/12/a_glassfish_tun.html

Speaking of databases, it’s quite important in glassfish to use JDBC drivers that perform statement caching; this allows the appserver to reuse prepared statements and is a huge performance win. The JDBC drivers that come bundled with the Sun Java Systems Application Server provide such caching; Oracle’s standard JDBC drivers do as well, as do recent drivers for Postgres and MySQL. Whichever driver you use, make sure to configure the properties to use statement caching when you set up the JDBC connection pool — e.g., for Oracle’s JDBC drivers, include the properties

ImplicitCachingEnabled=true
MaxStatements=200

When dropping a connection, you will drop it’s entire cache, which, in a highly performant environment can be costly. Another thing you are dropping, is the dedicated connection to the database server, ergo the cursors you were using, and all optimization that was done for specific queries under those cursors. So think twice if you afford dropping all conections!

Connection Validation – Table name

Since we were using ORACLE, the fastest table to use for validation would be DUAL. I have tracked the v$sql views of my Oracle instance to see which query is being run for validation, and came to the conclusion that the validation is done by issuing a:

select count(*) from DUAL

Connection Settings – Validate at most once

Now this was the tricky part. Do not let yourself get fooled by “validate at most once 0 (zero) seconds” Not enabled does not mean not enabled. It means that the validation will be done every time the connection will be used. In a system under heavy load, this could be happening several times/second/connection. I specifically checked on that by doing a trace on the v$sql view, and following the number of executions.

Now, in order to avoid this, make sure you set the value to a relevant (to your business case) number. Setting it to 60 seconds for example, has the following meaning:

  1. The first time the connection will be used, a validation will take place. If the validation fails, the next one will be used, as described above.
  2. After the connection has been validated, it will be used by all requesting threads for as long as 60 seconds, regardless if inbetween the connection goes corrupt. For 60 seconds, this connection will be marked as VALID
  3. After 60 seconds, regardless who requests the connection (it could be the same thread that started the validation in the first place), a new validation will take place.

Configuration Proposal

We decided to go with the following parameters, which could be the ones you need (or not) depending on your business cases:

Glassfish Connection Validation Settings ( all to be found in the administration console>connection pools> advanced)

Statement Cache Size: 200 (that means 200 statements will be cached / thread – watch out with this one, don’t set it too high if you are Storage bound)

Wrap JDBC Objects: Enabled

Pooling: Enabled

Validate at most once: 60 seconds

Connection validation: required

Validation method: table

Table name: dual

And this is how the connection parameter looks in the domain.xml file, if you want to set it manually:

<jdbc-connection-pool validation-table-name=”DUAL” max-pool-size=”200″ datasource-classname=”oracle.jdbc.pool.OracleDataSource” pool-resize-quantity=”10″ res-type=”javax.sql.DataSource” steady-pool-size=”50″ statement-cache-size=”200″ name=”myPool” is-connection-validation-required=”true” validate-atmost-once-period-in-seconds=”60″>

 

I loved dealing with this one! :)

Cheers,

Alex

References: http://blogs.sun.com/JagadishPrasath/entry/connection_validation_in_glassfish_jdbc

Jasper Reports – Cascade Parameter Reports in IReport & Jasper Server 3.7.5

February 2, 2011 5 comments

I have long awaited for this functionality in Jasper Server. And it was beautifully served starting Jasper Server 3.7.5

What i needed to do, was to do a cascade query, which would allow me eventually to select a single (or list) of id’s, based on the previous selections. Since i have spent some time integrating this in my reports, i thought it could help others acchieve this also, since it is not really “out of the box”.

I will start by defining the scope of the report, the ER diagram of the tables, and will then dive into configuring the needed resources, both in Jasper Server and IReport.

As i am using Jasper Reports for building performance reports, i am using the following four tables (relevant for this document):

  • info {id,build,portal_version,revision_number) – containing the primary key, software major version name, and the portal version (the hudson build id). I am using the primary key  in a one to many relationship in the following table, where i hold the map between the tests that i ran, and the software version (the revision_number is obsolete, as it is the same with the hudson build id)
  • testrun {build_id,test_id} – containing the map between the build and the tests (one to many)
  • testdescription{test_id,test_date,threads,users,rampup,scenario_id, architecture_id,etc.} – holding test information for each test that has been run (numbe of threads, date, etc., and the component tested, which in this case is represented by (bad naming) “scenario_id
  • testresults {id,testrun_id,t,lt,ts,lb,…etc} – holding the test results imported from JMeter reports

For a better understanding, i have provided the ER Diagram for this four tables:

ER Diagram Performance Reports

ER Diagram Performance Reports

So, what we want to do, is building a report from the testresults, that reside in “testresults” table. For that, we need the “testresults.testrun_id” value, which we want to extract after previously having selected the needed information. We will follow the following steps:

  1. Query and display  the contents of  the table “info“, and select the major version and revision number that we are interested in. We will store the result (only “info.id” ) into a parameter called ic_version, that we will use in the second query for finding all components that have been tested against this software version
  2. Query and display the tested components (scenario_id) from the table “testdescription” based on the chosen info.id, which we now have in the ic_version parameter. We will do a join over the “testrun” table in order to sort that information. We’ll store the result of the selection (only “testdescription.scenario_id“) into a second parameter, called ic_component that we will now use to find the tests that have been run against this component
  3. Query and display all tests from “testrun” that match ic_component criteria ( all tests that have been run against a component, on a specific software version). We will store the result of the selection in a third parameter, called ic_testconfig, that we will pass on to the internal report query

Let’s do this, one by one. We will start by creating the needed resource in Jasper Server.

Server Side Configuration – Jasper Server

  1. Query and display the contents of “info”, store results into a server side parameter
    1. Log in as Jasper Administrator to your Jasper Server instance
    2. Go to “Input Data Types”. Right click > Add resource – Query
    3. Name it “q_version_select” and label it “Query version select”
    4. Choose the server sided Data Source (From the Repository)
    5. Type in your query:
      select id,build,portal_version ,revision_number from info order by id
    6. Now that we have the query, we will need a server sided parameter to store the selection that we are going to do from the result set of this query. We need to create an Input Control on the server
      Go to “Input Data Types”. Right click > Add resource > Other – Input Control
    7. Name it “ic_version“. Prompt text should be “Choose software version”. Type  should be “single select query”.Click “next”
    8. Select the query from the repository ( the q_version_select query that we just created in step 1-5)
    9. Select “id” as value column (this will be the value stored in the parameter), and whatever you want for the displayed (visible columns). They will only be displayed to make your selection easier (i chose them all)
  2. Query and display the tested components on the software version, using the parameter “ic_version
    1. We need to create the second query, which will use the “ic_version” parameter
    2. Go to “Input Data Types”. Right click > Add resource – Query
    3. Name it “q_select_component” and label it “Query component select”
    4. Choose the server sided Data Source (From the Repository)
    5. Type in your query:
      select distinct tr.test_id,td.scenario_id,td.architecture_id
      from testrun tr
      inner join info ON tr.build_id = info.id
      inner join testdescription td on td.test_id = tr.test_id
      where info.id=$P{ic_version} group by td.scenario_id order by scenario_id,architecture_id
    6. Now that we have the query, we will need a server sided parameter to store the selection that we are going to do from the result set of this query. We need to create an Input Control on the server
      Go to “Input Data Types”. Right click > Add resource > Other – Input Control
    7. Name it “ic_component“. Prompt text should be “Choose tested component”. Type  should be “single select query”.Click “next”
    8. Select the query from the repository ( the q_select_component that we just created in step 1-5)
    9. Select “scenario_id” as value column (this will be the value stored in the parameter), and whatever you want for the displayed (visible columns). They will only be displayed to make your selection easier (i chose scenario_id and architecture_id)
  3. Query and display the test id and test configuration (in case you had different load scenarios for the same test and same component)
    1. We need to create the third query, which will use the “ic_component” parameter
    2. Go to “Input Data Types”. Right click > Add resource – Query
    3. Name it “q_select_configuration” and label it “Query test id and configuration”
    4. Choose the server sided Data Source (From the Repository)
    5. Type in your query:
      select
            td.test_id,
            td.scenario_id,
            td.architecture_id,
            td.test_date,
            td.threads,
            td.users
      from
      testdescription td
      inner join
      testrun tr ON td.test_id = tr.test_id
      inner join
      info ON tr.build_id = info.id
      where
      td.scenario_id=$P{ic_component}
            and
      info.id=$P{ic_version}
      order by
            td.architecture_id,td.test_date
    6. Now that we have the query, we will need a server sided parameter to store the selection that we are going to do from the result set of this query. We need to create an Input Control on the server
      Go to “Input Data Types”. Right click > Add resource > Other – Input Control
    7. Name it “ic_testconfig“. Prompt text should be “Choose test id and configuration”. Type  should be “multi select query” (maybe you need to create a report from multiple tests). Click “next”
    8. Select the query from the repository ( the q_select_configuration that we just created in step 1-5)
    9. Select “test_id” as value column (this will be the value stored in the parameter), and whatever you want for the displayed (visible columns). They will only be displayed to make your selection easier (i chose test_id and test_date and threads (virtual users))

We have now reached the final step, where we have stored the selected test id in a parameter called “ic_testconfig”. We will use this parameter in the internal report query in IReport. Let’s just see how the cascading looks at this point (of course, a report is already created in IReport, but i will detail that below):

First we select the software version

Jasper Reports Cascade Parameters

Second, we select the tested component

 

 

Jasper Reports Cascade Parameters

Last, we select the tests that we want to build the load report from

So, the main idea is, that based on the first selection, the second drop list changes dynamically. The third list changes according to the second selection, and so on. You could have as many drop down lists as you like in your form.

Client Side Configuration – IReport

In order to build a server hosted report, which uses the resources we defined above, we need to synchronize the resources. Therefore, we need to add the server side input controls we just defined to the report. You do that by following these steps:

  1. Open IReport and expand the report you want to use
  2. Select the “Input Controls” subfolder of the report – Right Click > Link an existing input control (we want to use the one on the server, otherwise we would have defined it locally)

    IReport - Link existing input control

    IReport - Link existing input control

  3. Choose datatypes as location for the input controls

    IReport - Add server located input control - Datatypes

    IReport - Add server located input control - Datatypes

  4. Add the three input controls that we defined in the first part, one by one: ic_version, ic_component, ic_testconfig
  5. For each server side input control, we need a local defined parameter with the same name and type. Add the following three parameters in the Parameters Tree:
    • ic_version of type string
    • ic_component of type string
    • ic_testconfig of type collection, with a default expression of: new ArrayList(Arrays.asList(new String[] {“a”}))

    We are now ready to build the local query (the report query), which will use the last selected parameter, ic_testconfig

  6. Define the local query based on ic_testconfig parameter:
    select 
               tr.col1,
               tr.col2,
               etc.
    from
              testresults tr
    where
              $X{IN,tr.testrun_id,ic_testconfig}

As you can see, we use the ic_testconfig parameter that we used in the cascade for defining the test id for the load report.

That’s it. Here is a list of things to remember:

  1. Every query should have an input control on the server
  2. Every subsequent query should use the input control from step 1 as sql predicate
  3. Every input control on the server has to be linked in the report as “existing input control”
  4. Every input control defined on the server and linked as existing input control, has also have to be defined as local parameter, of the same type, and with the same name

 

 

Command Line Glassfish Monitoring in Jasper Reports using Glassfish Rest Monitoring

January 31, 2011 2 comments

Recently i have spent some time thinking how i can integrate active monitoring of Glassfish critical resources into my reactive Performance Reports.  I was having a performance report showing me both response times and throughput, but i needed to know why, at some points in time, my throughput was decreasing. There could have been several reasons, like JMS, JDBC, too many open connections , etc… I needed to have those values in my report, so i could easily identify problems without proactively monitoring while testing. So i started thinking about ways to do it.

At first, i wanted to monitor the following resources (there are lots to follow, but now i’ll just stick to these ones, as these ones were the ones i needed in the beginning)

  • jdbc usage – the number of connections used at runtime
  • threads busy – the number of busy threads at runtime
  • open http connections – the number of open connections at runtime
  • keep alive connections – the number of connections in keep-alive mode at runtime
  • http peak queued requests – the peak number of requests that had to wait in a queue before being processed
  • count of specific beans in our software

I also needed to develop a solution that would allow me adding new monitoring statistics later, in a “plug-in” fashion.

Basically, there are three ways (of which i am aware of at least) that you can do it:

  1. Using JMX programatically
    Basically, you use the JMX Api, by registering the MBean server, and then interrogating each managed bean according to your needs. As i prefer shell scripting to developing (sic!), i turned my back to this solution, and started looking into the next one. Those who want to see this in action can check it out here: 

  2. Using a custom built JMX command line monitor
    I needed a tool that could interrogate the MBean server, and return the result into a file, on a timely fashion. It had to be able to be controlled through my shell script, which would control what and when to interrogate. There are several solutions on the market (i am talking about the open source ones) like: 

    • jmxterm – http://wiki.cyclopsgroup.org/jmxterm – I think of all that i have tried, this one was the easiest and most straight-forward to use. The best about it is that you can define commands to be sent into a file, and use the file as command input. That way, if your target is to interrogate the server in a high-pause (let’s say every 5 minutes) fashion, then jmxterm is a pretty good solution.
    • command line jmx client - http://crawler.archive.org/cmdline-jmxclient/ (quite old, not very flexible, only one command at a time
  3. Using the REST Management Interface provided by Glassfish
    Basically, Glassfish provides two interfaces, one for managing resources, the other one for monitoring. 

    • Glassfish Management Interface – http://yourserver:4848/management/domain
    • Glassfish Monitoring Interface – http://yourserver:4848/monitoring/domain

    The fact that every attribute can be monitored via an HTTP request, makes this the best candidate for my purposes. Let me detail that

Glassfish comes preconfigured with every monitoring level set as low. This means that in order to start monitoring, we need to enable monitoring for specific modules. Let’s do that, one by one, for the modules that we need. You need to call the management interface of Glassfish:

http://yourserver:4848/management/domain  (or directly http://yourserver:4848/management/domain/configs/config/server-config/monitoring-service/module-monitoring-levels for going directly to the monitoring levels page) Set the desired modules to HIGH:

Glassfish Rest Interface - Enabling Monitoring

Glassfish Rest IGlassfish Rest Interface - Enabling Monitoring

The changes are dynamic, you do  not need to restart the server. Let’s check if this worked out. I am going to request the number of active connections, by calling the monitoring interface of the http listener in a browser:

http://yourserver:4848/monitoring/domain/server/network/http-listener-1/keep-alive

The result lookis like this:

Monitoring Glassfish Keep Alive Connections

Monitoring Glassfish Keep Alive Connections

This works for every attribute that you normal query through the MBeans Browser in JConsole or VisualVM. Now, i was speaking about needing a way to control the requests from command line (shell script), the delays, and a way to import and present the data in the same report with my performance report. I needed some way to make the request from the command line, so i turned to wget. Unfortunately, wget cannot append the result into a file, therefore i switched to curl. Therefore, the request that i just sent above, using a browser, can now be sent as a curl request:

curl -s -u admin:adminadmin  http://yourserver:4848/monitoring/domain/server/network/http-listener-1/keep-alive

Now, this is the last level of granularity that you will obtain. This request will provide you with all keep alive monitoring statistics:

  • countconnections
  • counttimeouts
  • secondstimeouts
  • maxrequests
  • countflushes
  • counthits
  • countrefusals

Now, if we are only interested in the number of keep alive connections, we need to extract that from the answer. Nothing easier, when using regular expressions. Let’s do that for “countconnections’. We will store the result into a variable, using shell scripting:

HTTP_KEEP_ALIVE_CONNECTIONS=`curl -s -u admin:adminadmin  http://yourserver:4848/monitoring/domain/server/network/http-listener-1/keep-alive  | grep countconnections | grep -o -E ‘”count”:[0-9]*’ | sed ‘s/["]*[a-z]*["][:]*//’`

This will return the value of the keep alive connections parameter alone. If we wanted to check on the number of http connections we would use:

HTTP_CONNECTIONS_OPEN=`curl -s -u admin:adminadmin http://yourserver:4848/monitoring/domain/server/network/http-listener-1/connection-queue | grep countopenconnections | grep -o -E ‘”count”:[0-9]*’ | sed ‘s/["]*[a-z]*["][:]*//’`

That gives you so much flexibility, doesn’t it? Let’s just collect all this information on a time basis, using a function. We will collect statistics every x seconds, as long as the monitoring process is enabled. We enable the monitoring process by creating a temporary file called “/tmp/glassfish_stats”. The idea behind this is to start monitoring when we start the load test, and stop monitoring once the last request of the load test has been sent (when we would then remove the /tmp/glassfish_stats file, therefore stopping the monitoring process

function trace_gf_statistics
{
CMD_PARAM_PROTOCOL=$1
CMD_PARAM_SERVER=$2
CMD_PARAM_PORT=$3
CMD_PARAM_INTERVAL=$4

#Check on temporary file. If it exists, stop monitoring. Otherwise, monitor every x defined seconds
status=`ls /tmp | grep glassfish_stats`

while [ "$status" != "" ];
do

 MONITOR_TIMESTAMP=`date +%H-%M-%S`

 #JDBC Monitoring
 JDBC_CONN_USED=`curl -s -u admin:adminadmin http://
$CMD_PARAM_SERVER:$CMD_PARAM_PORT/monitoring/domain/server/resources/
mypool| grep numconnused |
grep -o -E '"current":[0-9]*' | sed 's/["]*[a-z]*["][:]*//'`

 #Thread Pool Monitoring
 HTTP_THREAD_POOL_THREAD_COUNT=`curl -s -u admin:adminadmin http://
$CMD_PARAM_SERVER:$CMD_PARAM_PORT/monitoring/domain/server/network/
http-listener-1/thread-pool | grep currentthreadsbusy |
grep -o -E '"count":[0-9]*' | sed 's/["]*[a-z]*["][:]*//'`

 #Keep Alive Connections
 HTTP_KEEP_ALIVE_CONNECTIONS=`curl -s -u admin:adminadmin  http://
$CMD_PARAM_SERVER:$CMD_PARAM_PORT/monitoring/domain/server/network/
http-listener-1/keep-alive  | grep countconnections |
grep -o -E '"count":[0-9]*' | sed 's/["]*[a-z]*["][:]*//'`

 #Open connections

 HTTP_CONNECTIONS_OPEN=`curl -s -u admin:adminadmin http://
$CMD_PARAM_SERVER:$CMD_PARAM_PORT/monitoring/domain/server/network/
http-listener-1/connection-queue | grep countopenconnections |
grep -o -E '"count":[0-9]*' | sed 's/["]*[a-z]*["][:]*//'`

 HTTP_CONNECTIONS_PEAK_QUEUED=`curl -s -u admin:adminadmin http://
$CMD_PARAM_SERVER:$CMD_PARAM_PORT/monitoring/domain/server/network/
http-listener-1/connection-queue | grep peakqueued |
grep -o -E '"count":[0-9]*' | sed 's/["]*[a-z]*["][:]*//'`

 #Bean Monitoring

 BEANMON_MYTESTBEAN_CURRENT=`curl -s -u admin:adminadmin  http://
$CMD_PARAM_SERVER:$CMD_PARAM_PORT/monitoring/domain/server/
applications/myapplication/mytestbean/bean-cache  |
grep numbeansincache | grep -o -E '"current":[0-9]*' |
sed 's/["]*[a-z]*["][:]*//'`

 BEANMON_MYTESTBEAN_PEAK=`curl -s -u admin:adminadmin  http://
$CMD_PARAM_SERVER:$CMD_PARAM_PORT/monitoring/domain/server/
applications/myapplication/mytestbean/bean-cache  |
grep numbeansincache | grep -o -E '"highwatermark":[0-9]*' |
sed 's/["]*[a-z]*["][:]*//'`

 echo $MONITOR_TIMESTAMP":JDBC   - Connections used:
"$JDBC_CONN_USED >> ${JMETER_RESULTS}/glassfish_stats.log

 echo $MONITOR_TIMESTAMP":HTTP   - Thread Usage:
"$HTTP_THREAD_POOL_THREAD_COUNT >> ${JMETER_RESULTS}/glassfish_stats.log

 echo $MONITOR_TIMESTAMP":HTTP   - Keep Alive Connections:
"$HTTP_KEEP_ALIVE_CONNECTIONS >> ${JMETER_RESULTS}/glassfish_stats.log

 echo $MONITOR_TIMESTAMP":HTTP   - Open Connections:
"$HTTP_CONNECTIONS_OPEN >> /${JMETER_RESULTS}/glassfish_stats.log

 echo $MONITOR_TIMESTAMP":HTTP   - Peak Queued Connections:
"$HTTP_CONNECTIONS_PEAK_QUEUED >> /${JMETER_RESULTS}/glassfish_stats.log

 echo $MONITOR_TIMESTAMP":Beans  - Mytestbean Current:
"$BEANMON_MYTESTBEAN_CURRENT >> /${JMETER_RESULTS}/glassfish_stats.log

 echo $MONITOR_TIMESTAMP":Beans  - Mytestbean Peak:
"$BEANMON_MYTESTBEAN_PEAK >> /${JMETER_RESULTS}/glassfish_stats.log

 sleep $CMD_PARAM_INTERVAL
 status=`ls /tmp | grep glassfish_stats`
done
cp ${JMETER_RESULTS}/glassfish_stats.log ${JMETER_TRANSFORMATION}glassfish_stats.log
}

So basically, i am querying the resources every x seconds, appending them to an export file, that i will use in the end for importing and transforming. As one can see, i use a “:” delimited file, where i export the following:

  • timestamp
  • monitored resource
  • value

In the end, it looks something like this:

16-07-05:JDBC   - Connections used:0
16-07-05:HTTP   - Thread Usage:0
16-07-05:HTTP   - Keep Alive Connections:2
16-07-05:HTTP   - Open Connections:16783
16-07-05:HTTP   - Peak Queued Connections:51
16-07-05:Beans  - Mytestbean Current:0
16-07-05:Beans  - Mytestbean Peak:177

Now, all i have to do is to import the results into the database, and prepare the report. And this is how it looks in the end:

Monitoring Glassfish JDBC - Connections used

Monitoring Glassfish JDBC - Connections used

And now bean monitoring:

Glassfish Bean Monitoring

Glassfish Bean Monitoring

And this is how the final report looks like (sorry, i will get back with a clear view of it. Haven’t had the time to adapt this one to paper size yet, so i only have it in extended format )

Jasper Report with Glassfish Monitoring

Jasper Report with Glassfish Monitoring

The best part in this, is that if you need to monitor a new resources, it will all come to two things:

  1. Setting the variable and the curl request
  2. Adding the result to the export file

The structure of the database, organised as (test_id,timestamp,label,value) will take this on the fly, regardless of the number of monitored resources. You can add as many subreports as you want, monitoring mainly everything that you need. The timestamps will help you check what happened at a specific point in time (for example when the throughput decreased…)

This kicks the hell out of commercial tools, doesn’t it ?

Good luck with setting your monitoring environment, and let me know if you encounter any problems.

cheers,

Alex

J2EE – Full Garbage Collections when running with CMS Garbage Collection Strategy

January 11, 2011 4 comments

There’s no reason relating once more about the main garbage collection strategies. Mainly, there are two of them, one designed for throughput, the other for better response times.

Parallel Garbage Collection

This garbage collector is designed for throughput. It will use all CPU power in order to clear your old generation as soon as possible. The downside of this strategy, is that the bigger the heap, the longer the “stop the world” time will be. If you are allowing yourself application stop times of more than 5 seconds, and response time is not that important, this is a good strategy to choose.

CMS – XX:+UseConcMarkSweepGC

On the other hand, if you work in a highly interactive application, and you need to make sure that response times are in an acceptable range, therefore not allowing long wait times, then you should be choosing the CMS collector, which will considerably reduce application stop times, also taking advantage of powerfull hardware configurations and paralellity.

Now, if the CMS is the strategy you adopted, you should be expecting low application stop times, and no Full Garbage Collections. There are still times when Full Garbage Collections are triggered, and you start wondering why, since you specifically chose CMS.

These are the possible situations when a Full Garbage Collection is triggered, when working with CMS:

The RMI Distributed Garbage Collection

When working outside the JVM ( for example with external interfaces calling objects running in other JVM’s) , the RMI Garbage Collection will be triggered, in order to make sure that the JVM’s stay synchronized. This will only be triggered based on the rmigcinterval, which is default set on 3600000 ms ( one hour) and will only happen one hour after the last JVM Old Generation Garbage Collection. Basically, it says that ” if there’s been an hour already, and no old generation collection has been triggered, i should be doing something about it, so i’m going to trigger a Full Garbage Collection (thereby stopping the JVM )” You could easily see if this is the case, by monitoring the garbage collection log using HPJMeter Tool. This is a sample of the garbage collection log, where one can see the rate of the RMI triggered garbage collections:

RMI Garbage Collection triggered after last GC

RMI Garbage Collection triggered after last GC

RMI Garbage Collection

If you need to disable this kind of Garbage Collection, there are two ways to do it:

  • increase the rmigcinterval to a value big enough
  • disable explicit garbage collection by setting the DisableExplicitGC Parameter as jvm option (reccommended, for it also prohibits any poorly programmed code to explicit call Full Garbage Collections)

CMS Time Failure

Basically, what CMS tries to do, is proactively start an Old Generation collection while the application is still running (parallel to the application) It will trigger itself by default when the occupancy of the old generation reaches 68 %. Now, if the CMS fails to finish the collection before the old generation gets filled up to 100 %, a Full Garbage Collection will be triggered. That can normally happen only when the load on your application is high enough to occupy the old generation that quickly ( poorly configured heap)

PermGen fill-up

The last, but not least is the filling up of the PermGenSpace. If your application is loading classes repeatidly, the permgen will easily be filled. Even if there is no memory leak, the only collector that collects the permgen is the Full GC. Therefore, whenever the PermGen is filled, a Full GC will be triggered. This might be confusing, since you have a lot of free heap, in both old generation and young generation. Here is a sample of the garbage collection log, for a heap configured to 8 G maximum space, and 5 G young generation:

2727.298: [GC 3340602K->802865K(4617552K), 0.2234180 secs]
2754.630: [GC 3319473K->863600K(4617552K), 0.3183730 secs]
2862.396: [GC 3380208K->832610K(4617552K), 0.2813350 secs]
2907.214: [GC 3349218K->886328K(4617552K), 0.2823410 secs]
2921.866: [Full GC 2011172K->587426K(4617552K), 4.4077830 secs]
2949.352: [GC 3104034K->632358K(4617552K), 0.1023640 secs]
2969.806: [GC 3148966K->656114K(4617552K), 0.1410020 secs]
2988.923: [GC 3172722K->681356K(4617552K), 0.1764440 secs]
3006.377: [GC 3197964K->722131K(4617552K), 0.1794230 secs]
3024.395: [GC 3238739K->725537K(4617552K), 0.2815690 secs]
3039.723: [GC 3242145K->739136K(4617552K), 0.2104230 secs]
3054.622: [GC 3255744K->804870K(4617552K), 0.2881420 secs]
3068.541: [GC 3321478K->786337K(4617552K), 0.2396040 secs]
3083.404: [GC 3302945K->830937K(4617552K), 0.1963600 secs]
3096.678: [GC 3347545K->836541K(4617552K), 0.1920160 secs]
3112.045: [GC 3353149K->896975K(4617552K), 0.3088930 secs]
3126.127: [GC 3413583K->888960K(4617552K), 0.2133740 secs]
3126.511: [Full GC 1048029K->826121K(4617552K), 5.6385590 secs]
3144.967: [GC 3342729K->938778K(4732328K), 0.2383430 secs]
3157.949: [GC 3455386K->1035760K(4732328K), 0.3590400 secs]
3195.042: [GC 3552368K->983156K(4732328K), 0.2514770 secs]
3249.780: [GC 3499764K->951762K(4732328K), 0.2490240 secs]

As one can see, the heap occupancy is far from being full, and still the Full GC’s are being triggered. This can also be seen by using VisualVM’s GC Plugin, which will show the garbage collection activity in livetime:

PermGen filled triggers Full GC

PermGen filled triggers Full GC

Young Generation and it’s survivors are full

The last situation that i can think of, and i have seen, is when the heap is poorly configured for the load, for example when the maximumtenuringthreshold is set to high, and the application uses a large set of long lived objects. That way you can easily fill the young generation, and the survivors, before the threshold will be reached. Therefore long lived objects will never make it to the old generation and the Young Generation will be filled. This is the situation where the JVM comes and says ” if there is no place to allocate objects, i have to trigger a Full Garbage Collection”

Out of memory

Needless to say that this is the most common cause for Full Garbage Collections. Any memory leak will translate in time in a filled Old Generation. Objects hanging in the old generation will not be able to be cleaned, therefore at some point in time, the CMS will not make it anymore, and will trigger a Full Garbage Collection. Usually when this happens, you should be seing lots of Full GC’s, one after the other, because the GC cannot free space anymore.

A properly configured heap, based on the expected load is one of the most important things to take care of, and this will be one of the next topics i will write about, configuring and tuning the heap based on load, benchmarks and monitoring.

I hope i summarized all of them, would be happy to see comments or critics.

Cheers,

Alex

Categories: garbage collection

Oracle – Index Performance Topics – Index clustering factor

December 3, 2010 2 comments

When starting to work on this assignment, the only information i had was that up from a point (after some million transactions) our database was getting slow. I needed to know why a database like Oracle was behaving so badly after less than 100 million transactions in the database. Clearly, it was a problem of contention, a problem of waiting. I needed to know why that was, so the first thing i did was to ask our DBA for his Oracle Database Architecture book, and dig in.

After getting a better view on the logical (and physical) structure of the Oracle DB, i  had another discussion with the DBA. It was still unclear to me how, despite the fact that our queries were using the indexes, we not only had problems in reading, but in writing also. Together we found out that the size of the (all)  indexes on some of our columns were at some points bigger  (if not double) the size of the data. Oracle was starting to spend a lot of time internally on managing the indexes.

We started to do an analysis on the biggest tables, and their indexes, in order to find out:

  • who were the biggest consumers (storage)
  • which were the indexes that were summing up the storage
  • which indexes did we really need, and which could we drop

Of course, one would say that at least the last point here should have been done before creating the indexes. Unfortunately we fell into the trap of creating the indexes based on gut or on daily operations (or performance tests), not really following the business scenarios.

Like i already mentioned, we also had some very long response times when doing a read operation on the database (a normal business scenario, where a user would retrieve about 1000 records from the database) for specific queries involving the same tables. I run a test on one of those queries, using Oracle’s trace function to see where did Oracle spend that much time. I was amazed by the results:

  • Running the query on a table containing 2.5 million records – 30 seconds
  • Running the query on a table containing 30 million records – timeout!!!

Now, how was that possible? Let us dive into the real problem

Displaying storage and structure statistics on Oracle tables and indexes

Without having access to the Oracle Statistics ( we use TOAD for that )The first thing that i did, was to design myself a query that would satisfy the following requirements:

  • show the number of rows / table
  • show the number of blocks / table
  • show the total size in bytes /table
  • show the indexes and their size / table
  • show the indexes clustering factor
  • show the level of each index
  • show the number of leaf blocks for each index

I needed to display only the big consumers, so i limited that to all tables having more than 1 million records. After playing a little with oracle’s tables, i came up with the following snippet:

select
	a.table_name,
	b.blocks,
	b.num_rows,
	(b.blocks*4)/1024 as table_storage_mb,
	a.index_name,
	sum(ue.BYTES)/(1024*1024) as index_storage_mb,
	a.clustering_factor,
	a.BLEVEL,
	a.LEAF_BLOCKS
from
	user_indexes a
inner join
	user_tables b
on
	a.table_name=b.table_name
inner join
	user_extents ue
on
	a.index_name=ue.segment_name
where
	b.num_rows is not null
and
	b.num_rows > 1000000
GROUP BY
	a.table_name,
	b.num_rows,
	(b.blocks*4)/1024,
	a.index_name,
	a.clustering_factor,
	a.BLEVEL,
	a.LEAF_BLOCKS
ORDER BY
	table_storage_mb desc,
	a.table_name,
	index_storage_mb desc,
	a.index_name

This returned the following results (i had to shorten the name of the tables, indexes, and the table headers)

The table headers have the following meaning:

TBL – Table; TROWS – Rows in table; TBLKS – Table Blocks; T-BM – Table storage in MBytes; INAME – Index name; IMB – Index storage in MBytes; ICL_FACT – Index clustering factor; LF_BLKS – Index Leaf Blocks

TBL TROWS TBLKS T_MB INAME IMB ICL_FACT LF_BLKS
TBL1 42902100 5016000 19593 G_ID 2398 40179600 597100
TBL1 42902100 5016000 19593 GRID 1857 13046900 479900
TBL1 42902100 5016000 19593 S_12971 1823 40074600 459700
TBL2 25483220 3536257 13813 GSTAT 1336 3552644 340778
TBL2 25483220 3536257 13813 GIDENT 1258 25104930 341222
TBL2 25483220 3536257 13813 DOM 1136 3702424 296940
TBL2 25483220 3536257 13813 GT_ID 1125 3667955 292807
TBL2 25483220 3536257 13813 S_12887 950 24086249 238102
TBL3 75535253 1973395 7708 GR_ID 4882 35830627 1157981
TBL3 75535253 1973395 7708 S_12920 4324 38781564 1000276
TBL4 78783000 1961120 7660 AC_TYP 4640 4400100 1161300
TBL4 78783000 1961120 7660 EN_TYP 4027 4416300 1044600
TBL4 78783000 1961120 7660 J_ID 3624 37360000 916000
TBL4 78783000 1961120 7660 S_12807 3506 39205900 903400
TBL4 78783000 1961120 7660 A_NO 3496 31640500 836500
TBL4 78783000 1961120 7660 PRF 3254 4371100 836900
TBL4 78783000 1961120 7660 DOM 3125 2440500 787300
TBL4 78783000 1961120 7660 AC_ID 1895 33555500 508700
TBL5 79051899 938137 3664 S_12696 3617 36049298 870383
TBL6 44204014 882129 3445 GR_ID 2299 40927895 577875
TBL6 44204014 882129 3445 S_12702 2000 39682980 485310
TBL7 39489495 763975 2984 CR 2425 35744077 586481
TBL7 39489495 763975 2984 S_12841 1858 37524532 475976
TBL7 39489495 763975 2984 DOM 1806 1021153 424511
TBL8 27613451 718196 2805 S_12766 1617 13522078 398187
TBL8 27613451 718196 2805 NAME 1570 2276059 367771
TBL8 27613451 718196 2805 DOM 1299 884218 300834
TBL8 27613451 718196 2805 OPT_TYP 1143 871585 273024
TBL8 27613451 718196 2805 CM_ID 1028 12481243 239797
TBL9 39562401 600298 2344 B_ID 2171 40086857 575137
TBL9 39562401 600298 2344 S_12746 2041 39395915 534743
TBL10 23879420 409768 1600 G_ID 1208 21892261 281819
TBL10 23879420 409768 1600 P_ID 1186 13944495 283708
TBL10 23879420 409768 1600 S_12879 1133 21613961 262726
TBL10 23879420 409768 1600 DA1 1065 22903952 254882

Oracle Index Clustering Factor – Performance issues

The Oracle Reference Manual definition on the index clustering factor looks like this:

It indicates the amount of order of the rows in the table based on the values of the index:

  • If the value is near the number of blocks, then the table is very well ordered.
    In this case, the index entries in a single leaf block tend to point to rows that are stored in the same data blocks
  • If the value is near the number of rows, then the table is very randomly ordered.
    In this case, it is unlikely that the index entries in the same leaf block will point to rows in the same data blocks

I like referring to Tom Kyte’s simplified definition of this factor. In his book ( Expert Oracle Database Architecture) Tom says that:

we could also view the clustering factor as a number that represents the number of logical i/o’s against the table, that would be performed to read the entire table via the index.

Let’s have an example, out of the resultset of the query above:

TBL2 25483220 3536257 13813 GSTAT 1336 3552644 340778
TBL2 25483220 3536257 13813 GIDENT 1258 25104930 341222
TBL2 25483220 3536257 13813 DOM 1136 3702424 296940
TBL2 25483220 3536257 13813 GT_ID 1125 3667955 292807
TBL2 25483220 3536257 13813 S_12887 950 24086249 238102

First, i will do a select count(id) on the table, which will use the primary key (the indexes with the ‘S’ prefix are system generated indexes on primary keys)

select count(id) from TBL2 – bad clustering factor ( near to the number of rows)

This will do an Index Full Scan, using the S_12887 index, with the following results:

index full scan – cost 14998, card 1638820, cr_buf_gets: 14923 – 83 sec

Second, i will do a select on the id, using the GSTAT index, which has a good clustering factor (near to the number of blocks)

select /*+ INDEX (TBL2GSTAT    ) */ count(id) from TBL2

This will also do an Index Full Scan, this time using the index that i pointed out (GSTAT), with the following results:

index full scan – cost 9283, card 1638820, cr_buf_gets – 10647 – 13 sec

As you can see, running the same query on an index with a good clustering factor was 5 times better!

I need to present a graphical representation of how oracle will distribute the data into blocks, when dealing first with a well organised index, and then with a badly organised index (high clustering factor) I will not try to reinvent the wheel ( :) ) , so i will just use the graphical representation that Mohammed Mehraj Hussain did in his post

Good Index Clustering Factor - Rows spreaded

As you can see, index values in the same leaf block tend to point to rows that are distributed in the same blocks.

Bad Index Clustering Factor - Rows spreaded

Bad Index Clustering Factor - Rows spreaded

In this case, index values in the same leaf block tend to point to rows that are spread over multiple blocks.

So what???

Exactly, so what? Oracle is a super power database, so it really shouldn’t matter where the data is located. A block is a block, and Oracle will read it anyway right?

WRONG!

And this is the moment  where i have to point out the reason why this is so important.

When going for the data, ORACLE does an index range scan, and gets a list of blocks. If he notices that the next row in the index is located on the same database block as the row it has just read, Oracle will not performa another I/O operation to retrieve the table block from the buffer cache, because it already has a handle to the block, so it will just use it. If the row is not on the same block, then it will release the block, and perform another I/O into the buffer cache to retrieve the next block to be processed (see Tom Kyte’s book – Expert Oracle Database Architecture 9i and 10g – Apress)

So let’s suppose our database is configured to support storing 100 rows of data into one block of data. If we had 1000 rows of data, and 100 index values in a leaf node, then, in a well organized index structure (good clustering factor), in order to read all data from the database, we will need exactly 10 I/O’s ( additional to the 3 I/O’s to get to the leaf node) Otherwise, in the most pessimistic scenario, when dealing with a badly organized index, we could use as much as 1000 I/O operations against the table.

Now, see the difference? And this was just an example for a small set of data. Imagine querying tables containing millions of rows, like the ones above…

Using sequences for generating index values and effects on performance

When using sequences for generating your index values, you have two options:

  • you either use one sequence for all tables: in this case you will definitely have a problem with the index clustering values, because the scattering factor in the values of the index of one table will be very high
  • you use one sequence / table: in this case you are (more or less) sure that the index values are near to each other, in an ascending order

Let’s discuss the two options for a second.

Using one sequence for all tables: let us suppose a transaction writes data into ten tables, and that each of the ten tables has an index whose values are generated by the same sequence. After 10 transactions, the index for the first table would look like:

(1,11,21,31,41,51,61,71,81,91,101)

This will scatter the way Oracle distributes the data, so that, in the worse case scenario, for 10 transactions writing in the first table, we will need 10 blocks of data (instead of two, like in a well ordered index) Doing a query to retrieve the data based on this index, will generate therefore an I/O for each row to be retrieved…costly, isn’t it?

Using a separate sequence for each of the tables: in this case the values in the index will be ascending, near to each other, so that  the index above will look totally different:

(1,2,3,4,5,6,7,8,9,10)

and the data will be distributed evenly, in two blocks of data, reaching the scope, a well ordered index, with a good clustering factor, drastically reducing the number of I/O’s on the table

Sounds like a great solution. True, as long as you are running in a single application server environment. But what happens when you have multiple application servers, each of them retrieving a set of numbers from the sequence? Let me detail that for a minute

Using sequences for generating index values in a clustered application server environment

So, supposing that using a sequence / table is the right implementation, let us imagine we want to have a distributed system, running on four application servers, and one database. What will happen is that each application server will call the sequence, which will return the configured number of sequences. Let’s say that we have configured the sequence to generate 1000 values / call. A typical workflow would look like this:

  • First application server gets the values 1 – 1000
  • Second application server gets the values 10001 – 2000
  • Third application server: 2001 – 3000
  • Fourth application server: 3001 – 4000

Four users, landing each on a different application server (let’s suppose they land on the servers above ascending), running the same transaction, will generate the following values in the index:

(1, 1001, 2001, 3001, 2, 1002, 2002, 3002, 4002, ….)

So we are back to the initial problem…, a scattered index, therefore a bad clustering factor. Solutions? Don’t know yet, but still looking for them. The problem is quite complex, and i am no DBA … :)

Will get back here once i know what to do, and once the solution that me and my team will decide for will prove itself.

Until then, this was probably the longest post (in time spent, and content) after the WELD memory leak ( which was also a lot of fun) I have read and learned a lot while working on this subject, and i hope i can be of help to people out there having the same, or similar problems.

For the final words, i will quote Tom, like i usually do in the last days :) :

you can treat a database like a black box, and just stick data into it, or you can understand how it works and exploit it fully (…) If you choose to understand exactly how Oracle database platform should be used, then you will find that there are few information management problems that you cannot solve quickly and elegant

 

Cheers,

Alex

J2EE Performance problems and patterns series – The ORACLE redo logs

Today i am starting a (yet another) new series, which i will call “J2EE performance problems and patterns”. The scope of this series is to point out different performance problems, or configuration/tuning parameters that translate into performance problems. As usual, i will use only open source tools for debugging / monitoring different environments.

The first topic of these series are the oracle redo logs. I will try a top down approach, starting with the source problem, going to the symptoms, fixing them, and running the tests again, in order to check the effects on performance

1. The Problem

I have been many times confronted with CPU usage patterns that show sudden decreases in throughput, specially in the world of JAVA, where a full garbage collection got the name of “stop the world” garbage collection. Usually, when testing for performance, you aim at using 80 % of the resources: CPU, threads, jdbc connection pools, etc. Usually you expect to see a CPU usage running stable for as long as no full garbage collection occurs, something like this:

Visual VM - Stable CPU usage

Stable CPU Usage

Yes, you might say that this is not what you would really call stable, still, the workload in this scenario was also very variable (variable number of requests / second) Anyway, running a first look on the graph gives you the feeling of 40-45 % CPU usage.

Well, after running the performance test, trying to gradually increase the load on the server (the user load – number of virtual users – was increased from one iteration to another), i suddenly noticed a change in the throughput. Although there was still enough CPU for me to climb on with the number of users, the throughput was decreasing. I carefully started to monitor the CPU usage using Visual VM. This was the first result that i got while monitoring the test:

CPU pauses - Visual VM

CPU pauses - Visual VM

I decided to run the test once again, to give this problem a level of reproduction. I was amazed to see that a second run delivered a much worse result:

Cpu Usage VisualVM - Pauses in CPU usage - Low throughput

 

2. Analyzing the problem

First thing i turned to was the number of successful transactions. I was amazed to see that each and every one transaction had succeeded. There was absolutely no exception in the server log, and all transactions were completed. With the cost of a very low throughput, of course. This was a clear sign that somewhere, some resource was not “servicing”. I decided to take them one by one:

  • Full Garbage Collections: Behaviours like that are usually due to full garbage collections, which stop the world, and cause a throughput decrease of the CPU down to 0 (CPU is fully used for Garbage Collection) Still, the pattern above did not match a full garbage collection pattern at all. This is how it should have looked like , had this been the problem:
    Full Garbage Collection pattern

    Full Garbage Collection pattern

    The big blue lines (spikes) are actually the full garbage collections. None of them yet in the graphic representing my problem

  • EJB Pool Size: Well, the thing with stateless pools, is that under heavy load, they tend to become a bottleneck. Considering that Glassfish comes with a preconfigured EJB Pool of 32, that will very fast be consumed. Monitoring the EJB pool usage, i could see that the high watermark (the maximum number of stateless beans in the poll that have been ever used) was still under the preconfigured limit ( i already increased the limit to 150) So EJB was not the problem
  • JDBC Pool Size: This should really stay in “normal” limits, specially when working with such a great database as ORACLE. When the maximum threshold is reached, that signalizes a problem in your application or database configuration. Still, monitoring the JDBC Pool usage i could see that the maximum threshold was never being reached. So JDBC was not the problem
  • At this point, we were running somewhere like 100 – 150 transactions against the database, each of them writing considerable amount of data into several tables. Having the experience of I/O bottlenecks before (specially in a virtualized test environment), i run a disk monitoring on the oracle database, only to see that exactly at this points, there was a rather “huge” ratio of writing on the disk. I decided to have a chat with our DBA, and find out some more on the internals of ORACLE. And this was the moment it got interesting.

3. The chat with the DBA and the Redo Logs

So i had some ideas about the Oracle Redo Logs. I heard about them, and i was thinking at them like a periodical process, that, somewhere in time, takes over the control on the disk by writing a lot, influencing therefore the oracle performance…sounds vague to you? Well it definitely sounded more than vague to me. I needed clarification.

So after asking our DBA if the Redo Logs could be the problem (without really knowing how they work), he said to me right away: “sure, let’s have a look”. And what a look it was:

Oracle Redo Log Statistic

Oracle Redo Log Switch Statistic

This was the statistic on the log switch frequency. Our server, at peak hours (when we were testing it for performance) was having a rate of 50 to 70 log switches / hour. Before going further, let’s have a small talk on the REDO Logs, what they are, and how they can affect performance.

Redo Log Files are transaction logs, usually used for recovery purposes. What will happen is that, without having a full database backup in place, in case of a hardware failure, or power interruption, Oracle will use these transaction logs to restore the system to the point it was before the failure. Actually, every operation performed in Oracle will generate redo information to be written to the online redo logs.

Oracle has at least two online redo log file groups, each of the group having one or more log members. The log members are fixed in size, and are being used in a circular way. Oracle will write to log file group 1 files, and when it fills up those files, will switch to the next log file group., and then back (in case you only have 2 groups) This switching from one group to another is what Oracle calls a “log switch”. Now, like Tom Kyte also points out in his great Oracle book, a log switch may cause a temporary “pause” in a poorly configured database. I will quote him next:

“Since the redo logs are used to recover transactions in the event of a failure, we must assure ourselves that we won’t need the contents of a redo log file in the event of a failure before we reuse it. If Oracle is not sure that it won’t need the contents of a log file, it will suspend operations in the database momentarily and make sure that the data in the cache that this redo “protects” is safely written (checkpointed) onto disk itself. Once Oracle is sure of that, processing will resume.”

A checkpoint is the writing of dirty blocks from the buffer cache to disk. This is handled by a process called DBWn, which is an Oracle background process. Now, if we attempt to use a new log file, Oracle initiates a checkpoint. At this point DBWn starts writing to disk all files protected by log file group 1. If we attempt using the first group again, before DBWn finished writing, the following message will occur:

Thread 1 cannot allocate new log, sequence 19166
Private strand flush not complete

(This is a sample from our trace)

At this point, processing (servicing) was suspended in the Database while DBWn finished the writing (the checkpoint). Oracle gives ALL PROCESSING POWER to DBWn for it to finish faster, therefore stops servicing

We then took a look at our configuration: our log file size was 100 MB, which was to small for the load we were using.

4. Tuning the Redo log files and retesting

We decided to increase the redo log file size from 100 to 250 MB, and retest. And this is how it looked like after tuning:

Redo Log File Tuning - CPU usage

Redo Log File Tuning - CPU usage

There was no pause anymore (not the “stop servicing” type of pause), and the cpu usage and throughput was pretty stable by this time.

5. Conclusion

Redo log files, as a integral part of the database layer, can be a bottleneck in performance, if not properly configured. The problem will mostly appear in test scenarios with high load and large rate of data to be inserted. The bigger the data needed to be inserted, the larger the redo log files.

Read more on Oracle Redo Logs:

Tom Kyte – Expert Oracle Database Architecture (APress)

Next topic : JMS ( Java Messaging Service) and how it can affect performance

Cheers,

Alex

Follow

Get every new post delivered to your Inbox.

Join 269 other followers