[PATCH 2 of 6 v2] util: add an elapsed time wrapper

[Simon Farnsworth]

On 03/02/2017 00:54, Bryan O'Sullivan wrote:
> On Thu, Feb 2, 2017 at 11:32 AM, Bryan O'Sullivan <bos at serpentine.com
> <mailto:bos at serpentine.com>> wrote:
>
>
>     To be honest, this seems like a heavily over-engineered approach to me.
>
>
> I don't like giving such vague feedback, but I was hopping off the
> shuttle this morning and couldn't write anything more concrete at the
> time. Sorry about that.
>
> I also feel somewhat apologetic about seagulling in abruptly with a
> critique after months and months of silence, but ... hi?
>
> I wanted to substantiate my sense of unease with this patchset. Here's
> what I came up with.
>
> First, you'll want to take a look at my different approach, which I just
> sent out a moment ago. (It's not cooked, and I forgot to add the "RFC"
> tag, but you get the idea.)
>
> Next, performance. Here's a little
> benchmark: http://pastebin.com/f9eFEWiq
> <https://urldefense.proofpoint.com/v2/url?u=http-3A__pastebin.com_f9eFEWiq&d=DwMFaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=mEgSWILcY4c4W3zjApBQLA&m=Z_ILapZ4MOSTKVH08OWF7ibTePT7tfFDPNqh5YnzmFQ&s=iN5BYr4m1lyQkPVl1UVCnw43-0a3kpVooUdu2lfAGzU&e=>
>
> On my laptop, base Mercurial runs it in 0.15 seconds.
> With performance logging enabled, your patchset takes 0.36 seconds.
> And my patchset takes 0.16, with no need to enable or disable anything.
>
> To be clear, the performance numbers should not be persuasive, because a
> typical invocation of Mercurial will call ui.write maybe 1% as often as
> the benchmark does. But what they do is give me another angle from which
> to look at "this doesn't feel right to me".
>
I'd assumed that with Mercurial encouraging extension authors to wrap 
functions, the overhead wasn't significant. Your patchset and message 
had me run a couple of experiments on my Mac, using the timeit module, 
and a trivial function:

def func():
	print "Hello"

This is both trivial, and on the sort of complexity order of the 
functions I'm trying to measure.

The baseline I got was that 1,000,000 invocations of this function take 
2.0 seconds elapsed time.

I then added if True to the function, to get a sense of the pain of 
making it conditional:

def func():
	if True:
		print "Hello"

This takes 2.3 seconds for the same million repetitions.

I then restored the unconditional version of func(); using a simple 
wrapper that just does if True: func(), I get 2.4 seconds, while a 
class-based unconditional wrapper is 2.7 seconds:

class wrapper:
	def __init__(self, func):
		self.func = func
	def __call__(self, *args, **kwargs):
		self.func(*args, **kwargs)

It looks to me like the conditional actually adds significant pain in 
its own right, almost as much as the complex class based wrapper does.

Assuming the community doesn't object strongly, I'll redo to be 
unconditionally measuring time (and only conditionally logging it), as 
the overhead of conditionality seems excessive for this purpose.

> Your patch adds a bunch of allocation and indirection on what for this
> benchmark is a fast path, which is why it appears so costly.
>
> Abstractions in Python have a heavy runtime cost and of course the usual
> "now I have an abstraction to understand" overhead, and so you have to
> be particularly judicious in creating and using them.
>
> The above approach of indirection via a wrapper object doesn't meet my
> personal "abstraction that pays for the cost of understanding and using
> it" bar, especially as the alternative approach in my patchset is both
> simple to understand and has almost no overhead.
>
> Also, the way that you're conditionally recording time used in both this
> and later patches (for crecord and extdiff) strikes me as unnecessarily
> complex. My patches demonstrate that doing so unconditionally is simpler
> and has inconsequential overhead.

I definitely want the reporting to be conditional - if you're not going 
to use the time, we shouldn't output it. My mental model for Python 
costs was wrong (and is now corrected), and I'll redo the time gathering 
accordingly.

 From my point of view, the goals are:

  1. Establish groups of "not Mercurial's fault" slowness - stdio, 
extdiff, editor invoked for histedit etc. This combines with FB infra to 
let us focus on cases where Mercurial code is the bottleneck.

  2. Do so in such a way that users not on FB infra aren't affected 
unless they choose to be, even if they're using things like logtoprocess 
today.

It looks like I met goal 2 at the expense of goal 1, and I'm going to 
need to rework to get a nicer compromise in place between the goals.

-- 
Simon Farnsworth