mirror of
https://github.com/abraunegg/onedrive
synced 2024-05-18 13:46:41 +02:00
Add performance output for key functions (#2180)
* Add developer option 'display_processing_time' to control if performance timing is outputted or not * If option is enabled, print performance data around how long key functions are taking to process data to assist with understanding any performance related questions
This commit is contained in:
parent
4f15c35256
commit
7daf8797f8
|
@ -157,7 +157,11 @@ final class Config
|
||||||
// - Force client to use /children rather than /delta to query changes on OneDrive
|
// - 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
|
// - This option flags nationalCloudDeployment as true, forcing the client to act like it is using a National Cloud Deployment
|
||||||
boolValues["force_children_scan"] = false;
|
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
|
// EXPAND USERS HOME DIRECTORY
|
||||||
// Determine the 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
|
// Need to avoid using ~ here as expandTilde() below does not interpret correctly when running under init.d or systemd scripts
|
||||||
|
|
51
src/main.d
51
src/main.d
|
@ -6,6 +6,7 @@ import std.net.curl: CurlException;
|
||||||
import core.stdc.signal;
|
import core.stdc.signal;
|
||||||
import std.traits, std.format;
|
import std.traits, std.format;
|
||||||
import std.concurrency: receiveTimeout;
|
import std.concurrency: receiveTimeout;
|
||||||
|
import std.datetime;
|
||||||
static import log;
|
static import log;
|
||||||
|
|
||||||
OneDriveApi oneDrive;
|
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?
|
// Are we forcing to use /children scan instead of /delta to simulate National Cloud Deployment use of /children?
|
||||||
if (cfg.getValueBool("force_children_scan")) {
|
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();
|
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
|
// Do we need to validate the syncDir to check for the presence of a '.nosync' file
|
||||||
if (cfg.getValueBool("check_nomount")) {
|
if (cfg.getValueBool("check_nomount")) {
|
||||||
|
@ -1547,12 +1554,20 @@ int main(string[] args)
|
||||||
return EXIT_FAILURE;
|
return EXIT_FAILURE;
|
||||||
}
|
}
|
||||||
try {
|
try {
|
||||||
|
|
||||||
|
// performance timing
|
||||||
|
SysTime startSyncProcessingTime = Clock.currTime();
|
||||||
string startMessage = "Starting a sync with OneDrive";
|
string startMessage = "Starting a sync with OneDrive";
|
||||||
string finishMessage = "Sync with OneDrive is complete";
|
string finishMessage = "Sync with OneDrive is complete";
|
||||||
|
|
||||||
// perform a --monitor sync
|
// perform a --monitor sync
|
||||||
if ((cfg.getValueLong("verbose") > 0) || (logMonitorCounter == logInterval) || (fullScanRequired) ) {
|
if ((cfg.getValueLong("verbose") > 0) || (logMonitorCounter == logInterval) || (fullScanRequired) ) {
|
||||||
// log to console and log file if enabled
|
// 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 {
|
} else {
|
||||||
// log file only if enabled so we know when a sync started when not using --verbose
|
// log file only if enabled so we know when a sync started when not using --verbose
|
||||||
log.fileOnly(startMessage);
|
log.fileOnly(startMessage);
|
||||||
|
@ -1567,9 +1582,15 @@ int main(string[] args)
|
||||||
log.error("ERROR: The following inotify error was generated: ", e.msg);
|
log.error("ERROR: The following inotify error was generated: ", e.msg);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
SysTime endSyncProcessingTime = Clock.currTime();
|
||||||
if ((cfg.getValueLong("verbose") > 0) || (logMonitorCounter == logInterval) || (fullScanRequired) ) {
|
if ((cfg.getValueLong("verbose") > 0) || (logMonitorCounter == logInterval) || (fullScanRequired) ) {
|
||||||
// log to console and log file if enabled
|
// 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 {
|
} else {
|
||||||
// log file only if enabled so we know when a sync completed when not using --verbose
|
// log file only if enabled so we know when a sync completed when not using --verbose
|
||||||
log.fileOnly(finishMessage);
|
log.fileOnly(finishMessage);
|
||||||
|
@ -1772,7 +1793,7 @@ void performSync(SyncEngine sync, string singleDirectory, bool downloadOnly, boo
|
||||||
}
|
}
|
||||||
} else {
|
} else {
|
||||||
// sync from OneDrive first before uploading files to OneDrive
|
// 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
|
// 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.";
|
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(logOutputMessage);
|
||||||
log.vdebug(syncCallLogOutput);
|
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?
|
// 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
|
// 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
|
// 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
|
// 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) {
|
if (!monitorEnabled) {
|
||||||
// --synchronize in use
|
// --synchronize in use
|
||||||
|
log.log("Performing a database consistency and integrity check on locally stored data ... ");
|
||||||
// standard process flow
|
// standard process flow
|
||||||
sync.scanForDifferences(localPath);
|
sync.scanForDifferences(localPath);
|
||||||
} else {
|
} 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
|
// To change this behaviour adjust 'monitor_interval' and 'monitor_fullscan_frequency' to desired values in the application config file
|
||||||
if (fullScanRequired) {
|
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);
|
sync.scanForDifferencesDatabaseScan(localPath);
|
||||||
// handle any inotify events that occured 'whilst' we were scanning the database
|
// handle any inotify events that occured 'whilst' we were scanning the database
|
||||||
m.update(true);
|
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
|
// handle any inotify events that occured 'whilst' we were scanning the local filesystem
|
||||||
m.update(true);
|
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
|
// 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
|
// This MAY not be the case when using sync_list, thus a full walk of OneDrive ojects is required
|
||||||
|
|
||||||
|
|
66
src/sync.d
66
src/sync.d
|
@ -270,6 +270,8 @@ final class SyncEngine
|
||||||
private bool bypassDataPreservation = false;
|
private bool bypassDataPreservation = false;
|
||||||
// is National Cloud Deployments configured
|
// is National Cloud Deployments configured
|
||||||
private bool nationalCloudDeployment = false;
|
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
|
// array of all OneDrive driveId's for use with OneDrive Business Folders
|
||||||
private string[] driveIDsArray;
|
private string[] driveIDsArray;
|
||||||
|
|
||||||
|
@ -619,6 +621,19 @@ final class SyncEngine
|
||||||
log.vdebug("Setting nationalCloudDeployment = true");
|
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
|
// set cleanupLocalFiles to true
|
||||||
void setCleanupLocalFiles()
|
void setCleanupLocalFiles()
|
||||||
{
|
{
|
||||||
|
@ -1213,6 +1228,20 @@ final class SyncEngine
|
||||||
string deltaLinkAvailable;
|
string deltaLinkAvailable;
|
||||||
bool nationalCloudChildrenScan = false;
|
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
|
// 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
|
// Quota details are ONLY available for the main default driveId, as the OneDrive API does not provide quota details for shared folders
|
||||||
try {
|
try {
|
||||||
|
@ -1479,6 +1508,13 @@ final class SyncEngine
|
||||||
}
|
}
|
||||||
|
|
||||||
for (;;) {
|
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
|
// 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:
|
// 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.'
|
// '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
|
// 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
|
// 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)
|
// is nrChanges >= min_notify_changes (default of min_notify_changes = 5)
|
||||||
if (nrChanges >= cfg.getValueLong("min_notify_changes")) {
|
if (nrChanges >= cfg.getValueLong("min_notify_changes")) {
|
||||||
// nrChanges is >= than 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);
|
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) {
|
foreach (item; changes["value"].array) {
|
||||||
bool isRoot = false;
|
bool isRoot = false;
|
||||||
string thisItemParentPath;
|
string thisItemParentPath;
|
||||||
|
@ -2118,6 +2162,14 @@ final class SyncEngine
|
||||||
log.vdebug("Updating completed deltaLink in DB to: ", deltaLink);
|
log.vdebug("Updating completed deltaLink in DB to: ", deltaLink);
|
||||||
itemdb.setDeltaLink(driveId, id, 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) {
|
if ("@odata.nextLink" in changes) {
|
||||||
// Update deltaLink to next changeSet bundle
|
// Update deltaLink to next changeSet bundle
|
||||||
deltaLink = changes["@odata.nextLink"].str;
|
deltaLink = changes["@odata.nextLink"].str;
|
||||||
|
@ -2141,6 +2193,18 @@ final class SyncEngine
|
||||||
// empty the skipped items
|
// empty the skipped items
|
||||||
skippedItems.length = 0;
|
skippedItems.length = 0;
|
||||||
assumeSafeAppend(skippedItems);
|
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
|
// process the change of a single DriveItem
|
||||||
|
|
Loading…
Reference in a new issue