Instrument the git storage code

This allows fairly fine grained analysis on what part of loading from
and saving to git we are spending our time. Compute performance and
network speed play a significant role in how all this plays out.

The routine to check if we can reach the cloud server is modified to
send updates every second so we don't hang without any feedback for five
seconds when there is network but we can't reach the cloud server (not
an unlikely scenario in many dive locations with poor network quality)

Signed-off-by: Dirk Hohndel <dirk@hohndel.org>

1 files changed, 59 insertions, 17 deletions

diff --git a/subsurface-core/git-access.c b/subsurface-core/git-access.c
index 36413a55c..5bc720cd4 100644
--- a/subsurface-core/git-access.c
+++ b/subsurface-core/git-access.c
@@ -29,20 +29,47 @@ void set_git_update_cb(int(*cb)(int, const char *))
 	update_progress_cb = cb;
 }
 
-static int update_progress(int percent)
+// total overkill, but this allows us to get good timing in various scenarios;
+// the various parts of interacting with the local and remote git repositories send
+// us updates which indicate progress (and no, this is not smooth and definitely not
+// proportional - some parts are based on compute performance, some on network speed)
+// they also provide information where in the process we are so we can analyze the log
+// to understand which parts of the process take how much time.
+
+// last_git_storage_update_val is used to detect when we suddenly go back to smaller
+// "percentage" value because we are back to executing earlier code a second (or third
+// time) in that case a negative percentage value is sent to the callback function as a
+// special case to mark that situation. Overall this ensures monotonous percentage values
+int last_git_storage_update_val;
+
+int git_storage_update_progress(int percent, const char *text)
 {
-	static int last_percent = -10;
+	static int delta = 0;
+
+	if (percent == 0) {
+		delta = 0;
+	} else if (percent > 0 && percent < last_git_storage_update_val) {
+		delta = last_git_storage_update_val + delta;
+		if (update_progress_cb)
+			(*update_progress_cb)(-delta, "DELTA");
+		if (verbose)
+			fprintf(stderr, "set git storage percentage delta to %d\n", delta);
+	}
+
+	last_git_storage_update_val = percent;
+
+	percent += delta;
+
 	int ret = 0;
 	if (update_progress_cb)
-		ret = (*update_progress_cb)(percent, "");
-	if (verbose && percent - 10 >= last_percent) {
-		last_percent = percent;
-		fprintf(stderr, "git progress %d%%\n", percent);
-	}
+		ret = (*update_progress_cb)(percent, text);
+	if (verbose)
+		fprintf(stderr, "git storage progress %d%% (%s)\n", percent, text);
 	return ret;
 }
 
 // the checkout_progress_cb doesn't allow canceling of the operation
+// map the git progress to 70..90% of overall progress
 static void progress_cb(const char *path, size_t completed_steps, size_t total_steps, void *payload)
 {
 	(void) path;
@@ -50,11 +77,12 @@ static void progress_cb(const char *path, size_t completed_steps, size_t total_s
 
 	int percent = 0;
 	if (total_steps)
-		percent = 100 * completed_steps / total_steps;
-	(void)update_progress(percent);
+		percent = 70 + 20 * completed_steps / total_steps;
+	(void)git_storage_update_progress(percent, "checkout_progress_cb");
 }
 
 // this randomly assumes that 80% of the time is spent on the objects and 20% on the deltas
+// map the git progress to 70..90% of overall progress
 // if the user cancels the dialog this is passed back to libgit2
 static int transfer_progress_cb(const git_transfer_progress *stats, void *payload)
 {
@@ -62,12 +90,18 @@ static int transfer_progress_cb(const git_transfer_progress *stats, void *payloa
 
 	int percent = 0;
 	if (stats->total_objects)
-		percent = 80 * stats->received_objects / stats->total_objects;
+		percent = 70 + 16 * stats->received_objects / stats->total_objects;
 	if (stats->total_deltas)
-		percent += 20 * stats->indexed_deltas / stats->total_deltas;
-	return update_progress(percent);
+		percent += 4 * stats->indexed_deltas / stats->total_deltas;
+	/* for debugging this is useful
+	char buf[100];
+	snprintf(buf, 100, "transfer cb rec_obj %d tot_obj %d idx_delta %d total_delta %d local obj %d", stats->received_objects, stats->total_objects, stats->indexed_deltas, stats->total_deltas, stats->local_objects);
+	return git_storage_update_progress(percent, buf);
+	 */
+	return git_storage_update_progress(percent, "transfer cb");
 }
 
+// the initial push to sync the repos is mapped to 10..15% of overall progress
 static int push_transfer_progress_cb(unsigned int current, unsigned int total, size_t bytes, void *payload)
 {
 	(void) bytes;
@@ -75,8 +109,8 @@ static int push_transfer_progress_cb(unsigned int current, unsigned int total, s
 
 	int percent = 0;
 	if (total != 0)
-		percent = 100 * current / total;
-	return update_progress(percent);
+		percent = 12 + 5 * current / total;
+	return git_storage_update_progress(percent, "push trasfer cb");
 }
 
 char *get_local_dir(const char *remote, const char *branch)
@@ -387,7 +421,7 @@ static int try_to_update(git_repository *repo, git_remote *origin, git_reference
 
 	if (verbose)
 		fprintf(stderr, "git storage: try to update\n");
-
+	git_storage_update_progress(9, "try to update");
 	if (!git_reference_cmp(local, remote))
 		return 0;
 
@@ -422,6 +456,7 @@ static int try_to_update(git_repository *repo, git_remote *origin, git_reference
 	if (git_oid_equal(&base, remote_id)) {
 		if (verbose)
 			fprintf(stderr, "local is newer than remote, update remote\n");
+		git_storage_update_progress(10, "git_update_remote, local was newer");
 		return update_remote(repo, origin, local, remote, rt);
 	}
 	/* Merging a bare repository always needs user action */
@@ -439,6 +474,7 @@ static int try_to_update(git_repository *repo, git_remote *origin, git_reference
 			return report_error("Local and remote do not match, local branch not HEAD - cannot update");
 	}
 	/* Ok, let's try to merge these */
+	git_storage_update_progress(11, "try to merge");
 	ret = try_to_git_merge(repo, &local, remote, &base, local_id, remote_id);
 	if (ret == 0)
 		return update_remote(repo, origin, local, remote, rt);
@@ -460,6 +496,7 @@ static int check_remote_status(git_repository *repo, git_remote *origin, const c
 
 	if (verbose)
 		fprintf(stderr, "git storage: check remote status\n");
+	git_storage_update_progress(7, "git check remote status");
 
 	if (git_branch_lookup(&local_ref, repo, branch, GIT_BRANCH_LOCAL)) {
 		if (is_subsurface_cloud)
@@ -479,6 +516,7 @@ static int check_remote_status(git_repository *repo, git_remote *origin, const c
 		else if (rt == RT_HTTPS)
 			opts.callbacks.credentials = credential_https_cb;
 		opts.callbacks.certificate_check = certificate_check_cb;
+		git_storage_update_progress(8, "git remote push (no remote existed)");
 		error = git_remote_push(origin, &refspec, &opts);
 	} else {
 		error = try_to_update(repo, origin, local_ref, remote_ref, remote, branch, rt);
@@ -502,7 +540,7 @@ int sync_with_remote(git_repository *repo, const char *remote, const char *branc
 	}
 	if (verbose)
 		fprintf(stderr, "sync with remote %s[%s]\n", remote, branch);
-
+	git_storage_update_progress(2, "sync with remote");
 	git_repository_config(&conf, repo);
 	if (rt == RT_HTTPS && getProxyString(&proxy_string)) {
 		if (verbose)
@@ -529,6 +567,7 @@ int sync_with_remote(git_repository *repo, const char *remote, const char *branc
 	if (rt == RT_HTTPS && !canReachCloudServer()) {
 		// this is not an error, just a warning message, so return 0
 		report_error("Cannot connect to cloud server, working with local copy");
+		git_storage_update_progress(18, "can't reach cloud server, working with local copy");
 		return 0;
 	}
 	if (verbose)
@@ -540,6 +579,7 @@ int sync_with_remote(git_repository *repo, const char *remote, const char *branc
 	else if (rt == RT_HTTPS)
 		opts.callbacks.credentials = credential_https_cb;
 	opts.callbacks.certificate_check = certificate_check_cb;
+	git_storage_update_progress(6, "git fetch remote");
 	error = git_remote_fetch(origin, NULL, &opts, NULL);
 	// NOTE! A fetch error is not fatal, we just report it
 	if (error) {
@@ -554,6 +594,7 @@ int sync_with_remote(git_repository *repo, const char *remote, const char *branc
 		error = check_remote_status(repo, origin, remote, branch, rt);
 	}
 	git_remote_free(origin);
+	git_storage_update_progress(18, "done with sync with remote");
 	return error;
 }
 
@@ -701,8 +742,9 @@ static struct git_repository *get_remote_repo(const char *localdir, const char *
 		rt = RT_OTHER;
 
 	if (verbose > 1) {
-		fprintf(stderr, "git storage: accessing %s\n", remote);
+		fprintf(stderr, "git_remote_repo: accessing %s\n", remote);
 	}
+	git_storage_update_progress(1, "start git interaction");
 	/* Do we already have a local cache? */
 	if (!stat(localdir, &st)) {
 		if (!S_ISDIR(st.st_mode)) {