[darcs-devel] strace timing logs Re: a couple of quick timings

[David Roundy]

On Thu, Feb 07, 2008 at 06:47:08AM -0700, zooko wrote:
> > Please make sure this is not a memory problem, since otherwise the
> > timing is fairly worthless (and the issue is really in memory
> > usage)... Also, checking what kind of load is on the machine (with say
> > top) could help -- is it CPU-intensive or IO-intensive workload? Or is
> > it mostly idling?
> 
> Wait, why would the timing be worthless?

Well, it would make the timing worth a whole lot less than a measurement of
the memory use.  Knowing whether it's a memory-use issue vs a cpu-use (or
system-call-use) problem makes a big difference.

> The timing is a measure of how long it takes darcs and hg to do a  
> task which I need to do (import ciphercycles tarball) on a machine  
> that I need to use to do it.  Hg works fine in this situation.
> 
> Anyway, I'm re-running it now, with "strace -r -tt" for detailed  
> timing information.  top shows that darcs is using 94 M virt, 88 M  
> res, and consistently using about 40% to 50% CPU (it is sharing CPU  
> with a ghc compile).  The darcs status-update-line output (you know,  
> the nice new keep-the-user-informed feature of darcs-2) currently  
> says "Writing pristine 2049/2058 :  
> e07cd73fa2a129ece7aa452f7fe29b6c6185e8e1", and has said this same  
> thing for at least ten minutes.
> 
> 
> time strace -o tar.strace.log.txt -r -tt tar xjvf  
> ciphercycles-20070205.tar.bz2
> 
> 0m2.7s
> 
> time strace -o darcsinit.log.txt -r -tt darcs init --hashed
> 
> 0m0.3s
> 
> time strace -o darcsadd.log.txt -r -tt darcs add -r  
> ciphercycles-20070205
> 
> 0m7.8s
> 
> time strace -o darcsrecord.log.txt -r -tt darcs record --all -- 
> author=zooko at zooko.com -m'init import of ciphercycles-20070205'
> 
> 34m20.0s
> 
> (Hm, perhaps sharing the CPU with ghc compile made it take twice as  
> long.  Or perhaps doing the strace logging slowed it down.)
> 
> 
> And now for Mercurial:
> 
> time strace -o tar.strace.log.txt -r -tt tar xjvf  
> ciphercycles-20070205.tar.bz2
> 
> 0m2.3s
> 
> time strace -o hginit.strace.log.txt -r -tt hg init
> 
> 0m0.2s
> 
> time strace -o hgaddremove.strace.log.txt -r -tt hg addremove
> 
> 0m1.9s
> 
> time strace -o hgcommit.strace.log.txt -r -tt hg commit -m'init  
> import of ciphercycles-20070205'
> 
> 0m5.5s
> 
> 
> Here is a .tar.bz2 containing all of the strace logs produced --  
> https://zooko.com/stracelogs.tar.bz2 .  They contain fine-grained  
> (microsecond) timing of each system call, so they should be a good  
> help diagnosing why darcs is thousands of times slower than hg for  
> this.  Here's the first clue:
> 
> wc -l straceit*/*.strace.log.txt
> 
>      12662 straceit/darcsadd.strace.log.txt
>        323 straceit/darcsinit.strace.log.txt
>    1912200 straceit/darcsrec.strace.log.txt
>      14150 straceithg/hgaddremove.strace.log.txt
>      59911 straceithg/hgcommit.strace.log.txt
>       3614 straceithg/hginit.strace.log.txt
>      15736 straceithg/tar.strace.log.txt
>      15448 straceit/tar.strace.log.txt
>    2034044 total
> 
> 
> So darcs made 1.9 million system calls to do darcs record while hg  
> made 60,000 system calls to do hg commit.

Thanks, that's a good clue!
-- 
David Roundy
Department of Physics
Oregon State University