Blog
Exadata, Missing Metric
Category: Engineer System Author: Fernando Simon (Board Member) Date: 5 years ago Comments: 0

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.”

 


TFA error after GI upgrade to 19c
Category: Database Author: Fernando Simon (Board Member) Date: 5 years ago Comments: 0

TFA error after GI upgrade to 19c

Recently I made an Exadata stack upgrade/update to the last 19.2 version (19.2.7.0.0.191012) and I upgraded the GI from 18c to 19c (last 19c version – 19.5.0.0.191015) and after that, TFA does not work.
Since I don’t want to complete execute a TFA clean and reinstallation I tried to find the error and the solution. Here I want to share with you the workaround (since there is no solution yet) that I discovered and used to fix the error.

 

The environment

 

The actual environment is:
  • Old Grid Infrastructure: Version 18.6.0.0.190416
  • New Grid Infrastructure: Version 19.5.0.0.191015
  • Exadata domU: Version 19.2.7.0.0.191012 running kernel 4.1.12-124.30.1.el7uek.x86_64
 

TFA error

 

After upgrade the GI from 18c to 19c, the TFA does not work. If you try to start it or collect log using it, you can receive errors. In the environment described here, the TFA was running fine with the 18c version, and the rootupgrade script from 18c to 19c does not report an error.
And to be more precise, the TFA upgrade from 18c to 19c called by rootupgrade was ok (according to the log – I will show later). But even after that, the error occurs.
The provided solution as usual (by MOS support): download the lastest TFA and reinstall the actual one. Unfortunately, I not like this approach because can lead to an error during GI upgrade for next releases (like 20) and updates (19.6 as an example).
So, when I tried to collect TFA:

 

[root@exsite1c1 ~]# /u01/app/19.0.0.0/grid/tfa/bin/tfactl diagcollect

WARNING - TFA Software is older than 180 days. Please consider upgrading TFA to the latest version.

TFA-00002 Oracle Trace File Analyzer (TFA) is not running

Please start TFA before running collections

[root@exsite1c1 ~]#

 

So, when checking for running TFA I made ps -ef and not saw process running:

 

[root@exsite1c1 ~]# ps -ef |grep tfa

root      10665      1  0 Nov21 ?        00:00:06 /bin/sh /etc/init.d/init.tfa run >/dev/null 2>&1 </dev/null

root      40285  37137  0 11:05 pts/0    00:00:00 grep --color=auto tfa

[root@exsite1c1 ~]#

 

And if I try to start TFA (as root), nothing report (error or OK):

 

[root@exsite1c1 ~]# /etc/init.d/init.tfa start

Starting TFA..

Waiting up to 100 seconds for TFA to be started..

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

. . . . .

[root@exsite1c1 ~]#

[root@exsite1c1 ~]# ps -ef |grep tfa

root      10665      1  0 Nov21 ?        00:00:06 /bin/sh /etc/init.d/init.tfa run >/dev/null 2>&1 </dev/null

root      46031  37137  0 11:07 pts/0    00:00:00 grep --color=auto tfa

[root@exsite1c1 ~]#

 

Checking in the MOS I saw related problems with bad Perl version. For this TFA release is needed version 5.10 at lease. But was not the case:

 

[root@exsite1c1 ~]# perl -v




This is perl 5, version 16, subversion 3 (v5.16.3) built for x86_64-linux-thread-multi

(with 39 registered patches, see perl -V for more detail)




Copyright 1987-2012, Larry Wall




Perl may be copied only under the terms of either the Artistic License or the

GNU General Public License, which may be found in the Perl 5 source kit.




Complete documentation for Perl, including FAQ lists, should be found on

this system using "man perl" or "perldoc perl".  If you have access to the

Internet, point your browser at http://www.perl.org/, the Perl Home Page.




[root@exsite1c1 ~]#

 

Searching the problem

 

Digging for the source of the problem I checked the rootupgrade but the report was good. The TFA upgrade completed with success:

 

[root@exsite1c1 ~]# vi /u01/app/grid/crsdata/exsite1c2/crsconfig/rootcrs_exsite1c2_2019-11-15_12-12-21AM.log

...

...

2019-11-14 14:18:40: Executing the [UpgradeTFA] step with checkpoint [null] ...

2019-11-14 14:18:40: Executing cmd: /u01/app/19.0.0.0/grid/bin/clsecho -p has -f clsrsc -m 595 '1' '18' 'UpgradeTFA'

2019-11-14 14:18:40: Executing cmd: /u01/app/19.0.0.0/grid/bin/clsecho -p has -f clsrsc -m 595 '1' '18' 'UpgradeTFA'

2019-11-14 14:18:40: Command output:

>  CLSRSC-595: Executing upgrade step 1 of 18: 'UpgradeTFA'.

>End Command output

2019-11-14 14:18:40: CLSRSC-595: Executing upgrade step 1 of 18: 'UpgradeTFA'.

2019-11-14 14:18:40: Executing cmd: /u01/app/19.0.0.0/grid/bin/clsecho -p has -f clsrsc -m 4015

2019-11-14 14:18:40: Executing cmd: /u01/app/19.0.0.0/grid/bin/clsecho -p has -f clsrsc -m 4015

2019-11-14 14:18:40: Command output:

>  CLSRSC-4015: Performing install or upgrade action for Oracle Trace File Analyzer (TFA) Collector.

>End Command output

2019-11-14 14:18:40: CLSRSC-4015: Performing install or upgrade action for Oracle Trace File Analyzer (TFA) Collector.

2019-11-14 14:18:40: Executing the [ValidateEnv] step with checkpoint [null] ...

2019-11-14 14:18:40: Executing cmd: /u01/app/19.0.0.0/grid/crs/install/tfa_setup -silent -crshome /u01/app/19.0.0.0/grid

2019-11-14 14:18:40: Executing cmd: /u01/app/19.0.0.0/grid/bin/clsecho -p has -f clsrsc -m 595 '2' '18' 'ValidateEnv'

2019-11-14 14:18:40: Executing cmd: /u01/app/19.0.0.0/grid/bin/clsecho -p has -f clsrsc -m 595 '2' '18' 'ValidateEnv'

2019-11-14 14:18:40: Command output:

>  CLSRSC-595: Executing upgrade step 2 of 18: 'ValidateEnv'.

...

...

2019-11-14 14:23:45: Command output:

> 

>  TFA Installation Log will be written to File : /tmp/tfa_install_293046_2019_11_14-14_18_40.log

...

...

2019-11-14 14:23:45: Command output:

>  CLSRSC-4003: Successfully patched Oracle Trace File Analyzer (TFA) Collector.

>End Command output

 

And other related logs reported complete success:

 

[root@exsite1c1 ~]# cat /tmp/tfa_install_293046_2019_11_14-14_18_40.log

[2019-11-14 14:18:40] Log File written to : /tmp/tfa_install_293046_2019_11_14-14_18_40.log

[2019-11-14 14:18:40]

[2019-11-14 14:18:40] Starting TFA installation

[2019-11-14 14:18:40]

[2019-11-14 14:18:40] TFA Version: 192000 Build Date: 201904260414

[2019-11-14 14:18:40]

[2019-11-14 14:18:40] About to check previous TFA installations ...

[2019-11-14 14:18:40] TFA HOME : /u01/app/18.0.0/grid/tfa/exsite1c1/tfa_home

[2019-11-14 14:18:40]

[2019-11-14 14:18:40] Installed Build Version: 184100 Build Date: 201902260236

[2019-11-14 14:18:40]

[2019-11-14 14:18:40] INSTALL_TYPE GI

[2019-11-14 14:18:40] Shutting down TFA for Migration...

[2019-11-14 14:20:24]

[2019-11-14 14:20:24] Removing /etc/init.d/init.tfa...

[2019-11-14 14:20:24]

[2019-11-14 14:20:24] Migrating TFA to /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfa_home...

[2019-11-14 14:20:50]

[2019-11-14 14:20:50] Starting TFA on exsite1c1...

[2019-11-14 14:20:50]

[2019-11-14 14:21:05]

[2019-11-14 14:21:05] TFA_INSTALLER /u01/app/19.0.0.0/grid/crs/install/tfa_setup

[2019-11-14 14:21:05] TFA is already installed. Upgrading TFA

[2019-11-14 14:21:05]

[2019-11-14 14:21:05] TFA patching CRS or DB from zipfile extracted to /tmp/.293046.tfa

[2019-11-14 14:21:06] TFA Upgrade Log : /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfapatch.log

[2019-11-14 14:23:31] Patch Status : 0

[2019-11-14 14:23:31] Patching OK : Running install_ext

[2019-11-14 14:23:32] Installing oratop extension..

[2019-11-14 14:23:32]

.-----------------------------------------------------------------.

| Host      | TFA Version | TFA Build ID         | Upgrade Status |

+-----------+-------------+----------------------+----------------+

| exsite1c1 |  19.2.0.0.0 | 19200020190426041420 | UPGRADED       |

| exsite1c2 |  18.4.1.0.0 | 18410020190226023629 | NOT UPGRADED   |

'-----------+-------------+----------------------+----------------'




[2019-11-14 14:23:44] Removing Old TFA /u01/app/18.0.0/grid/tfa/exsite1c1/tfa_home...

[2019-11-14 14:23:45] Cleanup serializable files

[2019-11-14 14:23:45]

[root@exsite1c1 ~]#

[root@exsite1c1 ~]# cat /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfapatch.log




TFA will be upgraded on Node exsite1c1:







Upgrading TFA on exsite1c1 :




Stopping TFA Support Tools...




Shutting down TFA for Patching...




Shutting down TFA

. . . . .

. . .

Successfully shutdown TFA..




No Berkeley DB upgrade required




Copying TFA Certificates...







Starting TFA in exsite1c1...




Starting TFA..

Waiting up to 100 seconds for TFA to be started..

. . . . .

Successfully started TFA Process..

. . . . .

TFA Started and listening for commands




Enabling Access for Non-root Users on exsite1c1...




[root@exsite1c1 ~]#

 

One know problem occurs when (for some reason) the nodes of the clusters lost the sync for TFA. I tried to do the sync, and this pointed one clue:

 

[root@exsite1c1 ~]# /u01/app/19.0.0.0/grid/tfa/bin/tfactl syncnodes

WARNING - TFA Software is older than 180 days. Please consider upgrading TFA to the latest version.




/u01/app/19.0.0.0/grid/tfa/exsite1c1/tfa_home/bin/synctfanodes.sh: line 237: /u01/app/18.0.0/grid/perl/bin/perl: No such file or directory

TFA-00002 Oracle Trace File Analyzer (TFA) is not running




Current Node List in TFA :

1.




Unable to determine Node List to be synced. Please update manually.




Do you want to update this node list? [Y|N] [N]: ^C[root@exsite1c1 ~]#

[root@exsite1c1 ~]#

 

As you can see, the syncnodes.sh made a reference for the old 18c GI home. And inside of the sync script, you can see the reference of that like 237 (my mark below) checked for PERL, and this came from the file tfa_setup.txt.

 

[root@exsite1c1 ~]# vi /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfa_home/bin/synctfanodes.sh

...

...

        if [ `$GREP -c '^PERL=' $tfa_home/tfa_setup.txt` -ge 1 ]    <== TFA CHECK

        then

                PERL=`$GREP '^PERL=' $tfa_home/tfa_setup.txt | $AWK -F"=" '{print $2}'`;

        fi




        if [ `$GREP -c '^CRS_HOME=' $tfa_home/tfa_setup.txt` -ge 1 ]

        then

                CRS_HOME=`$GREP '^CRS_HOME=' $tfa_home/tfa_setup.txt | $AWK -F"=" '{print $2}'`;

        fi




        if [ `$GREP -c '^RUN_MODE=' $tfa_home/tfa_setup.txt` -ge 1 ]

        then

                RUN_MODE=`$GREP '^RUN_MODE=' $tfa_home/tfa_setup.txt | $AWK -F"=" '{print $2}'`;

        fi

fi




RUSER=`$RUID | $AWK '{print $1}' | $AWK -F\( '{print $2}' | $AWK -F\) '{print $1}'`;




if [ $RUSER != $DAEMON_OWNER ]

then

        $ECHO "User '$RUSER' does not have permissions to run this script.";

        exit 1;

fi




SSH_USER="$DAEMON_OWNER";




HOSTNAME=`hostname | $CUT -d. -f1 | $PERL -ne 'print lc'`;    <===== LINE 237

...

...

 

Checking tfa_setup.txt

Checking the file we can see the error:

 

[root@exsite1c1 ~]# cat /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfa_home/tfa_setup.txt

CRS_HOME=/u01/app/18.0.0/grid

exsite1c1%CRS_INSTALLED=1

NODE_NAMES=exsite1c1

ORACLE_BASE=/u01/app/grid

JAVA_HOME=/u01/app/18.0.0/grid/jdk/jre

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/OPatch/crs/log

exsite1c1%CFGTOOLS%DIAGDEST=/u01/app/12.1.0.2/grid/cfgtoollogs

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/crf/db/exsite1c1

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/crs/log

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/cv/log

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/evm/admin/log

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/evm/admin/logger

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/evm/log

exsite1c1%INSTALL%DIAGDEST=/u01/app/12.1.0.2/grid/install

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/log

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/network/log

exsite1c1%DBWLM%DIAGDEST=/u01/app/12.1.0.2/grid/oc4j/j2ee/home/log

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/opmn/logs

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/racg/log

exsite1c1%ASM%DIAGDEST=/u01/app/12.1.0.2/grid/rdbms/log

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/scheduler/log

exsite1c1%CRS%DIAGDEST=/u01/app/12.1.0.2/grid/srvm/log

exsite1c1%ACFS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/acfs

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/core

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/crsconfig

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/crsdiag

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/cvu

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/evm

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/output

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/trace

exsite1c1%INSTALL%DIAGDEST=/u01/app/oraInventory/ContentsXML

exsite1c1%INSTALL%DIAGDEST=/u01/app/oraInventory/logs

TRACE_LEVEL=1

INSTALL_TYPE=GI

PERL=/u01/app/18.0.0/grid/perl/bin/perl

RDBMS_ORACLE_HOME=/u01/app/oracle/product/12.1.0.2/dbhome_1||

RDBMS_ORACLE_HOME=/u01/app/oracle/product/11.2.0.4/dbhome_1||

RDBMS_ORACLE_HOME=/u01/app/12.2.0.1/grid||

TZ=Europe/Luxembourg

RDBMS_ORACLE_HOME=/u01/app/18.0.0/grid||

localnode%ADRBASE=/u01/app/grid

RDBMS_ORACLE_HOME=/u01/app/oracle/product/18.0.0/dbhome_1||

localnode%ADRBASE=/u01/app/oracle

RDBMS_ORACLE_HOME=/u01/app/oracle/product/11.2.0.4/financ||

localnode%ADRBASE=/u01/app/oracle

RDBMS_ORACLE_HOME=/u01/app/oracle/product/12.1.0.2/financ||

localnode%ADRBASE=/u01/app/oracle

DAEMON_OWNER=root

RDBMS_ORACLE_HOME=/u01/app/oracle/agent/13.2.0/agent_13.2.0.0.0||

RDBMS_ORACLE_HOME=/u01/app/12.1.0.2/grid||

RDBMS_ORACLE_HOME=/u01/app/19.0.0.0/grid||

localnode%ADRBASE=/u01/app/grid

CRS_ACTIVE_VERSION=

[root@exsite1c1 ~]#

 

As you can see above, the CRS_HOME, JAVA_HOME, PERL, and ORACLE_HOME parameters are pointing to the old GI folder. As a workaround I edited the tfa_setup.txt in both nodes and fixed the GI folder from 18.0 to 19.0:

 

[root@exsite1c1 ~]# vi /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfa_home/tfa_setup.txt

[root@exsite1c1 ~]#

[root@exsite1c1 ~]#

[root@exsite1c1 ~]#

[root@exsite1c1 ~]# cat /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfa_home/tfa_setup.txt

CRS_HOME=/u01/app/19.0.0.0/grid

exsite1c1%CRS_INSTALLED=1

NODE_NAMES=exsite1c1

ORACLE_BASE=/u01/app/grid

JAVA_HOME=/u01/app/19.0.0.0/grid/jdk/jre

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/OPatch/crs/log

exsite1c1%CFGTOOLS%DIAGDEST=/u01/app/19.0.0.0/grid/cfgtoollogs

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/crf/db/exsite1c1

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/crs/log

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/cv/log

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/evm/admin/log

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/evm/admin/logger

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/evm/log

exsite1c1%INSTALL%DIAGDEST=/u01/app/19.0.0.0/grid/install

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/log

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/network/log

exsite1c1%DBWLM%DIAGDEST=/u01/app/19.0.0.0/grid/oc4j/j2ee/home/log

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/opmn/logs

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/racg/log

exsite1c1%ASM%DIAGDEST=/u01/app/19.0.0.0/grid/rdbms/log

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/scheduler/log

exsite1c1%CRS%DIAGDEST=/u01/app/19.0.0.0/grid/srvm/log

exsite1c1%ACFS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/acfs

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/core

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/crsconfig

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/crsdiag

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/cvu

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/evm

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/output

exsite1c1%CRS%DIAGDEST=/u01/app/grid/crsdata/exsite1c1/trace

exsite1c1%INSTALL%DIAGDEST=/u01/app/oraInventory/ContentsXML

exsite1c1%INSTALL%DIAGDEST=/u01/app/oraInventory/logs

TRACE_LEVEL=1

INSTALL_TYPE=GI

PERL=/u01/app/19.0.0.0/grid/perl/bin/perl

RDBMS_ORACLE_HOME=/u01/app/oracle/product/12.1.0.2/dbhome_1||

RDBMS_ORACLE_HOME=/u01/app/oracle/product/11.2.0.4/dbhome_1||

TZ=Europe/Luxembourg

RDBMS_ORACLE_HOME=/u01/app/oracle/product/18.0.0/dbhome_1||

localnode%ADRBASE=/u01/app/oracle

RDBMS_ORACLE_HOME=/u01/app/oracle/product/11.2.0.4/financ||

localnode%ADRBASE=/u01/app/oracle

RDBMS_ORACLE_HOME=/u01/app/oracle/product/12.1.0.2/financ||

localnode%ADRBASE=/u01/app/oracle

DAEMON_OWNER=root

RDBMS_ORACLE_HOME=/u01/app/oracle/agent/13.2.0/agent_13.2.0.0.0||

RDBMS_ORACLE_HOME=/u01/app/19.0.0.0/grid||

localnode%ADRBASE=/u01/app/grid

CRS_ACTIVE_VERSION=19.0.0.0

[root@exsite1c1 ~]#

 

And after edit was possible to start TAF correctly:

 

[root@exsite1c1 ~]# /etc/init.d/init.tfa start

Starting TFA..

Waiting up to 100 seconds for TFA to be started..

. . . . .

Successfully started TFA Process..

. . . . .

WARNING - TFA Software is older than 180 days. Please consider upgrading TFA to the latest version.

TFA Started and listening for commands

[root@exsite1c1 ~]#

[root@exsite1c1 ~]#

[root@exsite1c1 ~]# ps -ef |grep tfa

root     113905      1  0 11:31 ?        00:00:00 /bin/sh /etc/init.d/init.tfa run >/dev/null 2>&1 </dev/null

root     115917      1 99 11:31 ?        00:00:24 /u01/app/19.0.0.0/grid/jdk/jre/bin/java -server -Xms256m -Xmx512m -Djava.awt.headless=true -Ddisable.checkForUpdate=true -XX:ParallelGCThreads=5 oracle.rat.tfa.TFAMain /u01/app/19.0.0.0/grid/tfa/exsite1c1/tfa_home

root     117853  37137  0 11:31 pts/0    00:00:00 grep --color=auto tfa

[root@exsite1c1 ~]#

 

And execute the diagcollect:

 

[root@exsite1c1 ~]# /u01/app/19.0.0.0/grid/tfa/bin/tfactl diagcollect

WARNING - TFA Software is older than 180 days. Please consider upgrading TFA to the latest version.

 

By default TFA will collect diagnostics for the last 12 hours. This can result in large collections

For more targeted collections enter the time of the incident, otherwise hit <RETURN> to collect for the last 12 hours

[YYYY-MM-DD HH24:MI:SS,<RETURN>=Collect for last 12 hours] :

 

Collecting data for the last 12 hours for all components...

Collecting data for all nodes

 

Collection Id : 20191122124148exsite1c1

 

Detailed Logging at : /u01/app/grid/tfa/repository/collection_Fri_Nov_22_12_41_49_CET_2019_node_all/diagcollect_20191122124148_exsite1c1.log

2019/11/22 12:41:53 CET : NOTE : Any file or directory name containing the string .com will be renamed to replace .com with dotcom

2019/11/22 12:41:53 CET : Collection Name : tfa_Fri_Nov_22_12_41_49_CET_2019.zip

2019/11/22 12:41:54 CET : Collecting diagnostics from hosts : [exsite1c1, exsite1c2]

2019/11/22 12:41:54 CET : Scanning of files for Collection in progress...

2019/11/22 12:41:54 CET : Collecting additional diagnostic information...

2019/11/22 12:44:13 CET : Completed collection of additional diagnostic information...

2019/11/22 13:15:39 CET : Getting list of files satisfying time range [11/22/2019 00:41:53 CET, 11/22/2019 13:15:39 CET]

2019/11/22 13:40:42 CET : Collecting ADR incident files...

2019/11/22 13:40:48 CET : Completed Local Collection

2019/11/22 13:40:48 CET : Remote Collection in Progress...

.---------------------------------------.

|           Collection Summary          |

+-----------+-----------+-------+-------+

| Host      | Status    | Size  | Time  |

+-----------+-----------+-------+-------+

| exsite1c2 | Completed | 412MB |  318s |

| exsite1c1 | Completed | 284MB | 3534s |

'-----------+-----------+-------+-------'

 

Logs are being collected to: /u01/app/grid/tfa/repository/collection_Fri_Nov_22_12_41_49_CET_2019_node_all

/u01/app/grid/tfa/repository/collection_Fri_Nov_22_12_41_49_CET_2019_node_all/exsite1c1.tfa_Fri_Nov_22_12_41_49_CET_2019.zip

/u01/app/grid/tfa/repository/collection_Fri_Nov_22_12_41_49_CET_2019_node_all/exsite1c2.tfa_Fri_Nov_22_12_41_49_CET_2019.zip

[root@exsite1c1 ~]#

[root@exsite1c1 ~]# /u01/app/19.0.0.0/grid/tfa/bin/tfactl diagcollect -since 1h

WARNING - TFA Software is older than 180 days. Please consider upgrading TFA to the latest version.

Collecting data for all nodes

 

Collection Id : 20191122134319exsite1c1

 

Detailed Logging at : /u01/app/grid/tfa/repository/collection_Fri_Nov_22_13_43_20_CET_2019_node_all/diagcollect_20191122134319_exsite1c1.log

2019/11/22 13:43:24 CET : NOTE : Any file or directory name containing the string .com will be renamed to replace .com with dotcom

2019/11/22 13:43:24 CET : Collection Name : tfa_Fri_Nov_22_13_43_20_CET_2019.zip

2019/11/22 13:43:24 CET : Collecting diagnostics from hosts : [exsite1c1, exsite1c2]

2019/11/22 13:43:24 CET : Scanning of files for Collection in progress...

2019/11/22 13:43:24 CET : Collecting additional diagnostic information...

2019/11/22 13:44:49 CET : Getting list of files satisfying time range [11/22/2019 12:43:24 CET, 11/22/2019 13:44:49 CET]

2019/11/22 13:45:50 CET : Completed collection of additional diagnostic information...

2019/11/22 13:59:19 CET : Collecting ADR incident files...

2019/11/22 13:59:19 CET : Completed Local Collection

2019/11/22 13:59:19 CET : Remote Collection in Progress...

.--------------------------------------.

|          Collection Summary          |

+-----------+-----------+-------+------+

| Host      | Status    | Size  | Time |

+-----------+-----------+-------+------+

| exsite1c2 | Completed | 230MB | 295s |

| exsite1c1 | Completed | 105MB | 955s |

'-----------+-----------+-------+------'

 

Logs are being collected to: /u01/app/grid/tfa/repository/collection_Fri_Nov_22_13_43_20_CET_2019_node_all

/u01/app/grid/tfa/repository/collection_Fri_Nov_22_13_43_20_CET_2019_node_all/exsite1c2.tfa_Fri_Nov_22_13_43_20_CET_2019.zip

/u01/app/grid/tfa/repository/collection_Fri_Nov_22_13_43_20_CET_2019_node_all/exsite1c1.tfa_Fri_Nov_22_13_43_20_CET_2019.zip

[root@exsite1c1 ~]#

 

TFA error #2

Another error that I got in another cluster that passed for the same update/upgrade process was related with *ser files in tfa home. If I try to use TFA (with diagcolect as an example) I receive this error:

 

[root@exsite2c1 ~]# /u01/app/19.0.0.0/grid/tfa/exsite2c1/tfa_home/bin/tfactl diagcollect

WARNING - TFA Software is older than 180 days. Please consider upgrading TFA to the latest version.

Storable binary image v2.10 contains data of type 101. This Storable is v2.9 and can only handle data types up to 30 at /usr/lib64/perl5/vendor_perl/Storable.pm line 381, at /u01/app/19.0.0.0/grid/tfa/exsite2c1/tfa_home/bin/common/tfactlshare.pm line 25611.

[root@exsite2c1 ~]#   

 

If you look in the MOS, will point to PERL version. But it is not the case here, the perl it is more than 5.10 version for this version of Exadata. The solution was more *.ser files to another folder (remove from TFA home), or delete it. After that, no more “Storage binary error” (but the error about with tfa_setup.txt continues):

 

[root@exsite2c1 ~]# mv /u01/app/19.0.0.0/grid/tfa/exsite2c1/tfa_home/internal/*ser /tmp

[root@exsite2c1 ~]# ls -l /u01/app/19.0.0.0/grid/tfa/exsite2c1/tfa_home/internal/*ser

ls: cannot access /u01/app/19.0.0.0/grid/tfa/exsite2c1/tfa_home/internal/*ser: No such file or directory

[root@exsite2c1 ~]#

 

Problem and Solution

It is not clear the source of the problem in this case. As you saw above, the logs of upgrade/update of GI from 18c to 19c reported success, even for TFA. But it is clear that tfa_setup.txt was left with wrong parameters inside. And if you look closely you can see that exists reference to the new GI home in the first version.

But unfortunately, the needed parameters were left with the wrong values. The workaround was just to change the tfa_setup.txt and fix the wrong folders for parameters. Was not tested to execute the $GI_HOME/grid/crs/install/tfa_setup -silent -crshome $GI_HOME to fix the filed, but you can try. The idea was trying to identify the issue instead of just remove TFA and reinstall it.

Again, this is a workaround tested in my environment and worked. You need to verify logs and other files to see if you hit the same issues. If yes, at least, you can try.

 
 

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.”

 


Exadata, Workaround for oracka.ko error
Category: Engineer System Author: Fernando Simon (Board Member) Date: 5 years ago Comments: 0

Exadata, Workaround for oracka.ko error

Recently I made an Exadata stack upgrade/update to the last 19.2 version (19.2.7.0.0.191012) released in October of 2019, and update the GI to the last 19c version (19.5.0.0.191015) and after that, I hade some issues to create 11G databases.
So, when I try to create an 11G RAC database, the error “File -oracka.ko- was not found” appears and creation fails. Here I want to share with you the workaround (since there is no solution yet) that I discovered and used to bypass the error.

 

The environment

 

The actual environment is:
  • Grid Infrastructure: Version 19.5.0.0.191015
  • Exadata domU: Version 19.2.7.0.0.191012 running kernel 4.1.12-124.30.1.el7uek.x86_64
  • 11G Database: Version 11.2.0.4.180717
  • ACFS: Used to store some files

oracka.ko

So, calling dbca:

 

[DEV-oracle@exsite1c1-]$ /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/dbca -silent -createDatabase -templateName General_Purpose.dbc -gdbName D11TST19 -adminManaged -sid D11TST19 -sysPassword oracle11 -systemPassword oracle11 -characterSet WE8ISO8859P15 -emConfiguration NONE -storageType ASM -diskGroupName DATAC8 -recoveryGroupName RECOC8 -nodelist exsite1c1,exsite1c2 -sampleSchema false

Copying database files

100% complete

Look at the log file "/u01/app/oracle/cfgtoollogs/dbca/D11TST19/D11TST19.log" for further details.

[DEV-oracle@exsite1c1-]$

 

And at the log:

 

[DEV-oracle@exsite1c1-]$ cat /u01/app/oracle/cfgtoollogs/dbca/D11TST19/D11TST19.log

Creating and starting Oracle instance

PRCR-1006 : Failed to add resource ora.d11tst19.db for d11tst19

PRCD-1094 : Failed to create start dependency for database d11tst19 on the ASM cluster filesystem where ACFS path /u01/app/oracle/product/11.2.0.4/dbhome_1 resides

PRCT-1129 : Execution of ACFS driver state check failed on local node with result Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

ACFS-9200: Supported

DBCA_PROGRESS : 100%

[DEV-oracle@exsite1c1-]$

 

If you check for the trace of database creation:

 

[DEV-oracle@exsite1c1-]$ vi /u01/app/oracle/cfgtoollogs/dbca/D11TST19/trace.log

[Thread-166] [ 2019-11-07 08:30:37.860 CET ] [ASMFactoryImpl.isACFSSupported:954]  Entry: oraHome=/u01/app/oracle/product/11.2.0.4/dbhome_1, m_crsHome=/u01/app/19.0.0.0/grid

[Thread-166] [ 2019-11-07 08:30:37.860 CET ] [ASMFactoryImpl.isACFSSupported:958]  Checking if ACFS now...

[Thread-166] [ 2019-11-07 08:30:37.861 CET ] [USMDriverUtil.<init>:117]  Checking file exists for: /u01/app/19.0.0.0/grid/bin/acfsdriverstate

[Thread-166] [ 2019-11-07 08:30:37.862 CET ] [NativeSystem.isCmdScv:502]  isCmdScv: cmd=[]

[Thread-182] [ 2019-11-07 08:30:37.866 CET ] [StreamReader.run:61]  In StreamReader.run

[Thread-181] [ 2019-11-07 08:30:37.868 CET ] [StreamReader.run:61]  In StreamReader.run

[Thread-182] [ 2019-11-07 08:30:38.230 CET ] [StreamReader.run:65]  ERROR>Argument "2/8" isn't numeric in numeric ne (!=) at /u01/app/19.0.0.0/grid/lib/osds_acfsroot.pm line 2093.

[Thread-182] [ 2019-11-07 08:30:38.230 CET ] [StreamReader.run:65]  ERROR>Argument "2/8" isn't numeric in numeric ne (!=) at /u01/app/19.0.0.0/grid/lib/osds_acfsroot.pm line 2093.

[Thread-182] [ 2019-11-07 08:30:38.235 CET ] [StreamReader.run:65]  ERROR>error:  cannot delete old /u01/app/19.0.0.0/grid/usm/install/Oracle/EL7UEK/x86_64/4.1.12-112.16.4/4.1.12-112.16.4-x86_64/bin/oracka.ko

[Thread-182] [ 2019-11-07 08:30:38.235 CET ] [StreamReader.run:65]  ERROR>        Permission denied

[Thread-181] [ 2019-11-07 08:30:38.310 CET ] [StreamReader.run:65]  OUTPUT>Errors uncompressing file: oracka.zip.

[Thread-181] [ 2019-11-07 08:30:38.405 CET ] [StreamReader.run:65]  OUTPUT>File -oracka.ko- was not found.

[Thread-181] [ 2019-11-07 08:30:38.485 CET ] [StreamReader.run:65]  OUTPUT>Error # 50 - . Output: .

[Thread-182] [ 2019-11-07 08:30:38.504 CET ] [StreamReader.run:65]  ERROR>error:  cannot delete old /u01/app/19.0.0.0/grid/usm/install/Oracle/EL7UEK/x86_64/4.1.12-112.16.4/4.1.12-112.16.4-x86_64/bin/oracka.ko

[Thread-182] [ 2019-11-07 08:30:38.504 CET ] [StreamReader.run:65]  ERROR>        Permission denied

[Thread-181] [ 2019-11-07 08:30:38.587 CET ] [StreamReader.run:65]  OUTPUT>Errors uncompressing file: oracka.zip.

[Thread-181] [ 2019-11-07 08:30:38.667 CET ] [StreamReader.run:65]  OUTPUT>File -oracka.ko- was not found.

[Thread-181] [ 2019-11-07 08:30:38.753 CET ] [StreamReader.run:65]  OUTPUT>Error # 50 - . Output: .

[Thread-181] [ 2019-11-07 08:30:40.877 CET ] [StreamReader.run:65]  OUTPUT>ACFS-9200: Supported

[Thread-166] [ 2019-11-07 08:30:40.881 CET ] [UnixSystem.dorunRemoteExecCmd:3232]  retval = 0

[Thread-166] [ 2019-11-07 08:30:40.881 CET ] [UnixSystem.dorunRemoteExecCmd:3256]  exitValue = 0

[Thread-166] [ 2019-11-07 08:30:40.882 CET ] [USMDriverUtil.checkACFSState:267]  Printing ACFS output

[Thread-166] [ 2019-11-07 08:30:40.882 CET ] [USMDriverUtil.checkACFSState:268]  Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

ACFS-9200: Supported

[Thread-166] [ 2019-11-07 08:30:40.882 CET ] [InstanceStepOPS.executeImpl:1014]  PRCR-1006 : Failed to add resource ora.d11tst19.db for d11tst19

PRCD-1094 : Failed to create start dependency for database d11tst19 on the ASM cluster filesystem where ACFS path /u01/app/oracle/product/11.2.0.4/dbhome_1 resides

PRCT-1129 : Execution of ACFS driver state check failed on local node with result Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

ACFS-9200: Supported

[Thread-166] [ 2019-11-07 08:30:40.883 CET ] [BasicStep.configureSettings:304]  messageHandler being set=oracle.sysman.assistants.util.SilentMessageHandler@5a943dc4

[Thread-166] [ 2019-11-07 08:30:40.883 CET ] [BasicStep.configureSettings:304]  messageHandler being set=oracle.sysman.assistants.util.SilentMessageHandler@5a943dc4

oracle.sysman.assistants.util.step.StepExecutionException: PRCR-1006 : Failed to add resource ora.d11tst19.db for d11tst19

PRCD-1094 : Failed to create start dependency for database d11tst19 on the ASM cluster filesystem where ACFS path /u01/app/oracle/product/11.2.0.4/dbhome_1 resides

PRCT-1129 : Execution of ACFS driver state check failed on local node with result Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

Errors uncompressing file: oracka.zip.

File -oracka.ko- was not found.

Error # 50 - . Output: .

ACFS-9200: Supported

        at oracle.sysman.assistants.dbca.backend.InstanceStepOPS.executeImpl(InstanceStepOPS.java:1015)

        at oracle.sysman.assistants.util.step.BasicStep.execute(BasicStep.java:210)

        at oracle.sysman.assistants.util.step.BasicStep.callStep(BasicStep.java:251)

        at oracle.sysman.assistants.dbca.backend.DBEntryStep.executeImpl(DBEntryStep.java:229)

        at oracle.sysman.assistants.util.step.BasicStep.execute(BasicStep.java:210)

        at oracle.sysman.assistants.util.step.Step.execute(Step.java:140)

        at oracle.sysman.assistants.util.step.StepContext$ModeRunner.run(StepContext.java:2711)

        at java.lang.Thread.run(Thread.java:637)

[Thread-166] [ 2019-11-07 08:30:40.883 CET ] [SQLEngine.done:2189]  Done called

 

So, as you can see in the trace the process for database creation when detecting that ACFS is in place, tries to unzip some files (.ko, kernel objects) related to ACFS access but receive the error or that cannot delete old oracka.ko and for uncompressing file oracka.zip.

 

Source of the problem

Checking for the problem, we can see that access denied occurs for folder $GI_HOME/usm/install/Oracle/EL7UEK/x86_64/4.1.12-112.16.4/4.1.12-112.16.4-x86_64/bin/ inside of GI home. And as you can see is the same family of our domU kernel version. Inside os MOS there is no reference for this error, and after open the SR for Oracle was sent do dev team without ETA (as usual).
Because of that I continue to check and checked the folder:

 

[root@exsite1c1 ~]# cd /u01/app/19.0.0.0/grid/usm/install/Oracle/EL7UEK/x86_64/4.1.12-112.16.4/4.1.12-112.16.4-x86_64/bin/

[root@exsite1c1 bin]#

[root@exsite1c1 bin]# ls -l

total 151244

-rw-r--r-- 1 root oinstall  3085340 Sep  1 12:40 oracka.ko

-rw-r--r-- 1 root oinstall  2304100 Sep  1 12:44 oracka_mod_kga.ko

-rw-r--r-- 1 grid oinstall   623207 Oct  9 17:13 oracka_mod_kga.zip

-rw-r--r-- 1 grid oinstall   889060 Oct  9 17:14 oracka.zip

-rw-r--r-- 1 root oinstall 64000932 Sep  1 12:04 oracleacfs.ko

-rw-r--r-- 1 grid oinstall 19246647 Oct  9 17:13 oracleacfs.zip

-rw-r--r-- 1 root oinstall 27882452 Sep  1 11:25 oracleadvm.ko

-rw-r--r-- 1 grid oinstall  8777000 Oct  9 17:13 oracleadvm.zip

-rw-r--r-- 1 root oinstall  8776676 Sep  1 12:55 oracleafd.ko

-rw-r--r-- 1 grid oinstall  2879744 Oct  9 17:14 oracleafd.zip

-rw-r--r-- 1 root oinstall 10696156 Sep  1 11:04 oracleoks.ko

-rw-r--r-- 1 grid oinstall  3346594 Oct  9 17:14 oracleoks.zip

-rw-r--r-- 1 root oinstall  1757116 Sep  1 13:02 oracleolfs.ko

-rw-r--r-- 1 grid oinstall   567865 Oct  9 17:14 oracleolfs.zip

[root@exsite1c1 bin]#

 

As you can see, the GI Home came with some ko files already uncompressed and the permission for a group just as read. So, the delete and uncompressing by dbca will not work properly, and as a workaround to solve the issue, I changed the permission for folder bin and ko files to allow change for oinstall – made in all nodes of the cluster:

 

[root@exsite1c1 4.1.12-112.16.4-x86_64]# pwd

/u01/app/19.0.0.0/grid/usm/install/Oracle/EL7UEK/x86_64/4.1.12-112.16.4/4.1.12-112.16.4-x86_64

[root@exsite1c1 4.1.12-112.16.4-x86_64]#

[root@exsite1c1 4.1.12-112.16.4-x86_64]#

[root@exsite1c1 4.1.12-112.16.4-x86_64]# chmod g+w bin

[root@exsite1c1 4.1.12-112.16.4-x86_64]#

[root@exsite1c1 4.1.12-112.16.4-x86_64]#

[root@exsite1c1 4.1.12-112.16.4-x86_64]# ls -l

total 4

drwxrwxr-x 2 grid oinstall 4096 Nov  8 15:08 bin

[root@exsite1c1 4.1.12-112.16.4-x86_64]# cd bin

[root@exsite1c1 bin]# chown grid:oinstall oracka.ko oracka_mod_kga.ko oracleacfs.ko oracleadvm.ko oracleafd.ko oracleoks.ko oracleolfs.ko

[root@exsite1c1 bin]#
After executing this in both nodes, the dbca finish:

 

[DEV-oracle@exsite1c1-]$ /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/dbca -silent -createDatabase -templateName General_Purpose.dbc -gdbName D11TST19 -adminManaged -sid D11TST19 -sysPassword oracle11 -systemPassword orcle11 -characterSet WE8ISO8859P15 -emConfiguration NONE -storageType ASM -diskGroupName DATAC8 -recoveryGroupName RECOC8 -nodelist exsite1c1,exsite1c2 -sampleSchema false

Creating and starting Oracle instance

1% complete

…

96% complete

100% complete

Look at the log file "/u01/app/oracle/cfgtoollogs/dbca/D11TST19/D11TST19.log" for further details.

[DEV-oracle@exsite1c1-]$

[DEV-oracle@exsite1c1-]$ $ORACLE_HOME/bin/srvctl status database -d D11TST19

Instance D11TST191 is running on node exsite1c1

Instance D11TST192 is running on node exsite1c2

[DEV-oracle@exsite1c1-]$

 

Just to check the ko files and bin folder already came with wrong permissions in the original 19c packages:

 

[grid@exsite1c1 +ASM1]$ cd /u01/patches/grid

[grid@exsite1c1 +ASM1]$ unzip -q V982068-01.zip

[grid@exsite1c1 +ASM1]$ cd usm/install/Oracle/EL7UEK/x86_64/4.1.12-112.16.4/4.1.12-112.16.4-x86_64/bin

[grid@exsite1c1 +ASM1]$ ls -l

total 149116

-rw-r--r-- 1 grid oinstall  3085340 Feb 23  2019 oracka.ko

-rw-r--r-- 1 grid oinstall  2304100 Feb 23  2019 oracka_mod_kga.ko

-rw-r--r-- 1 grid oinstall   623214 Feb 23  2019 oracka_mod_kga.zip

-rw-r--r-- 1 grid oinstall   889106 Feb 23  2019 oracka.zip

-rw-r--r-- 1 grid oinstall 62740980 Feb 23  2019 oracleacfs.ko

-rw-r--r-- 1 grid oinstall 18881690 Feb 23  2019 oracleacfs.zip

-rw-r--r-- 1 grid oinstall 27485580 Feb 23  2019 oracleadvm.ko

-rw-r--r-- 1 grid oinstall  8643808 Feb 23  2019 oracleadvm.zip

-rw-r--r-- 1 grid oinstall  8773444 Feb 23  2019 oracleafd.ko

-rw-r--r-- 1 grid oinstall  2878816 Feb 23  2019 oracleafd.zip

-rw-r--r-- 1 grid oinstall 10655524 Feb 23  2019 oracleoks.ko

-rw-r--r-- 1 grid oinstall  3335912 Feb 23  2019 oracleoks.zip

-rw-r--r-- 1 grid oinstall  1757348 Feb 23  2019 oracleolfs.ko

-rw-r--r-- 1 grid oinstall   567876 Feb 23  2019 oracleolfs.zip

[grid@exsite1c1 +ASM1]$ cd ..

[grid@exsite1c1 +ASM1]$ ls -l

total 4

drwxr-xr-x 2 grid oinstall 4096 Apr 18  2019 bin

[grid@exsite1c1 +ASM1]$

 

The sum of all problems

This error for oracka.zip and oracka.ko occurs because there is a sum of little details. The release of GI 19c version already came with bad folder permission. The release update 19.5.0.0.191015 does not solve the issue too (and even the installation or rootupgrade script). This bin folder was checked by dbca because the kernel image for Exadata 19.2.7.0.0 (19.2.7.0.0.191012) comes with kernel 4.1.12-124.30.1.el7uek.x86_64 and the ACFS modules for this family are there. And to finish the sum of all problems, the ACFS was used and for that reason, it tries to use that kernel modules to check access.
So, since there is no solution at MOS (today while I am publishing this post), and there is no official workaround, was needed to find own solution. So, the workaround described here it is just temporary to allow 11g RAC database creation for this specific sun of Exadata Version + GI Home 19c + ACFS in use.
 

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.”


Exadata, Understanding Metrics
Category: Engineer System Author: Fernando Simon (Board Member) Date: 5 years ago Comments: 0

Exadata, Understanding Metrics

Metrics for Exadata deliver to you one way to deeply see, and understand, what it is happening for Exadata Storage Server and Exadata Software. Understand it is fundamental to identify and solve problems that can be hidden (or even unsee) from the database side. In this post, I will explain details about these metrics and what you can do using them.
My last article about Exadata Storage Server metrics was about one example of how to use them to identify problems that do not appear in the database side. In that post, I showed how I used the metric DB_FC_IO_BY_SEC to identify bad queries.
The point for Exadata (that I made in that article), is that most of the time, Exadata is so powerful that bad statements are handled without a problem because of the features that exist (flashcache, smartio, and others). But another point is that usually, Exadata is a high consolidated environment, where you “consolidate” a lot of databases and it is normal that some of them have different workloads and needs. Using metrics can help you to do a fine tune of your environment, but besides that, it delivers to you one way to check and control everything that’s happening.
In this post, I will not explain each metric one by one, but guide you to understand metrics and some interesting and important details about them.

 

Understanding metrics

 

Metrics for Exadata are values extract directly from hardware or directly from storage server software. Values from “IOPS from each disk”, or “MB/s read by SMARTIO” are an example of what you can discover. Directly from the docs:
“Metrics are recorded observations of important run-time properties or internal instrumentation values of the storage cell and its components, such as cell disks or grid disks. Metrics are a series of measurements that are computed and retained in memory for an interval of time, and stored on a disk for a more permanent history.”
To check the definition for Exadata metrics, and all metrics available the best place it the official Exadata User Guide, chapter 6. You can see the definition for all metrics and other important information. I really recommend that you read it to be aware of what you can extract from the metrics.
When reading metrics, you can read the current values (from the last minute), or from history view. From the historic list, values are for each minute from the last 7 days. So, with metrics, you cover 24×7 for each minute during the last 7 days. So, a good source of information to help you. And most important, they are individual and read from each storage server.

 

Reading metrics

 

To read metrics you can connect directly in the storage server and with the cellcli use the “list metriccurrent” or “list metrichistory” commands to read it:

 

[root@exacellsrvx-01 ~]# cellcli

CellCLI: Release 18.1.9.0.0 - Production on Sun Dec 08 15:01:42 BRST 2019




Copyright (c) 2007, 2016, Oracle and/or its affiliates. All rights reserved.




CellCLI> list metriccurrent

         CD_BY_FC_DIRTY                          CD_00_exacellsrvx-01                            0.000 MB

…

…

         SIO_IO_WR_RQ_FC_SEC                     SMARTIO                                         0.000 IO/sec

         SIO_IO_WR_RQ_HD                         SMARTIO                                         2,768,097 IO requests

         SIO_IO_WR_RQ_HD_SEC                     SMARTIO                                         0.000 IO/sec

 

Since it is based in the list command you can detail it, restrict with where, or change the attributes to display it:

 

CellCLI> list metriccurrent where name = 'FL_IO_DB_BY_W_SEC' detail

         name:                   FL_IO_DB_BY_W_SEC

         alertState:             normal

         collectionTime:         2019-12-08T15:10:14-02:00

         metricObjectName:       FLASHLOG

         metricType:             Instantaneous

         metricValue:            0.189 MB/sec

         objectType:             FLASHLOG




CellCLI> list metriccurrent where name = 'FL_IO_DB_BY_W_SEC' attributes name, metricvalue, collectionTime

         FL_IO_DB_BY_W_SEC       0.133 MB/sec    2019-12-08T15:11:14-02:00




CellCLI>

 

You can query the metric for each one of the attributes. Like all metrics for IORM or all metrics for that have FC in the name. If you want to query values in the past, you need to use list metrichistory:

 

CellCLI> list metrichistory where name = 'FL_IO_DB_BY_W_SEC' and collectionTime = '2019-12-08T15:21:14-02:00' attributes name, metricvalue, collectionTime

         FL_IO_DB_BY_W_SEC       0.196 MB/sec    2019-12-08T15:21:14-02:00




CellCLI>

 

Metric types

There are three types of metrics: Instantaneous (value reflect the moment when was read), Rate (values computed based in the period of time), Cumulative (values since you started storage server from the last time).
All the metrics type Rate, usually are expressed by second. This means that Exadata counted the values from the last minute and divided it by seconds. So, the *_SEC means the average based at the last minute.
One important detail is that some have the “small” and “large” metrics. This means that if your request from the database needs more than 128KB the values are marked as large *LG*, otherwise, as small *SM*.

 

Using metrics

 

To understand metrics for Exadata it is important to know the limits for your hardware, and for Exadata the good (and quick way) is the datasheet. Using the X8M datasheet as an example we can see that the max GB/s per second for each storage server is around 1.78 (25GB/s for full rack divided by 14 storage – as for example). Understand these numbers are important, I recommend you to read the datasheet and understand them.
Since every storage computes each metric in the separate way you need to query each one to have the big picture. But this does not mean that some metrics need to be analyzed globally, instead of per each server. I usually divide Exadata metrics in two ways, Isolated and Per Database.

 

Isolated Metrics

 

I consider isolated metrics that are important to check for each server. They express values that are important to check isolated per each storage server. Some metrics that I like to check isolated:
  • CL_CPUT: The cell CPU utilization.
  • CL_MEMUT: The percentage of total physical memory used.
  • N_HCA_MB_RCV_SEC: The number of megabytes received by the InfiniBand interfaces per second
  • N_HCA_MB_TRANS_SEC: The number of megabytes transmitted by the InfiniBand interfaces per second.
  • CD_IO_BY_R_LG_SEC: The rate which is the number of megabytes read in large blocks per second from a cell disk.
  • CD_IO_BY_R_SM_SEC: The rate which is the number of megabytes read in small blocks per second from a cell disk.
  • CD_IO_BY_W_LG_SEC: The rate which is the number of megabytes written in large blocks per second on a cell disk.
  • CD_IO_BY_W_SM_SEC: The rate which is the number of megabytes written in small blocks per second on a cell disk.
  • CD_IO_RQ_R_LG_SEC: The rate which is the number of requests to read large blocks per second from a cell disk.
  • CD_IO_RQ_R_SM_SEC: The rate which is the number of requests to read small blocks per second from a cell disk.
  • CD_IO_RQ_W_LG_SEC: The rate which is the number of requests to write large blocks per second to a cell disk.
  • CD_IO_RQ_W_SM_SEC: The rate which is the number of requests to write small blocks per second to a cell disk.
  • CD_IO_TM_R_LG_RQ: The rate which is the average latency of reading large blocks per request to a cell disk.
  • CD_IO_TM_R_SM_RQ: The rate which is the average latency of reading small blocks per request from a cell disk.
  • CD_IO_TM_W_LG_RQ: The rate which is the average latency of writing large blocks per request to a cell disk.
  • CD_IO_TM_W_SM_RQ: The rate which is the average latency of writing small blocks per request to a cell disk.
  • CD_IO_UTIL: The percentage of device utilization for the cell disk.
  • FC_BY_ALLOCATED: The number of megabytes allocated in flash cache.
  • FC_BY_USED: The number of megabytes used in flash cache.
  • FC_BY_DIRTY: The number of megabytes in flash cache that are not synchronized to the grid disks.
  • FC_IO_BY_R_SEC: The number of megabytes read per second from flash cache.
  • FC_IO_BY_R_SKIP_SEC: The number of megabytes read from disks per second for I/O requests that bypass flash cache. Read I/O requests that bypass flash cache go directly to disks. These requests do not populate flash cache after reading the requested data.
  • FC_IO_BY_R_MISS_SEC: The number of megabytes read from disks per second because not all requested data was in flash cache.
  • FC_IO_BY_W_SEC: The number of megabytes per second written to flash cache.
  • FC_IO_BY_W_SKIP_SEC: The number of megabytes written to disk per second for I/O requests that bypass flash cache.
  • FC_IO_RQ_R_SEC: The number of read I/O requests satisfied per second from flash cache.
  • FC_IO_RQ_W_SEC: The number of I/O requests per second which resulted in flash cache being populated with data.
  • FC_IO_RQ_R_SKIP_SEC: The number of read I/O requests per second that bypass flash cache. Read I/O requests that bypass flash cache go directly to disks
  • FC_IO_RQ_W_SKIP_SEC: The number of write I/O requests per second that bypass flash cache
  • FL_IO_DB_BY_W_SEC: The number of megabytes written per second were written to hard disk by Exadata Smart Flash Log
  • FL_IO_FL_BY_W_SEC: The number of megabytes written per second were written to flash by Exadata Smart Flash Log.
  • FL_IO_TM_W_RQ: Average redo log write latency. It includes write I/O latency only.
  • FL_RQ_TM_W_RQ: Average redo log write request latency.
  • FL_IO_W_SKIP_BUSY: The number of redo writes during the last minute that could not be serviced by Exadata Smart Flash Log.
  • N_MB_RECEIVED_SEC: The rate which is the number of megabytes received per second from a particular host.
  • N_MB_SENT_SEC: The rate which is the number of megabytes received per second from a particular host.
  • SIO_IO_EL_OF_SEC: The number of megabytes per second eligible for offload by smart I/O.
  • SIO_IO_OF_RE_SEC: The number of interconnect megabytes per second returned by smart I/O.
  • SIO_IO_RD_FC_SEC: The number of megabytes per second read from flash cache by smart I/O.
  • SIO_IO_RD_HD_SEC: The number of megabytes per second read from hard disk by smart I/O.
  • SIO_IO_RD_RQ_FC_SEC: The number of read I/O requests per second from flash cache by smart I/O.
  • SIO_IO_RD_FC_HD_SEC: The number of read I/O requests per second from hard disk by smart I/O.
  • SIO_IO_WR_FC_SEC: The number of megabytes per second of flash cache population writes by smart I/O.
  • SIO_IO_SI_SV_SEC: The number of megabytes per second saved by the storage index.
With these metrics you can discover, by example, in each server:
  • Percentage of CPU and memory utilization.
  • GB/s sent by Smart I/O to one database server. And if you compare with the ingest that came from the database you can see percentage safe by smartio.
  • The number of flashcache reads that was redirected to disk because the data was not there. Here if you see increase the value tread, maybe you have fixed (or have a lot of data) in flash cache and your queries are demanding other tables.
  • For celldisk (CD*) metrics it is important to divide by metricObjectName attribute to identify the read from Disks and from Flash. There is no direct metrics for FD*, they are present (at storage level) as a celldisk, but they have different throughputs values. This is true for EF too that just have flash.
  • For flashcache directly, you can check the allocated values (usually 100%), but also the “dirty” usage when data it does not sync (between flash and disks), this can mean a lot of writes for your database, bad query design, or high pressure between consolidating databases (maybe you can disable for one category/database trough IORM).
  • From smartscan you can check the MB/s read from flashcache or disk to offload your query. Or even check MB/s that was saved by storage index.
So, as you can see there is a lot of information that you can extract from storage server. I prefer to read these separately (per storage) because if I consider globally (smartio or flascache as an example), I don’t have a correct representation of what it is happening under the hood. Maybe, a good value from one storage can hide a bad from another when I calculate the averages.
The idea for these metrics is to provide one way to see Exadata storage software overview. The amount of data that it is reading from hardware (CD_* metrics) and how it is used by the features. You can see how was safe by storage index of smarscan as an example, or see if the flashcache is correct populated (and not dirty). And even help to identify some queries that may are bypassing the flashache or not using smartio.
 

Database Metrics

 

The concept of global metrics does not exist directly in the Exadata, you still need to read separately from each storage server. But I recommend that check it globally, doing the sum for values from each storage server to analyze it. One example it the IOPS (or MB/s) for database, you usually want to know the value for the entire Exadata and not for each server.
In the list, I will put just for database, but you have the same for PDB, Consumer Groups, and from Categories. Remember that for IORM the hierarchy is first Categories and after Databases when creating the plans.
  • DB_FC_BY_ALLOCATED: The number of megabytes allocated in flash cache for this database.
  • DB_FC_IO_BY_SEC: The number of megabytes of I/O per second for this database to flash cache.
  • DB_FC_IO_RQ_LG_SEC: The number of large I/O requests issued by a database to flash cache per second.
  • DB_FC_IO_RQ_SM_SEC: The number of small I/O requests issued by a database to flash cache per second.
  • DB_FL_IO_BY_SEC: The number of megabytes written per second to Exadata Smart Flash Log.
  • DB_FL_IO_RQ_SEC: The number of I/O requests per second issued to Exadata Smart Flash Log.
  • DB_IO_BY_SEC: The number of megabytes of I/O per second for this database to hard disks.
  • DB_IO_LOAD: The average I/O load from this database for hard disks. For a description of I/O load, see CD_IO_LOAD.
  • DB_IO_RQ_LG_SEC: The rate of large I/O requests issued to hard disks by a database per second over the past minute.
  • DB_IO_RQ_SM_SEC: The rate of small I/O requests issued to hard disks by a database per second over the past minute.
  • DB_IO_TM_LG_RQ: The rate which is the average latency of reading or writing large blocks per request by a database from hard disks.
  • DB_IO_TM_SM_RQ: The rate which is the average latency of reading or writing small blocks per request by a database from hard disks.
  • DB_IO_UTIL_LG: The percentage of hard disk resources utilized by large requests from this database.
  • DB_IO_UTIL_SM: The percentage of hard disk resources utilized by small requests from this database.
  • DB_IO_WT_LG_RQ: The average IORM wait time per request for large I/O requests issued to hard disks by a database.
  • DB_IO_WT_SM_RQ: The average IORM wait time per request for small I/O requests issued to hard disks by a database.
With these metrics you can see how the database/pdb/cg/ct are using the Exadata. As an example, you can check the MB/s (or IOPS) read from flashcache by seconds. And if you compare with CD_* as an example, you can discover which database is using more it. The same can be done by flashlog.

 

What you can discover

 

With metrics you can discover a lot of things that are hidden when you just look from the database side (AWR as an example). And it is more critical when you have a consolidated environment in your Exadata. You can compare values from different databases and have insights from something that is not correct (as my example from the previous post).
Here I will show you another example. Again, all the values I collected using my script that you can check in my post at OTN. This script connects in each storage server and retrieves the values from the last 10 minutes. After that I stored, I made the average value for the minutes reported. This means that every point listed below are the average values computed for every 10 minutes.

 

 

Look above. This graph represents the values from DB_IO_BY_SEC metric. As you can see, the database reached around 1.6 to 1.7GB/s of disk usage. And if you remember for Exadata datasheet, this means that this database used almost everything from disk capacity/throughput from Exadata storage. This can be confirmed by:
As you can see, the average was around 85 to 90 percent of IO/Utilization for this database. But if I look at the values for each minute, I can see some high usage around 95%.
And as you can image, other databases started to see wait time for the same moment:
If you compare the three graphs at the same time, you can see that when one database started to use a lot from the storage server (around the max throughput from hardware), another database started to see more wait time for each request. The value below is expressed in ms/r (milliseconds per request).
This is one example of what you can discover using metrics. In this case specifically, the analyses started because one application DBA Team reported that started to notice some slow queries during the morning. But the application changed nothing in the previous 4 months and the AWR and tuning their queries helped nothing. Using the metric was discovered that another database deployed a new version with bad SQL. But looking from this database, everything appears normal.

 

How to read

 

If you want to read metrics the best way if trough cellcli, but sometimes you don’t need it of you can’t. You can use the Enterprise Manager/Cloud Control to check some information, but you don’t have all the metrics available, but can use the Exadata plugin to check IOPS and MB/s.
Still, at EM/CC you can try to check the KPI for Storage server and write some queries direct to EM/CC database. Oracle has a good reference about this procedure in this PDF: https://www.oracle.com/technetwork/database/availability/exadata-storage-server-kpis-2855362.pdf
You can still use the Oracle Management Cloud for Exadata to help you to identify bottlenecks in your environment. You can use some IA and Oracle expertise to identify trends easier and be more proactive than reactive https://cloudcustomerconnect.oracle.com/files/32e7361eed/OMC_For_EXADATA_whitepaper_v28.pdf or this blog post from Oracle.  
Another way is writing/use one script to integrate with your monitoring tool. You can use my script as a guide and adapt it to your needs. The script can be checked in my post at Oracle OTN (Portuguese Version, Spanish Version, unfortunately, there is no English version. Was sent to be published, but never was – I don’t know why), the version published read all metrics and output it in one line. You can use it to insert it into one database or save it in one file as you desire.

 

Insights

 

The idea for metric analysis is to check it and have insights about what can be wrong. Sometimes it is easy to identify (like the example before), but other times you need to dig in a lot of metrics to find the problem (smartio, flashcache, dirty cache, etc).
But unfortunately, to understand metric you need to truly understand Exadata. It is more than a simple knowledge of the hardware or how to patch the Exadata. You need to understand the limits for your machine (datasheet can help), database tuning (to understand a bad query plan), and where to search (which metric use). You need to use this together to have the insights, and unfortunately, this came just with day-to-day usage/practice.
The idea for this post was to provide you a guide, or even a shortcut, to understand the Exadata metric and do more. I did not cover every metric, or every detail for each metric, but tried to show you how to read, analyze, and use it to identify problems.
 

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.”

 


1 … 11 12 13 14 15 … 32
LUXOUG – LUXEMBOURG ORACLE USERS GROUP
© 2024 LUXOUG – LUXEMBOURG ORACLE USERS GROUP