Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Oracle 19C Incorrect AWR Snapshots Reported in Multitenant DB #189

Closed
dfhawthorne opened this issue Jan 13, 2021 · 14 comments · Fixed by #190
Closed

Oracle 19C Incorrect AWR Snapshots Reported in Multitenant DB #189

dfhawthorne opened this issue Jan 13, 2021 · 14 comments · Fixed by #190

Comments

@dfhawthorne
Copy link
Contributor

When run a TPC-C workload against an Oracle 19C PDB, the AWR snapshots reported are for the CDB not the PDB:

Vuser 1:Start Snapshot 220 taken at 13 JAN 2021 17:31 of instance DEMO19C (1) of database DEMOCDB1 (1856558291)
Vuser 1:Timing test period of 5 in minutes
Timer: 3 minutes elapsed
Vuser 1:1 ...,
Timer: 4 minutes elapsed
Vuser 1:2 ...,
Timer: 5 minutes elapsed
Vuser 1:3 ...,
Vuser 1:4 ...,
Vuser 1:5 ...,
Vuser 1:Test complete, Taking end AWR snapshot.
Vuser 1:End Snapshot 220 taken at 13 JAN 2021 17:31 of instance DEMO19C (1) of database DEMOCDB1 (1856558291)
Vuser 1:Test complete: view report from SNAPID 220 to 220
Vuser 1:2 Active Virtual Users configured
Vuser 1:TEST RESULT : System achieved 195 NOPM from 0 Oracle TPM

Note The same SNAPID is reported as the start and end values.

This issue appears to be similar to #13.

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 14, 2021

Thanks for the Issue and proposed solution. I've tested it on 12c and confirmed it doesn't have an impact on the existing version. Currently creating a pluggable 19c install to test there so may take a little while to test and give feedback.

@sm-shaw sm-shaw linked a pull request Jan 14, 2021 that will close this issue
@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 15, 2021

So I setup a 19c/19.3 database with a pluggable database. The 12c version I had used was 12.1 and the behaviour does seem to be different. It has been a while since I looked into this so I might easily be missing something. To test I used the unmodified HammerDB v4.0 without the patch. I set up a container database RAZCDB1 and pluggable RAZPDB1. When I installed the test schema in RAZPDB1 and ran a test it appeared to take the snapshots from the container and also reported the TPM.

Hammerdb Log @ Fri Jan 15 10:26:09 EST 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Processing 1000000 transactions with output suppressed...
Vuser 3:Processing 1000000 transactions with output suppressed...
Vuser 1:Rampup 1 minutes complete ...
Vuser 1:Rampup complete, Taking start AWR snapshot.
Vuser 1:Start Snapshot 5 taken at 15 JAN 2021 10:27 of instance RAZCDB1 (1) of database RAZCDB1 (171153594)
Vuser 1:Timing test period of 2 in minutes
Vuser 1:1 ...,
Vuser 1:2 ...,
Vuser 1:Test complete, Taking end AWR snapshot.
Vuser 1:End Snapshot 6 taken at 15 JAN 2021 10:29 of instance RAZCDB1 (1) of database RAZCDB1 (171153594)
Vuser 1:Test complete: view report from SNAPID 5 to 6
Vuser 1:2 Active Virtual Users configured
Vuser 1:TEST RESULT : System achieved 9300 NOPM from 19099 Oracle TPM

But then when generating the report it gave 2 options for the AWR_ROOT and the AWR_PDB, listing the AWR_PDBs showed the following (and generating the snapshot gave the correct data).

Specify the location of AWR Data
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
AWR_ROOT - Use AWR data from root (default)
AWR_PDB - Use AWR data from PDB
Enter value for awr_location: AWR_PDB

Listing all Completed Snapshots
Instance     DB Name	  Snap Id	Snap Started	Snap Level
------------ ------------ ---------- ------------------ ----------

RAZCDB1      RAZCDB1		  1  15 Jan 2021 10:18	  1
				  2  15 Jan 2021 10:20	  1
				  3  15 Jan 2021 10:23	  1
				  4  15 Jan 2021 10:25	  1
				  5  15 Jan 2021 10:27	  1
				  6  15 Jan 2021 10:29	  1


WORKLOAD REPOSITORY PDB report (PDB snapshots)

DB Name         DB Id    Unique Name DB Role          Edition Release    RAC CDB
------------ ----------- ----------- ---------------- ------- ---------- --- ---
RAZCDB1        171153594 RAZCDB1     PRIMARY          EE      19.0.0.0.0 NO  YES

Instance     Inst Num Startup Time
------------ -------- ---------------
RAZCDB1             1 15-Jan-21 09:28

Container DB Id  Container Name       Open Time
--------------- --------------- ---------------
      171153594 RAZPDB1         15-Jan-21 09:29

Whereas listing the container showed no snapshots from the workload.

Listing all Completed Snapshots
Instance     DB Name	  Snap Id	Snap Started	Snap Level
------------ ------------ ---------- ------------------ ----------

RAZCDB1      RAZCDB1		  1  15 Jan 2021 10:00	  1

I'm not completey up to date with what has changed from the previous version and I do notice that the instance name and database name is the same for me whereas in the listing above it is different. However it seemed to work by using the option to report AWR_PDB.

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 20, 2021

Further testing below on pluggable databases on 12c and 19c. On 12c snapshot time and ID is incorrect and TPM is reported as 0. On 19c snapshot time and ID is correct and TPM is reported. Also in selecting option AWR_PDB on 12c no snapshots are taken in the pluggable database on 19c the snapshots are there and report the workload correctly.

It appears that 19c has fixed this issue without requiring any updates to HammerDB and therefore the pull request is not needed.

Oracle Linux 7.5/Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

Hammerdb Log @ Wed Jan 20 11:42:35 GMT 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Processing 1000000 transactions with output suppressed...
Vuser 3:Processing 1000000 transactions with output suppressed...
Vuser 1:Rampup 1 minutes complete ...
Vuser 1:Rampup complete, Taking start AWR snapshot.
Vuser 1:Start Snapshot 724 taken at 14 JAN 2021 16:03 of instance VULCDB1 (1) of database VULCDB1 (1846545596)
Vuser 1:Timing test period of 2 in minutes
Vuser 1:1 ...,
Vuser 1:2 ...,
Vuser 1:Test complete, Taking end AWR snapshot.
Vuser 1:End Snapshot 724 taken at 14 JAN 2021 16:03 of instance VULCDB1 (1) of database VULCDB1 (1846545596)
Vuser 1:Test complete: view report from SNAPID 724 to 724
Vuser 1:2 Active Virtual Users configured
Vuser 1:TEST RESULT : System achieved 46326 NOPM from 0 Oracle TPM

Oracle Linux 8.0/Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production Version 19.3.0.0.0

Hammerdb Log @ Wed Jan 20 06:58:32 EST 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Processing 1000000 transactions with output suppressed...
Vuser 3:Processing 1000000 transactions with output suppressed...
Vuser 1:Rampup 1 minutes complete ...
Vuser 1:Rampup complete, Taking start AWR snapshot.
Vuser 1:Start Snapshot 7 taken at 20 JAN 2021 06:59 of instance RAZCDB1 (1) of database RAZCDB1 (171153594)
Vuser 1:Timing test period of 2 in minutes
Vuser 1:1 ...,
Vuser 1:2 ...,
Vuser 1:Test complete, Taking end AWR snapshot.
Vuser 1:End Snapshot 8 taken at 20 JAN 2021 07:01 of instance RAZCDB1 (1) of database RAZCDB1 (171153594)
Vuser 1:Test complete: view report from SNAPID 7 to 8
Vuser 1:2 Active Virtual Users configured
Vuser 1:TEST RESULT : System achieved 6691 NOPM from 13042 Oracle TPM

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 25, 2021

I have double checked this by creating a new pluggable database and the behaviour is the same as above, the workload creates the AWR snapshots and reports the TPM correctly in the pluggable database without any modification to HammerDB.

Note: I am using DBCA to create a new pluggable database from the seed database so there may be something different in the way it is created that enables this to work?

Something that is different is the views DBA_HIST_SNAPSHOT and DBA_HIST_SYSSTAT that HammerDB queries have different definitions from version 12.2.0.1.0 to 19.3.0.0.0, the former using AWR_ROOT_SNAPSHOT and the latter AWR_CDB_
SNAPSHOT so there is definitely something different in how this works.

The current standing is that it is not currently possible to get HammerDB v4.0 to NOT work against a pluggable database as was tested in 12.2. It will be necessary to do this to be able to verify a fix.

Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production Version 19.3.0.0.0
SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SNAPSHOT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STARTUP_TIME","BEGIN_INTERVAL_TIME","
END_INTERVAL_TIME","FLUSH_ELAPSED","SNAP_LEVEL","ERROR_COUNT","SNAP_FLAG","SNAP_
TIMEZONE","BEGIN_INTERVAL_TIME_TZ","END_INTERVAL_TIME_TZ","CON_ID" from AWR_CDB_
SNAPSHOT

SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SYSSTAT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STAT_ID","STAT_NAME","VALUE","CON_DBI
D","CON_ID" from AWR_CDB_SYSSTAT
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0

SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SNAPSHOT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STARTUP_TIME","BEGIN_INTERVAL_TIME","
END_INTERVAL_TIME","FLUSH_ELAPSED","SNAP_LEVEL","ERROR_COUNT","SNAP_FLAG","SNAP_
TIMEZONE","CON_ID" from AWR_ROOT_SNAPSHOT

SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SYSSTAT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STAT_ID","STAT_NAME","VALUE","CON_DBI
D","CON_ID" from AWR_ROOT_SYSSTAT

@dfhawthorne
Copy link
Contributor Author

dfhawthorne commented Jan 26, 2021

As requested in the PR, my results are:

Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.9.0.0.0

SQL> show user
USER is "SYSTEM"
SQL> show con_name

CON_NAME
------------------------------
CDB$ROOT
SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SNAPSHOT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STARTUP_TIME","BEGIN_INTERVAL_TIME","
END_INTERVAL_TIME","FLUSH_ELAPSED","SNAP_LEVEL","ERROR_COUNT","SNAP_FLAG","SNAP_
TIMEZONE","BEGIN_INTERVAL_TIME_TZ","END_INTERVAL_TIME_TZ","CON_ID" from AWR_CDB_
SNAPSHOT


SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SYSSTAT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STAT_ID","STAT_NAME","VALUE","CON_DBI
D","CON_ID" from AWR_CDB_SYSSTAT


SQL> alter session set container=tpcv3r3a;

Session altered.

SQL> show user
USER is "SYSTEM"
SQL> show con_name

CON_NAME
------------------------------
TPCV3R3A
SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SNAPSHOT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STARTUP_TIME","BEGIN_INTERVAL_TIME","
END_INTERVAL_TIME","FLUSH_ELAPSED","SNAP_LEVEL","ERROR_COUNT","SNAP_FLAG","SNAP_
TIMEZONE","BEGIN_INTERVAL_TIME_TZ","END_INTERVAL_TIME_TZ","CON_ID" from AWR_CDB_
SNAPSHOT


SQL> select text_vc from dba_views where view_name = 'DBA_HIST_SYSSTAT';

TEXT_VC
--------------------------------------------------------------------------------
select "SNAP_ID","DBID","INSTANCE_NUMBER","STAT_ID","STAT_NAME","VALUE","CON_DBI
D","CON_ID" from AWR_CDB_SYSSTAT

I cannot see any difference in the view definitions.

We appear to be at different patch levels. Mine is:

Patch Description: Database Release Update : 19.9.0.0.201020 (31771877)

@dfhawthorne
Copy link
Contributor Author

There are no obvious fixes listed in "Database 19 Release Updates and Revisions Bugs Fixed Lists (Doc ID 2523220.1)" that could explain the differences in behaviour seen between 19.3 and 19.9.

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 27, 2021

I have upgraded to Version 19.10.0.0.0 and still see the same behaviour i.e. the snapshots are taken and TPM reported without modification. The documentation also suggests that this is the correct behaviour:
Managing Automatic Workload Repository in a Multitenant Environment
However I checked the documentation for 12.2.0.1 and the documentation is the same as above suggesting that this should also work, however for me 12.2 doesn't. I created a new PDB with DBCA to be sure and here you do not get the correct data in DBA_HIST_SNAPSHOT. More investigation is needed to find the cause of the different behaviour.

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 28, 2021

It looks like I am seeing the correct behaviour according to this document from Oracle Support.
DBA_HIST_SYSSTAT is Different Output at CDB and PDB Level (Doc ID 2711623.1)

In this earlier document Oracle Multitenant: New Features it confirms that since 12.2 we get "Automatic Workload Repository (AWR) Data at PDB Level" but as per issue #13 "Oracle 12.2 introduced new view AWR_PDB_SNAPSHOT that broke TPM reporting and reports value as 0". HammerDB queries CDB wide DBA_HIST_SNAPSHOT." so we expect snapshots to work in 12.2 but not be able to query them from DBA_HIST_SNAPSHOT and that is what I am seeing in testing 12.2.

However Doc ID 2711623.1 says that from 18.1, dba_hist views do include the PDB level information and explicitly says that you don't need to query over awr_pdb_sysstat to get this. This is why I am seeing the TPM reported at the end of the workload in 19c (but not 12c). So what this document is saying I am seeing in 19c. HammerDB queries the DBA_HIST views and this does work in a PDB. Therefore HammerDB should not need a workaround for 19c as this functionality was added into Oracle from 18.1. It looks like you have an additional issue in Oracle that is preventing the expected functionality from working - for example a profile can disable AWR in a PDB.

@dfhawthorne
Copy link
Contributor Author

The problem I see originates from differing AWR snapshot collection settings between the PDB and CDB.

The original code seems to assume that the AWR snapshot number for the PDB will always be ahead of that for the CDB.

Connection

I am looking at the PDB data using the SYSTEM user:

USER is "SYSTEM"
CON_NAME 
------------------------------
TPCV3R3A

Latest 60 AWR Snapshots

The latest 60 AWR Snapshots are:

SQL> SELECT
  2        rownum,
  3        con_id,
  4        instance_number,
  5        instance_name,
  6        db_name,
  7        dbid,
  8        snap_id,
  9        to_char(end_interval_time, 'DD MON YYYY HH24:MI')
 10    FROM
 11        (
 12            SELECT
 13                di.instance_number,
 14                di.instance_name,
 15                di.db_name,
 16                di.dbid,
 17                ds.snap_id,
 18                ds.end_interval_time,
 19                di.con_id
 20            FROM
 21                dba_hist_snapshot            ds,
 22                dba_hist_database_instance   di
 23            WHERE
 24                ds.dbid = di.dbid
 25                AND ds.instance_number = di.instance_number
 26                AND ds.startup_time = di.startup_time
 27            ORDER BY
 28                ds.snap_id DESC
 29        )
 30    WHERE
 31        ROWNUM <= 60;

    ROWNUM     CON_ID INSTANCE_NUMBER INSTANCE_NAME    DB_NAME         DBID    SNAP_ID TO_CHAR(END_INTERVAL_TIME,
---------- ---------- --------------- ---------------- --------- ---------- ---------- --------------------------
         1          0               1 DEMO19C          DEMOCDB1  1860701772        184 29 JAN 2021 07:00         
         2          0               1 DEMO19C          DEMOCDB1  1860701772        183 29 JAN 2021 06:18         
         3          0               1 DEMO19C          DEMOCDB1  1860701772        182 28 JAN 2021 21:00         
         4          0               1 DEMO19C          DEMOCDB1  1860701772        181 28 JAN 2021 20:00         
         5          0               1 DEMO19C          DEMOCDB1  1860701772        180 28 JAN 2021 19:00         
         6          0               1 DEMO19C          DEMOCDB1  1860701772        179 28 JAN 2021 18:00         
         7          0               1 DEMO19C          DEMOCDB1  1860701772        178 28 JAN 2021 17:00         
         8          0               1 DEMO19C          DEMOCDB1  1860701772        177 28 JAN 2021 16:00         
         9          0               1 DEMO19C          DEMOCDB1  1860701772        176 28 JAN 2021 15:00         
        10          0               1 DEMO19C          DEMOCDB1  1860701772        175 28 JAN 2021 14:00         
        11          0               1 DEMO19C          DEMOCDB1  1860701772        174 28 JAN 2021 13:00         

    ROWNUM     CON_ID INSTANCE_NUMBER INSTANCE_NAME    DB_NAME         DBID    SNAP_ID TO_CHAR(END_INTERVAL_TIME,
---------- ---------- --------------- ---------------- --------- ---------- ---------- --------------------------
        12          0               1 DEMO19C          DEMOCDB1  1860701772        173 28 JAN 2021 11:42         
        13          0               1 DEMO19C          DEMOCDB1  1860701772        172 28 JAN 2021 11:27         
        14          0               1 DEMO19C          DEMOCDB1  1860701772        171 28 JAN 2021 11:25         
        15          0               1 DEMO19C          DEMOCDB1  1860701772        170 28 JAN 2021 11:09         
        16          0               1 DEMO19C          DEMOCDB1  1860701772        169 28 JAN 2021 11:07         
        17          0               1 DEMO19C          DEMOCDB1  1860701772        168 28 JAN 2021 10:51         
        18          0               1 DEMO19C          DEMOCDB1  1860701772        167 28 JAN 2021 10:49         
        19          0               1 DEMO19C          DEMOCDB1  1860701772        166 28 JAN 2021 10:34         
        20          0               1 DEMO19C          DEMOCDB1  1860701772        165 28 JAN 2021 10:32         
        21          0               1 DEMO19C          DEMOCDB1  1860701772        164 28 JAN 2021 10:17         
        22          0               1 DEMO19C          DEMOCDB1  1860701772        163 28 JAN 2021 10:14         

    ROWNUM     CON_ID INSTANCE_NUMBER INSTANCE_NAME    DB_NAME         DBID    SNAP_ID TO_CHAR(END_INTERVAL_TIME,
---------- ---------- --------------- ---------------- --------- ---------- ---------- --------------------------
        23          0               1 DEMO19C          DEMOCDB1  1860701772        162 28 JAN 2021 09:59         
        24          0               1 DEMO19C          DEMOCDB1  1860701772        161 28 JAN 2021 09:56         
        25          0               1 DEMO19C          DEMOCDB1  1860701772        160 28 JAN 2021 09:41         
        26          0               1 DEMO19C          DEMOCDB1  1860701772        159 28 JAN 2021 09:38         
        27          0               1 DEMO19C          DEMOCDB1  1860701772        158 28 JAN 2021 09:23         
        28          0               1 DEMO19C          DEMOCDB1  1860701772        157 28 JAN 2021 09:21         
        29          0               1 DEMO19C          DEMOCDB1  1860701772        156 28 JAN 2021 09:05         
        30          0               1 DEMO19C          DEMOCDB1  1860701772        155 28 JAN 2021 09:01         
        31          0               1 DEMO19C          DEMOCDB1  1860701772        154 28 JAN 2021 08:45         
        32          0               1 DEMO19C          DEMOCDB1  1860701772        153 27 JAN 2021 21:00         
        33          0               1 DEMO19C          DEMOCDB1  1860701772        152 27 JAN 2021 20:00         

    ROWNUM     CON_ID INSTANCE_NUMBER INSTANCE_NAME    DB_NAME         DBID    SNAP_ID TO_CHAR(END_INTERVAL_TIME,
---------- ---------- --------------- ---------------- --------- ---------- ---------- --------------------------
        34          0               1 DEMO19C          DEMOCDB1  1860701772        151 27 JAN 2021 19:00         
        35          0               1 DEMO19C          DEMOCDB1  1860701772        150 27 JAN 2021 18:00         
        36          0               1 DEMO19C          DEMOCDB1  1860701772        149 27 JAN 2021 17:00         
        37          0               1 DEMO19C          DEMOCDB1  1860701772        148 27 JAN 2021 16:00         
        38          0               1 DEMO19C          DEMOCDB1  1860701772        147 27 JAN 2021 15:01         
        39          0               1 DEMO19C          DEMOCDB1  1860701772        146 27 JAN 2021 14:00         
        40          0               1 DEMO19C          DEMOCDB1  1860701772        145 27 JAN 2021 13:00         
        41          0               1 DEMO19C          DEMOCDB1  1860701772        144 27 JAN 2021 12:00         
        42          0               1 DEMO19C          DEMOCDB1  1860701772        143 27 JAN 2021 11:00         
        43          0               1 DEMO19C          DEMOCDB1  1860701772        142 27 JAN 2021 10:01         
        44          0               1 DEMO19C          DEMOCDB1  1860701772        141 27 JAN 2021 08:44         

    ROWNUM     CON_ID INSTANCE_NUMBER INSTANCE_NAME    DB_NAME         DBID    SNAP_ID TO_CHAR(END_INTERVAL_TIME,
---------- ---------- --------------- ---------------- --------- ---------- ---------- --------------------------
        45          0               1 DEMO19C          DEMOCDB1  1860701772        140 24 JAN 2021 15:15         
        46          0               1 DEMO19C          DEMOCDB1  1860701772        139 24 JAN 2021 15:00         
        47          0               1 DEMO19C          DEMOCDB1  1860701772        138 24 JAN 2021 14:58         
        48          0               1 DEMO19C          DEMOCDB1  1860701772        137 24 JAN 2021 14:43         
        49          0               1 DEMO19C          DEMOCDB1  1860701772        136 24 JAN 2021 14:40         
        50          0               1 DEMO19C          DEMOCDB1  1860701772        135 24 JAN 2021 14:25         
        51          0               1 DEMO19C          DEMOCDB1  1860701772        134 24 JAN 2021 14:22         
        52          0               1 DEMO19C          DEMOCDB1  1860701772        133 24 JAN 2021 14:07         
        53          0               1 DEMO19C          DEMOCDB1  1860701772        132 24 JAN 2021 14:04         
        54          0               1 DEMO19C          DEMOCDB1  1860701772        131 24 JAN 2021 13:49         
        55          0               1 DEMO19C          DEMOCDB1  1860701772        130 24 JAN 2021 13:46         

    ROWNUM     CON_ID INSTANCE_NUMBER INSTANCE_NAME    DB_NAME         DBID    SNAP_ID TO_CHAR(END_INTERVAL_TIME,
---------- ---------- --------------- ---------------- --------- ---------- ---------- --------------------------
        56          0               1 DEMO19C          DEMOCDB1  1860701772        129 24 JAN 2021 13:31         
        57          0               1 DEMO19C          DEMOCDB1  1860701772        128 24 JAN 2021 13:28         
        58          0               1 DEMO19C          DEMOCDB1  1860701772        127 24 JAN 2021 13:13         
        59          3               1 DEMO19C          DEMOCDB1   987761581        127 29 JAN 2021 06:28         
        60          0               1 DEMO19C          DEMOCDB1  1860701772        126 24 JAN 2021 13:10         

60 rows selected. 

The first available AWR snapshot for the PDB (CON_ID=3) is at row number 59.

AWR Snapshot Settings

My AWR settings are different between the PDB and CDB. The AWR snapshot interval for the PDB is much longer that for the CDB:

SQL> SELECT
  2      src_dbname,
  3      snap_interval,
  4      retention
  5  FROM
  6      dba_hist_wr_control;

SRC_DBNAME    SNAP_INTERVAL          RETENTION
------------- ---------------------- ----------------------
CDB$ROOT      +00 01:00:00.000000000 +08 00:00:00.000000000
TPCV3R3A      +40150 00:01:00.000000 +21960 00:00:00.000000

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 29, 2021

OK, great I can reproduce now in 19c. If I advance the CDB snap ids ahead of the PDB then the query to find the snapshots grabs the latest CDB snap id as DBA_HIST_SNAPSHOT from a PDB shows both the CDB and PDB snapshots and orders them by snap id. Therefore the query returns the latest CDB snap id twice.

So as a simpler solution we can instead list the snapshots by END_INTERVAL_TIME, rather than SNAP_ID, so the query would change to the following meaning only the order by clause has changed.
SELECT INSTANCE_NUMBER, INSTANCE_NAME, DB_NAME, DBID, SNAP_ID, TO_CHAR(END_INTERVAL_TIME,'DD MON YYYY HH24:MI') FROM (SELECT DI.INSTANCE_NUMBER, DI.INSTANCE_NAME, DI.DB_NAME, DI.DBID, DS.SNAP_ID, DS.END_INTERVAL_TIME FROM DBA_HIST_SNAPSHOT DS, DBA_HIST_DATABASE_INSTANCE DI WHERE DS.DBID=DI.DBID AND DS.INSTANCE_NUMBER=DI.INSTANCE_NUMBER AND DS.STARTUP_TIME=DI.STARTUP_TIME ORDER BY DS.END_INTERVAL_TIME DESC) WHERE ROWNUM=1
In testing this works on 19c even when the CDB snap ids are higher. Theoretically there is a very slim chance that the CDB could take a snapshot at almost exactly the same time (but fractionally later) as HammerDB does in the PDB. However in HammerDB the 2 statements are consecutive, 'take the snapshot' then 'query the snapshot' so this is going to very unlikely, querying the most recent snapshot after just taking one should give us the latest one taken in the PDB being tested. If the CDB takes a snapshot during a test this will not have an impact as HammerDB stores the PDB start and end snap ids when they are queried just after they are taken at the start and end. The advantage is that this does not have a dependence on a particular version so will work on 18c as well as 19c (if Doc ID 2711623.1 is correct). Also as clearly Oracle have changed this functionality (how the DBA_HIST_* views work in a PDB) a number of times and it does not seem to have been documented anywhere then this is likely to be a more future proof solution that will work for single instance, RAC and pluggable for 21c and beyond as well.
Note that I have tested in 12.2 and this is still consistent with 2711623.1 in that this change doesn't work (as would be expected) so it would be expected to only work from 18.1 which would be acceptable. In 12c you would need to connect system to the CDB.
This is a change I would be fine in accepting as having minimal potential disruption.

@dfhawthorne
Copy link
Contributor Author

Commit 8748981 pushed with suggested change.

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 30, 2021

There is a comment in #190, this change is good but the statement also appears in the asnychronous timed script so the change needs to be made there as well. This was really good troubleshooting to pinpoint the SNAP_ID ordering especially as the Oracle dcoumentation is incredibly sparse around the changes to the DBA_HIST_* views in PDBs.

dfhawthorne added a commit to dfhawthorne/HammerDB that referenced this issue Jan 30, 2021
@dfhawthorne
Copy link
Contributor Author

Test script is:

diset tpcc async_scale true
diset tpcc ora_driver timed
loadscript
vuset vu 1
vucreate
vurun

Confirmed error with async mode:

Vuser 1:RUNNING
Vuser 1:Beginning rampup time of 2 minutes
Vuser 2:RUNNING
Vuser 2:Started asynchronous clients:vuser2:ac1 vuser2:ac2 vuser2:ac3 vuser2:ac4 vuser2:ac5 vuser2:ac6 vuser2:ac7 vuser2:ac8 vuser2:ac9 vuser2:ac10

hammerdb>Vuser 1:Rampup 1 minutes complete ...
Vuser 1:Rampup 2 minutes complete ...
Vuser 1:Rampup complete, Taking start AWR snapshot.
Vuser 1:Start Snapshot 213 taken at 31 JAN 2021 08:45 of instance DEMO19C (1) of database DEMOCDB1 (1860701772)
Vuser 1:Timing test period of 5 in minutes
Vuser 1:1 ...,
Vuser 1:2 ...,
Vuser 1:3 ...,
Vuser 1:4 ...,
Vuser 1:5 ...,
Vuser 1:Test complete, Taking end AWR snapshot.
Vuser 1:End Snapshot 213 taken at 31 JAN 2021 08:45 of instance DEMO19C (1) of database DEMOCDB1 (1860701772)
Vuser 1:Test complete: view report from SNAPID 213 to 213
Vuser 1:1 VU * 10 AC = 10 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 13 NOPM from 0 Oracle TPM
Vuser 1:FINISHED SUCCESS
Vuser 2:All asynchronous clients complete
Vuser 2:FINISHED SUCCESS
ALL VIRTUAL USERS COMPLETE

After fix is applied, the error is corrected:

Vuser 1:Rampup 1 minutes complete ...
Vuser 1:Rampup 2 minutes complete ...
Vuser 1:Rampup complete, Taking start AWR snapshot.
Vuser 1:Start Snapshot 134 taken at 31 JAN 2021 09:31 of instance DEMO19C (1) of database DEMOCDB1 (987761581)
Vuser 1:Timing test period of 5 in minutes
Vuser 1:1 ...,
Vuser 1:2 ...,
Vuser 1:3 ...,
Vuser 1:4 ...,
Vuser 1:5 ...,
Vuser 1:Test complete, Taking end AWR snapshot.
Vuser 1:End Snapshot 135 taken at 31 JAN 2021 09:36 of instance DEMO19C (1) of database DEMOCDB1 (987761581)
Vuser 1:Test complete: view report from SNAPID 134 to 135
Vuser 1:1 VU * 10 AC = 10 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 11 NOPM from 28 Oracle TPM
Vuser 1:FINISHED SUCCESS
Vuser 2:All asynchronous clients complete
Vuser 2:FINISHED SUCCESS
ALL VIRTUAL USERS COMPLETE

Now the correct AWR snap IDs are reported, and the Oracle TPM is calculated correctly.

Confirmed that change did not regress the fix for SYNC mode:

Vuser 1:RUNNING
Vuser 1:Beginning rampup time of 2 minutes
Vuser 2:RUNNING
Vuser 2:Processing 1000000 transactions with output suppressed...

hammerdb>Vuser 1:Rampup 1 minutes complete ...
Vuser 1:Rampup 2 minutes complete ...
Vuser 1:Rampup complete, Taking start AWR snapshot.
Vuser 1:Start Snapshot 136 taken at 31 JAN 2021 09:58 of instance DEMO19C (1) of database DEMOCDB1 (987761581)
Vuser 1:Timing test period of 5 in minutes
Vuser 1:1 ...,
Vuser 1:2 ...,
Vuser 1:3 ...,
Vuser 1:4 ...,
Vuser 1:5 ...,
Vuser 1:Test complete, Taking end AWR snapshot.
Vuser 1:End Snapshot 137 taken at 31 JAN 2021 10:03 of instance DEMO19C (1) of database DEMOCDB1 (987761581)
Vuser 1:Test complete: view report from SNAPID 136 to 137
Vuser 1:1 Active Virtual Users configured
Vuser 1:TEST RESULT : System achieved 685 NOPM from 1444 Oracle TPM
Vuser 1:FINISHED SUCCESS
Vuser 2:FINISHED SUCCESS
ALL VIRTUAL USERS COMPLETE

@sm-shaw
Copy link
Contributor

sm-shaw commented Jan 31, 2021

Excellent, this all looks good now. Many thanks, accepting PR.

sm-shaw pushed a commit that referenced this issue Jan 31, 2021
* Get correct AWR Snap IDs for PDB under 19C
Under Oracle 19C, there are separate AWR repositories for the CDB and each PDB.
These repositories can be distinguished by CON_ID.
This patch adds extra code if the major DB version is 19 or greater.
This extra code extracts the CON_ID for the current PDB from the
SYS_CONTEXT('USERENV','CON_ID') function call.

* Corrected Wrong CON_ID in AWR Snapshots for Root

When connected to the root container (CDB$ROOT) in an Oracle multi-tenant database instance, the value returned by the SYS_CONTEXT('USERENV','CON_ID') call is one (1).

However, the value of CON_ID in the DBA_HIST_DATABASE_INSTANCE for AWR snapshots taken while connected to root container is zero (0).

For PDBs, these values are equal.

* Simpler solution using time stamps
Future proofing against possible changes.
There is a very small chance of a race condition between CDB and PDB AWR snapshots.
See #188 for further discussion and analysis.

* Fixed for ASYNC as well for #189
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants