Skip to content

Commit

Permalink
Improve performance with reduced execution time and lower CPU/system …
Browse files Browse the repository at this point in the history 
…resource usage (#2880)

* Use global variables for logging verbose|debug logging state
* Only perform debug logging steps including calculations and/or output if debugging is actually enabled
* Only perform verbose logging steps including calculations and/or output if verbose is actually enabled
* Optimise code execution and reduce resource usage by ~12% in real time, ~65% in CPU time, and ~87% in system time.
  • Loading branch information
@abraunegg
abraunegg authored Oct 7, 2024
1 parent dba409a commit 576b46e
Show file tree
Hide file tree
Showing 11 changed files with 1,239 additions and 1,049 deletions.
158 changes: 87 additions & 71 deletions src/clientSideFiltering.d
View file

Large diffs are not rendered by default.

155 changes: 78 additions & 77 deletions src/config.d
View file

Large diffs are not rendered by default.

78 changes: 45 additions & 33 deletions src/curlEngine.d
View file
Original file line number Diff line number Diff line change
Expand Up @@ -64,7 +64,7 @@ class CurlResponse {
json = content.parseJSON();
} catch (JSONException e) {
// Log that a JSON Exception was caught, dont output the HTML response from OneDrive
addLogEntry("JSON Exception caught when performing HTTP operations - use --debug-https to diagnose further", ["debug"]);
if (debugLogging) {addLogEntry("JSON Exception caught when performing HTTP operations - use --debug-https to diagnose further", ["debug"]);}
}
return json;
};
Expand All @@ -73,8 +73,10 @@ class CurlResponse {
hasResponse = true;
this.responseHeaders = http.responseHeaders();
this.statusLine = http.statusLine;
addLogEntry("HTTP Response Headers: " ~ to!string(this.responseHeaders), ["debug"]);
addLogEntry("HTTP Status Line: " ~ to!string(this.statusLine), ["debug"]);
if (debugLogging) {
addLogEntry("HTTP Response Headers: " ~ to!string(this.responseHeaders), ["debug"]);
addLogEntry("HTTP Status Line: " ~ to!string(this.statusLine), ["debug"]);
}
}

@safe pure HTTP.StatusLine getStatus() {
Expand All @@ -87,15 +89,17 @@ class CurlResponse {
// Is 'retry-after' in the response headers
if ("retry-after" in responseHeaders) {
// Set the retry-after value
addLogEntry("curlEngine.http.perform() => Received a 'Retry-After' Header Response with the following value: " ~ to!string(responseHeaders["retry-after"]), ["debug"]);
addLogEntry("curlEngine.http.perform() => Setting retryAfterValue to: " ~ responseHeaders["retry-after"], ["debug"]);
if (debugLogging) {
addLogEntry("curlEngine.http.perform() => Received a 'Retry-After' Header Response with the following value: " ~ to!string(responseHeaders["retry-after"]), ["debug"]);
addLogEntry("curlEngine.http.perform() => Setting retryAfterValue to: " ~ responseHeaders["retry-after"], ["debug"]);
}
delayBeforeRetry = to!int(responseHeaders["retry-after"]);
} else {
// Use a 120 second delay as a default given header value was zero
// This value is based on log files and data when determining correct process for 429 response handling
delayBeforeRetry = 120;
// Update that we are over-riding the provided value with a default
addLogEntry("HTTP Response Header retry-after value was missing - Using a preconfigured default of: " ~ to!string(delayBeforeRetry), ["debug"]);
if (debugLogging) {addLogEntry("HTTP Response Header retry-after value was missing - Using a preconfigured default of: " ~ to!string(delayBeforeRetry), ["debug"]);}
}
return delayBeforeRetry;
}
Expand Down Expand Up @@ -209,14 +213,16 @@ class CurlEngine {
// We are releasing a curl instance back to the pool
void releaseEngine() {
// Log that we are releasing this engine back to the pool
addLogEntry("CurlEngine releaseEngine() called on instance id: " ~ to!string(internalThreadId), ["debug"]);
addLogEntry("CurlEngine curlEnginePool size before release: " ~ to!string(curlEnginePool.length), ["debug"]);
if (debugLogging) {
addLogEntry("CurlEngine releaseEngine() called on instance id: " ~ to!string(internalThreadId), ["debug"]);
addLogEntry("CurlEngine curlEnginePool size before release: " ~ to!string(curlEnginePool.length), ["debug"]);
}

// cleanup this curl instance before putting it back in the pool
cleanup(true); // Cleanup instance by resetting values and flushing cookie cache
synchronized (CurlEngine.classinfo) {
curlEnginePool ~= this;
addLogEntry("CurlEngine curlEnginePool size after release: " ~ to!string(curlEnginePool.length), ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool size after release: " ~ to!string(curlEnginePool.length), ["debug"]);}
}
// Perform Garbage Collection
GC.collect();
Expand Down Expand Up @@ -299,13 +305,15 @@ class CurlEngine {

if (httpsDebug) {
// Output what options we are using so that in the debug log this can be tracked
addLogEntry("http.dnsTimeout = " ~ to!string(dnsTimeout), ["debug"]);
addLogEntry("http.connectTimeout = " ~ to!string(connectTimeout), ["debug"]);
addLogEntry("http.dataTimeout = " ~ to!string(dataTimeout), ["debug"]);
addLogEntry("http.operationTimeout = " ~ to!string(operationTimeout), ["debug"]);
addLogEntry("http.maxRedirects = " ~ to!string(maxRedirects), ["debug"]);
addLogEntry("http.CurlOption.ipresolve = " ~ to!string(protocolVersion), ["debug"]);
addLogEntry("http.header.Connection.keepAlive = " ~ to!string(keepAlive), ["debug"]);
if (debugLogging) {
addLogEntry("http.dnsTimeout = " ~ to!string(dnsTimeout), ["debug"]);
addLogEntry("http.connectTimeout = " ~ to!string(connectTimeout), ["debug"]);
addLogEntry("http.dataTimeout = " ~ to!string(dataTimeout), ["debug"]);
addLogEntry("http.operationTimeout = " ~ to!string(operationTimeout), ["debug"]);
addLogEntry("http.maxRedirects = " ~ to!string(maxRedirects), ["debug"]);
addLogEntry("http.CurlOption.ipresolve = " ~ to!string(protocolVersion), ["debug"]);
addLogEntry("http.header.Connection.keepAlive = " ~ to!string(keepAlive), ["debug"]);
}
}
}

Expand Down Expand Up @@ -419,7 +427,7 @@ class CurlEngine {
// Cleanup this instance internal variables that may have been set
void cleanup(bool flushCookies = false) {
// Reset any values to defaults, freeing any set objects
addLogEntry("CurlEngine cleanup() called on instance id: " ~ to!string(internalThreadId), ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine cleanup() called on instance id: " ~ to!string(internalThreadId), ["debug"]);}

// Is the instance is stopped?
if (!http.isStopped) {
Expand Down Expand Up @@ -456,21 +464,23 @@ class CurlEngine {
// Shut down the curl instance & close any open sockets
void shutdownCurlHTTPInstance() {
// Log that we are attempting to shutdown this curl instance
addLogEntry("CurlEngine shutdownCurlHTTPInstance() called on instance id: " ~ to!string(internalThreadId), ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine shutdownCurlHTTPInstance() called on instance id: " ~ to!string(internalThreadId), ["debug"]);}

// Is this curl instance is stopped?
if (!http.isStopped) {
addLogEntry("HTTP instance still active: " ~ to!string(internalThreadId), ["debug"]);
addLogEntry("HTTP instance isStopped state before http.shutdown(): " ~ to!string(http.isStopped), ["debug"]);
if (debugLogging) {
addLogEntry("HTTP instance still active: " ~ to!string(internalThreadId), ["debug"]);
addLogEntry("HTTP instance isStopped state before http.shutdown(): " ~ to!string(http.isStopped), ["debug"]);
}
http.shutdown();
addLogEntry("HTTP instance isStopped state post http.shutdown(): " ~ to!string(http.isStopped), ["debug"]);
if (debugLogging) {addLogEntry("HTTP instance isStopped state post http.shutdown(): " ~ to!string(http.isStopped), ["debug"]);}
object.destroy(http); // Destroy, however we cant set to null
addLogEntry("HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);
if (debugLogging) {addLogEntry("HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);}

} else {
// Already stopped .. destroy it
object.destroy(http); // Destroy, however we cant set to null
addLogEntry("Stopped HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);
if (debugLogging) {addLogEntry("Stopped HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);}
}
// Perform Garbage Collection
GC.collect();
Expand All @@ -483,14 +493,14 @@ class CurlEngine {

// Get a curl instance for the OneDrive API to use
CurlEngine getCurlInstance() {
addLogEntry("CurlEngine getCurlInstance() called", ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine getCurlInstance() called", ["debug"]);}

synchronized (CurlEngine.classinfo) {
// What is the current pool size
addLogEntry("CurlEngine curlEnginePool current size: " ~ to!string(curlEnginePool.length), ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool current size: " ~ to!string(curlEnginePool.length), ["debug"]);}

if (curlEnginePool.empty) {
addLogEntry("CurlEngine curlEnginePool is empty - constructing a new CurlEngine instance", ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool is empty - constructing a new CurlEngine instance", ["debug"]);}
return new CurlEngine; // Constructs a new CurlEngine with a fresh HTTP instance
} else {
CurlEngine curlEngine = curlEnginePool[$ - 1];
Expand All @@ -499,12 +509,14 @@ CurlEngine getCurlInstance() {
// Is this engine stopped?
if (curlEngine.http.isStopped) {
// return a new curl engine as a stopped one cannot be used
addLogEntry("CurlEngine was in a stopped state (not usable) - constructing a new CurlEngine instance", ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine was in a stopped state (not usable) - constructing a new CurlEngine instance", ["debug"]);}
return new CurlEngine; // Constructs a new CurlEngine with a fresh HTTP instance
} else {
// return an existing curl engine
addLogEntry("CurlEngine was in a valid state - returning existing CurlEngine instance", ["debug"]);
addLogEntry("CurlEngine instance ID: " ~ curlEngine.internalThreadId, ["debug"]);
if (debugLogging) {
addLogEntry("CurlEngine was in a valid state - returning existing CurlEngine instance", ["debug"]);
addLogEntry("CurlEngine instance ID: " ~ curlEngine.internalThreadId, ["debug"]);
}
return curlEngine;
}
}
Expand All @@ -513,10 +525,10 @@ CurlEngine getCurlInstance() {

// Release all CurlEngine instances
void releaseAllCurlInstances() {
addLogEntry("CurlEngine releaseAllCurlInstances() called", ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine releaseAllCurlInstances() called", ["debug"]);}
synchronized (CurlEngine.classinfo) {
// What is the current pool size
addLogEntry("CurlEngine curlEnginePool size to release: " ~ to!string(curlEnginePool.length), ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool size to release: " ~ to!string(curlEnginePool.length), ["debug"]);}
if (curlEnginePool.length > 0) {
// Safely iterate and clean up each CurlEngine instance
foreach (curlEngineInstance; curlEnginePool) {
Expand All @@ -534,7 +546,7 @@ void releaseAllCurlInstances() {
// Perform Garbage Collection on this destroyed curl engine
GC.collect();
// Log release
addLogEntry("CurlEngine released", ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine released", ["debug"]);}
}

// Clear the array after all instances have been handled
Expand All @@ -546,7 +558,7 @@ void releaseAllCurlInstances() {
// Return free memory to the OS
GC.minimize();
// Log that all curl engines have been released
addLogEntry("CurlEngine releaseAllCurlInstances() completed", ["debug"]);
if (debugLogging) {addLogEntry("CurlEngine releaseAllCurlInstances() completed", ["debug"]);}
}

// Return how many curl engines there are
Expand Down
36 changes: 19 additions & 17 deletions src/itemdb.d
View file
Original file line number Diff line number Diff line change
Expand Up @@ -127,21 +127,21 @@ Item makeDatabaseItem(JSONValue driveItem) {
bool typeSet = false;
if (isItemFile(driveItem)) {
// 'file' object exists in the JSON
addLogEntry("Flagging object as a file", ["debug"]);
if (debugLogging) {addLogEntry("Flagging object as a file", ["debug"]);}
typeSet = true;
item.type = ItemType.file;
}

if (isItemFolder(driveItem)) {
// 'folder' object exists in the JSON
addLogEntry("Flagging object as a directory", ["debug"]);
if (debugLogging) {addLogEntry("Flagging object as a directory", ["debug"]);}
typeSet = true;
item.type = ItemType.dir;
}

if (isItemRemote(driveItem)) {
// 'remote' object exists in the JSON
addLogEntry("Flagging object as a remote", ["debug"]);
if (debugLogging) {addLogEntry("Flagging object as a remote", ["debug"]);}
typeSet = true;
item.type = ItemType.remote;
}
Expand All @@ -163,7 +163,7 @@ Item makeDatabaseItem(JSONValue driveItem) {
if ("quickXorHash" in driveItem["file"]["hashes"]) {
item.quickXorHash = driveItem["file"]["hashes"]["quickXorHash"].str;
} else {
addLogEntry("quickXorHash is missing from " ~ driveItem["id"].str, ["debug"]);
if (debugLogging) {addLogEntry("quickXorHash is missing from " ~ driveItem["id"].str, ["debug"]);}
}

// If quickXorHash is empty ..
Expand All @@ -172,7 +172,7 @@ Item makeDatabaseItem(JSONValue driveItem) {
if ("sha256Hash" in driveItem["file"]["hashes"]) {
item.sha256Hash = driveItem["file"]["hashes"]["sha256Hash"].str;
} else {
addLogEntry("sha256Hash is missing from " ~ driveItem["id"].str, ["debug"]);
if (debugLogging) {addLogEntry("sha256Hash is missing from " ~ driveItem["id"].str, ["debug"]);}
}
}
} else {
Expand Down Expand Up @@ -296,7 +296,7 @@ final class ItemDatabase {

// What is the threadsafe value
auto threadsafeValue = db.getThreadsafeValue();
addLogEntry("SQLite Threadsafe database value: " ~ to!string(threadsafeValue), ["debug"]);
if (debugLogging) {addLogEntry("SQLite Threadsafe database value: " ~ to!string(threadsafeValue), ["debug"]);}

try {
// Set the enforcement of foreign key constraints.
Expand Down Expand Up @@ -613,12 +613,12 @@ final class ItemDatabase {

// If the item is of type remote, substitute it with the child
if (currItem.type == ItemType.remote) {
addLogEntry("Record is a Remote Object: " ~ to!string(currItem), ["debug"]);
if (debugLogging) {addLogEntry("Record is a Remote Object: " ~ to!string(currItem), ["debug"]);}
Item child;
if (selectById(currItem.remoteDriveId, currItem.remoteId, child)) {
assert(child.type != ItemType.remote, "The type of the child cannot be remote");
currItem = child;
addLogEntry("Selecting Record that is NOT Remote Object: " ~ to!string(currItem), ["debug"]);
if (debugLogging) {addLogEntry("Selecting Record that is NOT Remote Object: " ~ to!string(currItem), ["debug"]);}
}
}
}
Expand Down Expand Up @@ -654,7 +654,7 @@ final class ItemDatabase {
}

if (currItem.type == ItemType.remote) {
addLogEntry("Record selected is a Remote Object: " ~ to!string(currItem), ["debug"]);
if (debugLogging) {addLogEntry("Record selected is a Remote Object: " ~ to!string(currItem), ["debug"]);}
}

item = currItem;
Expand Down Expand Up @@ -845,10 +845,10 @@ final class ItemDatabase {
id = r2.front[1].dup;
}
} else {
// broken tree
addLogEntry("The following generated a broken tree query:", ["debug"]);
addLogEntry("Drive ID: " ~ to!string(driveId), ["debug"]);
addLogEntry("Item ID: " ~ to!string(id), ["debug"]);
// broken database tree
addLogEntry("The following generated a broken database tree query:");
addLogEntry("Drive ID: " ~ to!string(driveId));
addLogEntry("Item ID: " ~ to!string(id));
assert(0);
}
}
Expand Down Expand Up @@ -885,8 +885,10 @@ final class ItemDatabase {
string getDeltaLink(const(char)[] driveId, const(char)[] id) {
synchronized(databaseLock) {
// Log what we received
addLogEntry("DeltaLink Query (driveId): " ~ to!string(driveId), ["debug"]);
addLogEntry("DeltaLink Query (id): " ~ to!string(id), ["debug"]);
if (debugLogging) {
addLogEntry("DeltaLink Query (driveId): " ~ to!string(driveId), ["debug"]);
addLogEntry("DeltaLink Query (id): " ~ to!string(id), ["debug"]);
}
// assert if these are null
assert(driveId && id);

Expand Down Expand Up @@ -1054,7 +1056,7 @@ final class ItemDatabase {
void performCheckpoint() {
synchronized(databaseLock) {
// Log what we are attempting to do
addLogEntry("Attempting to perform a database checkpoint to merge temporary data", ["debug"]);
if (debugLogging) {addLogEntry("Attempting to perform a database checkpoint to merge temporary data", ["debug"]);}

try {
// Check the current DB Status - we have to be in a clean state here
Expand All @@ -1077,7 +1079,7 @@ final class ItemDatabase {

// Ensure there are no pending operations by performing a checkpoint
db.exec("PRAGMA wal_checkpoint(TRUNCATE);");
addLogEntry("Database checkpoint is complete", ["debug"]);
if (debugLogging) {addLogEntry("Database checkpoint is complete", ["debug"]);}

} catch (SqliteException exception) {
addLogEntry();
Expand Down
8 changes: 6 additions & 2 deletions src/log.d
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,11 @@ version(Notifications) {
import dnotify;
}

// Shared module object
// Shared Application Logging Level Variables
__gshared bool verboseLogging = false;
__gshared bool debugLogging = false;

// Private Shared Module Objects
private __gshared LogBuffer logBuffer;
// Timer for logging
private __gshared MonoTime lastInsertedTime;
Expand Down Expand Up @@ -310,7 +314,7 @@ void validateDBUSServerAvailability() {
logBuffer.sendGUINotification = false;
} else {
addLogEntry("D-Bus message bus daemon is available; GUI notifications are now enabled");
addLogEntry("D-Bus message bus daemon server details: " ~ to!string(dnotify.get_server_info()), ["debug"]);
if (debugLogging) {addLogEntry("D-Bus message bus daemon server details: " ~ to!string(dnotify.get_server_info()), ["debug"]);}
logBuffer.sendGUINotification = true;
}
} else {
Expand Down
Loading

0 comments on commit 576b46e

Please sign in to comment.