4

Each day is experiencing about 1GB sum total of all the transaction log backups that day, while at the end of that week the Full DB backup is about 180MB. For a business database for buying/selling things from/to vendors/customers the total size of a days worth of transaction log backups is at least 10 times larger than I would expect it should be in comparison to the size of the actual database.

How do I find what sql insert/update/delete/etc operations are causing so many / such large transactions? I'm envisioning that there is some bad code somewhere that re-writes an entire table just to update/insert 1 row, or something that is updating the same rows over and over again. I'd like to know what the bad transaction(s) are before going through all the db application code.

Most questions, including Why Does the Transaction Log Keep Growing or Run Out of Space? and other articles deal with people who have a transaction log file that keeps growing, usually due to them never backing it up. That is NOT the case with my problem. My transaction log file is no longer increasing in size, my question is about how to find what transactions are causing the regular large size of each of the backups, not the size of the log file.

We have an MS SQL Server 2012 database where we are

  • Using the Full recovery model
  • Weekly full backups, on Friday nights. (.bak)
  • Nightly differential backups (.dif)
  • 3 times per day transaction log backups (.trn) (Edit: it has been pointed out this should be much more often for better RPO)
  • all backups use compression.
  • DB is only used during regular office hours
  • DB has an application to perform a variety of tasks including some scheduled ones

I realise the actual sizes listed below are not large in the scheme of things due to this DB being only a few months old, but if this trend continues as the DB grows, I'm expecting trouble on multiple fronts. Here is the last 2 week's worth of backup file sizes.

14/11/2014  11:05 PM       200,873,984 Production_backup_2014_11_14_230500_8220928.trn
14/11/2014  11:18 PM       173,499,904 Production_backup_2014_11_14_231753_3214232.bak
15/11/2014  06:00 AM       321,033,728 Production_backup_2014_11_15_060001_9915061.trn
15/11/2014  10:00 AM            47,616 Production_backup_2014_11_15_100001_1784634.trn
15/11/2014  02:00 PM            59,392 Production_backup_2014_11_15_140001_0461018.trn
15/11/2014  06:00 PM            62,976 Production_backup_2014_11_15_180001_5854303.trn
15/11/2014  11:05 PM        71,506,432 Production_backup_2014_11_15_230501_3937283.dif
16/11/2014  06:00 AM        12,906,496 Production_backup_2014_11_16_060009_1822596.trn
16/11/2014  10:00 AM            11,776 Production_backup_2014_11_16_100001_2205645.trn
16/11/2014  02:00 PM            12,288 Production_backup_2014_11_16_140000_7731183.trn
16/11/2014  06:00 PM            12,288 Production_backup_2014_11_16_180001_4459573.trn
16/11/2014  11:05 PM        73,329,664 Production_backup_2014_11_16_230501_1010172.dif
17/11/2014  06:00 AM            12,288 Production_backup_2014_11_17_060001_2761826.trn
17/11/2014  10:00 AM        41,998,848 Production_backup_2014_11_17_100004_9331208.trn
17/11/2014  02:00 PM       167,330,304 Production_backup_2014_11_17_140004_6334692.trn
17/11/2014  06:00 PM       161,651,712 Production_backup_2014_11_17_180007_0122447.trn
17/11/2014  11:05 PM        92,433,408 Production_backup_2014_11_17_230501_6387196.dif
18/11/2014  06:00 AM       333,844,480 Production_backup_2014_11_18_060001_5745763.trn
18/11/2014  10:00 AM       126,087,680 Production_backup_2014_11_18_100005_0370500.trn
18/11/2014  02:00 PM       166,028,288 Production_backup_2014_11_18_140005_3971911.trn
18/11/2014  06:00 PM       179,916,288 Production_backup_2014_11_18_180006_2898091.trn
18/11/2014  11:05 PM        96,823,296 Production_backup_2014_11_18_230501_5082355.dif
19/11/2014  06:00 AM       339,789,312 Production_backup_2014_11_19_060002_0077560.trn
19/11/2014  10:00 AM       127,332,352 Production_backup_2014_11_19_100006_4801078.trn
19/11/2014  02:00 PM       174,851,584 Production_backup_2014_11_19_140006_7360844.trn
19/11/2014  06:00 PM       170,896,384 Production_backup_2014_11_19_180006_2771851.trn
19/11/2014  11:05 PM       100,923,904 Production_backup_2014_11_19_230501_2174429.dif
20/11/2014  06:00 AM       341,084,160 Production_backup_2014_11_20_060000_7971034.trn
20/11/2014  10:00 AM       143,212,544 Production_backup_2014_11_20_100005_7464239.trn
20/11/2014  02:00 PM       168,745,472 Production_backup_2014_11_20_140007_3616365.trn
20/11/2014  06:00 PM       169,514,496 Production_backup_2014_11_20_180006_5721553.trn
20/11/2014  11:05 PM       104,629,248 Production_backup_2014_11_20_230501_0945522.dif
21/11/2014  06:00 AM       345,049,088 Production_backup_2014_11_21_060003_5997426.trn
21/11/2014  10:00 AM       131,839,488 Production_backup_2014_11_21_100004_0817301.trn
21/11/2014  02:00 PM       179,260,416 Production_backup_2014_11_21_140006_1959629.trn
21/11/2014  06:00 PM       185,633,280 Production_backup_2014_11_21_180006_0060725.trn
21/11/2014  11:05 PM       211,755,520 Production_backup_2014_11_21_230500_9492206.trn
21/11/2014  11:19 PM       184,960,512 Production_backup_2014_11_21_231900_1599462.bak
22/11/2014  06:00 AM       342,386,688 Production_backup_2014_11_22_060003_6139255.trn
22/11/2014  10:00 AM           114,176 Production_backup_2014_11_22_100003_8050593.trn
22/11/2014  02:00 PM           131,584 Production_backup_2014_11_22_140001_5545860.trn
22/11/2014  06:00 PM           131,584 Production_backup_2014_11_22_180004_6338691.trn
22/11/2014  11:05 PM        74,345,984 Production_backup_2014_11_22_230501_0706925.dif
23/11/2014  06:00 AM        13,621,760 Production_backup_2014_11_23_060005_1215593.trn
23/11/2014  10:00 AM            12,288 Production_backup_2014_11_23_100000_8636227.trn
23/11/2014  02:00 PM           148,992 Production_backup_2014_11_23_140001_5174270.trn
23/11/2014  06:00 PM            12,800 Production_backup_2014_11_23_180001_0560033.trn
23/11/2014  11:05 PM        76,475,904 Production_backup_2014_11_23_230500_6863628.dif
24/11/2014  06:00 AM            24,576 Production_backup_2014_11_24_060002_1207776.trn
24/11/2014  10:00 AM        99,911,168 Production_backup_2014_11_24_100001_6216355.trn
24/11/2014  02:00 PM       161,881,088 Production_backup_2014_11_24_140006_1306524.trn
24/11/2014  06:00 PM       163,761,664 Production_backup_2014_11_24_180001_1006240.trn
24/11/2014  11:05 PM        96,010,752 Production_backup_2014_11_24_230500_8739860.dif
25/11/2014  06:00 AM       333,105,664 Production_backup_2014_11_25_060001_1277451.trn
25/11/2014  10:00 AM       141,830,656 Production_backup_2014_11_25_100004_1112999.trn
25/11/2014  02:00 PM       164,597,248 Production_backup_2014_11_25_140001_6337935.trn
25/11/2014  06:00 PM       176,773,632 Production_backup_2014_11_25_180004_9749028.trn
25/11/2014  11:05 PM       102,029,312 Production_backup_2014_11_25_230500_9038297.dif
26/11/2014  06:00 AM       334,088,704 Production_backup_2014_11_26_060001_1548298.trn
26/11/2014  10:00 AM       127,079,424 Production_backup_2014_11_26_100001_7924674.trn
26/11/2014  02:00 PM       165,528,576 Production_backup_2014_11_26_140005_2202075.trn
26/11/2014  06:00 PM       165,344,256 Production_backup_2014_11_26_180000_9116237.trn
26/11/2014  11:05 PM       104,935,936 Production_backup_2014_11_26_230500_6289926.dif
27/11/2014  06:00 AM       336,645,120 Production_backup_2014_11_27_060000_8290121.trn
27/11/2014  10:00 AM       128,401,920 Production_backup_2014_11_27_100008_6395607.trn
27/11/2014  02:00 PM       163,676,160 Production_backup_2014_11_27_140004_6019843.trn
27/11/2014  06:00 PM       167,849,472 Production_backup_2014_11_27_180005_9136346.trn
27/11/2014  11:05 PM       108,699,136 Production_backup_2014_11_27_230500_8885145.dif
28/11/2014  06:00 AM       338,519,040 Production_backup_2014_11_28_060001_1061047.trn
28/11/2014  10:00 AM       129,424,896 Production_backup_2014_11_28_100005_8038388.trn
28/11/2014  02:00 PM       171,059,712 Production_backup_2014_11_28_140014_1188080.trn

The db application doesn't run between 3am sunday until around 8am on the the Monday, so the .trn files over the weekend are mostly small as I would expect. I think I've mucked up the sequence of the weekly DB shrink and re-index so the backups around that are larger than they should be, but each .trn file after that should be quite small.

3
  • Please reconsider shrinking your data files on a schedule. You should also reconsider your 8 hour RPO. Nov 28 '14 at 8:30
  • 3
    Did you say shrink and re-index? You know those have conflicting effects, right? Why are you ever shrinking anything, when you know it's going to grow again? Did you really read the whole page you linked to at the beginning of your question? PLEASE STOP SHRINKING THINGS. Nov 28 '14 at 12:38
  • I'd be inclined to trace for an hour and run it through ClearTrace. Pay attention to the most frequently executed queries with writes. Any tables stand out as potentially supporting queue type behaviour? Nov 29 '14 at 13:30
1

You should be able to dump the output from fn_dump_dblog into a table to sort if needed. I'd recommend you decrease your backup interval to maybe every hour or so to make it easier to analyze the data (plus it will improve your ability to recover and reduce the time each backup takes). I tested a 453mb log and it took 10 minutes to read all 6.7 million rows. If you have a small one to test, take a look so you get an idea of which columns you want to look at like Paul Randal does in this post. I found this blog entry that had some good info on the different operations and more on how to analyze the log.

If you want to watch live transactions or get some nice filtering, I'd use an extended events session since you are on 2012. You can use the wizard if you aren't familiar with it and try the query detail sampling template and add corresponding starting events which should give you a good idea of what statements/transactions are executing. A combination of the two methods might help you correlate how much log a transaction makes since the transaction id is exposed to extended events and it is a column returned by the function.

1

Have you considered creating and running an extended event to monitor what queries are running to generate all those log records? The following post by Paul Randal touches upon two events to perhaps get started with.

http://sqlperformance.com/2013/11/sql-performance/transaction-log-monitoring

I haven't played with the transaction_log event or Database Log File IO Tracking template myself but have had plenty of success with other events over the years. Depending on what the transaction_log event or DB Log File IO template return you might also want to consider adding the sqlserver.sp_statement_completed event and sqlserver.sql_text and sqlserver.tsql_stack actions with a [Duration]>=(NNNNNNN) predicate to return any statements running over NNNNNNN microseconds.

1

I would suggest you run a profiler on the database with tsql replay and analyse the results. Another idea is to take a look at your plancache and check if there are query plans which will produce a huge overhead.

Another idea is to run perfmon on the sql server and run a profiler too. That way you might seen some big write accesses which you correlate to the profiler values too. Hopefully this will give you a good hint.

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.