PREEMPTIVE_OS_FILEOPS Waits and Filestream Restores

We had a case over the weekend where our automated restore process at client got hung up on this wait type, for a single database. What was the unique characteristic about this relatively medium (2-300 GB) database? It had a lot of filestream data–it seemed like the file count wasn’t that high, but my guess is the filestream data was the majority of the data in that database. When the job hung up, the restore had been waiting on PREEMPTIVE_OS_FILEOPS for over a day and still had a null value for percentage complete.

One interesting thing that happened was after I attempted to kill the restore process, it remained in place. My restore task was running in SQLCMD, so I went a step further, and killed the SQLCMD process on the server. The SPID in the database stayed alive, and since it was a non-production environment, and a weekend, I restarted the SQL service.

Per SQLSkills this wait type means “This wait type is a generic wait for when a thread is calling one of several Windows functions related to the file system”, and more commonly you see it on the end of a backup, when SQL Server is growing a log file, which does not benefit from instant file initialization (IFI). In our case the server did not have IFI enabled, and I suspect this was one of the contributors to the problem. After we enabled IFI, the restore complete in just under three hours.

EXEC sp_configure filestream_access_level, 2
RECONFIGURE
GO

CREATE DATABASE Filestream
ON
PRIMARY ( NAME = Arch1,
FILENAME = 'c:\data\archdat1.mdf'),
FILEGROUP FileStreamGroup1 CONTAINS FILESTREAM( NAME = FSData,
FILENAME = 'c:\filestream')
LOG ON ( NAME = Archlog1,
FILENAME = 'c:\data\archlog1.ldf')
GO

create table fs_table
(id INT IDENTITY (1,1),
UI UNIQUEIDENTIFIER ROWGUIDCOL NOT NULL UNIQUE,
FS_Data varbinary(max) filestream NULL)

Those are the database objects–I then used PowerShell to create some files, and generate an insert script.

$i=1
while ($i -le 10001)
{new-item -ItemType file -Path "C:\fstemp\" -Name Fs$i.txt -Value "Text file $i"; $i++}

$i=1
while ($i -lt 10001)
{add-content C:\temp\fsinsert.sql "`nINSERT INTO [dbo].[FS_Table] (UI, FS_Data) VALUES (NEWID(),(SELECT * FROM OPENROWSET(BULK N'C:\fstemp\FS$i.txt', SINGLE_BLOB) AS Image$i))"; $i++}

Those are just a couple of loops that create 10000 files and then insert them into the database. The files are very small (13-14 bytes), but it would be a very representative test. I kicked off a restore and ran procmon to see what the SQL Server was doing. SQL Server first queried the filestream directory for each file.

SQL Server is doing four operations for each file:

• Create File
• Query Standard Information
• Write File
• Close File

Since my files are very small, this happens very quickly, but it has to happen 5000x, which gives me enough time to prove this behavior. You should note that I was able to control for IFI being enabled–there was a performance improvement that I think is related to the number of operations. Instead of doing the four operations per file SQL Server appears to only creating and closing each file. Performance on my test instance was inconsistent, but I was working in a constrained VM (my CPU fan has been running all morning).

I suspect this restore process would be impacted by either a large number of files or a large volume of data. This can be confusing, as even though the restore process is running, this isn’t reflected in percent complete for the restore.

I hope you learned something in this post, I know I did. also, don’t #$%^ing store files in your database, unless you like hitting yourself with a hammer.