none
Azure SQL stored procedure ridiculously slow called from C# RRS feed

  • Question

  • Summary:

    We have two identical databases, one on a local server, one on Azure.

    We have a C# system that accesses these databases, calling stored procedures.

    The stored procedures are running very, very slowly when called from the C# system to the Azure database. They're running fine from C# to the local server, and from SSMS to both the Azure and the local databases.

    As an example, calling the stored procedure 'usp_DevelopmentSearch_Select'

    Local database, SSMS : 1 second

    Local database, C# : 1 second

    Azure database, SSMS : 1 second

    Azure database, C# : 17 minutes

    This is happening on multiple stored procedures, I'm just using usp_DevelopmentSearch_Select as an example, to test solutions and to trace the execution plan.

    I've ruled out ARITHABORT (the usual suspect), and it seems that running usp_DevelopmentSearch_Select in SSMS and from the C# system generate a functionally identical execution plan.

    Details:

    We write a very large C# system, which accesses SQL Server databases.

    Currently all our clients host their own databases locally on their own servers, however we are looking into the option of hosting the databases on Azure. So I set up some small Azure test databases, ironed out the kinks, and got an Azure-hosted system going.

    Then I copied one of our client's databases up, to compare performance hosted locally vs hosted on Azure.

    The actual client database is performing unusably badly on Azure!

    The first screen calls a stored procedure 'usp_DevelopmentSearch_Select'

    Connection to the database on their server:-

    In SSMS, calling the stored procedure (below) returns the values in about 1 second

    EXEC usp_DevelopmentSearch_Select @MaxRecord = 100, @SearchType = 'CUR'

    In our C# program, calling the stored procedure returns the values in about 1 second

    Connection to the database on Azure:-

    In SSMS, calling the stored procedure returns the values in about 1 second

    In our C# program, calling the stored procedure returns the values in about 17 minutes!

    Fast in SSMS and slow from C# usually means ARITHABORT, so I turned it on at the start of the stored procedure :

    SET ARITHABORT ON; 

    That didn't make any difference, so I updated it to convert the passed parameters to local variables.

    ALTER PROCEDURE [dbo].[usp_DevelopmentSearch_Select] (@MAXRECORD INT, @SEARCHTYPE VARCHAR(3)) AS BEGIN SET ARITHABORT ON; DECLARE @MAXRECORD_Var INT = @MAXRECORD DECLARE @SEARCHTYPE_Var VARCHAR(3) = @SEARCHTYPE ... (Updated all references from @MAXRECORD and @SEARCHTYPE

    to @MAXRECORD_Var and @SEARCHTYPE_Var) END

    Still no joy, so I got the Execution Plan details for both:-

    select o.object_id, s.plan_handle, h.query_plan 
    from sys.objects o 
    inner join sys.dm_exec_procedure_stats s on o.object_id = s.object_id
    cross apply sys.dm_exec_query_plan(s.plan_handle) h
    where o.object_id = object_id('usp_DevelopmentSearch_Select')

    And just to check, I reloaded the screen in the C# program, and checked the running query:-

    SELECT sqltext.TEXT,
    req.session_id,
    req.status,
    req.command,
    req.cpu_time,
    req.total_elapsed_time,
    req.plan_handle
    FROM sys.dm_exec_requests req
    CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS sqltext

    It is definitely using one of the two execution plans returned above.

    So, check the settings for the Execution Plans

    SELECT * FROM sys.dm_exec_plan_attributes (0x05002D00D1A1EA5510E66E783602000001);
    SELECT * FROM sys.dm_exec_plan_attributes (0x05002D00D1A1EA55E0FC6E783602000001);

    Compare Settings

    Set_Options is 4345 for both, so they're definitely both using ARITHABORT.

    The only differences are the localisation bits: Language and Date Format. The Azure database is stuck in American, can't seem to change that, while the C# program forces it to British.

    I tried the C# program without forcing it to British, and still got the same issue. It also used exactly the same Execution Plan, so clearly localisation doesn't affect that.

    So, I called up the info on the Execution Plans:-

    SELECT * FROM sys.dm_exec_query_plan (0x05002D00D1A1EA5510E66E783602000001);
    SELECT * FROM sys.dm_exec_query_plan (0x05002D00D1A1EA55E0FC6E783602000001);

    Saved them both, and compared the results:-

    Compare Execution Plans

    The two columns far left show the overall comparison: yellow being different, white being the same. As you can see, the two Execution Plans are almost identical, just with a handful of differences at the top.

    The first differences can be seen in the above screenshot: the 'StatementCompId' is one higher in the SSMS (left) pane than the C# (right) pane. Google doesn't want to tell me what StatementCompId is, but given they're in sequence I'm guessing it's the order to do them in, and the SSMS is one higher because the EXEC command that called the SP counts as one.

    For ease, I've compiled all the remaining differences into a single screenshot:-

    Compare Execution Plans

    Compile times and CPU usages, free memory, and a couple more 'StatementCompId'

    So, the two Execution Plans are functionally identical, with identical settings (except localisation which doesn't seem to have an effect).

    So why does it take around 17 minutes calling the Azure SP from C# compared to around 1 second calling the Azure SP from SSMS or the local SP from the locally-hosted database either way?

    The Stored Procedure itself is just a SELECT FROM, with a few LEFT JOINs to other tables, nothing fancy and it's never given us any trouble on locally-hosted databases.

    SELECT TOP (@MAXRECORD_Var) <FieldList>
    FROM (
        SELECT DISTINCT <FieldList>
        FROM <TableName> WITH (NOLOCK)
        LEFT JOIN <TableName> WITH (NOLOCK) ON <Link>
        LEFT JOIN <TableName> WITH (NOLOCK) ON <Link>
        LEFT JOIN <TableName> WITH (NOLOCK) ON <Link>
        LEFT JOIN <TableName> WITH (NOLOCK) ON <Link>
        LEFT JOIN <TableName> WITH (NOLOCK) ON <Link>
        WHERE (
            <Conditions>
        ) AS Base
    ORDER BY <FieldName>

    Edit : Azure Staging Pool Configurations and Automatic Tuning

    I tried out several different configurations on the Staging Pool, to see if that made a difference. I didn't try the worst query, as it was costing us money to up the eDTUs, but I tried several others, twice each (going down the list each time, so not the same one twice straight away).

    Timing Tests

    Going from 50 eDTUs to 100 eDTUs made a bit of a difference, so I guess on our Test Elastic Pool we use all of the 50, but after that it didn't make any difference. Oddly, the Premium gave worse performance than Standard in places.

    I then went through all the Performance options on the Azure Portal and see if that recommends anything.

    It suggested a couple of indexes, which I enabled, but that was all.

    Then I flipped the Automatic Tuning over from 'Server' to 'Azure Defaults'

    Azure Defaults

    I re-ran most of the same timing tests, just to see what difference it had made.

    Timing Tests After

    The query that had been taking 17 minutes now generally took 13 seconds, a massive improvement! Yay!

    The rest were a mixed bag. C was generally quicker, most still took around the same time, and E now takes nearly twice as long (26s up from 14s).

    There results also seemed to have a lot more variance than they did before, although it's possible that changing the eDTU size resets the tunings. The second run was usually better than the first, often noticeably so.

    Still all a lot slower than running the same system against a database on a local server, but a huge improvement for the slowest Stored Procedure at least.

    Edit : Fit Percents

    The Fit Percents after running the slowest query before updating the tuning

    CPU Fit Percent        Log Write Fit Percent    Physical Data Read Fit Percent
    0.824218750000        1.000000000000        0.996093750000

    And again after running the same query after updating the tuning.

    CPU Fit Percent        Log Write Fit Percent    Physical Data Read Fit Percent
    1.000000000000       1.000000000000        0.996093750000

    Seems to have made the CPU happier, anyway! :)

    Edit : Won't seem to let me post the pictures, so used text.

    Edit : Question Answers

    Can you detail at what service tier your Azure Database is deployed at?

    As detailed in an edit above, I tried several levels of Standard, and one of Premium

    One final question is if your application is connection from on-premise of if this is an Azure hosted application?

    The C# application is installed locally on the User's machine

    Edit: Answered further questions

    Apologies for the delay replying, we're currently short staffed and I've been covering other people.

    Want to follow-up on your issue to see if you have any additional information to help determine where the all the waite time is being spent. Thank you for providing additional information.

    The wait time is entirely running the query. C# sends the request and it shows as a running query straight away, then when the query stops running the data appears in the C# program straight away.

    Using the below query shows the query running, along with the execution plan handle, I refreshed it every couple of sends to see it starting and stopping

    SELECT sqltext.TEXT,
    req.session_id,
    req.status,
    req.command,
    req.cpu_time,
    req.total_elapsed_time,
    req.plan_handle
    FROM sys.dm_exec_requests req
    CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS sqltext

    And after it has finished, the below query gives me the elapsed time

    SELECT deqs.last_execution_time AS [Time], dest.TEXT AS [Query], last_elapsed_time
    FROM sys.dm_exec_query_stats AS deqs
    CROSS APPLY sys.dm_exec_sql_text(deqs.sql_handle) AS dest
    WHERE deqs.last_elapsed_time > 10000000
    ORDER BY deqs.last_execution_time DESC

    Both show that the wait time is the query running.

    Is that possible to get an execution plan of bad running query?

    I have two saved execution plans I can provide:-

    ExecutionPlanTook1Second.sqlplan - Stored Procedure run from SSMS

    ExecutionPlanTook17Minutes.sqlplan - Stored Procedure run from C#

    They appear to be functionally identical to me, the only differences seem to be compiles times and such, however as the file names suggest the once from SSMS took 1 second to run while the one from C# took 17 minutes to run.

    The 17 minutes was prior to flipping the Automatic Tuning over to 'Azure Defaults'.

    Unfortunately, I can't seem to find an option to attach files to a post. Is there a way to do that?

    Friday, November 29, 2019 5:33 PM

All replies

  • Thank you for bringing this to our attention. Can you detail at what service tier your Azure Database is deployed at?Let's take a look and see what is occurring by running the following query:

    SELECT 
        (COUNT(end_time) - SUM(CASE WHEN avg_cpu_percent > 80 THEN 1 ELSE 0 END) * 1.0) / COUNT(end_time) AS 'CPU Fit Percent'
        ,(COUNT(end_time) - SUM(CASE WHEN avg_log_write_percent > 80 THEN 1 ELSE 0 END) * 1.0) / COUNT(end_time) AS 'Log Write Fit Percent'
        ,(COUNT(end_time) - SUM(CASE WHEN avg_data_io_percent > 80 THEN 1 ELSE 0 END) * 1.0) / COUNT(end_time) AS 'Physical Data Read Fit Percent'
    FROM sys.dm_db_resource_stats


    This will identify where all the time is spent and the out put will look like the following, where in my case I have no activity:

    CPU Fit Percent         Log Write Fit Percent Physical Data Read Fit Percent
    1.000000000000 1.000000000000 1.000000000000


    Additionally, can you please navigate through the following Intelligent Performance section of the Azure Portal for your deployed database, to see what recommendations are being made. 

    One final question is if your application is connection from on-premise of if this is an Azure hosted application?

    Saturday, November 30, 2019 1:27 AM
    Moderator
  • Want to follow-up on your issue to see if you have any additional information to help determine where the all the waite time is being spent. Thank you for providing additional information.

    Regards,

    Mike

    Tuesday, December 3, 2019 8:47 PM
    Moderator
  • Is that possible to get an execution plan of bad running query?

    Best Regards,Uri Dimant SQL Server MVP, http://sqlblog.com/blogs/uri_dimant/

    MS SQL optimization: MS SQL Development and Optimization
    MS SQL Consulting: Large scale of database and data cleansing
    Remote DBA Services: Improves MS SQL Database Performance
    SQL Server Integration Services: Business Intelligence

    Wednesday, December 4, 2019 4:53 AM