Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))

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: