usp_JIWA_Creditors_AgedBalancesSummary performance

[pricerc]

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)

[pricerc]

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.

[Scott.Pearce]

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).

[Mike.Sheen]

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.

[pricerc]

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...

[pricerc]

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.

[Mike.Sheen]

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]

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

[pricerc]

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.

[Mike.Sheen]

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