- Home
- Windows Server
- Ask the Directory Services Team
- Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))
- Subscribe to RSS Feed
- Mark as New
- Mark as Read
- Bookmark
- Subscribe
- Printer Friendly Page
- Report Inappropriate Content
First published on TechNet on Apr 09, 2009
In this final scenario we will see a file being replicated successfully, but where the replication appears to be very slow. A bandwidth throttle has been configured within the DFSR replication group schedule to restrict traffic to 128Kbps. This is useful in understanding how throttling works as well as determining that slow replication has been configured intentionally.
(throttleupstream - Dfsr00010 - 2008.log and throttledownstream - Dfsr00012 - 2008.log)
These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x86SRV11 in the contoso.com domain. The logs are from 2008x86SRV10 (the upstream) and 2008x86SRV11 (the downstream). The replication schedule is at 128 Kilobits per second and the file being replicated is named “imageres.dll”. Debug logging severity is set to 5 to see additional details.
<Upstream> 20080909 17:01:15.186 2880 USNC 2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record: << file is created on the upstream server.
+ fid 0x500000000BB0A
+ usn 0x27d2a30
+ uidVisible 0
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90
+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90
+ parent {43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080910 00:01:15.186 GMT (0x1c912d857ca1d84)
+ createTime 20080910 00:01:15.186 GMT
+ csId {43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name imageres.dll << file named ‘imageres.dll’
+
<Upstream> 20080909 17:01:15.186 2880 USNC 2615 UsnConsumer::CreateNewRecord ID record created from USN_RECORD:
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x500000000BB0A
+ ParentFileRefNumber: 0xC00000000BA6B
+ USN: 0x27d2a30
+ TimeStamp: 20080909 17:01:15.186 Pacific Standard Time
+ Reason: Basic Info Change Close Data Extend Data Overwrite File Create
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: imageres.dll
+
<Upstream> 20080909 17:01:15.186 2880 LDBX 4300 Ldb::UpdateLastVersion Updating lastVersion:90
<Upstream> 20080909 17:01:15.186 2880 LDBX 3340 LdbManager::WakeUpSleepers Wake up callback 009786F8
<Upstream> 20080909 17:01:15.186 2956 UPST 1399 UpstreamTransport::FlushVvUp 002F58A8
<Upstream> 20080909 17:01:15.186 2956 UPST 1417 UpstreamTransport::FlushVvUp send connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} seqNumber:12 status:0 vvGeneration:8 vvUp:
<Upstream> 20080909 17:01:15.186 3980 SRTR 1880 SERVER_RequestVersionVector Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} seqNumber:13 changeType:all
<Upstream> 20080909 17:01:15.186 3980 SRTR 1927 SERVER_AsyncPoll Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85}
<Upstream> 20080909 17:01:15.186 3980 UPST 1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:002F58A8
<Upstream> 20080909 17:01:15.186 2956 UPST 1399 UpstreamTransport::FlushVvUp 002F58A8
<Upstream> 20080909 17:01:15.186 2956 UPST 1417 UpstreamTransport::FlushVvUp send connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} seqNumber:13 status:0 vvGeneration:8 vvUp:{0E1F0993-5130-4BB2-B409-FD13366B9A0C} |-> { 32, 33}
+ {5CB120DE-D2C2-452A-8280-B45FC155224F} |-> { 84..90}
+
<Upstream> 20080909 17:01:15.186 3980 SRTR 882 SERVER_RequestUpdates Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} credits:32 requestType:all
<Upstream> 20080909 17:01:15.186 3980 UPST 88 UpdateBuffer::UpdateBuffer UpdateBuffer created. connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}
<Upstream> 20080909 17:01:15.202 2956 JOIN 1122 Join::SubmitUpdate LDB Updating ID Record:
+ fid 0x500000000BB0A
+ usn 0x27d2a30
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080910 00:01:15.186 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90
+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90
+ parent {43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080910 00:01:15.186 GMT (0x1c912d857ca1d84)
+ createTime 20080910 00:01:14.874 GMT
+ csId {43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name imageres.dll
+
<Upstream> 20080909 17:01:15.202 3980 SRTR 1927 SERVER_AsyncPoll Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85}
<Upstream> 20080909 17:01:15.202 3980 UPST 1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:002F5308
<Upstream> 20080909 17:01:15.202 2956 JOIN 1167 Join::SubmitUpdate Sent: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 name:imageres.dll connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} csName:throttlerf
<snipped out information documented in other scenarios>
<Downstream> 20080909 17:01:18.905 3188 STAG 1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 state: Downloading (refCount==1)
<Downstream> 20080909 17:01:18.905 3188 STAG 4113 Staging::OpenForWrite name:imageres.dll uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 << upstream server ready to replicate file
<Downstream> 20080909 17:01:18.905 3188 DOWN 6256 DownstreamTransport::DownloadFileAsync rpcAsyncState:045AE088
<Downstream> 20080909 17:01:18.905 3188 DOWN 5970 DownstreamTransport::RpcAsyncPipeDownload rpcAsyncState:045AE088
<Upstream> 20080909 17:01:18.921 696 SRTR 2529 RpcAsyncPipeState::RpcAsyncPipeState this:009210A0 rpcAsyncState:002F58A8 context:00933280 bytePipe:002E8590
<Upstream> 20080909 17:01:18.921 696 SRTR 3051 RawGetFileDataAsyncState::RawGetFileDataAsyncState 009210A0
<Upstream> 20080909 17:01:18.921 696 SRTR 2596 RpcAsyncPipeState::Start this:009210A0
<Upstream> 20080909 17:01:18.921 696 SRTR 2710 RpcAsyncPipeState::InitializeDataReader Starting pipe thread. this:009210A0
<Upstream> 20080909 17:01:18.921 3784 SRTR 3079 RawGetFileDataAsyncState::DataPipeThread Entering data pipe thread. this:009210A0
<Upstream> 20080909 17:04:31.134 928 CFAD 10450 Config::AdReader::Peek Subscriptions Checksum, old = 20953, new = 20953
<Upstream> 20080909 17:09:07.506 3784 SRTR 3132 RawGetFileDataAsyncState::DataPipeThread Exiting data pipe thread. this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2940 RpcAsyncPipeState::Process Push eof this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2969 RpcAsyncPipeState::Process Completing this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2648 RpcAsyncPipeState::ProcessIoCompletion Release this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 3056 RawGetFileDataAsyncState::~RawGetFileDataAsyncState 009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2553 RpcAsyncPipeState::CloseDataPipe this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2556 RpcAsyncPipeState::CloseDataPipe Shutting down pipe. this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2543 RpcAsyncPipeState::~RpcAsyncPipeState this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2553 RpcAsyncPipeState::CloseDataPipe this:009210A0
<Upstream> 20080909 17:09:41.148 928 CFAD 10450 Config::AdReader::Peek Subscriptions Checksum, old = 20953, new = 20953
<Downstream> 20080909 17:01:23.327 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 4100 ms (waitResult 258) << downstream DFSR service replicates a percentage of the file at full bandwidth, then artificially stops replicating.
<Downstream> 20080909 17:01:25.030 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 1700 ms (waitResult 258)
<Downstream> 20080909 17:01:28.436 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 3400 ms (waitResult 258)
<Downstream> 20080909 17:01:38.437 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 10000 ms (waitResult 258)
<Downstream> 20080909 17:01:50.344 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 11900 ms (waitResult 258)
<Downstream> 20080909 17:02:02.751 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 12400 ms (waitResult 258)
<snipped out many repeats of this>
<Downstream> 20080909 17:14:55.987 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 5600 ms (waitResult 258)
<Downstream> 20080909 17:14:58.299 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 2300 ms (waitResult 258)
<Downstream> 20080909 17:15:01.909 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 3600 ms (waitResult 258)
<Downstream> 20080909 17:15:09.018 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 7100 ms (waitResult 258)
<Downstream> 20080909 17:15:18.518 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 9500 ms (waitResult 258) << After roughly 14 minutes the file has been replicated
<Downstream> 20080909 17:15:18.518 3188 DOWN 6093 DownstreamTransport::RpcAsyncPipeDownload Wait completion rpcAsyncState:045AE088 << RPC file download session pipe can be closed.
<Downstream> 20080909 17:15:18.550 3188 INCO 5735 InConnection::RdcGet Update syncInfoHistory
<Downstream> 20080909 17:15:18.550 3188 INCO 5610 InConnection::LogTransferActivity Received RAWGET uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 fileName:imageres.dll connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} stagedSize:12597886
<Downstream> 20080909 17:15:18.550 3188 MEET 1970 Meet::Download Done downloading content updateName:imageres.dll uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 << file has been copied to the staging directory on the downstream server.
This wraps up the 21-part blog series on reading the DFSR debug logs. I hope you found this interesting and helpful.
Understanding DFSR debug logging (Part 1: Logging Levels, Log Format, GUID’s)
Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)
Understanding DFSR debug logging (Part 3: The Log Scenario Format, File Added to Replicated Folder ....
Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows S....
Understanding DFSR debug logging (Part 5: File Modified on Windows Server 2003 R2)
Understanding DFSR debug logging (Part 6: Microsoft Office Word 97-2003 File Modified on Windows Se....
Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Serve....
Understanding DFSR debug logging (Part 8: File Deleted from Windows Server 2003 R2)
Understanding DFSR debug logging (Part 9: File is Renamed on Windows Server 2003 R2)
Understanding DFSR debug logging (Part 10: File Conflicted between two Windows Server 2008)
Understanding DFSR debug logging (Part 11: Directory created on Windows Server 2003 R2)
Understanding DFSR debug logging (Part 12: Domain Controller Bind and Config Polling on Windows Ser....
Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between tw....
Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream betwee....
Understanding DFSR debug logging (Part 15: Pre-Seeded Data Usage during Initial Sync)
Understanding DFSR debug logging (Part 16: File modification with RDC in very granular detail (uses....
Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses d....
Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity....
Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (use....
Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severit....
Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug....
You must be a registered user to add a comment. If you've already registered, sign in. Otherwise, register and sign in.