usp_JIWA_Creditors_AgedBalancesSummary performance

Support for Microsoft SQL Server in the context of Jiwa installations.

usp_JIWA_Creditors_AgedBalancesSummary performance

Postby pricerc » Thu Sep 08, 2022 8:18 am

Customer in question has ~ 6000 creditors and > 200,000 CR_Trans records in my 18-month-old copy of their data that I use for testing.

Their 'Creditor Balance As At' report was taking a couple of hours to run, and sometimes crashing. So they asked me to take a look.

The SP in question is usp_JIWA_Creditors_AgedBalancesSummary.

This calls usp_JIWA_Creditors_CreditorBalanceAsAt in a loop.

After much 'tuning', I had a version that was performing much better, with the loop replaced with a set-based update using a table-value-function version of usp_JIWA_Creditors_CreditorBalanceAsAt .

I then started doing some small batches to confirm that I was getting results that match the stock version.

But when I compared the performance of usp_JIWA_Creditors_CreditorBalanceAsAt with my table-value-function version in small batches. Or even one creditor at a time, the difference could not explain the performance difference between the stock usp_JIWA_Creditors_AgedBalancesSummary and my version when running a large batch.

So I set about adding some timing "instrumentation" to both the stock and my version, and modified my version back to using a loop so that I could time both versions of usp_JIWA_Creditors_CreditorBalanceAsAt (which are really very similar).

After doing this, the stock one can now run the full set in under 90 seconds. Instead of taking 2 1/2 hours.

And yet "all" I'd done is add some timing collection code around the call to usp_JIWA_Creditors_CreditorBalanceAsAt.

SQL Server can be really, really, weird sometimes.

So I went through, rewinding the instrumentation code, to figure out what did it.

What was the magical change?

Replacing this:

Code: Select all
SET @CurrentCreditorID = (SELECT TOP 1 CreditorID FROM @CreditorIDTable ORDER BY CreditorID)


with this

Code: Select all
SELECT TOP 1 @CurrentCreditorID = CreditorID FROM @CreditorIDTable


at about line 120 (depends on how your UI scripts it).

I had changed it to this so that I could add the account number and name to my timing message:
Code: Select all
select top (1) @CurrentCreditorID = CreditorID
         , @currentCreditorAccount = AccountNo
         , @currentCreditorName = CreditorName
      from @CreditorIDTable
      order by CreditorName;


(I did try it with different ORDER BY clauses; they make neglible difference)
/Ryan

ERP Consultant,
Advanced ERP Limited, NZ
https://aerp.co.nz
User avatar
pricerc
Senpai
Senpai
 
Posts: 504
Joined: Mon Aug 10, 2009 12:22 pm
Location: Auckland, NZ
Topics Solved: 20

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby pricerc » Thu Sep 08, 2022 10:14 am

A follow up.

That may have been a red herring.

I mean, that's what I did, and that's what happened, but it is not consistently reproducible.

I'm doing more testing.
/Ryan

ERP Consultant,
Advanced ERP Limited, NZ
https://aerp.co.nz
User avatar
pricerc
Senpai
Senpai
 
Posts: 504
Joined: Mon Aug 10, 2009 12:22 pm
Location: Auckland, NZ
Topics Solved: 20

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby Scott.Pearce » Thu Sep 08, 2022 10:18 am

We've seen similar behaviors. We've also seen something that performs well on one site perform poorly on another - it's a real balancing act. Running sp_updatestats may help, as may sp_recompile (after using this the first run may be slow, subsequent runs OK).
Scott Pearce
Senior Analyst/Programmer
Jiwa Financials
User avatar
Scott.Pearce
Senpai
Senpai
 
Posts: 745
Joined: Tue Feb 12, 2008 11:27 am
Location: New South Wales, Australia
Topics Solved: 221

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby Mike.Sheen » Thu Sep 08, 2022 10:48 am

Scott.Pearce wrote:We've seen similar behaviors. We've also seen something that performs well on one site perform poorly on another - it's a real balancing act. Running sp_updatestats may help, as may sp_recompile (after using this the first run may be slow, subsequent runs OK).


Also laundering parameters passed in through local variables (and have your queries in the SP use the local variables instead of the parameter variables) will sidestep parameter sniffing strategies MSSQL sometimes does to "help" in performance.
Mike Sheen
Chief Software Engineer
Jiwa Financials

If I do answer your question to your satisfaction, please mark it as the post solving the topic so others with the same issue can readily identify the solution
User avatar
Mike.Sheen
Overflow Error
Overflow Error
 
Posts: 2465
Joined: Tue Feb 12, 2008 11:12 am
Location: Perth, Republic of Western Australia
Topics Solved: 758

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby pricerc » Thu Sep 08, 2022 11:05 am

Ok,

I obviously didn't test the "order by" very well the first time.

I've done further testing using a small subset of creditors that netts me a list of 105 records.

The attached "stock" sql is the stock stored procedure reformatted using "Poor Man's SQL Formatter" in NotePad++ after putting a begin and end around it.

with this bit of code like this:
Code: Select all
   while exists (
         select top 1 CreditorID
         from @CreditorIDTable
         --order by CreditorID
         )
   begin
      set @CurrentCreditorID = (
            select top 1 CreditorID
            from @CreditorIDTable
            --order by CreditorID
            )


I get my 105 records in 17 seconds.

If I "uncomment" the order by in the 'set' command, then I give up after about 1 1/2 minutes.

For those playing at home, I've also attached a version that has some timing code that times the content of the loop.

It does the same thing. With the added benefit of showing you how long each record is taking.

Now here's the really weird bit.

The code that's wrapped in the timer logic is the same either way, and yet either the exec or update statement take an order of magnitude longer to run if the order by clause exists in the "set @creditorID" line:
Code: Select all
      set @startTime = sysdatetime();
      set @message = convert(varchar(30), @startTime, 126) + ', ' + @currentCreditorAccount + ', ' + @currentCreditorName;

      raiserror (@message, 0, 0) with nowait;

      exec usp_JIWA_Creditors_CreditorBalanceAsAt @SP_AsAtDate, @CurrentCreditorID, @CurrentBalance output, @P1Balance output, @P2Balance output, @P3Balance output, @FXCurrentBalance output, @FXP1Balance output, @FXP2Balance output, @FXP3Balance output

      update @MyTemp
      set CurrentBal = @CurrentBalance, Period1 = @P1Balance, Period2 = @P2Balance, Period3 = @P3Balance, FXCurrentBal = @FXCurrentBalance, FXPeriod1 = @FXP1Balance, FXPeriod2 = @FXP2Balance, FXPeriod3 = @FXP3Balance
      where CreditorID = @CurrentCreditorID

      set @endTime = sysdatetime();
      set @message = convert(varchar(30), @endTime, 126) + ', ' + @currentCreditorAccount + ', ' + convert(varchar(10), datediff(microsecond, @startTime, @endTime));

      raiserror (@message, 0, 0) with nowait;


As I type, I'm just wondering if it's some weird thing SQL's doing with the table variable.

@MyTemp's 'natural' order is by creditor name. Maybe updating them "in natural order" causes a slightly different query plan to updating them in "creditor id order".

I see more testing in my future...
Attachments
usp_JIWA_Creditors_AgedBalancesSummary with timings.sql
with timing diagnostics
(12.64 KiB) Downloaded 499 times
usp_JIWA_Creditors_AgedBalancesSummary stock.sql
"Stock" stored procedure
(5.82 KiB) Downloaded 506 times
/Ryan

ERP Consultant,
Advanced ERP Limited, NZ
https://aerp.co.nz
User avatar
pricerc
Senpai
Senpai
 
Posts: 504
Joined: Mon Aug 10, 2009 12:22 pm
Location: Auckland, NZ
Topics Solved: 20

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby pricerc » Thu Sep 08, 2022 11:14 am

Nope.

with the "order by" in play

2022-09-08T12:12:20.6861490, 8201
2022-09-08T12:12:23.3552980, 8201, execute time:2669149
2022-09-08T12:12:23.3565109, 8201, update time:1212
2022-09-08T12:12:23.3577542, GUA010
2022-09-08T12:12:25.3783080, GUA010, execute time:2020554
2022-09-08T12:12:25.3783080, GUA010, update time:0
2022-09-08T12:12:25.3794991, AUT015
2022-09-08T12:12:26.1735704, AUT015, execute time:794071
2022-09-08T12:12:26.1735704, AUT015, update time:0
2022-09-08T12:12:26.1742461, BAR030
2022-09-08T12:12:26.9673728, BAR030, execute time:793126
2022-09-08T12:12:26.9673728, BAR030, update time:0
2022-09-08T12:12:26.9681384, COM260
2022-09-08T12:12:29.1063146, COM260, execute time:2138176
2022-09-08T12:12:29.1075648, COM260, update time:1250


without the order by:

2022-09-08T12:13:21.8063997, 8858
2022-09-08T12:13:21.9103952, 8858, execute time:103996
2022-09-08T12:13:21.9117541, 8858, update time:1359
2022-09-08T12:13:21.9124651, 10222
2022-09-08T12:13:21.9124651, 10222, execute time:0
2022-09-08T12:13:21.9124651, 10222, update time:0
2022-09-08T12:13:21.9124651, 7925
2022-09-08T12:13:21.9137821, 7925, execute time:1317
2022-09-08T12:13:21.9137821, 7925, update time:0
2022-09-08T12:13:21.9137821, 9371
2022-09-08T12:13:21.9137821, 9371, execute time:0
2022-09-08T12:13:21.9149015, 9371, update time:1119
2022-09-08T12:13:21.9149015, 8321
2022-09-08T12:13:21.9175181, 8321, execute time:2617
2022-09-08T12:13:21.9175181, 8321, update time:0


what I did notice is that the first item always seems to take much longer.
/Ryan

ERP Consultant,
Advanced ERP Limited, NZ
https://aerp.co.nz
User avatar
pricerc
Senpai
Senpai
 
Posts: 504
Joined: Mon Aug 10, 2009 12:22 pm
Location: Auckland, NZ
Topics Solved: 20

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby Mike.Sheen » Thu Sep 08, 2022 11:47 am

pricerc wrote:Ok,

I obviously didn't test the "order by" very well the first time.

I've done further testing using a small subset of creditors that netts me a list of 105 records.

The attached "stock" sql is the stock stored procedure reformatted using "Poor Man's SQL Formatter" in NotePad++ after putting a begin and end around it.

with this bit of code like this:
Code: Select all
   while exists (
         select top 1 CreditorID
         from @CreditorIDTable
         --order by CreditorID
         )
   begin
      set @CurrentCreditorID = (
            select top 1 CreditorID
            from @CreditorIDTable
            --order by CreditorID
            )


I get my 105 records in 17 seconds.

If I "uncomment" the order by in the 'set' command, then I give up after about 1 1/2 minutes.

For those playing at home, I've also attached a version that has some timing code that times the content of the loop.

It does the same thing. With the added benefit of showing you how long each record is taking.

Now here's the really weird bit.

The code that's wrapped in the timer logic is the same either way, and yet either the exec or update statement take an order of magnitude longer to run if the order by clause exists in the "set @creditorID" line:
Code: Select all
      set @startTime = sysdatetime();
      set @message = convert(varchar(30), @startTime, 126) + ', ' + @currentCreditorAccount + ', ' + @currentCreditorName;

      raiserror (@message, 0, 0) with nowait;

      exec usp_JIWA_Creditors_CreditorBalanceAsAt @SP_AsAtDate, @CurrentCreditorID, @CurrentBalance output, @P1Balance output, @P2Balance output, @P3Balance output, @FXCurrentBalance output, @FXP1Balance output, @FXP2Balance output, @FXP3Balance output

      update @MyTemp
      set CurrentBal = @CurrentBalance, Period1 = @P1Balance, Period2 = @P2Balance, Period3 = @P3Balance, FXCurrentBal = @FXCurrentBalance, FXPeriod1 = @FXP1Balance, FXPeriod2 = @FXP2Balance, FXPeriod3 = @FXP3Balance
      where CreditorID = @CurrentCreditorID

      set @endTime = sysdatetime();
      set @message = convert(varchar(30), @endTime, 126) + ', ' + @currentCreditorAccount + ', ' + convert(varchar(10), datediff(microsecond, @startTime, @endTime));

      raiserror (@message, 0, 0) with nowait;


As I type, I'm just wondering if it's some weird thing SQL's doing with the table variable.

@MyTemp's 'natural' order is by creditor name. Maybe updating them "in natural order" causes a slightly different query plan to updating them in "creditor id order".

I see more testing in my future...



I've downloaded and run these stored procs against a copy of a customer database I have - 1,988 records in CR_Main and 168,727 records in CR_Trans.

Running the stored procs with the parameters for all creditors, as at todays date - both ordered by AccountNo and Name and BOTH stored procs return in 3 seconds - 42 rows returned.

So, It's not a general issue - it's something about the nature of your data or environment which is impacting things. I think you'll find the problem will simply go away after a while, once things grow a bit more and indexes and trees change.
Mike Sheen
Chief Software Engineer
Jiwa Financials

If I do answer your question to your satisfaction, please mark it as the post solving the topic so others with the same issue can readily identify the solution
User avatar
Mike.Sheen
Overflow Error
Overflow Error
 
Posts: 2465
Joined: Tue Feb 12, 2008 11:12 am
Location: Perth, Republic of Western Australia
Topics Solved: 758

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby Mike.Sheen » Thu Sep 08, 2022 11:56 am

If you are curious what the cause is, try running with execution plans on.
Mike Sheen
Chief Software Engineer
Jiwa Financials

If I do answer your question to your satisfaction, please mark it as the post solving the topic so others with the same issue can readily identify the solution
User avatar
Mike.Sheen
Overflow Error
Overflow Error
 
Posts: 2465
Joined: Tue Feb 12, 2008 11:12 am
Location: Perth, Republic of Western Australia
Topics Solved: 758

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby pricerc » Thu Sep 08, 2022 1:37 pm

Mike.Sheen wrote:If you are curious what the cause is, try running with execution plans on.


I've done that plenty. But if you just let it rip on that stored procedure without limiting it to just a handful of creditors, you'll likely crash your SSMS when it runs out of memory.
/Ryan

ERP Consultant,
Advanced ERP Limited, NZ
https://aerp.co.nz
User avatar
pricerc
Senpai
Senpai
 
Posts: 504
Joined: Mon Aug 10, 2009 12:22 pm
Location: Auckland, NZ
Topics Solved: 20

Re: usp_JIWA_Creditors_AgedBalancesSummary performance

Postby Mike.Sheen » Thu Sep 08, 2022 1:48 pm

pricerc wrote:
Mike.Sheen wrote:If you are curious what the cause is, try running with execution plans on.


I've done that plenty. But if you just let it rip on that stored procedure without limiting it to just a handful of creditors, you'll likely crash your SSMS when it runs out of memory.


Limiting to just a smaller range of creditors would be enough to reveal where the bulk of the time is spent.

If it offers up recommendations for indexes to be created, a couple of things to note:
1. It may or may not make things better
2. It may make things worse
3. If it does improve performance, it may not on other datasets, or on the same dataset tomorrow
4. If it does improve performance, dropping the index may also see the improved performance remain
5. A nice cup of tea may help you cope
Mike Sheen
Chief Software Engineer
Jiwa Financials

If I do answer your question to your satisfaction, please mark it as the post solving the topic so others with the same issue can readily identify the solution
User avatar
Mike.Sheen
Overflow Error
Overflow Error
 
Posts: 2465
Joined: Tue Feb 12, 2008 11:12 am
Location: Perth, Republic of Western Australia
Topics Solved: 758

Next

Return to Microsoft SQL Server

Who is online

Users browsing this forum: No registered users and 1 guest

cron