Re: Same query with different response time

  • From: Lok P <loknath.73@xxxxxxxxx>
  • To: Jonathan Lewis <jlewisoracle@xxxxxxxxx>
  • Date: Wed, 21 Jul 2021 01:05:29 +0530

I attached here three different sqls one update, one insert and one
select and sql monitor for each of them on Encrypted vs unencrypted
tablespace.  This time i'm not seeing any difference in the number of read
requests , rather it seems in all of the cases it's reading more bytes in
the case of encrypted tablespace as compared to non encrypted tablespace.

So does it mean that , as in case of encrypted objects the size will be
increased a bit for the objects , so this amount of degradation in
performance is expected and we should move ahead with this? Also I think
you also pointed towards 20-30% degradation. And here just to note we are
manually testing a few queries , as we don't have capability to run/test
full application suite on a similar volume database same as production.

*"Since data blocks are encrypted on disc and decrypted for memory then
keeping the working data sets cached becomes more important - my tests
suggested that for operations that were almost pure encryption/decryption
and very little else (e.g. direct path tablescans to filter and aggregated
blocks; insert into into encrypted t/s select from non-encrypted data),
there was (as you have seen) a significant performance impact (20% - 30%)."*

Jonathan, Does your above point means that , pure
encryption/decryption will have ~20-30% of degradation (mostly in a non exa
database), however in an exadata environment , queries doing direct
read/cell offload may suffer lesser? Won't the exadata cell disks have to
decrypt the required data and passon to buffer cache in the same fashion?


On Sat, Jul 17, 2021 at 9:04 AM Lok P <loknath.73@xxxxxxxxx> wrote:

Jonathan, We have created two different tablespaces(with and without
encryption) and are trying to test out the queries but yet to see any
significant difference in execution time/resource consumption in them. So i
was curious to know, as we were seeing the difference in run time here
mainly because of the avg read per request , sometimes they were
128KB/request whereas in other times 1MB/request for similar full segment
scan. So I wanted to understand if it's possible that oracle can opt for
~128KB/request for the same segment full scan at different times , because
of some other factor apart from encryption, say because of different load
in the database/storage server etc?

On Mon, Jun 28, 2021 at 10:23 PM Jonathan Lewis <jlewisoracle@xxxxxxxxx>
wrote:

Forget the application. Test the hypothesis that FIRST_ROWS and TSE do
not behave well together

Do you have a test database (on the same platform).

Create two tablespaces, one with TSE

Copy the same 8GB of data into each tablespace, index as appropriate

Run the tablescan queries you reported on each table - once with
ALL_ROWS, once with whatever FIRST_ROWS_N setting you have (I hope it's not
just first_rows which was deprecated several versions ago). Examine the
session stats and wait events for each execution individually - if
necessary start a new session for each query

Can you see anything in the stats that tells you that first_rows_n uses a
significantly different mechanism from all_rows, and that it uses more CPU
as a side effect. Is this happening in both the TSE and non-TSE
tablespaces; conversely is it the change from non-TSE to TSE that makes a
difference while first_rows and all_rows (on any one tablespace) act the
same way.

If you can conclude that the combination of first_rows_n and TSE
introduce a change in mechanism with significant performance side effects
you can go to your management with the results and ask them to choose
between TSE and FIRST_ROWS, and you can go to Oracle Corp. and tell them
that the combination introduces a side effect.

Regards
Jonathan Lewis





On Mon, 28 Jun 2021 at 17:13, Lok P <loknath.73@xxxxxxxxx> wrote:

Thank You Jonathan.

It is actually a third party database in which the default optimizer
mode has been set as 'first_rows'. This application is mostly relying on
indexed queries, but yes there are queries doing full scan too. I am not
sure if the 128KB request per table scan and no benefit out of cell
offload/storage indexes is just because of FIRST_ROWS optimizer mode. I am
thinking if i should test it using the FULL_ROWS hint, but then the plan
will change and that won't be an apple to apple comparison, correct me if
wrong. I can fetch the details from v$sesstat for these query runs, but yes
I may not be able to get the details of the before TSE version of the
query.

 But yes here the real concern for us is if the TSE is going to add such
an overhead and it's expected or we are missing something.

Regards
Lok


On Mon, Jun 28, 2021 at 5:37 PM Jonathan Lewis <jlewisoracle@xxxxxxxxx>
wrote:


There are four points to investigate in your Monitor repors:

a) Why are your "TABLE ACCESS STORAGE FULL"s  qualified by "FIRST ROWS"
-- this feature may have some bearing on the preformance.
b) Why are your tablescans (before tse) doing an average of about 128KB
per read request while the index fast full scan is going for 1MB ? Is this
related to FIRST ROWS
c) One (and only one) of your tablescans (after tse) using 1MB read
requests - what's different about that one?
d) The buffer gets value is consistent with the "read bytes" in all
cases, which suggests you're not getting any benefit from the storage cells
(cell offload/storage indexes).

Since most of your time difference is in the CPU usage you need to find
out what the session is doing by looking at the session activity stats
(v$sesstat) - it strikes me as perfectly feasible that if you are loading
1M blocks into the buffer cache and then decrypting them before examining
their content then the additional CPU spent decrypting them might easily
double the CPU load. But maybe there's a completely different explanation.

Regards
Jonathan Lewis



On Sat, 26 Jun 2021 at 15:18, Lok P <loknath.73@xxxxxxxxx> wrote:

Hello Listers,  We have seen TSE (tablespace encryption)
implementation in the past in multiple databases but have not verified any
performance aspect of this and we have also not got any complaint and now
this has been mandated by the security team to do it for all the 
databases.
However, we recently migrated one of the database to TSE i.e. tablespace
encryption(Not column level TDE) and it's the lower environment/dev
database, and dev team sent us few sql monitors noting performance
degradation post TSE (some were ~100% slower which we were not expecting).

Attached are a few of the sql monitors which we got , stating the
execution plan is same and volume is same , yet there is significant
increase in response time. So I am not sure if we can validate from the 
sql
monitor report, if the increase in execution time is only because of
tablespace encryption or anything else. So can you please guide me here,
how i can validate from this attached sql monitor if the degraded response
time is because of TSE/tablespace encryption or anything else and how we
can fix this issue?

It's version 19.9.0.0.0 of Oracle.

Regards
Lok


******************** UPDATE *****************


---------- NON TDE----------------

SQL Monitoring Report

SQL Text
------------------------------
update /*+ monitor */ USER_NONTDE.PBR set RL_OID='XXX' where RL_OID='SYSTEM'

Global Information
------------------------------
 Status              :  DONE                     
 Instance ID         :  2                        
 SQL ID              :  4qtkr8gsd38yz            
 SQL Execution ID    :  33554432                 
 Execution Started   :  07/19/2021 05:54:02      
 First Refresh Time  :  07/19/2021 05:54:02      
 Last Refresh Time   :  07/19/2021 05:56:16      
 Duration            :  134s                     
 Module/Action       :  TOAD 12.7.0.121/-        
 Program             :  Toad.exe                 

Global Stats
======================================================================
| Elapsed |   Cpu   |    IO    | Concurrency | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Gets  | Reqs | Bytes |
======================================================================
|     146 |      34 |      112 |        0.00 |     2M | 219K |  13GB |
======================================================================

SQL Plan Monitoring Details (Plan Hash Value=4200455362)
===========================================================================================================================================================
| Id |             Operation             |   Name    |  Rows   | Cost |   Time  
  | Start  | Execs |   Rows   | Read | Read  | Activity | Activity Detail |
|    |                                   |           | (Estim) |      | 
Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |   (# samples) 
  |
===========================================================================================================================================================
|  0 | UPDATE STATEMENT                  |           |         |      |         
1 |     +2 |     1 |        0 |      |       |          |                 |
|  1 |   UPDATE                          | PBR       |         |      |         
2 |     +1 |     1 |        0 |   48 | 384KB |          |                 |
|  2 |    OPTIMIZER STATISTICS GATHERING |           |   49974 | 477K |         
1 |     +2 |     1 |    28710 |      |       |          |                 |
|  3 |     TABLE ACCESS STORAGE FULL     | PBR       |   49974 | 477K |       
134 |     +2 |     1 |    28710 | 219K |  13GB |          |                 |
===========================================================================================================================================================


---------- TDE----------------


SQL Monitoring Report

SQL Text
------------------------------
update /*+ monitor */ USER_TDE.PBR set RL_OID='XXX' where RL_OID='SYSTEM'

Global Information
------------------------------
 Status              :  DONE                     
 Instance ID         :  2                        
 SQL ID              :  c0jxk30g2f83x            
 SQL Execution ID    :  33554432                 
 Execution Started   :  07/19/2021 05:43:20      
 First Refresh Time  :  07/19/2021 05:43:20      
 Last Refresh Time   :  07/19/2021 05:46:17      
 Duration            :  177s                     
 Module/Action       :  TOAD 12.7.0.121/-        
 Program             :  Toad.exe                 

Global Stats
=============================================================================
| Elapsed |   Cpu   |    IO    | Cluster  | PL/SQL  | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Time(s) |  Gets  | Reqs | Bytes |
=============================================================================
|     189 |      67 |      122 |     0.42 |    0.59 |     2M | 220K |  13GB |
=============================================================================

SQL Plan Monitoring Details (Plan Hash Value=4200455362)
===========================================================================================================================================================
| Id |             Operation             |   Name    |  Rows   | Cost |   Time  
  | Start  | Execs |   Rows   | Read | Read  | Activity | Activity Detail |
|    |                                   |           | (Estim) |      | 
Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |   (# samples) 
  |
===========================================================================================================================================================
|  0 | UPDATE STATEMENT                  |           |         |      |         
5 |     +2 |     1 |        0 |      |       |          |                 |
|  1 |   UPDATE                          | PBR       |         |      |         
6 |     +1 |     1 |        0 |   62 | 496KB |          |                 |
|  2 |    OPTIMIZER STATISTICS GATHERING |           |    8863 | 479K |         
5 |     +2 |     1 |    28710 |      |       |          |                 |
|  3 |     TABLE ACCESS STORAGE FULL     | PBR       |    8863 | 479K |       
177 |     +2 |     1 |    28710 | 220K |  13GB |          |                 |
===========================================================================================================================================================


************************* INSERT***************************

--------------NON TDE------------------------------



SQL Text
------------------------------
insert /*+ monitor */ into USER_NONTDE.PADT select * from USER_TDE.PADT where 
rownum < 100001

Global Information
------------------------------
 Status              :  DONE                     
 Instance ID         :  2                        
 SQL ID              :  d2zj2arpj3jku            
 SQL Execution ID    :  33554435                 
 Execution Started   :  07/19/2021 06:21:32      
 First Refresh Time  :  07/19/2021 06:21:32      
 Last Refresh Time   :  07/19/2021 06:21:49      
 Duration            :  17s                      
 Module/Action       :  TOAD 12.7.0.121/-        
 Program             :  Toad.exe                 

Global Stats
=========================================================================================================================================
| Elapsed |   Cpu   |    IO    | Application | Cluster  | Buffer | Read  | Read 
 | Uncompressed |  Offload   |    Offload     |  Cell   |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) |  Gets  | Reqs  | 
Bytes |    Bytes     | Elig Bytes | Returned Bytes | Offload |
=========================================================================================================================================
|      19 |    6.06 |       12 |        0.00 |     0.10 |   327K | 34529 | 
282MB |         11MB |       14MB |           12MB |   9.36% |
=========================================================================================================================================

SQL Plan Monitoring Details (Plan Hash Value=1401731568)
==================================================================================================================================================================
| Id |             Operation             |  Name   |  Rows   | Cost |   Time    
| Start  | Execs |   Rows   | Read  | Read  |  Mem  | Activity | Activity 
Detail |
|    |                                   |         | (Estim) |      | Active(s) 
| Active |       | (Actual) | Reqs  | Bytes | (Max) |   (%)    |   (# samples)  
 |
==================================================================================================================================================================
|  0 | INSERT STATEMENT                  |         |         |      |        16 
|     +2 |     1 |        0 |       |       |     . |          |                
 |
|  1 |   LOAD TABLE CONVENTIONAL         | PADT    |         |      |        16 
|     +2 |     1 |        0 | 34305 | 268MB |     . |          |                
 |
|  2 |    OPTIMIZER STATISTICS GATHERING |         |     66M | 252K |        16 
|     +2 |     1 |     100K |       |       |     . |          |                
 |
|  3 |     COUNT STOPKEY                 |         |         |      |        16 
|     +2 |     1 |     100K |       |       |     . |          |                
 |
|  4 |      TABLE ACCESS STORAGE FULL    | PADT    |     66M | 252K |        16 
|     +2 |     1 |     100K |   224 |  14MB |   7MB |          |                
 |
==================================================================================================================================================================


------------------TDE-----------------------------


SQL Monitoring Report

SQL Text
------------------------------
insert /*+ monitor */ into USER_TDE.PADT_OR select * from USER_TDE.PADT where 
rownum < 100001

Global Information
------------------------------
 Status              :  DONE                     
 Instance ID         :  2                        
 SQL Execution ID    :  33554435                 
 Execution Started   :  07/19/2021 06:20:59      
 First Refresh Time  :  07/19/2021 06:20:59      
 Last Refresh Time   :  07/19/2021 06:21:20      
 Duration            :  21s                      
 Module/Action       :  TOAD 12.7.0.121/-        
 Program             :  Toad.exe                 

Global Stats
=========================================================================================================================================
| Elapsed |   Cpu   |    IO    | Application | Cluster  | Buffer | Read  | Read 
 | Uncompressed |  Offload   |    Offload     |  Cell   |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) |  Gets  | Reqs  | 
Bytes |    Bytes     | Elig Bytes | Returned Bytes | Offload |
=========================================================================================================================================
|      23 |    8.39 |       15 |        0.00 |     0.00 |   356K | 37868 | 
310MB |         11MB |       16MB |           14MB |   9.38% |
=========================================================================================================================================

SQL Plan Monitoring Details (Plan Hash Value=1401731568)
======================================================================================================================================================================
| Id |             Operation             |    Name     |  Rows   | Cost |   
Time    | Start  | Execs |   Rows   | Read  | Read  |  Mem  | Activity | 
Activity Detail |
|    |                                   |             | (Estim) |      | 
Active(s) | Active |       | (Actual) | Reqs  | Bytes | (Max) |   (%)    |   (# 
samples)   |
======================================================================================================================================================================
|  0 | INSERT STATEMENT                  |             |         |      |       
 20 |     +2 |     1 |        0 |       |       |     . |          |            
     |
|  1 |   LOAD TABLE CONVENTIONAL         | PADT_OR     |         |      |       
 21 |     +1 |     1 |        0 | 37604 | 294MB |     . |          |            
     |
|  2 |    OPTIMIZER STATISTICS GATHERING |             |     66M | 252K |       
 20 |     +2 |     1 |     100K |       |       |     . |          |            
     |
|  3 |     COUNT STOPKEY                 |             |         |      |       
 20 |     +2 |     1 |     100K |       |       |     . |          |            
     |
|  4 |      TABLE ACCESS STORAGE FULL    | PADT        |     66M | 252K |       
 20 |     +2 |     1 |     100K |   264 |  16MB |   7MB |          |            
     |
======================================================================================================================================================================



**************************** SELECT****************************

---------------NON TDE----------------------------


SQL Monitoring Report

SQL Text
------------------------------
select /*+ monitor */ /*nontde*/count(*) FROM USER_NONTDE.PRC_ADT F, 
USER_NONTDE.PRC_HST B WHERE F.CID = B.CID

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)          
 Instance ID         :  1                        
 SQL ID              :  9pmtuv407bvd4            
 SQL Execution ID    :  16777216                 
 Execution Started   :  07/20/2021 10:14:53      
 First Refresh Time  :  07/20/2021 10:14:53      
 Last Refresh Time   :  07/20/2021 10:14:55      
 Duration            :  2s                       
 Module/Action       :  SQL*Plus/-               
 Program             :  sqlplus.exe              
 Fetch Calls         :  1                        

Global Stats
===========================================================================
| Elapsed |   Cpu   |    IO    | Cluster  | Fetch | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
===========================================================================
|    1.76 |    0.99 |     0.70 |     0.07 |     1 |  55285 | 1632 |  39MB |
===========================================================================

SQL Plan Monitoring Details (Plan Hash Value=3387689024)
==================================================================================================================================================================
| Id |            Operation             |       Name        |  Rows   | Cost |  
 Time    | Start  | Execs |   Rows   | Read | Read  | Activity | Activity 
Detail |
|    |                                  |                   | (Estim) |      | 
Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |   (# samples) 
  |
==================================================================================================================================================================
|  0 | SELECT STATEMENT                 |                   |         |      |  
       1 |     +2 |     1 |        1 |      |       |          |                
 |
|  1 |   SORT AGGREGATE                 |                   |       1 |      |  
       1 |     +2 |     1 |        1 |      |       |          |                
 |
|  2 |    NESTED LOOPS                  |                   |      5M | 1134 |  
       1 |     +2 |     1 |        0 |      |       |          |                
 |
|  3 |     INDEX STORAGE FAST FULL SCAN | PC_HST1           |      2M | 1060 |  
       1 |     +2 |     1 |       2M |  496 |  30MB |          |                
 |
|  4 |     INDEX RANGE SCAN             | PC_ADT1           |       3 |    1 |  
       2 |     +1 |    2M |        0 | 1136 |   9MB |          |                
 |
==================================================================================================================================================================


----------------------TDE-------------------------------

SQL Monitoring Report

SQL Text
------------------------------
select /*+ monitor */ /*tde*/count(*) FROM USER_TDE.PRC_ADT F, USER_TDE.PRC_HST 
B WHERE F.CID = B.CID

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)          
 Instance ID         :  1                        
 SQL ID              :  1krju1dggunmb            
 SQL Execution ID    :  16777216                 
 Execution Started   :  07/20/2021 10:17:35      
 First Refresh Time  :  07/20/2021 10:17:35      
 Last Refresh Time   :  07/20/2021 10:17:38      
 Duration            :  3s                       
 Module/Action       :  SQL*Plus/-               
 Program             :  sqlplus.exe              
 Fetch Calls         :  1                        

Global Stats
===========================================================================
| Elapsed |   Cpu   |    IO    | Cluster  | Fetch | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
===========================================================================
|    3.35 |    1.83 |     1.51 |     0.02 |     1 |   496K | 3705 |  57MB |
===========================================================================

SQL Plan Monitoring Details (Plan Hash Value=3628189650)
=================================================================================================================================================================
| Id |            Operation             |       Name       |  Rows   | Cost |   
Time    | Start  | Execs |   Rows   | Read | Read  | Activity | Activity Detail 
|
|    |                                  |                  | (Estim) |      | 
Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |   (# samples) 
  |
=================================================================================================================================================================
|  0 | SELECT STATEMENT                 |                  |         |      |   
      1 |     +3 |     1 |        1 |      |       |          |                 
|
|  1 |   SORT AGGREGATE                 |                  |       1 |      |   
      1 |     +3 |     1 |        1 |      |       |          |                 
|
|  2 |    NESTED LOOPS                  |                  |      5M | 1191 |   
      2 |     +2 |     1 |        0 |      |       |          |                 
|
|  3 |     INDEX STORAGE FAST FULL SCAN | PC_HST           |      2M | 1117 |   
      2 |     +2 |     1 |       2M |  542 |  33MB |          |                 
|
|  4 |     INDEX RANGE SCAN             | PC_ADT           |       3 |    1 |   
      3 |     +2 |    2M |        0 | 3163 |  25MB |          |                 
|
=================================================================================================================================================================

Other related posts: