SMB Opportunistic Locking Behavior
Behold the mysterious world of OpLocks (Opportunistic Locking). Often OpLocks will be disabled by a user or system administrator in order to help address a performance problem. And this practice might not always be the best course of action. Understanding how OpLocks behave in a trace can provide you more information so you can properly diagnose an OpLock issue.
What is an OpLock
OpLocks are used to enhance performance on a network where multiple people are accessing the same file. By the way these are somewhat different than the notion of "optimistic locking" in databases. Imagine that you are the only person editing a file on a server. Because nobody else has the file open, you could cache your changes locally for both read and writes. This would improve your performance because you wouldn't have to go over the network for any of this cached information.
Now imagine somebody else opens the file after you do. If you have changes in your local cache, this new user won't see those changes. OpLocks, or more specifically a break of an OpLock in this case, is how your computer is told to flush its local cache.
In general there are different levels of OpLocks, like Batch, Exclusive, and Level 2 which define how a file can be shared with respect to this local caching. But rather than go into a lot of detail about the specifics, let me point you to some references which do a good job of describing more detail.
- https://en.wikipedia.org/wiki/Opportunistic_Locking
- https://blogs.msdn.com/openspecification/archive/2009/05/22/client-caching-features-oplock-vs-lease.aspx
- File System Overview
- SMB
- SMB2
Example OpLocks in a Trace
In this example we have two clients - Windows XP (SMB) and Windows Vista (SMB2) viewing the same directory on a 3rd computer using explorer. As explorer reads the data, file collisions occur which cause various OpLock traffic. We will focus on a piece of this traffic and describe how the OpLock behavior is working. Once you see what normal traces look like, you can use this information to troubleshoot issues with OpLocks.
Setting up the Trace in Network Monitor
One nice feature I like to use is aliases. This gives me the ability to change IP addresses to something I can better recognize, especially when working with 3 machines as in this case. By right clicking on an address in the source or destination column, I can select "Create Alias for..." and then provide a friendly name. In my case I will call them SRV for the server, and Vista and XP for each client.
The second thing I'll do is add the display filter "SMB or SMB2" so that I only see these protocols. This will get rid of any TCP or unrelated traffic for this demonstration.
Finally, I also added comments to this particular trace. Comments are an easy way to document the traffic that occurs for others to learn from. By adding the "Comment Title" as a column, these comments show up and provide some commentary about what is going on. By the way, the # next to the frame number signifies which frames have a comment. Alternatively you can keep the comment tab open to see each comment as you click on frame. Using the latter method enabled you to see more detail in the description column.
Traffic Analysis
I copy and pasted the data from the Network Monitor summary view. Here is the traffic that occurs between the 3 machines:
Frame Number |
Source |
Destination |
Description |
Comment Title |
3110# |
Vista |
SRV |
SMB2:C CREATE (0x5), Context=DHnQ,Create Durable Open Handle, Context=MxAc,Maximal Access, Context=QFid,Request Unique File ID , FileName = ...\Documents\desktop.ini@#3110 |
Vista Client Opens desktop.ini, request oplock batch |
3111 |
XP |
SRV |
SMB:C; Transact2, Query Path Info, Query File Basic Info, Pattern = \...\Documents\desktop.ini |
|
3112 |
SRV |
XP |
SMB:C; Locking Andx, FID = 0x400E (\...\Documents\desktop.ini@#2519) |
|
3113 |
SRV |
XP |
SMB:R; Transact2, Query Path Info, Query File Basic Info |
|
3114# |
SRV |
Vista |
SMB2:R CREATE (0x5) Interim Response, FileName = ...\Documents\desktop.ini@#3110 |
Server response that this command is Pending |
3116# |
XP |
SRV |
SMB:C; Close, FID = 0x400E , FileName=\...\Documents\desktop.ini@#2519 |
XP Client closes desktop.ini |
3117 |
SRV |
XP |
SMB:R; Close, FID = 0x400E , FileName=\...\Documents\desktop.ini@#2519 |
|
3118# |
SRV |
Vista |
SMB2:R CREATE (0x5), Context=MxAc,Maximal Access, Context=DHnQ,Create Durable Open Handle, Context=QFid,Request Unique File ID, FID=0xFFFFFFFF002000C5(...\Documents\desktop.ini@#3110) |
Server responds to the Vista client with batch oplock granted |
3119# |
XP |
SRV |
SMB:C; Nt Create Andx, FileName = \...\Documents\desktop.ini |
XP client wants to open desktop.ini again |
3120# |
SRV |
Vista |
SMB2:N OPLOCK BREAK (0x12), Oplock Level II Notification, FID=0xFFFFFFFF002000C5,FileName=...\Documents\desktop.ini@#3110 |
Server send Oplock break to Level 2 Notification to Vista client |
3122 |
Vista |
SRV |
SMB2:C CREATE (0x5), Context=DHnQ,Create Durable Open Handle, Context=MxAc,Maximal Access, Context=QFid,Request Unique File ID , FileName = ...\Links@#3122 |
|
3123 |
SRV |
Vista |
SMB2:R CREATE (0x5), Context=MxAc,Maximal Access, Context=QFid,Request Unique File ID, FID=0xFFFFFFFF002000CD(...\Links@#3122) |
|
3124# |
Vista |
SRV |
SMB2:A OPLOCK BREAK (0x12), Oplock Level II Acknowledgment, FID=0xFFFFFFFF002000C5,FileName=...\Documents\desktop.ini@#3110 |
Vista Client sends Oplock Level 2 Acknowledge to Server |
3125# |
SRV |
Vista |
SMB2:R OPLOCK BREAK (0x12), Oplock Level II Response, FID=0xFFFFFFFF002000C5,FileName=...\Documents\desktop.ini@#3110 |
Server sends break OpLock break to Level 2 response |
3126 |
SRV |
XP |
SMB:R; Nt Create Andx, FID = 0x8008 (\...\Documents\desktop.ini@#3119) |
As we start in frame 3110, we see that the Vista client opens desktop.ini and requests a Batch OpLock. Since the OpLock request is part of the SMB Create, the actual request is buried in the frame details.
Frame: Number = 3110, Captured Frame Length = 386, MediaType = ETHERNET
...
+ SMBOverTCP: Length = 264
- SMB2: C CREATE (0x5), Context=DHnQ,Create Durable Open Handle, Context=MxAc,Maximal Access, Context=QFid,Request Unique File ID , FileName = paullo\Documents\desktop.ini@#3110
SMBIdentifier: SMB
+ SMB2Header: C CREATE (0x5),TID=0x0009, MID=0x04F2, PID=0xFEFF, SID=0x0001
- CCreate: 0x1
StructureSize: 57 (0x39)
SecurityFlags: 0 (0x0)
RequestedOplockLevel: SMB2_OPLOCK_LEVEL_BATCH - A batch oplock is requested.
...
Frames 3111-3113 contain other traffic our XP client is doing which also happens to touch desktop.ini.
In frame 3114 the server returns a STATUS_PENDING because the server is not yet ready to respond.
Frame: Number = 3114, Captured Frame Length = 194, MediaType = ETHERNET
...
+ SMBOverTCP: Length = 73
- SMB2: R CREATE (0x5) Interim Response, FileName = paullo\Documents\desktop.ini@#3110
SMBIdentifier: SMB
- SMB2Header: R CREATE (0x5),TID=0x0000, MID=0x04F2, PID=0x0000, SID=0x0001
StructureSize: 64 (0x40)
Epoch: 0 (0x0)
+ Status: 0x103, Facility = FACILITY_SYSTEM, Severity = STATUS_SEVERITY_SUCCESS, Code = (259) STATUS_PENDING
Command: CREATE (0x5)
...
Frame: Number = 3114, Captured Frame Length = 194, MediaType = ETHERNET
The XP Client is closing desktop.ini so the server will wait for that to complete first. This way it can grant the Batch OpLock the Vista client is requesting. If the XP client keeps the file open, the OpLock might have been denied. Once it completes, the SMB2 Create response is finally returned and the Batch OpLock is granted in frame 3118.
Frame: Number = 3118, Captured Frame Length = 394, MediaType = ETHERNET
...
+ SMBOverTCP: Length = 272
- SMB2: R CREATE (0x5), Context=MxAc,Maximal Access, Context=DHnQ,Create Durable Open Handle, Context=QFid,Request Unique File ID, FID=0xFFFFFFFF002000C5(paullo\Documents\desktop.ini@#3110)
SMBIdentifier: SMB
+ SMB2Header: R CREATE (0x5),TID=0x0000, MID=0x04F2, PID=0x0000, SID=0x0001
- RCreate: 0x1
StructureSize: 89 (0x59)
OplockLevel: SMB2_OPLOCK_LEVEL_BATCH - A batch oplock was granted.
...
Frame: Number = 3118, Captured Frame Length = 394, MediaType = ETHERNET
Next another create request for desktop.ini appears in frame 3119 as the XP client wants to reopen the file again. Since this is a second open of the same file, the server has to notify the Vista client to break its OpLock to Level 2 in frame 3120.
3119# |
XP |
SRV |
SMB:C; Nt Create Andx, FileName = \...\Documents\desktop.ini |
XP client wants to open desktop.ini again |
3120# |
SRV |
Vista |
SMB2:N OPLOCK BREAK (0x12), Oplock Level II Notification, FID=0xFFFFFFFF002000C5,FileName=...\Documents\desktop.ini@#3110 |
Server send Oplock break to Level 2 Notification to Vista client |
The exact algorithm for breaking an OpLock is explained in the system documents referenced above and is related to the file system, so I won't go over those specifics. But in general since two clients have the same file open, the local client caching algorithm has to change. The Vista client can no longer assume the file won't be changed and there for can't cache the file locally.
In frame 3124, the "notify" is acknowledged and now the server can respond back to the Vista client in frame 3125 that the OpLock was broken to level 2. Finally Frame 3126 is the response back to the XP client that the open on desktop.ini has been completed.
3124# |
Vista |
SRV |
SMB2:A OPLOCK BREAK (0x12), Oplock Level II Acknowledgment, FID=0xFFFFFFFF002000C5,FileName=...\Documents\desktop.ini@#3110 |
Vista Client sends Oplock Level 2 Acknowledge to Server |
3125# |
SRV |
Vista |
SMB2:R OPLOCK BREAK (0x12), Oplock Level II Response, FID=0xFFFFFFFF002000C5,FileName=...\Documents\desktop.ini@#3110 |
Server sends break OpLock break to Level 2 response |
3126 |
SRV |
XP |
SMB:R; Nt Create Andx, FID = 0x8008 (\...\Documents\desktop.ini@#3119) |
Troubleshooting Performance and OpLocks
The previous example worked smoothly as it usually does. But in some instances an OpLock request does not get a response in a timely fashion. In those cases you might see a 35 second delay which is the default timeout for an OpLock. This could cause application timeouts or what seems like a hanging application from the user’s perspective. Also this 35 second delay is a sure sign OpLocks are involved in a performance issue. Just remember that as shown in the example above, multiple clients are probably involved. And it's this type of interaction you must learn to recognize in order to troubleshoot a performance problem with OpLocks.
Comments
- Anonymous
January 01, 2003
thanks