[feat] add sync phase stats

6 files changed, 105 insertions, 0 deletions

diff --git a/client/changes/next-changelog.rst b/client/changes/next-changelog.rst
index bd56c857..d9dd26f9 100644
--- a/client/changes/next-changelog.rst
+++ b/client/changes/next-changelog.rst
@@ -23,6 +23,7 @@ Bugfixes
 
 Misc
 ~~~~
+- Add ability to get information about sync phases for profiling purposes.
 - Add script for setting up develop environment.
 - Refactor bootstrap to remove shared db lock.
 - `#1236 <https://leap.se/code/issues/1236>`_: Description of the new feature corresponding with issue #1236.
diff --git a/client/src/leap/soledad/client/api.py b/client/src/leap/soledad/client/api.py
index d65ddd04..bb28736b 100644
--- a/client/src/leap/soledad/client/api.py
+++ b/client/src/leap/soledad/client/api.py
@@ -62,6 +62,13 @@ from leap.soledad.client import encdecpool
 
 logger = logging.getLogger(name=__name__)
 
+
+# we may want to collect statistics from the sync process
+DO_STATS = False
+if os.environ.get('SOLEDAD_STATS'):
+    DO_STATS = True
+
+
 #
 # Constants
 #
@@ -299,6 +306,16 @@ class Soledad(object):
             sync_db=self._sync_db,
             sync_enc_pool=self._sync_enc_pool)
 
+    def sync_stats(self):
+        sync_phase = 0
+        if getattr(self._dbsyncer, 'sync_phase', None):
+            sync_phase = self._dbsyncer.sync_phase[0]
+        sync_exchange_phase = 0
+        if getattr(self._dbsyncer, 'syncer', None):
+            if getattr(self._dbsyncer.syncer, 'sync_exchange_phase', None):
+                sync_exchange_phase = self._dbsyncer.syncer.sync_exchange_phase[0]
+        return sync_phase, sync_exchange_phase
+
     #
     # Closing methods
     #
diff --git a/client/src/leap/soledad/client/http_target/__init__.py b/client/src/leap/soledad/client/http_target/__init__.py
index a16531ef..b7e54aa4 100644
--- a/client/src/leap/soledad/client/http_target/__init__.py
+++ b/client/src/leap/soledad/client/http_target/__init__.py
@@ -22,6 +22,7 @@ after receiving.
 """
 
 
+import os
 import logging
 
 from leap.common.http import HTTPClient
@@ -33,6 +34,12 @@ from leap.soledad.client.http_target.fetch import HTTPDocFetcher
 logger = logging.getLogger(__name__)
 
 
+# we may want to collect statistics from the sync process
+DO_STATS = False
+if os.environ.get('SOLEDAD_STATS'):
+    DO_STATS = True
+
+
 class SoledadHTTPSyncTarget(SyncTargetAPI, HTTPDocSender, HTTPDocFetcher):
 
     """
@@ -93,3 +100,6 @@ class SoledadHTTPSyncTarget(SyncTargetAPI, HTTPDocSender, HTTPDocFetcher):
         # the duplicated syncing bug. This could be reduced to the 30s default
         # after implementing Cancellable Sync. See #7382
         self._http = HTTPClient(cert_file, timeout=90)
+
+        if DO_STATS:
+            self.sync_exchange_phase = [0]
diff --git a/client/src/leap/soledad/client/http_target/api.py b/client/src/leap/soledad/client/http_target/api.py
index 94354092..b19ce9ce 100644
--- a/client/src/leap/soledad/client/http_target/api.py
+++ b/client/src/leap/soledad/client/http_target/api.py
@@ -14,6 +14,8 @@
 #
 # You should have received a copy of the GNU General Public License
 # along with this program. If not, see <http://www.gnu.org/licenses/>.
+import os
+import time
 import json
 import base64
 
@@ -27,6 +29,12 @@ from leap.soledad.common.errors import InvalidAuthTokenError
 from leap.soledad.client.http_target.support import readBody
 
 
+# we may want to collect statistics from the sync process
+DO_STATS = False
+if os.environ.get('SOLEDAD_STATS'):
+    DO_STATS = True
+
+
 class SyncTargetAPI(SyncTarget):
     """
     Declares public methods and implements u1db.SyncTarget.
@@ -187,6 +195,10 @@ class SyncTargetAPI(SyncTarget):
                  transaction id of the target replica.
         :rtype: twisted.internet.defer.Deferred
         """
+        # ---------- phase 1: send docs to server ----------------------------
+        if DO_STATS:
+            self.sync_exchange_phase[0] += 1
+        # --------------------------------------------------------------------
 
         self._ensure_callback = ensure_callback
 
@@ -203,6 +215,11 @@ class SyncTargetAPI(SyncTarget):
             last_known_trans_id,
             sync_id)
 
+        # ---------- phase 2: receive docs -----------------------------------
+        if DO_STATS:
+            self.sync_exchange_phase[0] += 1
+        # --------------------------------------------------------------------
+
         cur_target_gen, cur_target_trans_id = yield self._receive_docs(
             last_known_generation, last_known_trans_id,
             ensure_callback, sync_id,
@@ -214,6 +231,11 @@ class SyncTargetAPI(SyncTarget):
             cur_target_gen = gen_after_send
             cur_target_trans_id = trans_id_after_send
 
+        # ---------- phase 3: sync exchange is over --------------------------
+        if DO_STATS:
+            self.sync_exchange_phase[0] += 1
+        # --------------------------------------------------------------------
+
         defer.returnValue([cur_target_gen, cur_target_trans_id])
 
 
diff --git a/client/src/leap/soledad/client/sqlcipher.py b/client/src/leap/soledad/client/sqlcipher.py
index 22ddc87d..0ac05221 100644
--- a/client/src/leap/soledad/client/sqlcipher.py
+++ b/client/src/leap/soledad/client/sqlcipher.py
@@ -72,6 +72,12 @@ logger = logging.getLogger(__name__)
 sqlite_backend.dbapi2 = sqlcipher_dbapi2
 
 
+# we may want to collect statistics from the sync process
+DO_STATS = False
+if os.environ.get('SOLEDAD_STATS'):
+    DO_STATS = True
+
+
 def initialize_sqlcipher_db(opts, on_init=None, check_same_thread=True):
     """
     Initialize a SQLCipher database.
@@ -453,6 +459,9 @@ class SQLCipherU1DBSync(SQLCipherDatabase):
 
         self.shutdownID = None
 
+        if DO_STATS:
+            self.sync_phase = None
+
     @property
     def _replica_uid(self):
         return str(self.__replica_uid)
@@ -497,6 +506,10 @@ class SQLCipherU1DBSync(SQLCipherDatabase):
         :rtype: Deferred
         """
         syncer = self._get_syncer(url, creds=creds)
+        if DO_STATS:
+            self.sync_phase = syncer.sync_phase
+            self.syncer = syncer
+            self.sync_exchange_phase = syncer.sync_exchange_phase
         local_gen_before_sync = yield syncer.sync(
             defer_decryption=defer_decryption)
         self.received_docs = syncer.received_docs
diff --git a/client/src/leap/soledad/client/sync.py b/client/src/leap/soledad/client/sync.py
index 1879031f..9cafe62f 100644
--- a/client/src/leap/soledad/client/sync.py
+++ b/client/src/leap/soledad/client/sync.py
@@ -17,6 +17,8 @@
 """
 Soledad synchronization utilities.
 """
+import os
+import time
 import logging
 
 from twisted.internet import defer
@@ -29,6 +31,12 @@ from u1db.sync import Synchronizer
 logger = logging.getLogger(__name__)
 
 
+# we may want to collect statistics from the sync process
+DO_STATS = False
+if os.environ.get('SOLEDAD_STATS'):
+    DO_STATS = True
+
+
 class SoledadSynchronizer(Synchronizer):
     """
     Collect the state around synchronizing 2 U1DB replicas.
@@ -42,6 +50,12 @@ class SoledadSynchronizer(Synchronizer):
     """
     received_docs = []
 
+    def __init__(self, *args, **kwargs):
+        Synchronizer.__init__(self, *args, **kwargs)
+        if DO_STATS:
+            self.sync_phase = [0]
+            self.sync_exchange_phase = None
+
     @defer.inlineCallbacks
     def sync(self, defer_decryption=True):
         """
@@ -64,9 +78,16 @@ class SoledadSynchronizer(Synchronizer):
                  the local generation before the synchronization was performed.
         :rtype: twisted.internet.defer.Deferred
         """
+
         sync_target = self.sync_target
         self.received_docs = []
 
+        # ---------- phase 1: get sync info from server ----------------------
+        if DO_STATS:
+            self.sync_phase[0] += 1
+            self.sync_exchange_phase = self.sync_target.sync_exchange_phase
+        # --------------------------------------------------------------------
+
         # get target identifier, its current generation,
         # and its last-seen database generation for this source
         ensure_callback = None
@@ -106,6 +127,11 @@ class SoledadSynchronizer(Synchronizer):
         self.source.validate_gen_and_trans_id(
             target_my_gen, target_my_trans_id)
 
+        # ---------- phase 2: what's changed ---------------------------------
+        if DO_STATS:
+            self.sync_phase[0] += 1
+        # --------------------------------------------------------------------
+
         # what's changed since that generation and this current gen
         my_gen, _, changes = self.source.whats_changed(target_my_gen)
         logger.debug("Soledad sync: there are %d documents to send."
@@ -130,6 +156,11 @@ class SoledadSynchronizer(Synchronizer):
                 raise errors.InvalidTransactionId
             defer.returnValue(my_gen)
 
+        # ---------- phase 3: sync exchange ----------------------------------
+        if DO_STATS:
+            self.sync_phase[0] += 1
+        # --------------------------------------------------------------------
+
         # prepare to send all the changed docs
         changed_doc_ids = [doc_id for doc_id, _, _ in changes]
         docs_to_send = self.source.get_docs(
@@ -162,6 +193,12 @@ class SoledadSynchronizer(Synchronizer):
             "my_gen": my_gen
         }
         self._syncing_info = info
+
+        # ---------- phase 4: complete sync ----------------------------------
+        if DO_STATS:
+            self.sync_phase[0] += 1
+        # --------------------------------------------------------------------
+
         yield self.complete_sync()
 
         _, _, changes = self.source.whats_changed(target_my_gen)
@@ -170,6 +207,11 @@ class SoledadSynchronizer(Synchronizer):
         just_received = list(set(changed_doc_ids) - set(ids_sent))
         self.received_docs = just_received
 
+        # ---------- phase 5: sync is over -----------------------------------
+        if DO_STATS:
+            self.sync_phase[0] += 1
+        # --------------------------------------------------------------------
+
         defer.returnValue(my_gen)
 
     def complete_sync(self):