diff --git a/src/config.d b/src/config.d index afbdf9f7..cc938366 100644 --- a/src/config.d +++ b/src/config.d @@ -157,7 +157,11 @@ final class Config // - Force client to use /children rather than /delta to query changes on OneDrive // - This option flags nationalCloudDeployment as true, forcing the client to act like it is using a National Cloud Deployment boolValues["force_children_scan"] = false; - + // display_processing_time = true | false + // - Enabling this option will add function processing times to the console output + // - This then enables tracking of where the application is spending most amount of time when processing data when users have questions re performance + boolValues["display_processing_time"] = 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 diff --git a/src/main.d b/src/main.d index aa283704..13669468 100644 --- a/src/main.d +++ b/src/main.d @@ -6,6 +6,7 @@ import std.net.curl: CurlException; import core.stdc.signal; import std.traits, std.format; import std.concurrency: receiveTimeout; +import std.datetime; static import log; OneDriveApi oneDrive; @@ -1192,9 +1193,15 @@ int main(string[] args) // Are we forcing to use /children scan instead of /delta to simulate National Cloud Deployment use of /children? if (cfg.getValueBool("force_children_scan")) { - log.vdebug("Forcing client to use /children scan rather than /delta to simulate National Cloud Deployment use of /children"); + log.log("Forcing client to use /children scan rather than /delta to simulate National Cloud Deployment use of /children"); sync.setNationalCloudDeployment(); } + + // Do we need to display the function processing timing + if (cfg.getValueBool("display_processing_time")) { + log.log("Forcing client to display function processing times"); + sync.setPerformanceProcessingOutput(); + } // Do we need to validate the syncDir to check for the presence of a '.nosync' file if (cfg.getValueBool("check_nomount")) { @@ -1547,12 +1554,20 @@ int main(string[] args) return EXIT_FAILURE; } try { + + // performance timing + SysTime startSyncProcessingTime = Clock.currTime(); string startMessage = "Starting a sync with OneDrive"; string finishMessage = "Sync with OneDrive is complete"; + // perform a --monitor sync if ((cfg.getValueLong("verbose") > 0) || (logMonitorCounter == logInterval) || (fullScanRequired) ) { // log to console and log file if enabled - log.log(startMessage); + if (cfg.getValueBool("display_processing_time")) { + log.log(startMessage, " ", startSyncProcessingTime); + } else { + log.log(startMessage); + } } else { // log file only if enabled so we know when a sync started when not using --verbose log.fileOnly(startMessage); @@ -1567,9 +1582,15 @@ int main(string[] args) log.error("ERROR: The following inotify error was generated: ", e.msg); } } + SysTime endSyncProcessingTime = Clock.currTime(); if ((cfg.getValueLong("verbose") > 0) || (logMonitorCounter == logInterval) || (fullScanRequired) ) { // log to console and log file if enabled - log.log(finishMessage); + if (cfg.getValueBool("display_processing_time")) { + log.log(finishMessage, " ", endSyncProcessingTime); + log.log("Elapsed Sync Time with OneDrive Service: ", (endSyncProcessingTime - startSyncProcessingTime)); + } else { + log.log(finishMessage); + } } else { // log file only if enabled so we know when a sync completed when not using --verbose log.fileOnly(finishMessage); @@ -1772,7 +1793,7 @@ void performSync(SyncEngine sync, string singleDirectory, bool downloadOnly, boo } } else { // sync from OneDrive first before uploading files to OneDrive - if ((logLevel < MONITOR_LOG_SILENT) || (fullScanRequired)) log.log("Syncing changes from OneDrive ..."); + if ((logLevel < MONITOR_LOG_SILENT) || (fullScanRequired)) log.log("Syncing changes and items from OneDrive ..."); // For the initial sync, always use the delta link so that we capture all the right delta changes including adds, moves & deletes logOutputMessage = "Initial Scan: Call OneDrive Delta API for delta changes as compared to last successful sync."; @@ -1807,13 +1828,21 @@ void performSync(SyncEngine sync, string singleDirectory, bool downloadOnly, boo log.vdebug(logOutputMessage); log.vdebug(syncCallLogOutput); } - + + SysTime startIntegrityCheckProcessingTime = Clock.currTime(); + if (sync.getPerformanceProcessingOutput()) { + // performance timing for DB and file system integrity check - start + writeln("============================================================"); + writeln("Start Integrity Check Processing Time: ", startIntegrityCheckProcessingTime); + } + // What sort of local scan do we want to do? // In --monitor mode, when performing the DB scan, a race condition occurs where by if a file or folder is moved during this process // the inotify event is discarded once performSync() is finished (see m.update(false) above), so these events need to be handled // This can be remediated by breaking the DB and file system scan into separate processes, and handing any applicable inotify events in between if (!monitorEnabled) { // --synchronize in use + log.log("Performing a database consistency and integrity check on locally stored data ... "); // standard process flow sync.scanForDifferences(localPath); } else { @@ -1829,7 +1858,7 @@ void performSync(SyncEngine sync, string singleDirectory, bool downloadOnly, boo // // To change this behaviour adjust 'monitor_interval' and 'monitor_fullscan_frequency' to desired values in the application config file if (fullScanRequired) { - log.log("Performing a database consistency and integrity check on locally stored data ... "); + log.log("Performing a database consistency and integrity check on locally stored data due to fullscan requirement ... "); sync.scanForDifferencesDatabaseScan(localPath); // handle any inotify events that occured 'whilst' we were scanning the database m.update(true); @@ -1844,7 +1873,15 @@ void performSync(SyncEngine sync, string singleDirectory, bool downloadOnly, boo // handle any inotify events that occured 'whilst' we were scanning the local filesystem m.update(true); } - + + SysTime endIntegrityCheckProcessingTime = Clock.currTime(); + if (sync.getPerformanceProcessingOutput()) { + // performance timing for DB and file system integrity check - finish + writeln("End Integrity Check Processing Time: ", endIntegrityCheckProcessingTime); + writeln("Elapsed Function Processing Time: ", (endIntegrityCheckProcessingTime - startIntegrityCheckProcessingTime)); + writeln("============================================================"); + } + // At this point, all OneDrive changes / local changes should be uploaded and in sync // This MAY not be the case when using sync_list, thus a full walk of OneDrive ojects is required diff --git a/src/sync.d b/src/sync.d index 29110383..f4e87d81 100644 --- a/src/sync.d +++ b/src/sync.d @@ -270,6 +270,8 @@ final class SyncEngine private bool bypassDataPreservation = false; // is National Cloud Deployments configured private bool nationalCloudDeployment = false; + // has performance processing timings been requested + private bool displayProcessingTime = false; // array of all OneDrive driveId's for use with OneDrive Business Folders private string[] driveIDsArray; @@ -619,6 +621,19 @@ final class SyncEngine log.vdebug("Setting nationalCloudDeployment = true"); } + // set performance timing flag + void setPerformanceProcessingOutput() + { + displayProcessingTime = true; + log.vdebug("Setting displayProcessingTime = true"); + } + + // get performance timing flag + bool getPerformanceProcessingOutput() + { + return displayProcessingTime; + } + // set cleanupLocalFiles to true void setCleanupLocalFiles() { @@ -1213,6 +1228,20 @@ final class SyncEngine string deltaLinkAvailable; bool nationalCloudChildrenScan = false; + // Tracking processing performance + SysTime startFunctionProcessingTime; + SysTime endFunctionProcessingTime; + SysTime startBundleProcessingTime; + SysTime endBundleProcessingTime; + ulong cumulativeOneDriveItemCount = 0; + + if (displayProcessingTime) { + writeln("============================================================"); + writeln("Querying OneDrive API for relevant 'changes|items' stored online for this account"); + startFunctionProcessingTime = Clock.currTime(); + writeln("Start Function Processing Time: ", startFunctionProcessingTime); + } + // Update the quota details for this driveId, as this could have changed since we started the application - the user could have added / deleted data online, or purchased additional storage // Quota details are ONLY available for the main default driveId, as the OneDrive API does not provide quota details for shared folders try { @@ -1479,6 +1508,13 @@ final class SyncEngine } for (;;) { + + if (displayProcessingTime) { + writeln("------------------------------------------------------------"); + startBundleProcessingTime = Clock.currTime(); + writeln("Start 'change|item' API Response Bundle Processing Time: ", startBundleProcessingTime); + } + // Due to differences in OneDrive API's between personal and business we need to get changes only from defaultRootId // If we used the 'id' passed in & when using --single-directory with a business account we get: // 'HTTP request returned status code 501 (Not Implemented): view.delta can only be called on the root.' @@ -1846,6 +1882,11 @@ final class SyncEngine // OneDrive ships 'changes' in ~200 bundles. We display that we are processing X number of objects // Do not display anything unless we are doing a verbose debug as due to #658 we are essentially doing a --resync each time when using sync_list + // performance logging output + if (displayProcessingTime) { + writeln("Number of 'change|item' in this API Response Bundle from OneDrive to process: ", nrChanges); + } + // is nrChanges >= min_notify_changes (default of min_notify_changes = 5) if (nrChanges >= cfg.getValueLong("min_notify_changes")) { // nrChanges is >= than min_notify_changes @@ -1895,7 +1936,10 @@ final class SyncEngine log.vlog("Number of items from OneDrive to process: ", nrChanges); } } - + + // Add nrChanges to cumulativeOneDriveItemCount so we can detail how may items in total were processed + cumulativeOneDriveItemCount = cumulativeOneDriveItemCount + nrChanges; + foreach (item; changes["value"].array) { bool isRoot = false; string thisItemParentPath; @@ -2118,6 +2162,14 @@ final class SyncEngine log.vdebug("Updating completed deltaLink in DB to: ", deltaLink); itemdb.setDeltaLink(driveId, id, deltaLink); } + + // Processing Timing for this bundle + if (displayProcessingTime) { + endBundleProcessingTime = Clock.currTime(); + writeln("End 'change|item' API Response Bundle Processing Time: ", endBundleProcessingTime); + writeln("Elapsed Processing Time: ", (endBundleProcessingTime - startBundleProcessingTime)); + } + if ("@odata.nextLink" in changes) { // Update deltaLink to next changeSet bundle deltaLink = changes["@odata.nextLink"].str; @@ -2141,6 +2193,18 @@ final class SyncEngine // empty the skipped items skippedItems.length = 0; assumeSafeAppend(skippedItems); + + // Processing timing and metrics for everything that was processed + if (displayProcessingTime) { + endFunctionProcessingTime = Clock.currTime(); + // complete the bundle output + writeln("------------------------------------------------------------"); + writeln("Start Function Processing Time: ", startFunctionProcessingTime); + writeln("End Function Processing Time: ", endFunctionProcessingTime); + writeln("Elapsed Function Processing Time: ", (endFunctionProcessingTime - startFunctionProcessingTime)); + writeln("Total number of OneDrive items processed: ", cumulativeOneDriveItemCount); + writeln("============================================================"); + } } // process the change of a single DriveItem