Top Sql Statements - Commit....

Hi,

We've started using DPA on one of our clients sites and it's helped us a lot by highlighting some issues with some problem queries, we've now hit a bit of a roadblock because the top SQL Statements is now being listed as "/* Commit */" and i have no idea what that means or where it's coming from. When this happens the users see 30+ second delays on the DB for the simplest of queries.

To give an example the application will run normally and then hit a commit

So the wait type is write log, and both the web service and website that utilse the db are "triggering" it. I'm at a loss to what the commit actually is??

I'm looked at the help guidelines and it hasn't really got me any further.

We're using Entity Framework so I would have though that if it was that causing the issue i would see some reference to the query that caused the commit.

Background

Sql Server 2008 R2

Relatively large db 150gb, full recovery model.

Checked the transaction log's and their size all is fine, also checked the VLF's and they're< 30 on a 1GB file

Can any one help? I have lots more information i can give but to be honest I'm not sure what would be useful, so please let me know if you want me to elaborate further.

Note I'm a Dev not a DBA so be nice :-)

Find more posts tagged with

tsql

writelog

help

commit

slow performance

Accepted answers

mandevil

Also, keep in mind that if you are running AGs in synchronous mode, those log writes have to be hardened on the replica node before you will get a commit confirmation. This can cause significant performance hits in your transactional system.

In Mike's case, we took a look at his environment and DPA spelled it out very clearly that write operations during certain periods were taking a way long time. Clear textbook example of storage latency killing database performance.

All comments

mandevil

Hey Mike, here are some of my thoughts and things for you to look at.

Commits is being called out as it's own activity/statement likely because that's how it's being used by the application.

Think in terms like the following transaction:

begin transaction

update table foo set bar = 10

insert into table foo2 values (...)

delete from users where userid = (select userid from users where username = 'Mike.King')

commit

In this one transaction or unit of work, you have 3 SQL statements plus a commit. Each statement (and the commit) will accrue wait time against them which will be tracked/displayed by DPA.

When a commit is done, the database then has to persist that transaction to the transaction log so that it can replay it in case of a recovery since the last backup point (oversimplifying here a bit).

The time it takes to persist that transaction to the tran log is tracked by SQL Server under the WRITELOG wait type.

Things to look for:

Make sure the write latency for the storage where the transaction log resides is healthy (if mission critical database, less than 10ms). You can look for this by looking at the "Resources" correlation tab below the wait times in trend and timeslice. Look for a metric called SQL disk write latency. You can also drill into an hour in the Storage I/O tab and select the file for the transaction log, then select latency vs throughput to see what kind of volume and stalls I/O requests are being experienced for this file.
Also, look at the logic for the transactions as well. It's not uncommon for high volume transactions to commit after each and every update say instead of batching them up (batching means significantly reduced commits and reduced wait times).

Hope this helps and provides you at least some things to dig into.

Others may have thoughts or things to look at as well...

mike.king1

Hi,

Thanks for the reply it's really appreciated.

Ok that makes sense, with regard to it tracking it's own time and not being directlylinked. I can't really find any queries before hand though that are run in transactions. 90% of our calls are via Entity Framework, and the rest are Sprocs. I will dig into that further to see if there's anything I'm missing.

As for the disk and latency stats I've added the charts below. There definitely seems to be an issue here, but I guess it's chicken and egg and trying to see what is causing this spike, although there doesn't seem to be anything application based that would cause this when i investigate the SQL, mainly selects rather than update/inserts.

Few additional questions i have:

* I can see Tempdb/templog spike before everything else and seem to set the latency on an upward trend, if i can see the "commits" on DB A, is it possible that DB B is the cause which then makes DB A slow? Note all the logs/files are on the same disk, but our customer has discounted this as the cause.

* In the final graph the biggest proportion of Wait time is other waits, from reading i have done on the forum I can see that this is non-IO waits, so does this imply the issue is actually elsewhere?

Thanks,

Mike

mandevil

Let me verify if WRITELOG is included in i/o waits. I think it should be, but want to make sure.

This may be easier to discuss on a phone call... Can you open a support case and mention you have been working with me on this?

We can coordinate a time next week to hop on a screenshare and investigate more. (I'm currently OOO until Friday)

Let me know your thoughts.

mike.king1

Yeah that's great. I've raised the support call, so we'll arrange a call next week.

thanks,

Mike

glutenfreesql

I just wanted to clarify that when commit is run, it's not necessarily the entire transaction that is being persisted to disk. There is a continual process of persisting the transaction log to disk, even for uncommitted transactions.

SQL writes uncommitted transactions to the transaction log, especially on large transactions. The log will be written to disk, and associated data to the data file. If there is a system outage, if the commit statement cannot be found upon startup, then the transaction will be rolled back, and the accurate data will be restored from the transaction log.

This blog post says it well. http://www.sqlnotes.info/2011/10/04/sql-server-transaction-log-buffers/

"Log buffer is a small contiguous memory structure, only 60k maximum, to host in memory transaction logs per database. When the transaction is committed, entire buffer will be written to transaction log file before commit finishes. While running a big transaction, the log buffer will be filled up immediately. As this happens, the buffer will be forced to be written to the disk and being cleaned up for rest of the transactions. In concurrent transaction within one database scenario, the log buffer contains mixed logs from all active transactions. Any one of the transaction gets committed or the 60k buffer gets full will cause entire buffer to be written."

mandevil

glutenfreesql

That makes sense. Thanks for interacting with me on my first ever THWACK comment.

jsql

Where do I find that chart - Write Latency Compared to Top Files on D..... ?

bmrad

It's under the Storage IO tab. Drill into an hour, then you will see the latency comparison option.

Here is a link to our online demo for an Oracle database: http://database.demo.solarwinds.com/iwc/storageIo.iwc?repo_id=1&db_id=1011&day=Jul+26!991532581200000&time=-1&dType=0&dI…