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>

4 files changed, 104 insertions, 32 deletions

diff --git a/subsurface-core/checkcloudconnection.cpp b/subsurface-core/checkcloudconnection.cpp
index f028755d0..f29d971ba 100644
--- a/subsurface-core/checkcloudconnection.cpp
+++ b/subsurface-core/checkcloudconnection.cpp
@@ -6,6 +6,7 @@
 
 #include "pref.h"
 #include "helpers.h"
+#include "git-access.h"
 
 #include "checkcloudconnection.h"
 
@@ -22,6 +23,9 @@ CheckCloudConnection::CheckCloudConnection(QObject *parent) :
 #define MILK "Linus does not like non-fat milk"
 bool CheckCloudConnection::checkServer()
 {
+	if (verbose)
+		fprintf(stderr, "Checking cloud connection...\n");
+
 	QTimer timer;
 	timer.setSingleShot(true);
 	QEventLoop loop;
@@ -35,23 +39,29 @@ bool CheckCloudConnection::checkServer()
 	connect(&timer, &QTimer::timeout, &loop, &QEventLoop::quit);
 	connect(reply, &QNetworkReply::finished, &loop, &QEventLoop::quit);
 	connect(reply, &QNetworkReply::sslErrors, this, &CheckCloudConnection::sslErrors);
-	timer.start(5000); // wait five seconds
-	loop.exec();
-	if (timer.isActive()) {
-		// didn't time out, did we get the right response?
-		timer.stop();
-		if (reply->attribute(QNetworkRequest::HttpStatusCodeAttribute).toInt() == HTTP_I_AM_A_TEAPOT &&
-		    reply->readAll() == QByteArray(MILK)) {
-			reply->deleteLater();
-			mgr->deleteLater();
-			if (verbose > 1)
-				qWarning() << "Cloud storage: successfully checked connection to cloud server";
-			return true;
+	for (int seconds = 1; seconds <= 5; seconds++) {
+		timer.start(1000); // wait five seconds
+		loop.exec();
+		if (timer.isActive()) {
+			// didn't time out, did we get the right response?
+			timer.stop();
+			if (reply->attribute(QNetworkRequest::HttpStatusCodeAttribute).toInt() == HTTP_I_AM_A_TEAPOT &&
+			    reply->readAll() == QByteArray(MILK)) {
+				reply->deleteLater();
+				mgr->deleteLater();
+				if (verbose > 1)
+					qWarning() << "Cloud storage: successfully checked connection to cloud server";
+				git_storage_update_progress(last_git_storage_update_val + 1, "successfully checked cloud connection");
+				return true;
+			}
+		} else if (seconds < 5) {
+			git_storage_update_progress(last_git_storage_update_val + 1, "waited 1 sec for cloud connection");
+		} else {
+			disconnect(reply, SIGNAL(finished()), &loop, SLOT(quit()));
+			reply->abort();
 		}
-	} else {
-		disconnect(reply, SIGNAL(finished()), &loop, SLOT(quit()));
-		reply->abort();
 	}
+	git_storage_update_progress(last_git_storage_update_val + 1, "cloud connection failed");
 	if (verbose)
 		qDebug() << "connection test to cloud server failed" <<
 			    reply->error() << reply->errorString() <<
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)) {
diff --git a/subsurface-core/git-access.h b/subsurface-core/git-access.h
index 272ec116e..3a0c5160a 100644
--- a/subsurface-core/git-access.h
+++ b/subsurface-core/git-access.h
@@ -24,7 +24,11 @@ extern const char *saved_git_id;
 extern void clear_git_id(void);
 extern void set_git_id(const struct git_oid *);
 void set_git_update_cb(int (*)(int, const char *));
+int git_storage_update_progress(int percent, const char *text);
 char *get_local_dir(const char *remote, const char *branch);
+
+extern int last_git_storage_update_val;
+
 #ifdef __cplusplus
 }
 #endif
diff --git a/subsurface-core/save-git.c b/subsurface-core/save-git.c
index d089095b6..693abb623 100644
--- a/subsurface-core/save-git.c
+++ b/subsurface-core/save-git.c
@@ -911,9 +911,19 @@ static int create_git_tree(git_repository *repo, struct dir *root, bool select_o
 		trip->index = 0;
 
 	/* save the dives */
+	int notify_increment = dive_table.nr > 10 ? dive_table.nr / 10 : 1;
+	int last_threshold = 0;
 	for_each_dive(i, dive) {
 		struct tm tm;
 		struct dir *tree;
+		char buf[] = "save dives x0%";
+
+		if (i / notify_increment > last_threshold) {
+			// notify of progress - we cover the range of 20..50
+			last_threshold = i / notify_increment;
+			buf[11] = last_threshold + '0';
+			git_storage_update_progress(20 + 3 * last_threshold, buf);
+		}
 
 		trip = dive->divetrip;
 
@@ -1170,6 +1180,9 @@ int do_git_save(git_repository *repo, const char *branch, const char *remote, bo
 	if (verbose)
 		fprintf(stderr, "git storage: do git save\n");
 
+	if (!create_empty) // so we are actually saving the dives
+		git_storage_update_progress(19, "start git save");
+
 	/* Start with an empty tree: no subdirectories, no files */
 	tree.name[0] = 0;
 	tree.subdirs = NULL;
@@ -1181,6 +1194,9 @@ int do_git_save(git_repository *repo, const char *branch, const char *remote, bo
 		if (create_git_tree(repo, &tree, select_only))
 			return -1;
 
+	if (verbose)
+		fprintf(stderr, "git storage, write git tree\n");
+
 	if (write_git_tree(repo, &tree, &id))
 		return report_error("git tree write failed");