Martin Smith – StackOverFlow – DECRYPTBYKEY slower on SQL Server 2014 than SQL Server 2012

Intro

In our last post we spoke a bit about encryption, specifically sys.fn_varbintohexsubstring.

As I googled to find supportive and collaborative sources, I ran into Martin Smith’s question on encryption.

As Martin Smith’s word are far better, it does make sense to try to distill it.

Here are his words…

Martin Smith – DECRYPTBYKEY slower on SQL Server 2014 than SQL Server 2012

Link

We have been using symmetric keys for encryption/decryption on some SQL Server 2012 instances for a few years. We recently installed some new instances of SQL Server 2014 and came across some performance issues decrypting the data on SQL Server 2014 installations.

Consider a table looking like this:


CREATE TABLE [dbo].[tblCertTest]
(
     [article_id_enc] [varbinary](100) NOT NULL
   , [article_id] [int] NULL
) ON [PRIMARY]

And keys and certificates created like this:


CREATE MASTER KEY ENCRYPTION BY PASSWORD = 'Passwrrrrd12'

CREATE CERTIFICATE MyCertificateName
WITH SUBJECT = 'A label for this certificate'

CREATE SYMMETRIC KEY MySymmetricKeyName WITH
IDENTITY_VALUE = 'a fairly secure name',
ALGORITHM = AES_256,
KEY_SOURCE = 'a very secure strong password or phrase'
ENCRYPTION BY CERTIFICATE MyCertificateName;

Our data set has about 90000 rows, article_id is a 5 digit number. A bit simplified, article_id_enc is encrypted with the following command:


update tblCertTest 

set article_id_enc

    = ENCRYPTBYKEY(
                        KEY_GUID('MySymmetricKeyName')
                       ,convert(varbinary(100), article_id)
                  )

We have applied all available hotfixes, we’ve tried with different instances of both SQL Server 2012 and SQL Server 2014 with different setups like ssd disks, ram disks etc.

We have tried the query locally on the SQL Server and remote.

Execution plans and indexes are the same on all servers.

This SELECT statement takes about 50 ms on any SQL Server 2012 server, including simple development machines. On any SQL Server 2014 server (including really powerful ones) the query takes at least 1500 ms.


OPEN SYMMETRIC KEY MySymmetricKeyName
       DECRYPTION BY CERTIFICATE MyCertificateName

SELECT CONVERT(int, DecryptByKey(article_id_enc))
FROM dbo.tblCertTest

Any suggestions on why the query is performing so bad on SQL Server 2014? What’s changed?

 

Edit: I just noticed that there is a KB article FIX: A query that uses the DECRYPTBYKEY function takes a long time in SQL Server 2014 but I have that installed and it doesn’t appear to change the original conclusions below.

Running the following code in both SQL Server 2012 (11.0.5343.0) and 2014 (RTM) on a quadcore (Intel Core i5-2320) X64 desktop machine running Windows 10.


OPEN SYMMETRIC KEY MySymmetricKeyName 
    DECRYPTION BY CERTIFICATE MyCertificateName;

DECLARE @B VARBINARY(100);

WITH t
AS (SELECT ROW_NUMBER() OVER (ORDER BY @@SPID) AS article_id
FROM sys.all_objects o1,
sys.all_objects o2,
sys.all_objects o3,
sys.all_objects o4)

SELECT @B = ENCRYPTBYKEY
              (
                   KEY_GUID('MySymmetricKeyName')
                 , CONVERT(VARBINARY(100), article_id)
              )
FROM t

Process Explorer

And looking at it in Process Explorer

CPU

v2012

v2012

v2014

v2014

Thread

The Process Explorer “threads” window shows

v2012

A single thread is monopolizing the scheduler.

threads_v2012

v2014

Here the work is being performed by two threads (thread 3212 is running the idle task sqldk.dll!SOS_Scheduler::Idle).

threads_v2014

 

Tracing

 

v2012

( None Available )

v2014

Tracing the 2014 process shows that SQL Server and these two threads encounter a lot of context switches (trace taken at different time than previous screen shot hence differing thread ids)

tracing-v2014

 

Windows Performance Toolkit

Tracing the two processes with Windows Performance Toolkit shows some significant differences in time spent in different Modules

Modules Time Spent

v2012

modulestimespent-v2012

 

v2014

modulestimespent-v2014

 

Visual Studio  Code Profiler

And attaching the VS code profiler the 2012 version looks like this and the 2014 like this.

So it looks as though 2014 has additional logic to stop this hogging the scheduler and it gets switched off more frequently as highlighted by the additional items below.

v2012

encryptbykey-v2012

v2014

encryptbykey-v2014

Call Stacks

The call stacks for some of the more time consuming kernel calls are highlighted below:

consumingcallstacks

SQL Server

Back to MS SQL Server, let us issue a batch of encrypt statements.

Batch SQL Statement


SET STATISTICS TIME ON;

DECLARE @B VARBINARY(100);

OPEN SYMMETRIC KEY MySymmetricKeyName DECRYPTION BY CERTIFICATE MyCertificateName;

DBCC SQLPERF("sys.dm_os_wait_stats", CLEAR);

WITH t
     AS (SELECT ROW_NUMBER() OVER (ORDER BY @@SPID) AS article_id
         FROM   master..spt_values v1,
                master..spt_values v2
         WHERE  v1.type = 'P'
                AND v2.type = 'P'
                AND v1.number BETWEEN 1 AND 1000
                AND v2.number BETWEEN 1 AND 1000)
SELECT @B = ENCRYPTBYKEY(KEY_GUID('MySymmetricKeyName'), CONVERT(VARBINARY(100), article_id))
FROM   t

SELECT *
FROM   sys.dm_os_wait_stats
WHERE  wait_type IN ( 'PREEMPTIVE_OS_CRYPTOPS', 'SOS_SCHEDULER_YIELD' ); 

 

Wait Stats

v2012

It can clearly be seen that whilst the PREEMPTIVE_OS_CRYPTOPS wait type does exist in 2012 it is not used in this case.

Instead it looks as though the query more or less monopolises the scheduler (though still yielding voluntarily at the end of its 4 ms quantum – 4 * 597 = 2388)

 

waitstats-v2012

 

v2014

Whereas for 2014 every invocation of the ENCRYPTBYKEY function encounters this wait type and in this case it (combined with the context switches) added 8.2 seconds to overall elapsed time.

waitstats-v2014

SQL Server Affinitized to Single CPU

sqlserveraffinitisedtosinglecpu

My Take

  1. Surface
    • How the issue was discovered?
  2. Testing
    • The Test Segment?
      • All the System
      • Just specific areas where encryption is being used
    • Reproducibility
      • Over time as API introduced and specific to a new release is used and propagates through the system, overall and true version comparison will become less probable
    • How test load is gathered and persisted
    • How the test load is replayed and varied to increase sampling
  3. Management and StakeHolders
    • How the issue and impact was written and packaged to management
    • How the stakeholders is placated with hope that things will get better
  4. Holistic View
    • System
      • Is the system’s overall response better as Microsoft likely introduced this “must wait” state between each encrypt/decrypt cycle to allow other sessions access to the processor
      • What percentile of the overall data is encrypted
        • Just “Private” data?

Gratitude

I am thankful that Martin Smith took the time to write this up.  His thoroughness is uplifting.

I do not see how he was able to provide and fit this much thought in one “Stack Overflow” question.

Many years ago a friend related his feelings about a previous interview to me.  His words were something to the fact that “he does not know how seriously some people take their work.  And, that he sometimes questions their commitment from the questions asked him“.

It is obvious that Martin Smith takes his work seriously.  And, even more, he is a generous spirit, as here he is sharing his sweat and putting it out there knowing he is too far ahead.  And, that few can really help him.

Call it what you will, but to me it is a disciplined “Christopher McCandless’s – Into the Wild“.

 

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s