[feat] update profile-sync script, add plop profiling

Updating the profile-sync script to the latest deferred-based sync.

- Added a couple of options to have finer control about what output to
  get.
- Add support for the plop profiler https://pypi.python.org/pypi/plop/
- To get meaningful plop profiles, make sure to disable the system stats
  collection, like this::

  ./profile-sync.py --no-stats --plop -b /tmp/syncdata/ -p sikret user@provider

A good practice for this is having a pre-seeded soledad account
(currently you have to do that through the wizard, a cli will be very
nice to have in the coming future) with a known amount of data (for
instance, sending some mails with known payload weight).

It is VERY IMPORTANT that you *NEVER* process the data in this account
(ie, do not ever log in with a mail client, for instance, since that
will alter the original documents).

In order to have comparable results, you should always run this sync
script in similar conditions. Ideally, on a machine with runlevel 1.

Also, make sure of deleting the contents in the folder if you are
not using a temporal dir.

3 files changed, 75 insertions, 13 deletions

diff --git a/scripts/profiling/sync/profile-sync.py b/scripts/profiling/sync/profile-sync.py
index fdd5b5a6..6c8d249e 100644..100755
--- a/scripts/profiling/sync/profile-sync.py
+++ b/scripts/profiling/sync/profile-sync.py
@@ -1,13 +1,16 @@
-#!/usr/bin/python
-
+#!/usr/bin/env python
 
 import argparse
+import commands
+import getpass
 import logging
+import tempfile
 
+from datetime import datetime
+from twisted.internet import reactor
 
 from util import StatsLogger, ValidateUserHandle
-from client_side_db import get_soledad_instance
-#from plot import plot
+from client_side_db import _get_soledad_instance, _get_soledad_info
 
 
 # create a logger
@@ -15,6 +18,15 @@ logger = logging.getLogger(__name__)
 LOG_FORMAT = '%(asctime)s %(message)s'
 logging.basicConfig(format=LOG_FORMAT, level=logging.INFO)
 
+GITVER = commands.getoutput('git describe')
+
+
+def get_and_run_plop_collector():
+    from plop.collector import Collector
+    collector = Collector()
+    collector.start()
+    return collector
+
 
 # main program
 
@@ -33,6 +45,16 @@ if __name__ == '__main__':
     parser.add_argument(
         '-l', dest='logfile', required=False, default='/tmp/profile.log',
         help='the file to which write the log')
+    parser.add_argument(
+        '--no-stats', dest='do_stats', action='store_false',
+        help='skip system stats')
+    parser.add_argument(
+        '--plot', dest='do_plot', action='store_true',
+        help='do a graphical plot')
+    parser.add_argument(
+        '--plop', dest='do_plop', action='store_true',
+        help='run sync script under plop profiler')
+    parser.set_defaults(do_stats=True, do_plot=False, do_plop=False)
     args = parser.parse_args()
 
     # get the password
@@ -47,16 +69,54 @@ if __name__ == '__main__':
         basedir = tempfile.mkdtemp()
     logger.info('Using %s as base directory.' % basedir)
 
+    uuid, server_url, cert_file, token = \
+        _get_soledad_info(
+            args.username, args.provider, passphrase, basedir)
     # get the soledad instance
-    s = get_soledad_instance(
-        args.username, args.provider, passphrase, basedir)
+    s = _get_soledad_instance(
+        uuid, passphrase, basedir, server_url, cert_file, token)
+
     for i in xrange(10):
+        # XXX Profile this with more realistic payloads
         s.create_doc({})
 
-    sl = StatsLogger(
-        "soledad-sync", args.logfile, procs=["python"], interval=0.001)
-    sl.start()
-    s.sync()
-    sl.stop()
+    def start_sync():
+        if args.do_stats:
+            sl = StatsLogger(
+                "soledad-sync", args.logfile, procs=["python"], interval=0.001)
+            sl.start()
+        else:
+            sl = None
+
+        if args.do_plop:
+            plop_collector = get_and_run_plop_collector()
+        else:
+            plop_collector = None
+
+        t0 = datetime.now()
+        d = s.sync()
+        d.addCallback(onSyncDone, sl, t0, plop_collector)
+
+    def onSyncDone(sync_result, sl, t0, plop_collector):
+        print "GOT SYNC RESULT: ", sync_result
+        t1 = datetime.now()
+        if sl:
+            sl.stop()
+        if plop_collector:
+            from plop.collector import PlopFormatter
+            formatter = PlopFormatter()
+            plop_collector.stop()
+            # XXX mkdir profiles dir if not exist
+            with open('profiles/plop-sync-%s' % GITVER, 'w') as f:
+                f.write(formatter.format(plop_collector))
+
+        delta = (t1 - t0).total_seconds()
+        print "[+] Sync took %s seconds." % delta
+        reactor.stop()
+
+        if args.do_plot:
+            from plot import plot
+            plot(args.logfile)
 
-    #plot(args.logfile)
+    reactor.callWhenRunning(start_sync)
+    reactor.run()
diff --git a/scripts/profiling/sync/run_plop_server.sh b/scripts/profiling/sync/run_plop_server.sh
new file mode 100755
index 00000000..7b905c3d
--- /dev/null
+++ b/scripts/profiling/sync/run_plop_server.sh
@@ -0,0 +1,2 @@
+#!/bin/sh
+python -m plop.viewer --datadir=profiles
diff --git a/scripts/profiling/util.py b/scripts/profiling/util.py
index adf1de8c..e7e2ef9a 100644
--- a/scripts/profiling/util.py
+++ b/scripts/profiling/util.py
@@ -46,7 +46,7 @@ class StatsLogger(threading.Thread):
         stats = []
         stats.append("%f" % (now - self._start))   # elapsed time
         stats.append("%f" % psutil.cpu_percent())  # total cpu
-        stats.append("%f" % psutil.phymem_usage().percent)  # total memory
+        stats.append("%f" % psutil.virtual_memory().percent)  # total memory
         return ' '.join(stats)
 
     def _make_proc_stats(self):