Oracle Transparent Data Encryption Performance. Oracle 12.1.0.2 on Linux 5

 

Some performance test on Oracle TDE.  I have three tables t1, t2 and t3. All three tables have identical data and 1.6M rows. I’m going to come back and visit this a bit more later, but want to get some initial performance numbers out there.

1 RLOCKARD@pdev > desc t1 2 Name Null? Type 3 -------------------------------------- -------- ----------------- 4 ID NOT NULL NUMBER 5 NBR NUMBER 6 7 RLOCKARD@pdev > desc t2 8 Name Null? Type 9 -------------------------------------- -------- ----------------- 10 ID NOT NULL NUMBER 11 NBR NUMBER 12 13 RLOCKARD@pdev > desc t3 14 Name Null? Type 15 -------------------------------------- -------- ----------------- 16 ID NOT NULL NUMBER 17 NBR NOT NULL NUMBER ENCRYPT 18 19 TABLE_NAME TABLESPACE_NAME 20 ------------------------- ------------------------------ 21 REGION USERS 22 T3 USERS 23 T1 DAT 24 PRODUCTS BIG_SENSITIVE 25 T2 BIG_SENSITIVE 26 FNAMES USERS 27 ZIP USERS 28 STORES USERS 29 NETWORKS USERS 30 CUSTOMERS USERS 31 LNAMES USERS 32 ZIP_CODES USERS 33 SALES USERS 34 REGIONS USERS 35 STORE_USERS USERS 36 37 15 rows selected. 38 39 RLOCKARD@pdev > 40

Table T1 resides in the DAT tablespace that is not encrypted.  Selecting sum(nbr) from t1 where nbr between 40 and 45 executed in .27 seconds.  here there are a bunch of direct path reads followed by 188182 microseconds

1 RLOCKARD@pdev > @no_encrypt 2 RLOCKARD@pdev > set timing on 3 RLOCKARD@pdev > alter session set timed_statistics = true; 4 5 Session altered. 6 7 Elapsed: 00:00:00.03 8 RLOCKARD@pdev > alter session set statistics_level = all ; 9 10 Session altered. 11 12 Elapsed: 00:00:00.05 13 RLOCKARD@pdev > alter session set sql_trace = true ; 14 15 Session altered. 16 17 Elapsed: 00:00:00.06 18 RLOCKARD@pdev > alter session set max_dump_file_size=unlimited; 19 20 Session altered. 21 22 Elapsed: 00:00:00.02 23 RLOCKARD@pdev > alter session set tracefile_identifier = owi_trace; 24 25 Session altered. 26 27 Elapsed: 00:00:00.00 28 RLOCKARD@pdev > 29 RLOCKARD@pdev > BEGIN 30 2 dbms_monitor.session_trace_enable (waits=>true); 31 3 END; 32 4 / 33 34 PL/SQL procedure successfully completed. 35 36 Elapsed: 00:00:00.27 37 RLOCKARD@pdev > select sum(nbr) from t1 where nbr between 40 and 45; 38 39 SUM(NBR) 40 ---------- 41 4055760 42 43 1 row selected. 44 45 Elapsed: 00:00:00.27 46 RLOCKARD@pdev > 47 RLOCKARD@pdev > BEGIN 48 2 dbms_monitor.session_trace_disable; 49 3 END; 50 4 / 51 52 PL/SQL procedure successfully completed. 53 54 Elapsed: 00:00:00.01 55

1 WAIT #46912559622408: nam='direct path read' ela= 42 file number=78 first dba=3144 block cnt=8 obj#=92336 tim=1436288730005400 2 WAIT #46912559622408: nam='direct path read' ela= 45 file number=78 first dba=3152 block cnt=8 obj#=92336 tim=1436288730005873 3 WAIT #46912559622408: nam='direct path read' ela= 43 file number=78 first dba=3160 block cnt=8 obj#=92336 tim=1436288730006338 4 WAIT #46912559622408: nam='direct path read' ela= 44 file number=78 first dba=3168 block cnt=8 obj#=92336 tim=1436288730006835 5 WAIT #46912559622408: nam='direct path read' ela= 41 file number=78 first dba=3176 block cnt=8 obj#=92336 tim=1436288730007325 6 WAIT #46912559622408: nam='direct path read' ela= 45 file number=78 first dba=3184 block cnt=8 obj#=92336 tim=1436288730007807 7 WAIT #46912559622408: nam='direct path read' ela= 42 file number=78 first dba=3192 block cnt=8 obj#=92336 tim=1436288730008267 8 WAIT #46912559622408: nam='direct path read' ela= 38 file number=78 first dba=3202 block cnt=6 obj#=92336 tim=1436288730008762 9 WAIT #46912559622408: nam='direct path read' ela= 43 file number=78 first dba=3208 block cnt=8 obj#=92336 tim=1436288730009241 10 WAIT #46912559622408: nam='direct path read' ela= 45 file number=78 first dba=3216 block cnt=8 obj#=92336 tim=1436288730009633 11 WAIT #46912559622408: nam='direct path read' ela= 41 file number=78 first dba=3224 block cnt=8 obj#=92336 tim=1436288730010093 12 WAIT #46912559622408: nam='direct path read' ela= 73 file number=78 first dba=3232 block cnt=8 obj#=92336 tim=1436288730010585 13 WAIT #46912559622408: nam='direct path read' ela= 44 file number=78 first dba=3240 block cnt=8 obj#=92336 tim=1436288730011082 14 WAIT #46912559622408: nam='direct path read' ela= 43 file number=78 first dba=3248 block cnt=8 obj#=92336 tim=1436288730011545 15 WAIT #46912559622408: nam='direct path read' ela= 44 file number=78 first dba=3256 block cnt=8 obj#=92336 tim=1436288730012024 16 WAIT #46912559622408: nam='direct path read' ela= 45 file number=78 first dba=3296 block cnt=8 obj#=92336 tim=1436288730012491 17 WAIT #46912559622408: nam='direct path read' ela= 44 file number=78 first dba=3304 block cnt=8 obj#=92336 tim=1436288730012992 18 WAIT #46912559622408: nam='direct path read' ela= 41 file number=78 first dba=3312 block cnt=8 obj#=92336 tim=1436288730013200 19 WAIT #46912559622408: nam='direct path read' ela= 40 file number=78 first dba=3320 block cnt=8 obj#=92336 tim=1436288730013423 20 FETCH #46912559622408:c=0,e=188182,p=3113,cr=6199,cu=0,mis=0,r=1,dep=0,og=1,plh=3724264953,tim=1436288730013681 21 STAT #46912559622408 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=6199 pr=3113 pw=0 time=188179 us)' 22 STAT #46912559622408 id=2 cnt=95344 pid=1 pos=1 obj=92336 op='TABLE ACCESS FULL T1 (cr=6199 pr=3113 pw=0 time=180339 us cost=827 size=95049 card=31683)' 23 WAIT #46912559622408: nam='SQL*Net message from client' ela= 317 driver id=1413697536 #bytes=1 p3=0 obj#=92336 tim=1436288730014177 24 FETCH #46912559622408:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3724264953,tim=1436288730014283 25 WAIT #46912559622408: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=92336 tim=1436288730014321 26 WAIT #46912559622408: nam='SQL*Net message from client' ela= 760 driver id=1413697536 #bytes=1 p3=0 obj#=92336 tim=1436288730015101 27 CLOSE #46912559622408:c=0,e=18,dep=0,type=0,tim=1436288730015216 28

Now table T2 resides in an encrypted tablespace.  Lets run that same query and see what happens.  Okay, the execution time went up to 1.67 seconds.  Here on the FETCH line we see 1567559 microseconds of CPU time to decrypt the data after a bunch of direct path reads.

1 WAIT #46912560638840: nam='direct path read' ela= 48 file number=77 first dba=4928 block cnt=8 obj#=92341 tim=1436288983345072 2 WAIT #46912560638840: nam='direct path read' ela= 44 file number=77 first dba=4936 block cnt=8 obj#=92341 tim=1436288983349077 3 WAIT #46912560638840: nam='direct path read' ela= 47 file number=77 first dba=4944 block cnt=8 obj#=92341 tim=1436288983353083 4 WAIT #46912560638840: nam='direct path read' ela= 49 file number=77 first dba=4952 block cnt=8 obj#=92341 tim=1436288983357078 5 WAIT #46912560638840: nam='direct path read' ela= 48 file number=77 first dba=4960 block cnt=8 obj#=92341 tim=1436288983361086 6 WAIT #46912560638840: nam='direct path read' ela= 50 file number=77 first dba=4968 block cnt=8 obj#=92341 tim=1436288983365107 7 WAIT #46912560638840: nam='direct path read' ela= 52 file number=77 first dba=4976 block cnt=8 obj#=92341 tim=1436288983369245 8 WAIT #46912560638840: nam='direct path read' ela= 47 file number=77 first dba=4984 block cnt=8 obj#=92341 tim=1436288983373257 9 WAIT #46912560638840: nam='direct path read' ela= 39 file number=77 first dba=4994 block cnt=6 obj#=92341 tim=1436288983377270 10 WAIT #46912560638840: nam='direct path read' ela= 48 file number=77 first dba=5000 block cnt=8 obj#=92341 tim=1436288983381286 11 WAIT #46912560638840: nam='direct path read' ela= 48 file number=77 first dba=5008 block cnt=8 obj#=92341 tim=1436288983384340 12 WAIT #46912560638840: nam='direct path read' ela= 48 file number=77 first dba=5016 block cnt=8 obj#=92341 tim=1436288983388373 13 WAIT #46912560638840: nam='direct path read' ela= 49 file number=77 first dba=5024 block cnt=8 obj#=92341 tim=1436288983392414 14 WAIT #46912560638840: nam='direct path read' ela= 47 file number=77 first dba=5032 block cnt=8 obj#=92341 tim=1436288983396450 15 WAIT #46912560638840: nam='direct path read' ela= 47 file number=77 first dba=5040 block cnt=8 obj#=92341 tim=1436288983400460 16 WAIT #46912560638840: nam='direct path read' ela= 46 file number=77 first dba=5048 block cnt=8 obj#=92341 tim=1436288983404468 17 WAIT #46912560638840: nam='direct path read' ela= 45 file number=77 first dba=5056 block cnt=8 obj#=92341 tim=1436288983408470 18 WAIT #46912560638840: nam='direct path read' ela= 49 file number=77 first dba=5064 block cnt=8 obj#=92341 tim=1436288983412478 19 WAIT #46912560638840: nam='direct path read' ela= 17 file number=77 first dba=5072 block cnt=1 obj#=92341 tim=1436288983416457 20 FETCH #46912560638840:c=0,e=1567559,p=3095,cr=3099,cu=0,mis=0,r=1,dep=0,og=1,plh=3321871023,tim=1436288983420903 21 STAT #46912560638840 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=3099 pr=3095 pw=0 time=1567554 us)' 22 STAT #46912560638840 id=2 cnt=95344 pid=1 pos=1 obj=92341 op='TABLE ACCESS FULL T2 (cr=3099 pr=3095 pw=0 time=1559639 us cost=827 size=95049 card=31683)' 23 WAIT #46912560638840: nam='SQL*Net message from client' ela= 320 driver id=1413697536 #bytes=1 p3=0 obj#=92341 tim=1436288983421412 24 FETCH #46912560638840:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3321871023,tim=1436288983421496 25 WAIT #46912560638840: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=92341 tim=1436288983421533 26 WAIT #46912560638840: nam='SQL*Net message from client' ela= 648 driver id=1413697536 #bytes=1 p3=0 obj#=92341 tim=1436288983422201 27 CLOSE #46912560638840:c=0,e=18,dep=0,type=0,tim=1436288983422305 28

1 RLOCKARD@pdev > @tablespace_encryption.sql 2 RLOCKARD@pdev > set timing on 3 RLOCKARD@pdev > 4 RLOCKARD@pdev > alter session set timed_statistics = true; 5 6 Session altered. 7 8 Elapsed: 00:00:00.00 9 RLOCKARD@pdev > alter session set statistics_level = all ; 10 11 Session altered. 12 13 Elapsed: 00:00:00.00 14 RLOCKARD@pdev > alter session set sql_trace = true ; 15 16 Session altered. 17 18 Elapsed: 00:00:00.01 19 RLOCKARD@pdev > alter session set max_dump_file_size=unlimited; 20 21 Session altered. 22 23 Elapsed: 00:00:00.00 24 RLOCKARD@pdev > alter session set tracefile_identifier = owi_trace; 25 26 Session altered. 27 28 Elapsed: 00:00:00.00 29 RLOCKARD@pdev > 30 RLOCKARD@pdev > BEGIN 31 2 dbms_monitor.session_trace_enable (waits=>true); 32 3 END; 33 4 / 34 35 PL/SQL procedure successfully completed. 36 37 Elapsed: 00:00:00.00 38 RLOCKARD@pdev > select sum(nbr) from t2 where nbr between 40 and 45; 39 40 SUM(NBR) 41 ---------- 42 4055760 43 44 1 row selected. 45 46 Elapsed: 00:00:01.67 47 RLOCKARD@pdev > 48 RLOCKARD@pdev > BEGIN 49 2 dbms_monitor.session_trace_disable; 50 3 END; 51 4 / 52 53 PL/SQL procedure successfully completed. 54 55 Elapsed: 00:00:00.00 56 RLOCKARD@pdev > 57

Table T3 resides in the DAT tablespace and has the nbr column encrypted.  Execution time 19.86 seconds.

 

1 RLOCKARD@pdev > @column_encryption 2 RLOCKARD@pdev > set timing on 3 RLOCKARD@pdev > alter session set timed_statistics = true; 4 5 Session altered. 6 7 Elapsed: 00:00:00.00 8 RLOCKARD@pdev > alter session set statistics_level = all ; 9 10 Session altered. 11 12 Elapsed: 00:00:00.00 13 RLOCKARD@pdev > alter session set sql_trace = true ; 14 15 Session altered. 16 17 Elapsed: 00:00:00.01 18 RLOCKARD@pdev > alter session set max_dump_file_size=unlimited; 19 20 Session altered. 21 22 Elapsed: 00:00:00.00 23 RLOCKARD@pdev > alter session set tracefile_identifier = owi_trace; 24 25 Session altered. 26 27 Elapsed: 00:00:00.00 28 RLOCKARD@pdev > 29 RLOCKARD@pdev > BEGIN 30 2 dbms_monitor.session_trace_enable (waits=>true); 31 3 END; 32 4 / 33 34 PL/SQL procedure successfully completed. 35 36 Elapsed: 00:00:00.00 37 RLOCKARD@pdev > select sum(nbr) from t3 where nbr between 40 and 45; 38 39 SUM(NBR) 40 ---------- 41 4055760 42 43 1 row selected. 44 45 Elapsed: 00:00:19.86 46 RLOCKARD@pdev > 47 RLOCKARD@pdev > BEGIN 48 2 dbms_monitor.session_trace_disable; 49 3 END; 50 4 / 51 52 PL/SQL procedure successfully completed. 53 54 Elapsed: 00:00:00.00 55 RLOCKARD@pdev > 56 RLOCKARD@pdev > 57

Looking at the 10046 trace file, we see a large number of “direct path read’ then FETCH c=0, e=19848382.  c is the CPU used and e is the elapsed time in micro seconds.  So, after reading all the data into the SGA, the CPU spent 19.848382 seconds to decrypt the data.

1 WAIT #46912556873704: nam='direct path read' ela= 47 file number=10 first dba=17536 block cnt=8 obj#=92434 tim=1436288197076658 2 WAIT #46912556873704: nam='direct path read' ela= 46 file number=10 first dba=17544 block cnt=8 obj#=92434 tim=1436288197087637 3 WAIT #46912556873704: nam='direct path read' ela= 45 file number=10 first dba=17552 block cnt=8 obj#=92434 tim=1436288197098738 4 WAIT #46912556873704: nam='direct path read' ela= 43 file number=10 first dba=17560 block cnt=8 obj#=92434 tim=1436288197109734 5 WAIT #46912556873704: nam='direct path read' ela= 48 file number=10 first dba=17568 block cnt=8 obj#=92434 tim=1436288197120785 6 WAIT #46912556873704: nam='direct path read' ela= 45 file number=10 first dba=17576 block cnt=8 obj#=92434 tim=1436288197131809 7 WAIT #46912556873704: nam='direct path read' ela= 45 file number=10 first dba=17584 block cnt=8 obj#=92434 tim=1436288197142990 8 WAIT #46912556873704: nam='direct path read' ela= 45 file number=10 first dba=17592 block cnt=8 obj#=92434 tim=1436288197154216 9 WAIT #46912556873704: nam='direct path read' ela= 67 file number=10 first dba=17600 block cnt=8 obj#=92434 tim=1436288197167921 10 WAIT #46912556873704: nam='direct path read' ela= 59 file number=10 first dba=17608 block cnt=8 obj#=92434 tim=1436288197179630 11 WAIT #46912556873704: nam='direct path read' ela= 46 file number=10 first dba=17616 block cnt=8 obj#=92434 tim=1436288197190774 12 WAIT #46912556873704: nam='direct path read' ela= 56 file number=10 first dba=17624 block cnt=8 obj#=92434 tim=1436288197201914 13 WAIT #46912556873704: nam='direct path read' ela= 44 file number=10 first dba=17632 block cnt=8 obj#=92434 tim=1436288197213080 14 WAIT #46912556873704: nam='direct path read' ela= 47 file number=10 first dba=17640 block cnt=8 obj#=92434 tim=1436288197224429 15 WAIT #46912556873704: nam='direct path read' ela= 44 file number=10 first dba=17648 block cnt=8 obj#=92434 tim=1436288197235618 16 WAIT #46912556873704: nam='direct path read' ela= 56 file number=10 first dba=17656 block cnt=8 obj#=92434 tim=1436288197247424 17 FETCH #46912556873704:c=0,e=19848382,p=14178,cr=14181,cu=0,mis=0,r=1,dep=0,og=1,plh=463314188,tim=1436288197269519 18 STAT #46912556873704 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=14181 pr=14178 pw=0 time=19848378 us)' 19 STAT #46912556873704 id=2 cnt=95344 pid=1 pos=1 obj=92434 op='TABLE ACCESS FULL T3 (cr=14181 pr=14178 pw=0 time=19110498 us cost=3863 size=212000 card=4000)' 20 WAIT #46912556873704: nam='SQL*Net message from client' ela= 296 driver id=1413697536 #bytes=1 p3=0 obj#=92434 tim=1436288197270054 21 FETCH #46912556873704:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=463314188,tim=1436288197270136 22 WAIT #46912556873704: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=92434 tim=1436288197270200 23 WAIT #46912556873704: nam='SQL*Net message from client' ela= 584 driver id=1413697536 #bytes=1 p3=0 obj#=92434 tim=1436288197270805 24 CLOSE #46912556873704:c=0,e=17,dep=0,type=0,tim=1436288197270917 25