Exadata, Missing Metric

Understand metrics for Exadata Storage Server is important to understand how all the software features are being used and all the details from that. Here I will discuss one case where the FC_IO_BY_R_SEC metric can show not precise values. And I will discuss one missing metric that can save a lot.
If you have doubts about metrics, you can check my post about metrics, it was an introduction, but cover some aspects of how to read and use it. You can check my other post where I show how to use metric DB_FC_IO_BY_SEC to identify database problems that can be hidden when checking only from the database side.

 

Metrics collection

For this post, all metrics were collected from one storage server, but the behavior occurs in all cells from Exadata, and in all versions. And they were collected using the same timestamp be accurate. So, they represent one minute, but again, the same behavior that I show here occurs every time. When reading the metrics, please look at the metric name and the collect moment.
The idea for this post came when I was investigating storage usage from one database to see if we are hitting the limits for Exadata Storage. I needed to check disk, flash cache, and other details. For the behavior I show below, I already worked with Oracle about (SR, BUG, ER).

 

DB_FC_IO_BY_SEC

I already discussed about this metric in a previous post, but its report (according to the official doc) the “The number of megabytes of I/O per second for this database to flash cache”. Look the usage for the database DBPR1_EXA:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:42:00+01:00' and collectionTime < '2019-12-13T15:43:00+01:00' and name = 'DB_FC_IO_BY_SEC' and metricObjectName like 'DBPR1_EXA'

         DB_FC_IO_BY_SEC         DBPR1_EXA       850 MB/sec      2019-12-13T15:42:03+01:00




CellCLI>

 

As you can see, at 15:42:03 of 2019-12-13 the storage server reported that during the last minute this database made around 850 MB/s of reading from flash cache.
And this was the highest database consumption (that used more than 0.5 MB/s):

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:42:00+01:00' and collectionTime < '2019-12-13T15:43:00+01:00' and name like 'DB_.*BY.*SEC' and metricvalue > 0.5

         DB_FC_IO_BY_SEC         ORADB01P                1 MB/sec        2019-12-13T15:42:03+01:00

         DB_FC_IO_BY_SEC         ORADB02P                7 MB/sec        2019-12-13T15:42:03+01:00

         DB_FC_IO_BY_SEC         ORADB01V                1 MB/sec        2019-12-13T15:42:03+01:00

         DB_FC_IO_BY_SEC         ORADB03P                5 MB/sec        2019-12-13T15:42:03+01:00

         DB_FC_IO_BY_SEC         ORAD01P                 6 MB/sec        2019-12-13T15:42:03+01:00

         DB_FC_IO_BY_SEC         ORADBPR_EXA             2 MB/sec        2019-12-13T15:42:03+01:00

         DB_FC_IO_BY_SEC         DBPR1_EXA               850 MB/sec      2019-12-13T15:42:03+01:00

         DB_FC_IO_BY_SEC         DBP01                   104 MB/sec      2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         ORADB01P                1 MB/sec        2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         ORADB02P                7 MB/sec        2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         ORADB01V                1 MB/sec        2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         ORADB03P                5 MB/sec        2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         ORAD01P                 6 MB/sec        2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         ORADBPR_EXA             2 MB/sec        2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         DBPR1_EXA               850 MB/sec      2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         DBP01                   105 MB/sec      2019-12-13T15:42:03+01:00

         DB_FD_IO_BY_SEC         _OTHER_DATABASE_        1 MB/sec        2019-12-13T15:42:03+01:00

         DB_FL_IO_BY_SEC         DBP01                   1.150 MB/sec    2019-12-13T15:42:03+01:00

         DB_IO_BY_SEC            ORAD01P                 2 MB/sec        2019-12-13T15:42:03+01:00

         DB_IO_BY_SEC            ORADB1P_EXA             1 MB/sec        2019-12-13T15:42:03+01:00

         DB_IO_BY_SEC            DBP01                   2 MB/sec        2019-12-13T15:42:03+01:00




CellCLI>

 

If I sum all the database usage from flash cache, it will be around 950 MB/s.

 

FC_IO_BY_R_SEC

 

Since DB_FC_IO_BY_SEC reported just a small usage, I went check the metric for whole flash cache. So, I went to FC_IO_BY_R_SEC. This metric report (according to the docs): “The number of megabytes read per second from flash cache”. And since we are reading the metrics for flash cache direct, it report the number for all databases.
But, look the numbers:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:42:00+01:00' and collectionTime < '2019-12-13T15:43:00+01:00' and name = 'FC_IO_BY_R_SEC';

         FC_IO_BY_R_SEC  FLASHCACHE      19.343 MB/sec   2019-12-13T15:42:03+01:00




CellCLI>
 
So, at the same time moment that one database metric reported around 850 MB/s from FC reading, the metrics from FC reported around 19MB/s. Something it is not correct.
And even if I check the minute before and after (because maybe was a glimpse of time collection) the numbers are not quite different:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:41:00+01:00' and collectionTime < '2019-12-13T15:44:00+01:00' and name = 'FC_IO_BY_R_SEC';

         FC_IO_BY_R_SEC  FLASHCACHE      27.519 MB/sec   2019-12-13T15:41:03+01:00

         FC_IO_BY_R_SEC  FLASHCACHE      19.343 MB/sec   2019-12-13T15:42:03+01:00

         FC_IO_BY_R_SEC  FLASHCACHE      39.600 MB/sec   2019-12-13T15:43:03+01:00




CellCLI>

 

Others flash metrics

So, since the numbers appears to be complete wrong I searched for others metrics that report flash usage (disks and flash cache as example).

 

CD_IO_BY_*_*_SEC

 

I started to search with the lowest level possible, going directly to the celldisk metrics. For that I used CD_IO_BY_R_LG_SEC, CD_IO_BY_R_SM_SEC (for reads), CD_IO_BY_W_LG_SEC, and CD_IO_BY_W_SM_SEC (for writes). Basically, it reports: “The rate which is the number of megabytes read in large blocks per second from a cell disk”.
Filtering just from flash disks type I had this numbers:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:42:00+01:00' and collectionTime < '2019-12-13T15:43:00+01:00' and name like 'CD_IO_BY.*SEC.*' and metricobjectname like 'FD_.*' and metricvalue > 0

         CD_IO_BY_R_LG_SEC       FD_00_exastradm01       179 MB/sec      2019-12-13T15:42:03+01:00

         CD_IO_BY_R_LG_SEC       FD_01_exastradm01       296 MB/sec      2019-12-13T15:42:03+01:00

         CD_IO_BY_R_LG_SEC       FD_02_exastradm01       200 MB/sec      2019-12-13T15:42:03+01:00

         CD_IO_BY_R_LG_SEC       FD_03_exastradm01       250 MB/sec      2019-12-13T15:42:03+01:00

         CD_IO_BY_R_SM_SEC       FD_00_exastradm01       3.161 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_R_SM_SEC       FD_01_exastradm01       3.152 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_R_SM_SEC       FD_02_exastradm01       2.990 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_R_SM_SEC       FD_03_exastradm01       3.741 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_LG_SEC       FD_00_exastradm01       0.859 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_LG_SEC       FD_01_exastradm01       1.125 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_LG_SEC       FD_02_exastradm01       1.028 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_LG_SEC       FD_03_exastradm01       0.801 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_SM_SEC       FD_00_exastradm01       0.982 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_SM_SEC       FD_01_exastradm01       0.998 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_SM_SEC       FD_02_exastradm01       1.006 MB/sec    2019-12-13T15:42:03+01:00

         CD_IO_BY_W_SM_SEC       FD_03_exastradm01       0.937 MB/sec    2019-12-13T15:42:03+01:00




CellCLI>

 

As you can see, just picking up the CD_IO_BY_R_LG_SEC I got around 925 MB/s, a close number from the same that I got from the database metric reading the flash. Another hint from that says to me that reads are requesting more than 128KB for each access since they were counted as large (LG).

 

FL_IO_DB_BY_W_SEC and FL_IO_FL_BY_W_SEC

 

Since I was checking for bad flash report, I checked the flash log metrics but they reported close values from cell disk metrics:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:42:00+01:00' and collectionTime < '2019-12-13T15:43:00+01:00' and name like 'FL_IO.*_SEC'

         FL_IO_DB_BY_W_SEC       FLASHLOG        1.974 MB/sec    2019-12-13T15:42:03+01:00

         FL_IO_FL_BY_W_SEC       FLASHLOG        2.673 MB/sec    2019-12-13T15:42:03+01:00




CellCLI>

 

So, the metrics for disk usage, was OK, reporting correct values.

 

SIO_IO_RD_FC_SEC

 

As you can see, the metrics from database usage from flash cache are reporting the same values that were possible to check from the closest as from hardware report (celldisk). So, maybe could be a software misreading in-memory values.
Because of that, I checked from other metrics that can report form features that interact with flash cache. So, I checked from Smart I/O:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:42:00+01:00' and collectionTime < '2019-12-13T15:43:00+01:00' and name like 'SIO_.*SEC.*'

         SIO_IO_EL_OF_SEC        SMARTIO         1,223 MB/sec    2019-12-13T15:42:03+01:00

         SIO_IO_OF_RE_SEC        SMARTIO         34.688 MB/sec   2019-12-13T15:42:03+01:00

         SIO_IO_PA_TH_SEC        SMARTIO         0.000 MB/sec    2019-12-13T15:42:03+01:00

         SIO_IO_RD_FC_HD_SEC     SMARTIO         0.174 MB/sec    2019-12-13T15:42:03+01:00

         SIO_IO_RD_FC_SEC        SMARTIO         843 MB/sec      2019-12-13T15:42:03+01:00

         SIO_IO_RD_HD_SEC        SMARTIO         0.101 MB/sec    2019-12-13T15:42:03+01:00

         SIO_IO_RD_RQ_FC_HD_SEC  SMARTIO         0.183 IO/sec    2019-12-13T15:42:03+01:00

         SIO_IO_RD_RQ_FC_SEC     SMARTIO         850 IO/sec      2019-12-13T15:42:03+01:00

         SIO_IO_RD_RQ_HD_SEC     SMARTIO         0.000 IO/sec    2019-12-13T15:42:03+01:00

         SIO_IO_RV_OF_SEC        SMARTIO         3.392 MB/sec    2019-12-13T15:42:03+01:00

         SIO_IO_SI_SV_SEC        SMARTIO         362 MB/sec      2019-12-13T15:42:03+01:00

         SIO_IO_WR_FC_SEC        SMARTIO         0.008 MB/sec    2019-12-13T15:42:03+01:00

         SIO_IO_WR_HD_SEC        SMARTIO         0.000 MB/sec    2019-12-13T15:42:03+01:00

         SIO_IO_WR_RQ_FC_SEC     SMARTIO         0.017 IO/sec    2019-12-13T15:42:03+01:00

         SIO_IO_WR_RQ_HD_SEC     SMARTIO         0.000 IO/sec    2019-12-13T15:42:03+01:00




CellCLI>

 

And as you can see the SIO_IO_RD_FC_SEC (that means “The number of megabytes per second read from flash cache by smart I/O”) reported almost the same that value (843 MB/s) from the database and cell disk.

 

The Missing Metric

 

As you can see above, the metrics close from HW reported almost the same that was reported by DB. And from features usage, almost the same too. To be more clear is that:

 

 

So, it is not miss reading from memory since the Smart I/O report correctly. Returning the review for flash cache, all metrics are:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:42:00+01:00' and collectionTime < '2019-12-13T15:43:00+01:00' and name like 'FC_IO_BY.*' and metricvalue > 0;

         FC_IO_BYKEEP_W                          FLASHCACHE      519 MB                          2019-12-13T15:42:03+01:00

         FC_IO_BY_DISK_WRITE                     FLASHCACHE      111,626,264 MB                  2019-12-13T15:42:03+01:00

         FC_IO_BY_DISK_WRITE_SEC                 FLASHCACHE      2.052 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_R                              FLASHCACHE      1,475,538,050 MB                2019-12-13T15:42:03+01:00

         FC_IO_BY_R_ACTIVE_SECONDARY             FLASHCACHE      1,132,686 MB                    2019-12-13T15:42:03+01:00

         FC_IO_BY_R_ACTIVE_SECONDARY_MISS        FLASHCACHE      237,442 MB                      2019-12-13T15:42:03+01:00

         FC_IO_BY_R_DISK_WRITER                  FLASHCACHE      114,172,096 MB                  2019-12-13T15:42:03+01:00

         FC_IO_BY_R_DISK_WRITER_SEC              FLASHCACHE      2.057 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_R_DW                           FLASHCACHE      13,071,021,100 MB               2019-12-13T15:42:03+01:00

         FC_IO_BY_R_MISS                         FLASHCACHE      42,381,380 MB                   2019-12-13T15:42:03+01:00

         FC_IO_BY_R_MISS_DW                      FLASHCACHE      133,613,408 MB                  2019-12-13T15:42:03+01:00

         FC_IO_BY_R_MISS_SEC                     FLASHCACHE      0.438 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_R_SEC                          FLASHCACHE      19.343 MB/sec                   2019-12-13T15:42:03+01:00

         FC_IO_BY_R_SKIP                         FLASHCACHE      97,002,568 MB                   2019-12-13T15:42:03+01:00

         FC_IO_BY_W                              FLASHCACHE      1,761,639,940 MB                2019-12-13T15:42:03+01:00

         FC_IO_BY_W_DISK_WRITER                  FLASHCACHE      111,615,088 MB                  2019-12-13T15:42:03+01:00

         FC_IO_BY_W_DISK_WRITER_SEC              FLASHCACHE      2.052 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_W_FIRST                        FLASHCACHE      183,171,872 MB                  2019-12-13T15:42:03+01:00

         FC_IO_BY_W_FIRST_SEC                    FLASHCACHE      2.452 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_W_OVERWRITE                    FLASHCACHE      1,475,454,720 MB                2019-12-13T15:42:03+01:00

         FC_IO_BY_W_OVERWRITE_SEC                FLASHCACHE      1.346 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_W_POPULATE                     FLASHCACHE      103,121,912 MB                  2019-12-13T15:42:03+01:00

         FC_IO_BY_W_POPULATE_SEC                 FLASHCACHE      0.381 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_W_SEC                          FLASHCACHE      4.179 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_W_SKIP                         FLASHCACHE      1,039,399,810 MB                2019-12-13T15:42:03+01:00

         FC_IO_BY_W_SKIP_LG                      FLASHCACHE      605,535,040 MB                  2019-12-13T15:42:03+01:00

         FC_IO_BY_W_SKIP_LG_SEC                  FLASHCACHE      2.695 MB/sec                    2019-12-13T15:42:03+01:00

         FC_IO_BY_W_SKIP_SEC                     FLASHCACHE      6.589 MB/sec                    2019-12-13T15:42:03+01:00




CellCLI>

 

As you can above it is not the case for FC_IO_BY_R_SKIP (“The number of megabytes read from disks for I/O requests that bypass flash cache”) and FC_IO_BY_R_MISS_SEC (“The number of megabytes read from disks per second because not all requested data was in flash cache”). And even if we consider some minutes before and after:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:41:00+01:00' and collectionTime < '2019-12-13T15:44:00+01:00' and name = 'FC_IO_BY_R_SKIP';

         FC_IO_BY_R_SKIP         FLASHCACHE      97,002,568 MB   2019-12-13T15:41:03+01:00

         FC_IO_BY_R_SKIP         FLASHCACHE      97,002,568 MB   2019-12-13T15:42:03+01:00

         FC_IO_BY_R_SKIP         FLASHCACHE      97,002,568 MB   2019-12-13T15:43:03+01:00




CellCLI> list metrichistory where collectionTime > '2019-12-13T15:41:00+01:00' and collectionTime < '2019-12-13T15:44:00+01:00' and name = 'FC_IO_BY_W_SKIP';

         FC_IO_BY_W_SKIP         FLASHCACHE      1,039,399,420 MB        2019-12-13T15:41:03+01:00

         FC_IO_BY_W_SKIP         FLASHCACHE      1,039,399,810 MB        2019-12-13T15:42:03+01:00

         FC_IO_BY_W_SKIP         FLASHCACHE      1,039,401,150 MB        2019-12-13T15:43:03+01:00




CellCLI> list metrichistory where collectionTime > '2019-12-13T15:41:00+01:00' and collectionTime < '2019-12-13T15:44:00+01:00' and name like 'FC_IO_BY_.*_MISS.*SEC' and  metricvalue > 0

         FC_IO_BY_R_MISS_SEC     FLASHCACHE      0.702 MB/sec    2019-12-13T15:41:03+01:00

         FC_IO_BY_R_MISS_SEC     FLASHCACHE      0.438 MB/sec    2019-12-13T15:42:03+01:00

         FC_IO_BY_R_MISS_SEC     FLASHCACHE      0.521 MB/sec    2019-12-13T15:43:03+01:00




CellCLI>

 

But if we look closely the metrics from FC above, we can see the high value for FC_IO_BY_R_DW (“The number of megabytes of DW data read from flash cache”). And if we check some minutes we can see the usage:

 

CellCLI> list metrichistory where collectionTime > '2019-12-13T15:41:00+01:00' and collectionTime < '2019-12-13T15:44:00+01:00' and name = 'FC_IO_BY_R_DW';

         FC_IO_BY_R_DW   FLASHCACHE      13,070,966,800 MB       2019-12-13T15:41:03+01:00

         FC_IO_BY_R_DW   FLASHCACHE      13,071,021,100 MB       2019-12-13T15:42:03+01:00

         FC_IO_BY_R_DW   FLASHCACHE      13,071,055,900 MB       2019-12-13T15:43:03+01:00




CellCLI>

 

From that, we can see that at 15:41 the usage was 13,070,966,800 MB and at 15:42 the usage was 13,071,021,100 MB. And if we do the diff, between this minute the difference was 54300 MB. And if we divide by each sec we have 54300/60 = 905 MB/s.
So, the missing values were found, the flash cache read usage was counted as DW. But if you followed everything, we wad legitim reads from flash cache that was not counted at FC_IO_BY_R_SEC. So, the missing metric, in this case, it is FC_IO_BY_R_DW_SEC.

 

 

Reasons

The reason why the read was counted at FC_IO_BY_R_DW and not by the generic FC_IO_BY_R_SEC is not clear. Maybe because the block size of tablespace for the database is different than 8K, maybe the requests were large (more than 128 KB are we saw in cell disk metric). It is not clear why. Or maybe FC_IO_BY_R_SEC just report what was really read by flash cache from the database. It can occur that documentation is not clear and some details why this behavior occurs need to be clarified.
But we can see that FC_IO_BY_R_SEC don’t reflect the current usage in some cases. If you want to verify the FC usage, the metric FC_IO_BY_R_SEC can, sometimes, report wrong values. If the other metrics for FC are correct (like SKIP or MISS) was impossible to check at this point. One option is check directly at celldisk for flash disk usage to verify if you reached the limits for flash usage or check directly from database usage.
 

Disclaimer: “The postings on this site are my own and don’t necessarily represent my actual employer positions, strategies or opinions. The information here was edited to be useful for general purpose, specific data and identifications were removed to allow reach the generic audience and to be useful for the community.”