Tracing Single SQL in Oracle

Many times, while doing SQL tuning, we want to trace (event 10046) single SQL in database. Instead of going for module level tracing or session level using DBMS_MONITOR, we can simply use below alter system command to trace specific SQL

Example: I have a table T1 and index T_I_TABLE_NAME on that table.
I am running following SQL and I want to trace on this SQL

select * from T1 where table_name = 'SINGLE_PRODUCT_GROUPS';

I can just find out the SQL ID of above SQL

select sql_id, sql_text from v$sql where sql_text like '%SINGLE_PRODUCT_GROUPS%'

SQL_ID	      SQL_TEXT
------------- --------------------------------------------------------------------------------
8kybysnu4nn34 select * from T1 where table_name = 'SINGLE_PRODUCT_GROUPS'

Once I have the SQL ID, I can use below alter system to trace this SQL


alter system set events 'sql_trace[SQL:8kybysnu4nn34] plan_stat=all_executions,wait=true,bind=true';

Note that even though this is alter system, other SQL IDs run will not have any effect on tracing because we are tracing only specific SQL ID. So unless SQL ID 8kybysnu4nn34 is run, it will not generate any trace file.

Once SQL ID is run and trace is generated, you can turn off tracing using following statement


alter system set events 'sql_trace[SQL:8kybysnu4nn34] off';

This might generate multiple trace files as multiple sessions might run same SQL ID (depending on the application).

Hope this helps !!!

direct path read behavior in Oracle 11.2

Prior to 11g, whenever optimizer goes for full table scan, Oracle used to show “db file scattered read” as wait event. But starting from 11g, a full table scan can show (depending on certain conditions) “direct path read” wait event.

db file scattered read – happens when blocks for a table is read from datafile into buffer cache in SGA

direct path read – happens when blocks for a table is read from datafile into PGA

Problem with fetching data in db cache was, if table is big enough it will use many blocks in db cache causing performance issue. And if multiple SQLs are doing FTS (full table scan) then every session will try to use those blocks in buffer cache by acquiring the latch and can cause “cache buffer chain: latch” contention. This will spike CPU on the host.

With direct path read, block read from datafile goes to PGA and every session has its own chunk of memory allocated in PGA. So multiple sessions doing FTS on same table does not make situation as bad as it used to be with “db file scattered read”

There are certain conditions based on which oracle decides whether to go for direct path read or use buffer cache.
In the reference section, I have mentioned many good blog articles which discusses one or more of these behaviors.

_small_table_threshold

_small_table_threshold : This is a hidden parameter which helps server process decide whether to go for direct path read or buffer cache. Unit of this parameter is number of blocks and default value is 2% of buffer cache size.

DEO>@param
Enter Parameter name: _small_table

Parameter			                  Description						                           Session Va Instance V
------------------------------------- ------------------------------------------------------------ ---------- ----------
_small_table_threshold		          lower threshold level of table size for direct reads	       27107      27107

In my case this is set to 27107 blocks which is approximately 2% of my db_cache_size blocks (you need to convert db_cache_size in terms of Oracle blocks and take 2% of that value to arrive at default value).

If size of table (blocks below high water mark) is > _small_table_threshold then Oracle chooses to go for direct path read.
In many blog articles, its stated that if size of table is > 5 times _small_table_threshold then it goes for direct path read.

During my testing, I was not able to verify 5 times _small_table_threshold. Because as soon as table size if more than _small_table_threshold, it goes for direct path read. I have checked this behavior in 11.2.0.3 as well as in 11.2.0.4

Lets test the dependency of direct path read on this hidden parameter for partitioned as well as non-partitioned table

Non-Partitoned table

My Oracle version is 11.2.0.4. I have a non-partitioned table T1 created from DBA_OBJECTS. You can create any test table of significant size using any view in database or by using “CONNECT BY rownum<=” clause from dual. Gather stats on table.


DEO>select table_name, num_rows, blocks from dba_tables where table_name = 'T1';

TABLE_NAME			           NUM_ROWS   BLOCKS
------------------------------ ---------- ----------
T1				               91200	    3214

My table has 3214 blocks.

Setting _small_table_threshold to 5000


DEO>alter session set "_small_table_threshold" = 5000;

Session altered.

Since table size is < _small_table_threshold, it should not go for direct path read. Instead we should see blocks going into db cache.
We can check which object’s blocks are placed in buffer cache using X$KCBOQH table. So when full table scan goes into db cache, we should be able to see the same using this table.

Lets flush the buffer cache to make sure nothing is present in buffer cache.


DEO>alter system flush buffer_cache;

System altered.

DEO>select count(*) from T1;

  COUNT(*)
----------
     91200

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93840	   3209

As shown above FTS has read all buffers in db cache.

Now, lets reduce _small_table_threshold to 3000 and flush buffer cache again.

DEO>alter session set "_small_table_threshold"=3000;

Session altered.

DEO>alter system flush buffer_cache;

System altered.

Since table size > _small_table_threshold, we should see direct path read.
We can verify if a session has done direct path read using statistics “physical reads direct” from v$sesstat
Following query shows the same. In this case my SID is 6531.

DEO>r
  1* select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    2

So current value of direct path read stats is 2 before reading from table. Lets read data from table


DEO>select count(*) from T1;

  COUNT(*)
----------
     91200

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    3210

We see that if table size is more than _small_table_threshold it has gone for direct path read.
We can also confirm if db cache has anything related to our table T1. Remember than we flushed buffer cache before running last query on T1 table.

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93840	      1

We can see 1 block in db cache which is the header block. Header block is always read in buffer cache.

Partitioned Table

In case of partitioned table same behavior was observed but _small_table_threshold is compared with partitions we are selecting instead of entire table.

I have created similar partitioned table with 4 partitions


CREATE TABLE T1_PART
(
    col1 NUMBER,
    col2 VARCHAR2(100)
 )
 PARTITION BY LIST (col1)
 (
    PARTITION PART_1  VALUES (1)
  , PARTITION PART_2  VALUES (2)
  , PARTITION PART_3  VALUES (3)
  , PARTITION PART_4  VALUES (4)
 ) ;

INSERT INTO T1_PART (SELECT mod(rownum,4)+1, rpad('X',100,'X') FROM dual CONNECT BY rownum<=896000);

DEO>select table_name, partition_name, num_rows, blocks, avg_row_len from user_tab_partitions where table_name='T1_PART';

TABLE_NAME		       PARTITION_NAME			              NUM_ROWS   BLOCKS     AVG_ROW_LEN
-------------------    -------------------------------------- ---------- ---------- -----------
T1_PART 		       PART_1				                  128000      1948	    104
T1_PART 		       PART_2				                  128000      1948	    104
T1_PART 		       PART_3				                  128000      1948	    104
T1_PART 		       PART_4				                  128000      1948	    104

4 rows selected.

Each partition is 1948 blocks.
Lets change _small_table_threshold to 1800 and select values from single partition. Since partition size we are selecting > _small_table_threshold, it should go for direct path read


DEO>alter session set "_small_table_threshold"=1800;

Session altered.

DEO>select count(1) from T1_PART where col1 = 1;

  COUNT(1)
----------
    128000

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME = 'PART_1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	      1

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    5166

We are seeing “physical reads direct” stats value as 5166. This is a cumulative value. Previous value was 3210.
So it has read 5166 – 3210 = 1956 blocks which is approx same as number of blocks for 1 partition.

Also, we are see 1 block is read in buffer cache which is header block

To verify that _small_table_threshold is checked at partitions we are selecting and not at table level, lets increase _small_table_threshold to 3600 and continue to select single partition


DEO>alter session set "_small_table_threshold"=3600;

Session altered.

DEO>select count(1) from T1_PART where col1 = 1;

  COUNT(1)
----------
    128000

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    5168

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME = 'PART_1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1949

So no increase in “physical reads direct”, but we can see blocks are read in buffer as sum(NUM_BUF) is showing same as number of blocks for that partition.

If we select 2 partitions, it will again go for direct path read because sum of blocks of 2 partitions > _small_table_threshold (3600)


DEO>select count(1) from T1_PART where col1 in (1,2);

  COUNT(1)
----------
    256000

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    9064

Both partitions went for direct path read even though 1 partition was in buffer cache.
Above stat value if cumulative. It has increased by (9064 – 5168) 3896 blocks which is size of 2 partitions.

We can change this behavior using _direct_read_decision_statistics_driven parameter. Check later in this article.

What happens when the blocks are cached in buffer cache ?

If we have atleast 50% of blocks cached in buffer cache, Oracle will choose to use db cache instead of direct path read when using FTS. ALEX FATKULIN has published a very nice article http://afatkulin.blogspot.ie/2009/01/11g-adaptive-direct-path-reads-what-is.html about this behavior and he has provided a function to test this behavior.

But I am seeing different behavior in my instance. In my tests, Oracle is not going for db cache unless 98% blocks are in buffer cache.

In my case for table T1, we can select half the records from table to have approx 50% blocks cached in buffer cache and check the behavior.

Non-Partitioned Table

Lets increased _small_table_threshold to 5000 so that Oracle does not go for direct path read and read approx half the blocks in buffer cache. We are also flushing buffer cache to make sure nothing is present.


DEO>alter system flush buffer_cache;

System altered.

DEO>alter session set "_small_table_threshold"=5000;

Session altered.

DEO>select count(1) from T1 where rownum < 50000;

  COUNT(1)
----------
     49999

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93840	   1753

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                     5168

From above output we can see that more than 50% blocks are cached in buffer cache.
Now, lets change _small_table_threshold to 3000 again to check if FTS goes for direct path read or buffer cache.


DEO>alter session set "_small_table_threshold"=3000;

Session altered.

DEO>select count(1) from T1;

  COUNT(1)
----------
     91200

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93840	   1753

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct					                        8376

So even when we had more than 50% of blocks in buffer cache, its still going for direct path read. SUM(NUM_BUF) didnt change from 1753 to 3209 (all blocks on T1 table).
I increased number of blocks cached in buffer cache to 90% and it will still going for direct path read.

Only when approx 98% of blocks are cached then Oracle goes for db cache. I validated same behavior in 11.2.0.3 as well.

Partitioned Table

I repeated the same process for partitioned table and found same behavior. In this case Oracle checks for each partition instead of table.

Each partition has 1948 blocks. So lets put 90% of blocks in db cache and check behavior.
Lets increase _small_table_threshold to 3000 deliberately so that Oracle uses db cache.


DEO>alter session set "_small_table_threshold"=3000;

Session altered.

DEO>alter system flush buffer_cache;

System altered.

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME = 'PART_1') group by obj#;

no rows selected

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    2

DEO>--selecting 90% of records from PART_1
DEO>select count(*) from T1_PART where col1 = 1 and rownum < (128000*0.9);

  COUNT(*)
----------
    115199

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    2

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME = 'PART_1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1753

We have 90% of blocks of partition PART_1 in buffer cache.
Now we can reduce _small_table_threshold to 1800 and try selecting.


DEO>alter session set "_small_table_threshold"=1800;

Session altered.

DEO>--selecting complete PART_1
DEO>select count(*) from T1_PART where col1 = 1;

  COUNT(*)
----------
    128000

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME = 'PART_1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1753

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    1950

DEO>

As seen above, even with 90% of blocks in db cache, it goes for direct path read.
Lets repeat the same by putting 98% of blocks


DEO>alter session set "_small_table_threshold"=3000;

Session altered.

DEO>alter system flush buffer_cache;

System altered.

DEO>select count(*) from T1_PART where col1 = 1 and rownum < (128000*0.98);

  COUNT(*)
----------
    125439

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME = 'PART_1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1910

DEO>alter session set "_small_table_threshold"=1800;

Session altered.

DEO>select count(*) from T1_PART where col1 = 1;

  COUNT(*)
----------
    128000

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# = (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME = 'PART_1') group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1949

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                     1950

So with 98% of rows/blocks in db cache, Oracle does NOT go for direct path read.

What if we have 1 partition in cache and we select 2 partitions. Will it go for direct path read ?

I have kept _small_table_threshold=3000 which is more than 1 partition size but less than 2 partitions size


DEO>alter session set "_small_table_threshold"=3000;

Session altered.

DEO>select count(*) from T1_PART where col1 = 1;

  COUNT(*)
----------
    128000

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# in (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME in ('PART_1','PART_2')) group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1949

We have above PART_1 in db cache and nothing on PART_2. Lets select 2 partitions


DEO>select count(*) from T1_PART where col1 in (1,2);

  COUNT(*)
----------
    256000

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# in (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME in ('PART_1','PART_2')) group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1949
     93846	      1

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    5848

So even when 1 partition was in db cache, if we select 2 partitions, it will go for direct path read for both partitions.
Above stats value of 5848 is cumulative value from previous value of 1950. Difference comes out to be 3898 which is size in blocks of 2 partitions.

_direct_read_decision_statistics_driven

This parameter mainly affect the behavior of partition table.

We have seen above that if we have a partition cached in db cache and if we select 2 partitions, both partitions will go for direct path read. This happens when _direct_read_decision_statistics_driven is set to true (default).

When _direct_read_decision_statistics_driven parameter is true, Oracle uses table statistics to decide whether to go for direct path read or db cache (using db file scattered read).
When _direct_read_decision_statistics_driven parameter is false, Oracle uses the segment header block (the one which always gets selected in db cache) to decide whehter to go for direct path read or db cache. It means that value of _small_table_threshold will be compared with every segment(partition) and not as a whole with partitions we are selecting.

In all the above excercise _direct_read_decision_statistics_driven was set to true. So Oracle server process used table stats to decide the fetch method.

Let set _direct_read_decision_statistics_driven to false to check behavior.


DEO>alter session set "_direct_read_decision_statistics_driven"=false;

Session altered.

We have 1 partition cached entirely in db cache.


DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# in (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME in ('PART_1','PART_2')) group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1949
     93846	      1

Current value of physical reads direct stats is as below and _small_table_threshold is set to 1800 which is less than size of single partition


DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    3896

DEO>alter session set "_small_table_threshold" = 1800;

Session altered.

Lets select 2 partitions


DEO>select count(1) from T1_PART where col1 in (1,2);

  COUNT(1)
----------
    256000

1 row selected.

DEO>select a.sid, b.name, a.value from v$sesstat a, v$statname b where a.statistic# = b.statistic# and a.statistic# in (97) and a.sid = 6531;

       SID NAME 								                            VALUE
---------- ---------------------------------------------------------------- ----------
      6531 physical reads direct						                    5846

1 row selected.

DEO>select obj#, sum(num_buf) from X$KCBOQH where obj# in (select object_id from dba_objects where object_name = 'T1_PART' and SUBOBJECT_NAME in ('PART_1','PART_2')) group by obj#;

      OBJ# SUM(NUM_BUF)
---------- ------------
     93845	   1949
     93846	      1

2 rows selected.

If we check carefully, we have direct path read done for only 1 partition (5846 – 3896 = 1950). 1950 is size of single partition.
So Oracle has gone for direct path read for 2nd partition and it has used blocks cached in buffer cache for 1st partition.
Since we have set _direct_read_decision_statistics_driven to false, Oracle reads header block of individual segment to decide fetch method to be used for that segment.
Since 1st segment PART_1 was present entirely in db cache, it decided to use that. PART_2 was not present in db cache, only header block was present so it compared PART_2 size with _small_table_threshold and since PART_2 size > _small_table_threshold, it went with direct path read.

In above exercise (_direct_read_decision_statistics_driven = true), when we set _small_table_threshold to 3600 for partition table and tried selecting 2 partitions, both went for direct path read. Now if we do that, both partitions will go to db cache because size of individual partitions (from header block of each segment) will be compared individually and not as sum of blocks we are selecting.

_serial_direct_read

If you want to disable direct path read on FTS, you can make use of _serial_direct_read parameter. Many DBA are increasing value of _small_table_threshold to very high value (higher than any table in database) and prevents direct path reads. But Oracle has provided this hidden parameter _serial_direct_read, which if set to false will disable direct path reads.

Default value of this parameter is true, which means allow direct path reads.

You can also set event 10949 which can also be used to disable direct path reads. Setting this event is like setting _serial_direct_read=false.

alter session set events '10949 trace name context forever, level 1';

Hope this helps !!

References

https://dioncho.wordpress.com/2009/07/21/disabling-direct-path-read-for-the-serial-full-table-scan-11g/
http://afatkulin.blogspot.ie/2009/01/11g-adaptive-direct-path-reads-what-is.html
http://blog.tanelpoder.com/2012/09/03/optimizer-statistics-driven-direct-path-read-decision-for-full-table-scans-_direct_read_decision_statistics_driven/
http://oracle-tech.blogspot.com.tr/2014/04/smalltablethreshold-and-direct-path.html
http://oracle-tech.blogspot.com.tr/2014/04/directreaddecisionstatistcsdriven.html

Pointing MySQL Read-Replica to new master after failover

Here I am describing a simple scenario where we have a read replica (other than slave) which is currently pointing to master mysql instance.
We have another slave which is also pointing to same master. What we are going to see is, how to point read replica to new master after failover.

Environment:

To make you familier with environment, we have 3 instances of mysql

mysql_a -> Current master
mysql_b -> Current slave
mysql_c -> read replica pointing to mysql_a

Technically read replica is same as slave, but in this context we are saying read replica to make you understand that this is additional slave which does not take part in failover scenario.
So excercise is to failover master from mysql_a to mysql_b and point read replica mysql_c to mysql_b

I am using GTID on all 3 instances and both slaves are in sync with master.

On Master (mysql_a):

root [mysql] >show master status \G
*************************** 1. row ***************************
             File: bin_log.000007
         Position: 612
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-91
1 row in set (0.00 sec)

On Slave (mysql_b):

mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
               ...
               ...
              Master_Log_File: bin_log.000007
          Read_Master_Log_Pos: 612
               Relay_Log_File: relay_log.000010
                Relay_Log_Pos: 818
        Relay_Master_Log_File: bin_log.000007
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
            ...
            ...
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-91
            Executed_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-91
                Auto_Position: 1

On read-replica (mysql_c):

root [mysql] >show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
               ...
               ...
              Master_Log_File: bin_log.000007
          Read_Master_Log_Pos: 612
               Relay_Log_File: relay_log.000005
                Relay_Log_Pos: 442
        Relay_Master_Log_File: bin_log.000007
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
            ...
            ...
           Retrieved_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:91
            Executed_Gtid_Set: 6e68fbf2-f9a0-11e4-a3f7-90e2ba6ebdb0:1-7,
f7718b80-c237-11e4-baa8-a0369f370a52:1-91
                Auto_Position: 1

Lagging read-replica:

Before I failover, I want to make read replica lag by couple of transaction so that when we recover and point replica to new master we can clearly see transactions are getting applied from old and new master.
I will stop IO slave on read replica (mysql_c) so that it will stop reading binlog from master (mysql_a)

root [mysql] >stop slave IO_thread;
Query OK, 0 rows affected (0.03 sec)

root [mysql] >show slave status \G
*************************** 1. row ***************************
               Slave_IO_State:
               ...
               ...
             Slave_IO_Running: No
            Slave_SQL_Running: Yes

So any change to master will not be replicated to read replica (mysql_c)

Now, lets change few records in master and move forward its GTID

On Master (mysql_a):

root [deo] >show master status \G
*************************** 1. row ***************************
             File: bin_log.000007
         Position: 1220
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-93
1 row in set (0.00 sec)

I did couple of transactions on master (mysql_a) and increased GTID from 1-91 to 1-93.

I see that those trasactions are already applied to slave (mysql_b)

On Slave (mysql_b):

           Retrieved_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-93
            Executed_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-93
                Auto_Position: 1
1 row in set (0.00 sec)

But we didnt get those transaction on read replica (mysql_c) as IO thread is down

On read replica (mysql_c):

           Retrieved_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:91
            Executed_Gtid_Set: 6e68fbf2-f9a0-11e4-a3f7-90e2ba6ebdb0:1-7,
f7718b80-c237-11e4-baa8-a0369f370a52:1-91
                Auto_Position: 1

Failover:

Now, we will failover master to slave (mysql_b)

Failover is simple process. We just have to stop current master and make sure slave is not read only. Plus any other custom configuration that you have done on master, you can need to do the same on slave.

So after failover to mysql_b, my new master looks like below

mysql> show master status \G
*************************** 1. row ***************************
             File: bin_log.000003
         Position: 2495
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-93
1 row in set (0.00 sec)

we can also do reset master, that will flush binlog file and reset GTID to 1. But lets not do that as that is not the objective of our excercise.

Pointing read replica to new master:

Now, we need to point our read replica (which is still pointing to old master (mysql_a)) to new master (mysql_b)
To do that we need to recover the transactions that were missing from old master and continue receving transactions from new master.

When we do new transactions on new master, we get different GTID.
Example, I did 1 transaction after failover on new master and my new master status looks like below

mysql> show master status \G
*************************** 1. row ***************************
             File: bin_log.000003
         Position: 2802
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: c21f28d2-c243-11e4-baf5-2c600c20dba4:1,
f7718b80-c237-11e4-baa8-a0369f370a52:1-93
1 row in set (0.00 sec)
c21f28d2-c243-11e4-baf5-2c600c20dba4:1 is the new GTID

If we just start slave on read replica it will not be able to do fetch any transaction as old master is down. So we need to first point read replica to new master and then start slave which will fetch all old and new transactions

root [mysql] >stop slave;
Query OK, 0 rows affected (0.03 sec)

root [mysql] >change master to master_host='mysql_b.example.com', master_port=3306, master_user='replicate', MASTER_PASSWORD = 'welcome', MASTER_AUTO_POSITION = 1;
Query OK, 0 rows affected, 2 warnings (0.07 sec)

root [mysql] >start slave;
Query OK, 0 rows affected (0.03 sec)

root [mysql] >show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: mysql_b.example.com
                  ...
                  ...
           Retrieved_Gtid_Set: c21f28d2-c243-11e4-baf5-2c600c20dba4:1,
f7718b80-c237-11e4-baa8-a0369f370a52:92-93
            Executed_Gtid_Set: 6e68fbf2-f9a0-11e4-a3f7-90e2ba6ebdb0:1-7,
c21f28d2-c243-11e4-baf5-2c600c20dba4:1,
f7718b80-c237-11e4-baa8-a0369f370a52:1-93
                Auto_Position: 1

In above output of slave status, we can check Retrieved_Gtid_Set and we can clearly see it has retrieved previous master’s 2 transactions f7718b80-c237-11e4-baa8-a0369f370a52:92-93 as well as new transaction that I did after failover – c21f28d2-c243-11e4-baf5-2c600c20dba4:1
In Executed_Gtid_Set we can see it has executed all these transactions – c21f28d2-c243-11e4-baf5-2c600c20dba4:1 and f7718b80-c237-11e4-baa8-a0369f370a52:1-93

Hope this helps !!

Apache Cassandra – NoSQL storage solution

These days I am exploring another storage solution – Cassandra.

Apache Cassandra datastore was originally developed by Facebook as open source NoSQL data storage system. Its actually based on Amazon’s dynamoDB database. Apache Cassandra is an open source distributed database management system designed to handle large amounts of data across many commodity servers, providing high availability with no single point of failure. Cassandra offers robust support for clusters spanning multiple datacenters, with asynchronous masterless replication allowing low latency operations for all clients.

Datastax Technology has created enterprise edition of Cassandra which is built on Apache Cassandra. Today we have multiple flavors of Cassandra available from Apache as well as datastax.

Cassandra is a NoSQL database storage solution and it stores the data using simple key-value pairs. Along with enterprise software, datastax also provide huge documentation for learning Cassandra. They also provide self-paced training and instructor led training for learning Cassandra.

I have started learning Cassandra using self-paced training available at following location – https://academy.datastax.com/courses

Apart from that, datastax also has very active blog where they discuss different issues and features available in Cassandra – http://www.datastax.com/dev/blog/

Installation:

You can either go with full installation of Cassandra on multiple physical nodes and creating a cluster or you can simulate a cluster on single node using CCM (Cassandra Cluster Manager).

Going for official Cassandra software on multiple physical nodes might not be feasible for everyone. Thats why CCM is the best utility to learn Cassandra.

You can find instruction to install CCM at following location – http://www.datastax.com/dev/blog/ccm-a-development-tool-for-creating-local-cassandra-clusters

Valid Versions:

At the time of this writing, most stable version of Apache Cassandra is 2.1.14. Latest version of Apache Cassandra released is 2.1.15. You have older version like 2.0.9 which was also stable.

You can get complete list of Apache Cassandra at – http://archive.apache.org/dist/cassandra/

You can check datastax community versions of Cassandra at http://planetcassandra.org/cassandra/

Community version is for learning and is free to download, install and play around.

CCM Installation Issue:

I faced following issue when I installed CCM on my ubuntu 12.04 machine.

ccm create --version=2.0.9 --nodes=6 deo
Downloading http://archive.apache.org/dist/cassandra/2.0.9/apache-cassandra-2.0.9-src.tar.gz to /tmp/ccm-2oKzAH.tar.gz (10.810MB)
  11335077  [100.00%]
Extracting /tmp/ccm-2oKzAH.tar.gz as version 2.0.9 ...
Compiling Cassandra 2.0.9 ...
Deleted /home/local/advaitd/.ccm/repository/2.0.9 due to error
Traceback (most recent call last):
  File "/usr/local/bin/ccm", line 5, in <module>
    pkg_resources.run_script('ccm==2.0.3.1', 'ccm')
  File "/usr/lib/python2.7/dist-packages/pkg_resources.py", line 499, in run_script
    self.require(requires)[0].run_script(script_name, ns)
  File "/usr/lib/python2.7/dist-packages/pkg_resources.py", line 1235, in run_script
    execfile(script_filename, namespace, namespace)
  File "/usr/local/lib/python2.7/dist-packages/ccm-2.0.3.1-py2.7.egg/EGG-INFO/scripts/ccm", line 72, in <module>
    cmd.run()
  File "/usr/local/lib/python2.7/dist-packages/ccm-2.0.3.1-py2.7.egg/ccmlib/cmds/cluster_cmds.py", line 127, in run
    cluster = Cluster(self.path, self.name, install_dir=self.options.install_dir, version=self.options.version, verbose=True)
  File "/usr/local/lib/python2.7/dist-packages/ccm-2.0.3.1-py2.7.egg/ccmlib/cluster.py", line 51, in __init__
    dir, v = self.load_from_repository(version, verbose)
  File "/usr/local/lib/python2.7/dist-packages/ccm-2.0.3.1-py2.7.egg/ccmlib/cluster.py", line 64, in load_from_repository
    return repository.setup(version, verbose)
  File "/usr/local/lib/python2.7/dist-packages/ccm-2.0.3.1-py2.7.egg/ccmlib/repository.py", line 40, in setup
    download_version(version, verbose=verbose, binary=binary)
  File "/usr/local/lib/python2.7/dist-packages/ccm-2.0.3.1-py2.7.egg/ccmlib/repository.py", line 221, in download_version
    raise e
ccmlib.common.CCMError: Error compiling Cassandra. See /home/local/advaitd/.ccm/repository/last.log for details

 

I posted the same error on github community and immediately got a solution – https://github.com/pcmanus/ccm/issues/268

Suggested me to use binary version of Cassandra for download -v binary:2.0.9. Cluster creation was successful after using binary version.

You can create as many nodes cluster as you want to. All it does is, it creates those many directories and treat them as separate nodes.

I create six node cluster on my ubuntu machine.

advaitd@desktop:~$ ccm status
Cluster: 'deo'
--------------
node1: UP
node3: UP
node2: UP
node5: UP
node4: UP
node6: UP

CCM Installation details:

CCM creates hidden directory under your home directory and a separate installation directory for each node under that hidden directory as shown below.

advaitd@desktop:~$ pwd
/home/local/advaitd
advaitd@desktop:~$ ls -rlt .ccm
total 12
drwxr-xr-x 3 advaitd domain^users 4096 Apr 23 12:15 repository
-rw-r--r-- 1 advaitd domain^users    4 Apr 23 12:15 CURRENT
drwxr-xr-x 8 advaitd domain^users 4096 Apr 23 12:15 deo
advaitd@desktop:~$ ls -rlt .ccm/deo/
total 28
-rw-r--r-- 1 advaitd domain^users  291 Apr 23 12:15 cluster.conf
drwxr-xr-x 8 advaitd domain^users 4096 Apr 23 12:16 node2
drwxr-xr-x 8 advaitd domain^users 4096 Apr 23 12:16 node1
drwxr-xr-x 8 advaitd domain^users 4096 Apr 23 12:16 node5
drwxr-xr-x 8 advaitd domain^users 4096 Apr 23 12:16 node3
drwxr-xr-x 8 advaitd domain^users 4096 Apr 23 12:16 node6
drwxr-xr-x 8 advaitd domain^users 4096 Apr 23 12:16 node4
advaitd@desktop:~$

So in each of the above node directory we have a Cassandra software installed. Each of above node directory is considered as separate node and cluster is created.

Cassandra binary is running from each of the node directory. So we should be seeing 6 cassandra processes running on that host as shown below.

advaitd@desktop:~$ ps -aef | grep cassandra | grep -v grep | wc -l
6

I will be doing more learning and posting articles on Cassandra as well.

References:

http://cassandra.apache.org/

http://www.datastax.com/

http://en.wikipedia.org/wiki/Apache_Cassandra

https://github.com/pcmanus/ccm/issues

http://www.datastax.com/blog

http://docs.datastax.com/en/index.html

Oracle Performance Tuning – ASH Basics

Recently I got an opportunity to dig into performance of database. We were not facing any performance issue, but we wanted to understand whats happening under the hood. What are the bottlenecks and how do we prepare and scale our database further.

In future the load on the databases are going to be crazy and we want to make sure that we look into every consumer of our database and optimize the usage.

I went back into the basics of database performance tuning – ASH. Active session history is the beast which has loads of information and provides information at very granular level – “session”. We can dig into ASH data and generate different reports rolled-up against various entities like module, action, sql_id, user_id etc. We can determine how much each of these entities are using database resources.

DB Time:

One of the most fundamental measure of database performance is DB Time. This is the amount of time a session has spend on database activities. This is a combination of CPU Time + non-Idle wait times. This does not consider any idle wait time so even if session is done with its activity but just sitting idle doing nothing, that idle time is not considered part of DB Time.

This gives a very accurate measure of amount of database resources a session is burning.

Active Session History:

ASH or Active Session History provides snapshots of active sessions connected to database (status=ACTIVE in v$session) and loads of other information related to those sessions about what they were doing when snapshot was taken. To understand how we can extract this information and make sense about it, we need to understand how ASH is build and what that information means.

V$ACTIVE_SESSION_HISTORY

Active session history is exposed by database using a view V$ACTIVE_SESSION_HISTORY. This view stores samples taken every 1 sec. A background process MMNL (Memory manager lite) takes a snapshot from v$session and v$session_wait about the current state of active sessions and dumps the information in V$ACTIVE_SESSION_HISTORY. Note that only active sessions’s snapshot is taken.

V$ACTIVE_SESSION_HISTORY is a memory view stored in the form of circular buffer. It means that this view has size limit on its growth (approx 2MB / CPU). So when it reaches to that size it starts overwriting the oldest records in circular buffer. You can visualize the same using following figure

 

ash-architecture-and-advanced-usage-rmoug2014-7-638

 

 

 

 

 

 

 

 

So how these samples are useful to us in finding DB Time ?

Lets say a session has spend 10 sec of active time in database. It means DB time for that session is 10 sec. During this 10 sec of active time, we will have 10 samples of that session taken as interval time between snapshot is 1 sec. So if we just take a count(*) from V$ACTIVE_SESSION_HISTORY, we will see 10 records for that session. This means that to get DB Time of a session  we just have to take count(*) from V$ACTIVE_SESSION_HISTORY for that session.

Its little difficult to adjust to the fact that time parameter can be obtained using count(*) from a view. But this is because interval time between samples is 1 sec.

So DB Time is actually – [ Number of samples ] X [ Time interval between samples ]

Since time interval between samples is 1 sec, we can get DB time as number of samples which is count(*) from V$ACTIVE_SESSION_HISTORY

Again, calculating DB Time using count(*) from ASH is approximation as sessions which are taking fraction of times < 1 sec will not be counted if they happens between 2 samples and DB time of other sessions which ends just before next samples is taken will be counted until last samples when they were active. But those were very few cases and amount of DB time not measure in such cases will be very less compared to total DB time we are measuring. You can visualize the same using following figure.

 

Aas_ashDBA_HIST_ACTIVE_SESS_HISTORY

DBA_HIST_ACTIVE_SESS_HISTORY is a history table which maintains history of active sessions between AWR snapshots. Since V$ACTIVE_SESSION_HISTORY is a memory view and has limited space for growth, data from V$ACTIVE_SESSION_HISTORY flows to DBA_HIST_ACTIVE_SESS_HISTORY table.

DBA_HIST_ACTIVE_SESS_HISTORY table enables us to view active session data from the past. Data in DBA_HIST_ACTIVE_SESS_HISTORY is retained based on retention level set for AWR snapshots (30 days by default). So every time AWR snapshot happens, data from V$ACTIVE_SESSION_HISTORY goes into this table.

But NOT all data from V$ACTIVE_SESSION_HISTORY goes into DBA_HIST_ACTIVE_SESS_HISTORY. When AWR snapshot happens, it picks only 1 out of 10 samples from V$ACTIVE_SESSION_HISTORY into history table.

Complete visualization of active sessions looks like below

ash-architecture-and-advanced-usage-rmoug2014-7-638

 

 

 

 

 

 

 

 

Since AWR snapshot interval is 1 hour, it will take AWR snapshots every 1 hour and during that time 1 out of 10 samples form V$ACTIVE_SESSION_HISTORY will move to DBA_HIST_ACTIVE_SESS_HISTORY table.

So if want to calculate DB Time from DBA_HIST_ACTIVE_SESS_HISTORY table, we need to consider sample time as 10 sec instead of 1 sec.

DB Time = [ Number of samples ] X [ Time interval between samples ]
        = count(1) * 10

That’s why when we are calculating DB Time of a session or SQL from DBA_HIST_ACTIVE_SESS_HISTORY table, we need to take count(*) * 10.

Calculating DB Time

With this brief understanding of ASH, we can use these tables to find out DB time for a session and consolidate sessions to calculate DB Time for module/user etc.

If we can list modules in terms of % of DB time they are consuming in database, modules with high % of DB time are the one using most resources in database and has high impact to database. Same holds true at user level as well. We can find out which user is contributing highest DB time.

I have given couple of queries to find out % of DB Time different modules are contributing in database. This gives a fair idea about module wise resource consumption in database.

Note that I have randomized module names using DBMS_RANDOM.string(‘L’,TRUNC(DBMS_RANDOM.value(10,21))) to avoid exposing actual module name outside.


set line 999
set pagesize 999
set verify off
col module format a30;
BREAK ON REPORT
COLUMN DUMMY HEADING ''
compute sum of PCT_CPU on REPORT
with total_cpu as
(select   count(1)
 from     V$ACTIVE_SESSION_HISTORY
 where    SESSION_TYPE = 'FOREGROUND')
 select   module,
          count(1) "module_cpu",
          (select * from total_cpu) "total_cpu",
          round((count(1)/(select * from total_cpu))*100,2) PCT_CPU
from      V$ACTIVE_SESSION_HISTORY
where     SESSION_TYPE = 'FOREGROUND'
group by module order by PCT_CPU desc;

MODULE                         module_cpu  total_cpu    PCT_CPU
------------------------------ ---------- ---------- ----------
vvadcagpas                        29355     187065      15.69
cbkcbqchts                        26506     187065      14.17
zugkvhbajxpff                     24655     187065      13.18
tvfqhrkqzktiiceolrfd              10046     187065       5.37
paczxkndgsaqt                      6740     187065        3.6
pzqacdgxeqzbtqhalfc                6220     187065       3.33
nvqqscmayx                         5905     187065       3.16
zbirttdyoxxbslopnm                 5412     187065       2.89
bbztiihehigeqwxvk                  5051     187065        2.7
kvosekxfhkmfw                      4687     187065       2.51
aenyopwmok                         3977     187065       2.13
brfqfuwdyhyrej                     3256     187065       1.74
abruxykxhvqgfg                     3227     187065       1.73
zfrahazoqgdxubpni                  2759     187065       1.47
ddxinnevqd                         2633     187065       1.41
lructcsjkxhxatfidpf                2518     187065       1.35
naawhsfqvcaoathn                   2246     187065        1.2
sljzltjhhigepqfmcji                2142     187065       1.15
chvjvntynkjb                       2102     187065       1.12
zlzhwwhzbhfdtsszfedj               2005     187065       1.07
yvkuwzjkjhyeamco                   1610     187065        .86
fdjwspubzyhyxyzzkgyi               1578     187065        .84
risowlcnkizrbpgt                   1557     187065        .83
ywwdycosdpcfsflaubia               1539     187065        .82
pxlqrkmvreppum                     1496     187065         .8
amivlnlivqeesnqdkto                1404     187065        .75
jjaqyosqsc                         1347     187065        .72
yxkgfgktafvx                       1354     187065        .72
gqistslkwdw                        1328     187065        .71
bhuzvdpklocmnyimtzux               1272     187065        .68
uimycabvbjcczibrn                  1053     187065        .56
ksnvqslyker                         997     187065        .53
ofekwpklwpjtha                      975     187065        .52
wmkmovueneno                        904     187065        .48
umdtggtvdptkubfs                    795     187065        .42
dddegpqpwyalotxtoh                  761     187065        .41
pwycwyhavccwjuufqjx                 733     187065        .39
pxvcbhpfmeuwen                      729     187065        .39
nhezqmgkqccdcog                     716     187065        .38
ixtljofuazhpp                       628     187065        .34
mbotmyoairyqbdg                     600     187065        .32
aocabnswozdg                        586     187065        .31
qtdbdbuffprxj                       586     187065        .31
suiwwwtolcnkbnkcfwxw                560     187065         .3
btbdbtaztym                         562     187065         .3
xmvdgeczrot                         567     187065         .3
gkwzuwlgsh                          538     187065        .29
yhgmyqgqkvzmvbpsi                   463     187065        .25
obahkcsiafagmkxxu                   457     187065        .24
tcjoiyhzpuutbfhegn                  448     187065        .24
brlrkszrpmtw                        426     187065        .23
spzvvwzvoh                          435     187065        .23
ckvvarzrtpedhjl                     334     187065        .18
mnamshpswmsif                       329     187065        .18
gwvwypqrpwxkbugms                   293     187065        .16
clkuqearqhguezagwjlc                302     187065        .16
fskwtuctalnxhhu                     306     187065        .16
dyljhijlwyfmjy                      277     187065        .15
eqdifihzda                          255     187065        .14
nkrvwqrldd                          229     187065        .12
jkevokwkwokbnkbx                    231     187065        .12
niatevdadex                         198     187065        .11
qfjiifhiubvstyp                     200     187065        .11
acquoqslwxedulsmekbu                180     187065         .1
hjfimltalvopvuum                    156     187065        .08
bmyyhtzdqebo                        152     187065        .08
tkehpofgfe                          157     187065        .08
qnhgoqgstvq                         131     187065        .07
ddlloytpmyhpzpmk                    125     187065        .07
bvborwlump                          133     187065        .07
juirsmdjuejot                       124     187065        .07
saeoojlzfepjfybpclls                129     187065        .07
ppfdzcozyhxmf                       135     187065        .07
xbrwqdopemjqrhebglzs                115     187065        .06
zrfdsejwxgitsorat                   119     187065        .06
vsmsefmxnkoeb                        97     187065        .05
dvhoxhzayqyhsny                      98     187065        .05
cwjpiesdhpxvjs                      101     187065        .05
bvffncgtiojaj                        98     187065        .05
flfuciblxfzdcbo                      87     187065        .05
asucxewzdruwyfmg                     66     187065        .04
dztczkivnnbuzyuh                     67     187065        .04
hslcljfjmrhduw                       73     187065        .04
lywascpugxxjidx                      74     187065        .04
cawgdisaagltmie                      73     187065        .04
dpqbuvfkef                           68     187065        .04
tjpaushwfftmm                        54     187065        .03
ulgktcqvsazktojskfo                  56     187065        .03
ckoayyqtcxybkukgqvgl                 49     187065        .03
aqmphwbrngbotpxehyhe                 49     187065        .03
asqllnbivusyu                        60     187065        .03
skvrrqoshnirxbud                     59     187065        .03
vobtqhfewje                          58     187065        .03
xurrifyontk                          34     187065        .02
rliqgkwdwao                          42     187065        .02
ziwftblonh                           36     187065        .02
wzybbgmxkx                           30     187065        .02
vhumxxhimauc                         16     187065        .01
vssaefphdkebdx                       26     187065        .01
vjbjocafrwgdv                        11     187065        .01
xgcwcxrlzrjvysanlijw                 14     187065        .01
ztzxyfykhnxozdn                      20     187065        .01
btlbvffybkyjsn                       12     187065        .01
pmmqhsjuqhdaf                        22     187065        .01
kaumdvjqfcprmaeygr                   11     187065        .01
kadliemxdxhtzleqjr                   28     187065        .01
hlebszxkejjgkfbpmjew                 16     187065        .01
atwvjasykmlmldbipswh                 16     187065        .01
                                                     ----------
sum                                                      99.95

Similarly to check DB Time for sessions in past, we need to use DBA_HIST_ACTIVE_SESS_HISTORY table. Following query will provide % DB time used by individual modules calculated as % of total DB time between 2 AWR snapshots

set line 999
set pagesize 999
set verify off
BREAK ON REPORT
COLUMN DUMMY HEADING ''
compute sum of PCT_CPU on REPORT
with total_cpu as
(select   count(1)*10
from      dba_hist_active_sess_history
where     snap_id >= &begin_snap_id
and       snap_id < &end_snap_id
and       SESSION_TYPE = 'FOREGROUND')
select    module,
          count(1)*10 "module_cpu",
          (select * from total_cpu) "total_cpu",
          round((count(1)*10/(select * from total_cpu))*100,2) PCT_CPU
from      dba_hist_active_sess_history
where     snap_id >= &&begin_snap_id
and       snap_id < &&end_snap_id
and       SESSION_TYPE = 'FOREGROUND'
group by module order by PCT_CPU desc

 

 

Note that we have used count(*) * 10 in above query because 1 of 10 samples go to this table. Also, you need to specify begin_snap_id and end_snap_id and module DB Time usage during those snapshots will be calculated.

CPU Time

If we want to ignore waits and only focus on pure CPU used by modules, we can list modules as per CPU time they consume as % of total CPU time of database.

I think DB time is still better metric than CPU time because DB time covers waits as well. Waits slow down database.

We can calculate CPU time of a session by doing the same count(*) from V$ACTIVE_SESSION_HISTORY but we need to count only those samples during which session was actually using CPU. An ACTIVE session could be either using CPU to do some processing or it could be actively waiting on something (example IO when doing db file sequential read). Active session using CPU is represented by session_state = ‘ON CPU’. So we will count only those samples for session where session_state was ON CPU

Following query will give CPU time used by each module as % of total CPU time using V$ACTIVE_SESSION_HISTORY


set line 999
set pagesize 999
set verify off
BREAK ON REPORT
COLUMN DUMMY HEADING ''
compute sum of PCT_CPU on REPORT
with total_cpu as
(select count(1)
from  V$ACTIVE_SESSION_HISTORY
where   SESSION_TYPE != 'BACKGROUND'
and session_state = 'ON CPU')
select  module,
count(1) "module_cpu",
(select * from total_cpu) "total_cpu",
round((count(1)/(select * from total_cpu))*100,2) PCT_CPU
from  V$ACTIVE_SESSION_HISTORY
where SESSION_TYPE != 'BACKGROUND'
and   session_state = 'ON CPU'
group by module order by PCT_CPU desc

We can find similar CPU time for past sessions using DBA_HIST_ACTIVE_SESS_HISTORY table. Following query will provide CPU time used by module as % of total CPU time between 2 AWR snapshots


set line 999
set pagesize 999
set verify off
BREAK ON REPORT
COLUMN DUMMY HEADING ''
compute sum of PCT_CPU on REPORT
with total_cpu as
(select count(1)*10
from  dba_hist_active_sess_history
where   snap_id >= &&begin_snap_id
and   snap_id < &&end_snap_id
and   SESSION_TYPE != 'BACKGROUND'
and session_state = 'ON CPU')
select  module,
count(1)*10 "module_cpu",
(select * from total_cpu) "total_cpu",
round((count(1)*10/(select * from total_cpu))*100,2) PCT_CPU
from  dba_hist_active_sess_history
where   snap_id >= &&begin_snap_id
and   snap_id < &&end_snap_id
and   SESSION_TYPE != 'BACKGROUND'
and   session_state = 'ON CPU'
group by module order by PCT_CPU desc

Note, that in above query from DBA_HIST_ACTIVE_SESS_HISTORY, we have used count(*) * 10 because only 1 of 10 samples goes into this table.

I think for now above information is sufficient to give a basic idea about ASH.

I will be writing more articles on performance tuning using ASH as I dig further.

Hope this helps !!

“show slave hosts” on master not reporting hostname

If you have multiple MySQL slaves or complex topology, its difficult to remember what slaves are replicating from which master.

We can go to slave servers and check “show slave status” which list master host, but if we want to find out other way, we have can run “show slave hosts” from master.
This will list down all the slaves that are getting replicated from this master.

Only problem I faced was, “show slave hosts” was not reporting hostnames. They were empty.

root [fleetdb] >show slave hosts;
+-----------+------+------+-----------+--------------------------------------+
| Server_id | Host | Port | Master_id | Slave_UUID                           |
+-----------+------+------+-----------+--------------------------------------+
|         3 |      | 3306 |         2 | c21f28d2-c243-11e4-baf5-2c600c20dba4 |
+-----------+------+------+-----------+--------------------------------------+
1 row in set (0.01 sec)

After bit of RTFM, I came to know we need to set a parameter – “report_host” while starting slave. This will register slave hostname while connecting to master (for replication) and same will be shown in “show slave hosts”

This is a read-only parameter meaning, we need to bounce mysql instance after setting this parameter in /etc/my.cnf

So I set the parameter in /etc/my.cnf as below

report_host=slave-host1.mydb.example.com

We can specify any name here and same will be registered in master. But it make sense to provide actual host name.

Once I bounce mysql instance, my slave is started and it connects to master.
Now I check “show slave hosts” and it shows this host.

root [fleetdb] >show slave hosts;
+-----------+------------------------------+------+-----------+--------------------------------------+
| Server_id | Host                         | Port | Master_id | Slave_UUID                           |
+-----------+------------------------------+------+-----------+--------------------------------------+
|         3 | slave-host1.mydb.example.com | 3306 |         2 | c21f28d2-c243-11e4-baf5-2c600c20dba4 |
+-----------+------------------------------+------+-----------+--------------------------------------+
1 row in set (0.00 sec)

So we can easily know what slaves are connected to this master.

Hope this helps !!

Restoring Slave when GTID is enabled on master

This is a quick post on issues I faced while restoring a slave when GTID was enabled on master.

I have master created few days back and now I am trying to create a slave. I have GTID enabled on master.

Master status:

root [mysql] >show master status \G
*************************** 1. row ***************************
             File: bin_log.000002
         Position: 16682
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-59
1 row in set (0.00 sec)
root [mysql] >show variables like '%gtid%';
+--------------------------+-----------+
| Variable_name            | Value     |
+--------------------------+-----------+
| enforce_gtid_consistency | ON        |
| gtid_executed            |           |
| gtid_mode                | ON        |
| gtid_next                | AUTOMATIC |
| gtid_owned               |           |
| gtid_purged              |           |
+--------------------------+-----------+
6 rows in set (0.00 sec)

Step 1) Take backup from master

mysqldump -u root -p --databases deo fctest nosql --set-gtid-purged=off > /u01/backups/mysql_backup.sql

I used above command to take backup of master.

Note that I used –set-gtid-purged=off. If GTID is enabled on master and we are creating a slave, we want slave to start reading from the point when this backup is created. Because all previous information will be restored and available on slave as part of this backup restore.

If you want slave to start reading from this point and not from the beginning you should NOT set this variable to off. I will explain the significance of this variable later in the post.

Step 2) Install and create MySQL instance

Refer to my previous post http://avdeo.com/2014/02/18/installing-mysql/ for the same

Step 3) SCP backup file to slave server

slave-host.example.com$ scp master-host:/u01/backups/mysql_backup.sql /u01/backups/mysql_backup.sql

Step 4) Import backup into slave

slave-host.example.com$ mysql -u root -p </u01/backups/mysql_backup.sql

Step 5) Start Slave

We have to point slave to our master and then start slave.

When GTID is enabled, you can use MASTER_AUTO_POSITION=1 and slave should automatically start applying from correct GTID

mysql> CHANGE MASTER TO MASTER_HOST = 'master-host.example.com', MASTER_PORT = 3306, MASTER_USER = 'replicate', MASTER_PASSWORD = 'welcome', MASTER_AUTO_POSITION = 1;
Query OK, 0 rows affected, 2 warnings (0.12 sec)
mysql> start slave;
Query OK, 0 rows affected (0.03 sec)

mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: master-host.example.com
                  Master_User: replicate
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: bin_log.000002
          Read_Master_Log_Pos: 16682
               Relay_Log_File: relay_log.000002
                Relay_Log_Pos: 547
        Relay_Master_Log_File: bin_log.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1133
                   Last_Error: Error 'Can't find any matching row in the user table' on query. Default database: 'mysql'. Query: 'SET PASSWORD FOR 'root'@'master-host.example.com'='*DF216F57F1F2066124E1AA5491D995C3CB57E4C2''
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 341
              Relay_Log_Space: 17086
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1133
               Last_SQL_Error: Error 'Can't find any matching row in the user table' on query. Default database: 'mysql'. Query: 'SET PASSWORD FOR 'root'@'master-host.example.com'='*DF216F57F1F2066124E1AA5491D995C3CB57E4C2''
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 2
                  Master_UUID: f7718b80-c237-11e4-baa8-a0369f370a52
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 150304 08:03:47
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-59
            Executed_Gtid_Set: c21f28d2-c243-11e4-baf5-2c600c20dba4:1-59,
f7718b80-c237-11e4-baa8-a0369f370a52:1
                Auto_Position: 1
1 row in set (0.00 sec)

Now, if we see above slave status output, its showing error in SQL thread. SQL that is failing is Query: ‘SET PASSWORD FOR ‘root’@’master-host.example.com’=’*DF216F57F1F2066124E1AA5491D995C3CB57E4C2”

This is the first DML that was run on master. Its failing because master-host.example.com entry is not present in mysql.user table.  This is because its a slave on slave host and so root user entry will be present corresponding to slave host only.

Never the less, it should not be running DMLs from the beginning because we have restored everything until GTID 1-59.

Significance of –set-gtid-purged=off

The reason its applying transactions from the beginning is because we used –set-gtid-purged=off while taking backup.

When we are using GTID, we need to know in which GTID is the master and set it on the slave. MySQL keeps two global variables with GTID numbers on it:

  • gtid_executed: it contains a representation of the set of all transaction logged in the binary log
  • gtid_purged: it contains a representation of the set of all transactions deleted from the binary log

So now, the process is the following:

  • take a backup from the master and store the value of gtid_executed
  • restore the backup on the slave and set gtid_purged with the value of gtid_executed from the master

If we don’t use –set-gtid-purged=off in mysqldump, these global variables are automatically set in dump file created by mysqldump. So that when we apply that dump file on slave it will set these variables and slave will start pulling from GTID 60 onwards (in our example).

Fixing the issue

So at this point we have a backup which does not have GTID information. Lets see how to fix this issue manually.

I tried setting GTID_NEXT to 60 by first executing the transaction on master and make GTID 60 on master.

mysql> set gtid_next = "f7718b80-c237-11e4-baa8-a0369f370a52:60";
Query OK, 0 rows affected (0.00 sec)

mysql> begin; commit;
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

mysql> set gtid_next = "AUTOMATIC";
Query OK, 0 rows affected (0.00 sec)

mysql> stop slave;
Query OK, 0 rows affected (0.02 sec)

mysql> start slave;
Query OK, 0 rows affected (0.03 sec)

But this didn’t work.

We know that master is done until GTID 59 and we have those transaction in backup and slave also have them because backup was restored completely.

Lets try to set GTID_PURGED to remove those transactions from BINLOG

mysql> SET GLOBAL gtid_purged="f7718b80-c237-11e4-baa8-a0369f370a52:1:59";
ERROR 1840 (HY000): @@GLOBAL.GTID_PURGED can only be set when @@GLOBAL.GTID_EXECUTED is empty.

Its saying that GTID_EXECUTED should be empty. Lets check whats the current value and try to set to empty

mysql> show global variables like 'gtid_executed';
+---------------+--------------------------------------------------------------------------------------+
| Variable_name | Value                                                                                |
+---------------+--------------------------------------------------------------------------------------+
| gtid_executed | c21f28d2-c243-11e4-baf5-2c600c20dba4:1-59,
f7718b80-c237-11e4-baa8-a0369f370a52:1:59 |
+---------------+--------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
mysql> SET GLOBAL gtid_executed = "";
ERROR 1238 (HY000): Variable 'gtid_executed' is a read only variable

We cannot assign empty value to gtid_executed variable because its read-only and since we restored the backup gtid_executed is updated till the point this instance has executed the transactions.

Only way to fix this is using reset master on slave

When we issue reset master on slave, it will reset GTID_EXECUTED and make it null. After that we can set GTID_PURGED till 1-59 and slave can start applying from 60

mysql> reset master;
Query OK, 0 rows affected (0.07 sec)

mysql> show global variables like 'GTID_EXECUTED';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| gtid_executed |       |
+---------------+-------+
1 row in set (0.00 sec)
mysql> set global GTID_PURGED="f7718b80-c237-11e4-baa8-a0369f370a52:1-59";
Query OK, 0 rows affected (0.07 sec)

mysql> start slave;
Query OK, 0 rows affected (0.01 sec)
mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: master-host.example.com
                  Master_User: replicate
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: bin_log.000002
          Read_Master_Log_Pos: 16953
               Relay_Log_File: relay_log.000004
                Relay_Log_Pos: 442
        Relay_Master_Log_File: bin_log.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 16953
              Relay_Log_Space: 1202
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 2
                  Master_UUID: f7718b80-c237-11e4-baa8-a0369f370a52
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-60
            Executed_Gtid_Set: f7718b80-c237-11e4-baa8-a0369f370a52:1-60
                Auto_Position: 1
1 row in set (0.00 sec)

This fixed the issue.

Hope this helps !!

References:

http://www.percona.com/blog/2013/02/08/how-to-createrestore-a-slave-using-gtid-replication-in-mysql-5-6/