SQL Server transaction log suddenly growing

[pshute]

We've been backing up an VM running SQL Server for a long time, and suddenly the drive containing the datastore is losing space. It looks to me like the transaction log for just one of the databases has started growing.

The backup history still has a tick next to "Truncating SQL server transaction logs" like it has in the past.

Can anyone suggest how to diagnose this?

https://www.veeam.com/kb1746 suggests checking VeeamGuestHelper.log file or VeeamVSSSupport.log in C:\ProgramData\Veeam\Backup\ for database access errors, but I don't see either of those files in there.

We're running VBR 9.5.0.1038.

[Mike Resseler]

Peter,

Have a look at the drive that contains the transaction logs and see if there is a specific database that has growth in the logs. There are factors that can delay truncation such as a huge transaction that fails to finish or similar. It might be already good to figure out what database is being the issue and then troubleshoot further from there.

A transaction log also can grow (whatever the reason at that moment is) but doesn't automatically give his space back. Reducing the physical size of a log file requires shrinking that specific file

Let us know
Mike

[pshute]

Thanks, yes, it's only the one database. We track the file sizes, and the only one growing is this one particular log file.

I know truncation won't make the file smaller, but it should allow parts of it to be reused, and suddenly this isn't happening for this file. Is there any way to confirm that VBR performed truncation successfully on this particular file?

[Mike Resseler]

If you don't see any errors or warnings in the backup, it should truncate the logs successfully.

You also should see it in the statistics: https://helpcenter.veeam.com/docs/backu ... tml?ver=95

Can you check?

thanks
Mike

[pshute]

I am not seeing statistics like that for this server. Am I looking in the wrong place? This is what I see:

Code: Select all

26/01/2018 9:01:25 PM :: Queued for processing at 26/01/2018 9:01:25 PM  
26/01/2018 9:01:25 PM :: Required backup infrastructure resources have been assigned  
26/01/2018 10:59:32 PM :: VM processing started at 26/01/2018 10:59:32 PM  
26/01/2018 10:59:32 PM :: VM size: 228.0 GB (227.9 GB used)  
26/01/2018 10:59:33 PM :: Getting VM info from vSphere  
26/01/2018 11:01:19 PM :: Using guest interaction proxy xxx (Same subnet)  
26/01/2018 11:01:22 PM :: Inventorying guest system  
26/01/2018 11:01:24 PM :: Preparing guest for hot backup  
26/01/2018 11:01:48 PM :: Releasing guest  
26/01/2018 11:01:48 PM :: Creating VM snapshot  
26/01/2018 11:01:50 PM :: Getting list of guest file system local users  
26/01/2018 11:03:34 PM :: Saving [General_Container] yyy.vmx  
26/01/2018 11:03:34 PM :: Saving [General_Container] yyy.vmxf  
26/01/2018 11:03:35 PM :: Saving [General_Container] y.nvram  
26/01/2018 11:03:35 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 1 [nbd]  
26/01/2018 11:03:36 PM :: Hard disk 1 (50.0 GB) 2.9 GB read at 14 MB/s [CBT] 
26/01/2018 11:08:16 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 2 [nbd]  
26/01/2018 11:08:17 PM :: Hard disk 2 (60.0 GB) 60.0 GB read at 24 MB/s [CBT] 
26/01/2018 11:10:27 PM :: CBT data is invalid, failing over to legacy incremental backup. No action is required, next job run should start using CBT again. If CBT data remains invalid, follow KB1113 to perform CBT reset. Usual cause is power loss.  
26/01/2018 11:19:59 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 3 [nbd]  
26/01/2018 11:20:00 PM :: Hard disk 3 (20.0 GB) 228.0 MB read at 16 MB/s [CBT] 
26/01/2018 11:21:24 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 4 [nbd]  
26/01/2018 11:21:25 PM :: Hard disk 4 (30.0 GB) 30.0 GB read at 25 MB/s [CBT] 
26/01/2018 11:34:37 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 5 [nbd]  
26/01/2018 11:34:38 PM :: Hard disk 5 (40.0 GB) 7.7 GB read at 27 MB/s [CBT] 
26/01/2018 11:41:49 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 6 [nbd]  
26/01/2018 11:41:50 PM :: Hard disk 6 (28.0 GB) 25.3 GB read at 38 MB/s [CBT] 
26/01/2018 11:55:39 PM :: Removing VM snapshot  
26/01/2018 11:56:27 PM :: Saving GuestMembers.xml  
26/01/2018 11:56:29 PM :: Finalizing  
26/01/2018 11:56:30 PM :: Truncating transaction logs  
26/01/2018 11:56:32 PM :: Truncating SQL server transaction logs  
26/01/2018 11:57:11 PM :: Swap file blocks skipped: 4.0 MB  
26/01/2018 11:57:11 PM :: Deleted file blocks skipped: 35.0 GB  
26/01/2018 11:57:13 PM :: Busy: Source 99% > Proxy 21% > Network 0% > Target 0%  
26/01/2018 11:57:13 PM :: Primary bottleneck: Source  
26/01/2018 11:57:13 PM :: Network traffic verification detected no corrupted blocks  
26/01/2018 11:57:13 PM :: Processing finished at 26/01/2018 11:57:13 PM

[Mike Resseler]

I can see from those that the transaction logs are being truncated. So that looks good. Is the log still growing?

[pshute]

But why does my log look so different to the one in the link you provided? I don't see any entries like "Enumerating SQL Server databases", etc, like in that example.

The growth was happening overnight, coinciding with a nightly import job, which has been running for years. The only time we've seen growth like this before is when backups have been failing.

We stopped the import job on Thursday, and there was no growth in the three days since. We will run it manually today and see what happens.

[Mike Resseler]

The screenshot in the link shows the data from a transaction log backup job and not for the SQL backup job. That was a mistake from my side. Sorry. Keep us informed about the outcome

[pshute]

The log file grew again last night. I googled around and found this command to run in sql: select name, log_reuse_wait_desc from sys.databases

That tells me the reason any log files are waiting to reuse space. All our databases returned "NOTHING" except the one that's been growing. It returned "REPLICATION".

There's no replication configured for it. Apparently this database became corrupt and was repaired twice the week before I noticed the increase in size. It appears that one of the repairs, or something else the admin did and has forgotten, has got it thinking it's not allowed to reuse log space.

I ran this command: EXEC sp_removedbreplication databasename and now it also is reporting "NOTHING" in the above command.

I ran DBCC SQLPERF(logspace) and it now reports the log file has 0.3% space used. Previously it was 83%. Ie the truncation veeam did was waiting to take effect.

The file is still big, but my bet is that it will stop growing. I will shrink it back down to a reasonable size soon.

Thanks for your help with this. I wonder if it would be helpful to Veeam users if it detected this kind of problem and reported it in the job log, instead of just "Truncating SQL server transaction logs". Maybe it could check the percentage used of each database, and report if it didn't decrease after truncation. This is perhaps not the role of Veeam, but given the active part it plays in truncation, it might be a good place to alert database admins of impending trouble.

[Mike Resseler]

Peter,

First: I am very happy that you (most probably) found the solution. I like your idea around adding this data but my thought would be more to add it in a Veeam ONE report instead of in the job log. What do you think?

[pshute]

I think it should be in both.

[puran]

Hello,
You can go through to the following links:
https://support.microsoft.com/en-in/hel ... sql-server
http://www.sqlserverlogexplorer.com/err ... ction-full
This will give you some more helpful information.