[darcs-users] [issue1900] darcs seems particularly slow on MacOS X

[Florian Gilcher]

On Aug 2, 2010, at 3:31 PM, Eric Kow wrote:

> A bit more...
> 
>>> stat (and others) do not really seem to be the problem. Darcs spends the
>>> most time waiting, spending roughly 96% of the time in __semwait_signal,
>>> most probably because of read_nocancel and select.
> 
>> How do we find out what this means?  What's this __semwait_signal?
> 
> Pieter on #macdev also said that the semaphore is probably being used
> for the read_nocancel and the select.
> 
> OK then where do we go from here?  Miserable is my low-level ignorance
> with undergrad CSE381 but a distant memory [1].
> 
> Whipping out /Advanced Programming in the UNIX Environment/, I see that
> there may be a concept of IO Multiplexing to grasp, and that the
> select() function
> 
> * takes a set of descriptors you're interested in
> * waits until a descriptor is ready
> * returns which descriptors are ready
> 
> OK... but what's the wider context here?  What's causing these select()
> to be called and why?
> 
> And what's this read_nocancel?

read_nocancel() is read(), but does not allow POSIX cancellation. read() in
XNU is implemented by checking for such a point and then calling read_nocancel().

__semwait_signal(), as far as I can tell with my rusty C, is a function that
waits for a semaphore or a signal and returns success or the signal. It is 
implemented in the XNU kernel. The interesting thing is that the kernel itself 
does not seem to use it...

>>> the call numbers, __semwait_signal is called very rarely, compared to
>>> the calls to read, mmap, etc.
> 
> Hmm...
> 
>> OK, this bears highlighting:
>> 
>> * that's 8 minutes out of 9 minutes fetching ghc locally in __semwait_signal
>> * a function which is called less than 6000 times (cf. 87000 stat)
> 
> Err, hang on, that 8 minutes out of 9 number is bogus, sorry!
> 
> I had dumbly plugged in "4474726631771 nanoseconds in minutes" into
> Google's converter tool but missed a digit.  With the new 74 minute
> number, that can't mean what I assumed it meant.  Then what do these
> times correspond to?

Well, the call times can be way beyond the runtime. It is the sum
of the delta between all function entry timestamps and their corresponding exit. 
So, 4 threads entering __semwait_signal and waiting for 10 minutes would 
cause the sum to be 40 minutes.

I must admit that I fell to the numbers as well.

>> So this smells like the right kind of fishy.  Is this the kind of thing
>> we may be able to just poke and suddenly find ourselves with dramatic
>> improvements on OS X?
> 
>> Could the fancy graphical developer tools from Apple help with this at
>> all?
> 
> Would the DTrace probles in GHC 6.13 help us to gain any insight?
> * http://hackage.haskell.org/trac/ghc/wiki/DTrace

To be frank, building GHC is a pain, especially on OS X. When I have too much
free time, I will do that :).

> How about Instruments and Shark?
> * http://justtesting.org/profiling-garbage-collection-in-haskell-with
> * http://developer.apple.com/mac/library/DOCUMENTATION/DeveloperTools/Conceptual/InstrumentsUserGuide/Introduction/Introduction.html
> * http://www.jonathansaggau.com/blog/2008/09/using_shark_and_custom_dtrace.html 

Both seem to be nice and good, but I am horrible at using visual tools. I actually
used instruments at first and ditched it in favor of the command line. They good
products, so if someone has more luck...

Well, the good question that mornfall raised in the IRC channel is whether
Darcs is at fault here or just the victim of a fight of some IO layer vs. the
operating system.

Regards,
Florian

> [1] And if you happen to be in an undergraduate university setting
>    taking a similar class <http://www.seas.upenn.edu/~cse381/>, pay
>    more attention! It seems 1998-Eric's effort was woefully inadequate.

Thanks, too late as well.