2

Last night we upgraded a SQL Server 2012 server to SQL Server 2017 + CU 29. This is one of a matched set - we send the same message to both and each processes it. No, this is not AlwaysOn; we're using MSMQ to send the messages. This server was the first to be upgraded to 2017, the newest we could get to on that version of Windows. it is a physical box with 64gb of RAM and 2 E52650s running with hyperthreading on.

Since the upgrade, we've been having large performance issues, largely around LCK_M_IX waits on the insert into the hourly tables that the activated stored procedure writes to (messages come in, we parse the EDI and write to a series of tables for later use - it's only ever writes, no updates).

To try and fix it (upwards of 90k ms waits on LCK_M_IX shown in SP_WHOISACTUIVE) we dropped the threads from 30 to 15, and also moved to Compatability Level 140 and the new cardinality estimator (we had tried going back to see if it solved the blocking issue). We were able to raise the threads to 20; the machine has plenty of cores left. Note that the other server, still on SQL Server 2012, is NOT having any of these issues (they're both having a performance issue after a weekend, that's why we're upgrading)

Now, we seem to be doing good performance-wise, UNTIL it starts inserting into the next hour, at which point we see LCK_M_IX waits again. We dropped the fillfactor from 95 to 70 for the tables and also ran a specific UPDATE STATISTICS WITH FULLSCAN on the tables, but we still had it occur.

This last time, when we saw the locks, I ran:

UPDATE STATISTICS <mytablename> WITH FULLSCAN
go
dbcc freeproccache
go
dbcc dropcleanbuffers

between all of them, the blocking went away about 30s-60s later. Unsure what the actual fix was; when the next hour finishes, if it happens again, I'll do them separated by more than a minute to see if I can figure out what's going on.

UPDATE AN HOUR LATER: it was blocking. after a few minutes, since it wasn't going to fix itself, we ran UPDATE STATISTICS on the new table it's writing to, and 3 minutes later the blocking stopped. Still not sustainable, but we didn't need a FREEPROCCACHE or DROPCLEANBUFFERS.

Update two hours later: Had to do a FREEPROCCACHE to get it to work this time. Unsure why the stats updates were working before. I have no idea.

I now have info from query store. It says that for the insert, the first couple hundred times it runs, grabs plan 36384. That is "table valued function->compute scalar->compute scalar->table insert->sort->index insert->insert. But it only does a few hundred inserts then, because of the way our queues are working. Then it does nothing for the better part of an hour, and when it starts up again the existing plan goes from having a max duration of 5ms to a max duration of 82000ms and the average goes from 1.79ms to 400ms, std dev of 5500ms. It then uses that plan for 30k before I finally kick it out. When I do a freeproccache, the new plan generated (49980) is "Table Valued Function->Computer Scalar->Compute Scalar->Table Insert->Index Insert->Insert", and it proceeds to use that for about 500k times, with an average of 1.85ms and a max of 304ms, stdev of 2.5ms.

So for some reason that SORT prior to it appears to be causing the issue. But since each hour has its own table, how do I get it to insert properly?

Update several days later: Plans!

(note that there are a couple cardinality warnings. Actually, it's every field that comes out of that CLR function on the right, but since there are like 200 fields and SQL Sentry Plan Explorer doesn't anonymize it, I cut it down and did it manually for two fields)

Also: an ugly fix! If we manually update the stats for the tables we're writing to, it no longer has issues. The downside is I need to make sure that later maintenance doesn't "fix" it.

UPDATE STATISTICS [dbo].[tablea_20220621_10] WITH ROWCOUNT=100000, PAGECOUNT=12318;
UPDATE STATISTICS [dbo].[tablea_20220621_10] ([ncidx_20220621_10_request_id]) WITH ROWCOUNT=100000, PAGECOUNT=314;

Full gallery: https://imgur.com/gallery/dvTBbP9

Here's the basic definition for the table (there's a total of 200 fields, there's only one index and it's on the IDENTITY, but is nonclustered.)

CREATE TABLE mytablename
(
[ID] [bigint] NOT NULL IDENTITY(1, 1),
[BUNDLE_ID] [bigint] NOT NULL,
[TX_NUMBER] [bigint] NOT NULL,
[SEQUENCE_NUMBER] [bigint] NULL,
[DATE_SWITCHED] [datetime] NULL,
...bunch of fields deleted
) ON [PRIMARY]
GO
CREATE NONCLUSTERED INDEX [ncidx_mytable_id] ON [mytablename] ([ID]) WITH (FILLFACTOR=70) ON [PRIMARY]
GO

Obviously, this isn't sustainable, but I'm unsure where to go from here. When I looked earlier to see what the object was that was having issues, I did a DBCC PAGE and got the below part.

PAGE: (1:11671680)


BUFFER:


BUF @0x000000F9F30AB040

bpage = 0x00000109781C2000          bhash = 0x0000000000000000          bpageno = (1:11671680)
bdbid = 7                           breferences = 3                     bcputicks = 0
bsampleCount = 0                    bUse1 = 64097                       bstat = 0x9
blog = 0xab21215a                   bnext = 0x0000000000000000          bDirtyContext = 0x0000000000000000
bstat2 = 0x0                        

PAGE HEADER:


Page @0x00000109781C2000

m_pageId = (1:11671680)             m_headerVersion = 1                 m_type = 2
m_typeFlagBits = 0x0                m_level = 0                         m_flagBits = 0x200
m_objId (AllocUnitId.idObj) = 616874m_indexId (AllocUnitId.idInd) = 256 
Metadata: AllocUnitId = 72057634465382400                                Metadata: PartitionId = 0
Metadata: IndexId = -1              Metadata: ObjectId = 0              m_prevPage = (1:11669448)
m_nextPage = (5:1189096)            pminlen = 17                        m_slotCnt = 204
m_freeCnt = 3608                    m_freeData = 4336                   m_reservedCnt = 0
m_lsn = (12098536:210111:57)        m_xactReserved = 0                  m_xdesId = (11:-563572576)
m_ghostRecCnt = 4                   m_tornBits = -230377116             DB Frag ID = 1

Allocation Status

GAM (1:11247104) = NOT ALLOCATED    SGAM (1:11247105) = NOT ALLOCATED   PFS (1:11670984) = 0x8   0_PCT_FULL
DIFF (1:11247110) = CHANGED         ML (1:11247111) = NOT MIN_LOGGED    
13
  • Given that you're doing inserts into a heap, what effect would updating statistics or changing fill factor on the non-clustered index have?
    – Ben Thul
    Jun 17 at 23:08
  • @ben-thul , heck if I know. I can't explain why, so I was literally throwing anything at it that I could get to stick. And it seemed to work, but that seems to be timing. Let me go in and add what I just got from Query Store, which shows that the bad plan does an insert into the table , then a sort, then an insert into the index. The plan after I do a FREEPROCCACHE doesn't do that and seems to perform much better.
    – mbourgon
    Jun 18 at 0:33
  • 1
    @J.D. thanks! Naturally it doesn't do all of it, but enough to get it in here. Added. Along with images of the 2 plans.
    – mbourgon
    Jun 21 at 18:44
  • 1
    It's interesting to me that the cardinality of the table you're inserting into matters at all. But given that it seems to, one thing I'd try is to separate the "figure out what to insert" and "actually insert" with a temp table. I'd index that table the same way as your live table in the hope that the optimizer does a "these look the same to me" and obviates the sort.
    – Ben Thul
    Jun 21 at 20:51
  • 1
    If that's what you've got, it'd be (pseudo-code) create temp table in activated SP; while true { fetch 1000 messages; foreach message {insert into temp table results from processing SP} insert into live table from temp table; truncate temp table;}. That is, you needn't create one temp table for each call to your processing SP or even one per fetch from the queue; create it once and fill/empty it as necessary. But if you want to wait on MS, that's fine too.
    – Ben Thul
    Jun 23 at 3:25

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.