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 on Windows Server 2008)
Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008)
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 Server 2008)
Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)
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 Server 2008)
Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)
Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream between two Windows Server 2008)
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 debug severity 5))
Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses debug severity 5))
Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity 5))
Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (uses debug severity 5))
Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severity 5))
Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))

-          Ned Pyle