Calculate file transfer metrics in a consistent manner (#3091)

* Add back file transfer metrics which was available in v2.4.x (regression) 
* Calculate file transfer metrics in a consistent manner for all uploads and downloads

docs/application-config-options.md

@@ -21,6 +21,7 @@ Before reading this document, please ensure you are running application version
   - [disable_notifications](#disable_notifications)
   - [disable_upload_validation](#disable_upload_validation)
   - [display_running_config](#display_running_config)
+  - [display_transfer_metrics](#display_transfer_metrics)
   - [dns_timeout](#dns_timeout)
   - [download_only](#download_only)
   - [drive_id](#drive_id)
@@ -302,6 +303,19 @@ _**Config Example:**_ `display_running_config = "false"` or `display_running_con
 
 _**CLI Option Use:**_ `--display-running-config`
 
+### display_transfer_metrics
+_**Description:**_ This option will display file transfer metrics when enabled.
+
+_**Value Type:**_ Boolean
+
+_**Default Value:**_ False
+
+_**Config Example:**_ `display_transfer_metrics = "false"` or `display_transfer_metrics = "true"`
+
+_**Output Example:**_ `Transfer Metrics -  File: path/to/file.data | Size: 35768 Bytes | Duration: 2.27 Seconds | Speed: 0.02 Mbps (approx)`
+
+_**CLI Option Use:**_ *None - this is a config file option only*
+
 ### dns_timeout
 _**Description:**_ This setting controls the libcurl DNS cache value. By default, libcurl caches this info for 60 seconds. This libcurl DNS cache timeout is entirely speculative that a name resolves to the same address for a small amount of time into the future as libcurl does not use DNS TTL properties. We recommend users not to tamper with this option unless strictly necessary.
 

src/config.d

@@ -352,6 +352,10 @@ class ApplicationConfig {
 		// GUI File Transfer and Deletion Notifications
 		boolValues["notify_file_actions"] = false;
 		
+		// Display file transfer metrics
+		// - Enable the calculation of transfer metrics (duration,speed) for the transfer of a file
+		boolValues["display_transfer_metrics"] = false;
+		
 		// EXPAND USERS HOME DIRECTORY
 		// Determine the users home directory.
 		// Need to avoid using ~ here as expandTilde() below does not interpret correctly when running under init.d or systemd scripts

src/sync.d

@@ -2735,7 +2735,7 @@ class SyncEngine {
 		}
 	}
 	
-	// Download new file items as identified
+	// Download new/changed file items as identified
 	void downloadOneDriveItems() {
 		// Lets deal with all the JSON items that need to be downloaded in a batch process
 		size_t batchSize = to!int(appConfig.getValueLong("threads"));
@@ -2770,6 +2770,9 @@ class SyncEngine {
 		Item databaseItem;
 		bool fileFoundInDB = false;
 		
+		// Capture what time this download started
+		SysTime downloadStartTime = Clock.currTime();
+		
 		// Download item specifics
 		string downloadItemId = onedriveJSONItem["id"].str;
 		string downloadItemName = onedriveJSONItem["name"].str;
@@ -3112,6 +3115,10 @@ class SyncEngine {
 			if (!downloadFailed) {
 				// Download did not fail
 				addLogEntry("Downloading file: " ~ newItemPath ~ " ... done", fileTransferNotifications());
+				
+				// As no download failure, calculate transfer metrics in a consistent manner
+				displayTransferMetrics(newItemPath, jsonFileSize, downloadStartTime, Clock.currTime());
+				
 				// Save this item into the database
 				saveItem(onedriveJSONItem);
 				
@@ -4777,6 +4784,9 @@ class SyncEngine {
 		// Flag for if space is available online
 		bool spaceAvailableOnline = false;
 		
+		// Capture what time this upload started
+		SysTime uploadStartTime = Clock.currTime();
+		
 		// When we are uploading OneDrive Business Shared Files, we need to be targeting the right driveId and itemId
 		string targetDriveId;
 		string targetItemId;
@@ -4897,6 +4907,9 @@ class SyncEngine {
 			// Upload was successful
 			addLogEntry("Uploading modified file: " ~ localFilePath ~ " ... done", fileTransferNotifications());
 			
+			// As no upload failure, calculate transfer metrics in a consistent manner
+			displayTransferMetrics(localFilePath, thisFileSizeLocal, uploadStartTime, Clock.currTime());
+			
 			// What do we save to the DB? Is this a OneDrive Business Shared File?
 			if ((dbItem.type == ItemType.remote) && (dbItem.remoteType == ItemType.file)) {
 				// We need to 'massage' the old DB record, with data from online, as the DB record was specifically crafted for OneDrive Business Shared Files
@@ -6553,8 +6566,8 @@ class SyncEngine {
 		// Create the OneDriveAPI Upload Instance
 		OneDriveApi uploadFileOneDriveApiInstance;
 		
-		// Calculate upload speed
-		auto uploadStartTime = Clock.currTime();
+		// Capture what time this upload started
+		SysTime uploadStartTime = Clock.currTime();
 		
 		// Is this a dry-run scenario?
 		if (!dryRun) {
@@ -6713,18 +6726,11 @@ class SyncEngine {
 			addLogEntry("Uploading new file: " ~ fileToUpload ~ " ... done", fileTransferNotifications());
 		}
 		
-		// Upload has finished
-		auto uploadFinishTime = Clock.currTime();
-		// If no upload failure, calculate metrics, perform integrity validation
+		// If no upload failure, calculate transfer metrics, perform integrity validation
 		if (!uploadFailed) {
 			// Upload did not fail ...
-			auto uploadDuration = uploadFinishTime - uploadStartTime;
-			if (debugLogging) {
-				addLogEntry("File Size: " ~ to!string(thisFileSize) ~ " Bytes", ["debug"]);
-				addLogEntry("Upload Duration: " ~ to!string((uploadDuration.total!"msecs"/1e3)) ~ " Seconds", ["debug"]);
-				auto uploadSpeed = (thisFileSize / (uploadDuration.total!"msecs"/1e3)/ 1024 / 1024);
-				addLogEntry("Upload Speed: " ~ to!string(uploadSpeed) ~ " Mbps (approx)", ["debug"]);
-			}
+			// As no upload failure, calculate transfer metrics in a consistent manner
+			displayTransferMetrics(fileToUpload, thisFileSize, uploadStartTime, Clock.currTime());
 			
 			// OK as the upload did not fail, we need to save the response from OneDrive, but it has to be a valid JSON response
 			if (uploadResponse.type() == JSONType.object) {
@@ -10515,4 +10521,28 @@ class SyncEngine {
 			return objectParentDriveId;
 		}
 	}
+	
+	// Calculate the transfer metrics for the file to aid in performance discussions when they are raised
+	void displayTransferMetrics(string fileTransferred, long transferredBytes, SysTime transferStartTime, SysTime transferEndTime) {
+	
+		// We only calculate this if 'display_transfer_metrics' is enabled or we are doing debug logging
+		if (appConfig.getValueBool("display_transfer_metrics") || debugLogging) {
+	
+			// Calculations must be done on files > 0 transferredBytes
+			if (transferredBytes > 0) {
+				// Calculate transfer metrics
+				auto transferDuration = transferEndTime - transferStartTime;
+				double transferDurationAsSeconds = (transferDuration.total!"msecs"/1e3); // msec --> seconds
+				double transferSpeedAsMbps = ((transferredBytes / transferDurationAsSeconds) / 1024 / 1024); // bytes --> Mbps
+				
+				// Output the transfer metrics
+				string transferMetrics = format("File: %s | Size: %d Bytes | Duration: %.2f Seconds | Speed: %.2f Mbps (approx)", fileTransferred, transferredBytes, transferDurationAsSeconds, transferSpeedAsMbps);
+				addLogEntry("Transfer Metrics -  " ~ transferMetrics);
+				
+			} else {
+				// Zero bytes - not applicable
+				addLogEntry("Transfer Metrics -  N/A (Zero Byte File)");
+			}
+		}
+	}
 }