Monday, August 5, 2013

11gR2 :Query running fast on one node of RAC database while running very slow on the other 2 nodes

I came across this very interesting and unique problem recently.One of the query running on one of the RAC instances (version 11.2.0.3) was performing well where as on the other 2 instances it was performing pretty bad.The query was returning results in sub seconds on one node where as on the other 2 nodes it was taking long time (20-30 secs).I  took 10046 trace from both the instances and created a tkprof report .From the tkprof output looking  at node 1  disk reads were 0 where as on node 2 there were 167006   disk reads.That means the query was hitting cache on node 1 all the time whereas on node 2 and 3 it was doing physical reads all the time no matter how many times you run the query.

Following points to note

  • Execution plan didn't change and it remained the same across all the instances.
  • Stats were not collected from long time but that was another issue which we addressed later.
  • Queries were doing full table scans(because the filter predicate was the most popular value and it was obvious for the queries to go for FTS so FTS was not an issue).
  • db_cache_size is same on all the 3 instances

What changed?

The database was bounced in rolling fashion after some maintenance.

We tried to run the query  in question multiple times in hope that the data will get cached if we keep running it again and again but that was not helping.It was very strange behavior.

After analyzing the data for long time I noticed the the section "events waited on" in the tkprof .Which seemed little out of place.There were lot of waits on "Direct path read" on instance 2 and 3 where as there were no such wait events on node 1.

If you will do some research on "Direct path read" wait events you will come to know that the query results were skipping the buffer cache and were loaded directly into the PGA .Since the query results were never going though the buffer cache ,they were never getting cached and the query was doing physical reads each time it was getting executed.

Now the question arises ,How come the query results got cached on node 1 but not on other 2 .It is still a mystery but I used the following event to turn off the direct path reads on all the nodes and it resolved the issue.

alter system set events '10949 trace name context forever' ;

Interestingly this issue didn't happen at the time of upgrade from 10.2 to 11.2 but happened months later after database bounce.

The trade-off here is that that you need to to have db_cache_size large enough to accommodate all the query results which are frequently executed otherwise they will age out from the cache.In case you  are using AMM ,you need to set a minimum size for db_cache_size along with the parameters memory_target and memory_max_target.


If you want to create the tkprof  use the following procedure.

  • First create the 10046 trace using following
alter session set tracefile_identifier='10046_trace';
alter session set timed_statistics = true;  
alter session set statistics_level=all;  
alter session set max_dump_file_size = unlimited;  
alter session set events '10046 trace name context forever,level 12'; 
 -- Execute the queries or operations to be traced here --  
select * from dual;  
exit;

If the session is not exited then the trace can be disabled using:
alter session set events '10046 trace name context off';
  
  •  Generate tkprof reports from the raw SQL Traces in the USER_DUMP_DEST

    tkprof    "10046_trcfile"  "output_filename" sort=execpu, exedsk explain=user/password waits=yes


Please feel free to contact in case there are any questions or suggestions.

               

No comments: