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: