[viff-devel] Some profiling results

[Martin Geisler]

Hi everybody,

I have done some testing and come up with some strange numbers. I
measured the time each individual multiplication takes by storing a
timestamp when the multiplication is scheduled, and another when it
finishes.

I've attached two plots, one for 1000 multiplications and one for
4000. Each plot has the multiplication-number on the x-axis and the
time for that multiplication on the y-axis.

In both plots we see that the first multiplication takes very long, it
is sort of waiting on the other multiplications. I think this is
because we're not yielding to the reactor when we start all the
multiplications.

This also means that no network communication is started for the first
multiplication until after all multiplications have been scheduled --
this is actually not what we want...

Here are the plots, please let me know what you think of this.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: plot-1000.png
Type: image/png
Size: 3623 bytes
Desc: not available
URL: <http://lists.viff.dk/pipermail/viff-devel-viff.dk/attachments/20080924/9b001f26/attachment.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: plot-4000.png
Type: image/png
Size: 3600 bytes
Desc: not available
URL: <http://lists.viff.dk/pipermail/viff-devel-viff.dk/attachments/20080924/9b001f26/attachment-0001.png>
-------------- next part --------------


This is the change I made, in case someone wants to play around with
this:

diff --git a/viff/runtime.py b/viff/runtime.py
--- a/viff/runtime.py
+++ b/viff/runtime.py
@@ -49,6 +49,18 @@
 from twisted.internet.defer import maybeDeferred
 from twisted.internet.protocol import ReconnectingClientFactory, ServerFactory
 from twisted.protocols.basic import Int16StringReceiver
+
+PHASES = {}
+
+def begin(result, phase):
+    PHASES[phase] = time.time()
+    return result
+
+def end(result, phase):
+    stop = time.time()
+    start = PHASES.pop(phase, 0)
+    print "Finished %s in %f sec" % (phase, stop - start)
+    return result
 
 
 class Share(Deferred):
@@ -797,6 +809,9 @@
             result.addCallback(lambda a: a * share_b)
             return result
 
+        phase = "mul-%d" % self.program_counter[0]
+        begin(None, phase)
+
         # At this point both share_a and share_b must be Share
         # objects. So we wait on them, multiply and reshare.
         result = gather_shares([share_a, share_b])
@@ -804,6 +819,7 @@
         self.schedule_callback(result, self._shamir_share)
         self.schedule_callback(result, self._recombine,
                                threshold=2*self.threshold)
+        result.addCallback(end, phase)
         return result
 
     @increment_pc



-- 
Martin Geisler

VIFF (Virtual Ideal Functionality Framework) brings easy and efficient
SMPC (Secure Multi-Party Computation) to Python. See: http://viff.dk/.