Troubleshooting Masking Performance In-Place Oracle (KBA5985)

Key items 

The key elements to look for in the AWR report are: 

1. 'Report Details' - the time period of the AWR report.
2. Fore/Background Wait Events
3. SQL ordered by Elapsed Time
4. SQL ordered by CPU
5. SQL ordered by Gets
6. SQL ordered by Executions
7. SQL ordered by Read
8. Complete List of SQL Text
9. Other key values

 

Notes: 

• In the 'SQL ordered by' sections above, we can only see Reads since Oracle manages Writes behind the scene and if this is an issue, please consult your Oracle DBA.
• The number of Update Threads is not affect the AWR report (the number of rows is still COMMIT SIZE (default 10,000) per Commit).

1. Report Details

Verify that the AWR report covers the correct time period by checking: 

• Begin Snap and End Snap time
• Elapsed time

Example

 

---

2. Fore/Background Wait Events

The second step is to check 'Foreground Wait Events' and 'Background Wait Events'. This might indicate Wait Events that may slow the UPDATE performance, as these are Events performed in the background on Oracle.

Check:

• Total Wait Time (compare that with the AWR time period)
• Avg wait 

Check with your DBA for tuning recommendations. 

 

Example

• The image below is just an example of what the list looks like - events will differ.

Foreground Wait Events

Background Wait Events

---

3. SQL ordered by Elapsed Time

This indicates SQL statements by Elapsed Time - slow performance means longer Elapsed Time. Fast SQL statements might not be included in the list.

Check:

• Elapsed Time
• SQL Text (and check SQL Id to see full SQL statement)

Should the SELECT top the list then this is likely the bottleneck and SQL tuning is needed (check execution plan). For example, this can be caused by a WHERE clause on a column that is not indexed.

Example

• The example below shows Elapsed Times from a good execution.
• In this case, all three queries that are used by the masking job are shown.

---

4. SQL ordered by CPU

'SQL ordered by CPU' will indicate which SQL statement is taking the most Oracle CPU time. If the masking-generated SQL statements are not at the top - this indicates that Oracle is busy processing other queries. 

'Update' should be at the top.

Check:

• CPU Time (s)
• % Total

Example

5. SQL ordered by Gets

Buffer Gets is a good estimate of the number of rows masked for the UPDATE statement. Each record updated will require 1 Buffer Gets (there will be some extra). SELECT will likely (and hopefully) perform a Full Table Scan (in that case the SELECT will retrieve multiple records per Buffer Gets). 

Check:

• UPDATE
  • Buffer Gets (eg. 9,262,372) - A good estimate of the number of rows masked (the actual number of records in this table is 9 million).
  • Executions (eg. 900) - This is the number of Commits performed.
  • Elapsed Time (eg. 46.24 sec) - Time the database spent on Foreground Tasks updating the records¹.
     
• SELECT and SELECT COUNT
  • Buffer Gets (eg. 43,520) - around 1 Buffer Gets per Block.
  • Elapsed Time - The time the database spent on executing these SQL statements.
  • Executions (eg. 1) - Confirmation only - should always be 1.
    
     

Note¹: Elapsed Time excludes Background Events and time outside the database (for example network latency). 

6. SQL ordered by Executions

This view will only have SQL statements with a lot of executions (like the Update). This view will show the number of records (rows) processed.

• UPDATE
  • Executions (eg. 900) - This is the number of Commits performed.
  • Rows Processed (eg. 9,000,000) - This is the total number of rows updated.
  • Rows per Exec (eg. 10,000) - This should be the same as the Commit Size. 
     
• SELECT and SELECT COUNT
  • Note: Usually not listed here as 'SELECT' and 'SELECT COUNT' will only have 1 execution. 

7. SQL ordered by Reads

This indicates how many blocks were read via physical reads (not in the buffer cache) per statement.

Key measurements:

• SELECT and SELECT COUNT
  • Physical Reads - Reading and counting the records, there should be 1 Physical Read per block (could be less if there is an Index Scan).
  • The data is stored in x number of blocks and the engine required x blocks to read the data (unless there is a WHERE clause).
     
• UPDATE
  • Physical Reads - This is likely less than the number of blocks for the table (as blocks could be in SGA (memory)).
  • Note: Indexes on masked columns will result in a much larger number of Reads and could be a root cause of performance issues.

 

---

8. Complete List of SQL Text

The section 'Complete List of SQL Text' should include the following SQL statements from the masked table. 

The masking job will uses these three SQL statements per table:

• SELECT COUNT - this is the SQL counting the number of rows to mask.
• SELECT - this is the SQL for the 'Table input' step.
• UPDATE - this is the SQL for 'Update' step. 

9. Other key values

These are some important wait events and statistics and what they mean. Small numbers will usually indicate that they are not significant (what is a small or large number and if they are significant depends on your Oracle environment). 

• 'db file sequential read' means an Index was used. 
• 'db file scattered read' indicates a 'Full Table Scan' (see below as well).
• 'control file sequential read' could indicate that a backup is running at the same time.
• 'table fetch continued row' - indicates chained or migrated rows (aka data fragmentation). 

 

Other sections:

• 'Segment Statistics' - in this section, you should see your table - but look out for INDEX as this indicates an index fast full scan.
  • 'Segments by Table Scans' - for most of the jobs - Oracle should do a full Table Scan.

SELECT and UPDATE Performance Graph

By temporarily setting the Feedback Size = Commit Size to 10,000 and Row Limit = 200,000, the execution can be illustrated in a graph. This graph shows the performance as the buffers fill up and this will indicate the bottleneck.

An illustration of this can be seen below, which shows the job above. The graph shows the relative performance compared with the rpm of the overall masking job.

 

The characteristics are: 

• The SELECT performance is initially the max performance that can be fetched from the database. 
• As soon as the records start to appear and are masked they will be sent to the UPDATE step.
• The UPDATE performance is seen as soon as records are available to be updated.
• The SELECT will be at max speed until the initial buffers are full (around 20,000 - 30,0000 rows).
• The performance is then (in this case) capped to the performance of the masking operation.
• When all (relevant) buffers are full the SELECT step will be forced to the same performance as the UPDATE step.

Examples of Bottlenecks and Actions

No masking job is exactly the same and the characteristics will differ. With that said, the bottleneck can be identified in one of three areas. 

These areas are (with example graphs below):

Check 1 - Network performance

Ping the Masking Engine from the Oracle Server and collect latency data. Run this a few times to get a good average value for the latency.

ping Your_Masking_Engine

Check 2 - Collect trace file and timing data

To know how fast Oracle can perform the statements on the database, we need to enable tracing and collect some data. 

To collect the data, run the statement in the commands below:

• If possible, flush the cache and the shared pool before testing. 
• Use SQLPLUS or another tool and log in as sysdba.
• Set up tracing and make note of the trace file name.
• Run the statements below for the Read and the Update.
• Exit SQLPLUS.
• Run tkprof on the collected trace file. 

 

Flush cache and pool (requires dba)

alter system flush buffer_cache;
alter system flush shared_pool;
connect / as sysdba
set autotrace on statistics

Collecting the data

oradebug setmypid
oradebug tracefile_name
alter session set sql_trace=true;
set timing on
[Your Performance Statements]
exit
tkprof Your_Trace_File_From_Above.trc

Check 3 - SELECT Performance

The SELECT is here encapsulated in a SELECT COUNT to reduce the output size. 

Actions

• Change YOUR_TABLE to the table to test.
• Take note of the number of records.
• Take note of the duration to complete this statement (in milliseconds).

Performance Statement

select count(*) from (select rowid from USER.YOUR_TABLE);

Database performance estimates 

With the metadata above, the select performance can be calculated (note that this is the performance on the database and excludes network latency and java processing times): 

• SELECT rpm: RowCount / Duration * 1000 * 60
• SELECT bpm: UsedBlocks / Duration * 1000 * 60

Check 4 - UPDATE Performance 

The UPDATE performance is usually slower and the likely bottleneck. It is also harder to measure this as we can either do the test with UPDATE only (will be faster) or use a cursor with SELECT which will measure UPDATE and SELECT.

Actions

• Modify and use the SQL below.
• Change YOUR_TABLE to the table to test.
• Change MASKED_COL to the masked column (add multiple if multiple columns are masked).
• Take note of the number of records.
• Take note of the duration to complete this statement (in milliseconds). 

 

Warning:

Ensure there is enough UNDO to complete this DML. 

 

Performance Statement (simple)

update USER.YOUR_TABLE set MASKED_COL = MASKED_COL WHERE ROWNUM < 500000;

 

Performance Statement (alternative using cursor)

• Modify the datatype for 'my_col1' to match one of the columns.
• For multiple columns add one per column.

DECLARE
   CURSOR c1 is
      select rowid, MASKED_COL from USER.YOUR_TABLE;
   my_col1 VARCHAR2(20);
   my_rowid VARCHAR2(20);
BEGIN
   OPEN c1;
   FOR i IN 1..50 LOOP
   FOR i IN 1..10000 LOOP
      FETCH c1 INTO my_rowid,my_col1;
      EXIT WHEN c1%NOTFOUND;
      update USER.YOUR_TABLE set MASKED_COL=MASKED_COL where rowid=my_rowid;
      COMMIT;
   END LOOP;
   END LOOP;
   CLOSE c1;
END;
/

Database performance estimates 

With the metadata above, the UPDATE performance can be calculated. This includes rpm and bpm (rows and blocks per min) and is the performance on the database, excluding network latency and java processing times: 

• SELECT rpm: RowCount / Duration * 1000 * 60
• SELECT ppm: UsedPages / Duration * 1000 * 60

Reading the trace file data

Example of a trace file. 

• This is from 'SELECT COUNT(*)'
• 'Elapsed' time can be seen (Total). 
• The number of blocks can be seen in 'Fetch'. 
  • 'Disk' will show how many blocks were read from the disk (this might be lower due to cache). 
  • 'Query' will show the actual blocks needed. This is the best value to use.
• The number of rows can be seen in the Masking UI or in the aggregate in the trace file (40,960 in the example below). 

SQL STATEMENT ANALYZED

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.90          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.01       0.22        612        618          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.02       1.12        612        618          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=618 pr=612 pw=0 time=223635 us)
     40960      40960      40960   TABLE ACCESS FULL USERS (cr=618 pr=612 pw=0 time=102571 us cost=173 size=0 card=40960)