couchdb-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Adam Kocoloski <kocol...@apache.org>
Subject Re: chunkify profiling (was Re: Patch to couch_btree:chunkify)
Date Thu, 14 May 2009 15:03:31 GMT
Hi Paul,

On May 13, 2009, at 4:01 PM, Paul Davis wrote:

> Adam,
>
> No worries about the delay. I'd agree that the first graph doesn't
> really show much than *maybe* we can say the patch reduces the
> variability a bit.

Agreed.  The variance on the wallclock measurements is frustrating.  I  
started a thread about CPU time profiling on erlang-questions, as it  
seems to be automatically disabled on Linux and not even implemented  
on OS X.  I think wallclock time is generally the right way to go, but  
if we're testing two implementations of an algorithm that doesn't  
touch the disk then CPU time seems like the better metric to me.

> On the second graph, I haven't the faintest why that'd be as such.
> I'll have to try and setup fprof and see if I can figure out what
> exactly is taking most of the time.

I should clean up and post the code I used to make these  
measurements.  I wanted to just profile the couch_db_updater process,  
so I disabled hovercraft's delete/create DB calls at the start of  
lightning() and did them in my test code (so the updater PID didn't  
change on me).

Here's the fprof analysis from a trunk run -- in this case I believe  
it was 10k docs @ 1k bulk:

http://friendpaste.com/16xwiZuqwWrqYXQeaBS0fx

There's a lot of detail there, but if you stare at it awhile a few  
details start to emerge:

- 11218 ms total time spent in the emulator (line 13)
   - 10028 ms in couch_db_updater:update_docs_int/3 and funs called by  
it (line 47)
     - 3682 ms in couch_btree:add_remove/3 (line 70)
     - 1941 ms in couch_btree:lookup/2 (line 104)
     - 1262 ms in couch_db_updater:flush_trees/3 (line 265)
     -  951 ms in couch_db_updater:merge_rev_trees/7 (line 322)
     -  910 ms in couch_db_updater:commit_data/2 (line 330)

and so on.  Each of those numbers is an ACC that includes all the time  
spent in functions called by that function.  The five functions I  
listed have basically zero overlap, so I'm not double-counting.  You  
can certainly drill deeper and see which functions take the most time  
inside add_remove/3, etc.

> Perhaps we're looking at wrong
> thing by reducing term_to_binary. You did say that most of the time
> was spent in size/1 as opposed to term_to_binary the other day which
> is hard to believe at best.

Agreed, that's pretty difficult to believe.  Here's what I saw -- I  
defined a function

chunkify_sizer(Elem, AccIn) ->
     Size = size(term_to_binary(Elem)),
     {{Elem, Size}, AccIn+Size}.

Here's the profile for that function

%                                               CNT       ACC       OWN
{[{{couch_btree,'-chunkify/1-fun-0-',2},       22163,  268.312,   
154.927}],
  { {couch_btree,chunkify_sizer,2},             22163,  268.312,   
154.927},     %
  [{{erlang,term_to_binary,1},                  22163,  108.671,   
108.671},
   {garbage_collect,                               9,    4.714,     
4.714}]}.

60% of the time is spent in the body of chunkify_sizer, and only 40%  
in term_to_binary.  I've never seen size/1 show up explicitly in the  
profile, but if I define a dummy wrapper

get_size(Bin) ->
     erlang:size(Bin).

then get_size/1 will show up with a large OWN time, so I conclude that  
any time spent sizing a binary gets charged to OWN.

You know BERT better than I do -- you said the size of a binary is  
stored in its header, correct?

> I'll put this on the weekend agenda. Until I can show that its
> consistently faster I'll hold off.
>
> For reference, when you say 2K docs in batches of 1K, did you mean  
> 200K?

No, I meant 2k (2 calls to _bulk_docs).  200k would have generated a  
multi-GB trace and I think fprof:profile() would have melted my  
MacBook processing it.  YMMV ;-)

> Also, note to self, we should check speeds for dealing with uuids too
> to see if the non-ordered mode makes a difference.

Agreed.  At the moment fprof seems much better suited to identifying  
hot spots in code than comparing alternative implementations of a  
function.  Best thing I've come up with so far is comparing ratios of  
time spent in the function (as in Figure 2 above).

> Paul
>
> On Wed, May 13, 2009 at 3:33 PM, Adam Kocoloski  
> <kocolosk@apache.org> wrote:
>> Sorry for the delay on this front.  I ran hovercraft:lightning 20  
>> times each
>> with and without Paul's patch.  Each run inserted 2k docs in  
>> batches of
>> 1000.  Here are two plots showing the effect of the patch:
>>
>> http://dl.getdropbox.com/u/237885/insert_rate.png
>> http://dl.getdropbox.com/u/237885/chunkify_fraction.png
>>
>> The first plot histograms the insert rate for the two scenarios*.   
>> I don't
>> really see much of a difference.  The second plot uses fprof to  
>> plot the
>> fraction of time the couch_db_updater process spent in chunkify and  
>> any
>> functions called by chunkify.  For those familiar with fprof, it's  
>> the ratio
>> of ACC for couch_btree:chunkify/2 divided by OWN for the updater  
>> pid.  If
>> fprof is to be believed, the trunk code is almost 2x faster.
>>
>> Adam
>>
>> * the reason the insert rate is so low is because fprof is  
>> running.  Turning
>> off the profiler speeds things up by an order of magnitude, in  
>> accord with
>> the numbers Chris has posted.
>>


Mime
View raw message