[darcs-devel] a couple of quick timings
zooko
zooko at zooko.com
Fri Feb 8 04:54:25 UTC 2008
On Feb 7, 2008, at 1:11 PM, David Roundy wrote:
> Thanks for the test case, Zooko, and for pointing out this regression!
> Could you rerun your timings when you have pulled this change:
I pulled your latest patches and ran it again and it took around 20
seconds.
Way to go! That is within an order of magnitude of Mercurial, which
is, IMO, the gold standard of performance for portable (i.e., non-
git) decentralized revision control tools.
Hm, no it isn't actually within one order of magnitude (base 10) --
here are some timing results and some more strace results:
MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs109-
record.log.txt
real 0m9.330s
real 0m9.903s
MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs2pre-
record.log.txt
real 0m21.069s
real 0m20.032s
real 0m19.069s
MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs2pre-hf-
record.log.txt
real 0m24.494s
real 0m23.897s
real 0m23.920s
MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs2pre-d2f-
record.log.txt
real 0m24.028s
real 0m24.099s
real 0m23.737s
MAIN wonwin-mcbrootles-computer:~$ grep ^real time-hg-commit.log.txt
real 0m2.388s
real 0m2.028s
real 0m2.074s
real 0m2.045s
Here are strace logs of darcs and hg:
https://zooko.com/strace_logs-d2f_vs_hg.tar.bz2
MAIN wonwin-mcbrootles-computer:~$ wc -l hg_commit.strace.log.txt
d2f_record.strace.log.txt
59769 hg_commit.strace.log.txt
137595 d2f_record.strace.log.txt
HACK zooko-laptop:/tmp$ grep "^ ........... open("
hg_commit.strace.log.txt | wc -l
7934
HACK zooko-laptop:/tmp$ grep "^ ........... open("
d2f_record.strace.log.txt | wc -l
14183
$ find ciphercycles-20070205/ | wc -l
2100
So it looks like darcs is doing almost twice as many open() calls as
hg. Next, I chose a filename at random and grepped for that filename
in the strace logs:
$ grep "aes-128-poly1305-2/estream-c.c" d2f_record.strace.log.txt
0.000065 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000054 open("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3
0.000151 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000164 open("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3
$ grep "aes-128-poly1305-2/estream-c.c" hg_commit.strace.log.txt
0.000085 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000100 open("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
O_RDONLY|O_LARGEFILE) = 4
0.000108 open("/home/zooko/playground/timing/.hg/store/data/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c.i",
O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
0.000158 lstat64("/home/zooko/playground/timing/.hg/store/data/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c.i",
0xbf8698d8) = -1 ENOENT (No such file or directory)
0.000074 open("/home/zooko/playground/timing/.hg/store/data/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c.i",
O_RDWR|O_CREAT|O_APPEND|O_LARGEFILE, 0666) = 4
0.000041 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000075 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000076 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
So darcs is lstat'ing and opening the file twice, where hg is
lstating and opening the file once.
Digging in further, here are the relevant excerpts of the log from
the strace of darcs:
0.000065 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
...
0.000054 open("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3
0.000064 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000048 fcntl64(3, F_GETFL) = 0x8800 (flags O_RDONLY|
O_NONBLOCK|O_LARGEFILE)
0.000033 fcntl64(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
0.000032 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfb7f4f4) =
-1 ENOTTY (Inappropriate ioctl for device)
0.000039 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000048 read(3, "#define ECRYPT_API\n#if TUNINGNUM"..., 8192)
= 847
0.000046 close(3) = 0
(That's the entire file -- it is 847 bytes.)
...
0.000151 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
...
0.000164 open("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3
0.000106 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000098 fcntl64(3, F_GETFL) = 0x8800 (flags O_RDONLY|
O_NONBLOCK|O_LARGEFILE)
0.000063 fcntl64(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
0.000063 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfb7f4f4) =
-1 ENOTTY (Inappropriate ioctl for device)
0.000066 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000099 read(3, "#define ECRYPT_API\n#if TUNINGNUM"..., 8192)
= 847
0.000427 close(3) = 0
And here are the comparable excerpts from the strace of hg:
0.000085 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
...
0.000100 open("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
O_RDONLY|O_LARGEFILE) = 4
0.000049 fstat64(4, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000053 fstat64(4, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000042 _llseek(4, 0, [0], SEEK_CUR) = 0
0.000027 fstat64(4, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000042 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0xb7ba5000
0.000029 _llseek(4, 0, [0], SEEK_CUR) = 0
0.000029 read(4, "#define ECRYPT_API\n#if TUNINGNUM"..., 4096)
= 847
0.000040 read(4, "", 4096) = 0
0.000027 close(4) = 0
...
0.000041 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
0.000075 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
(Heh -- hg is making a list and checking it twice.)
...
0.000076 lstat64("/home/zooko/playground/timing/
ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c",
{st_mode=S_IFREG|0644, st_size=847, ...}) = 0
Regards,
Zooko
More information about the darcs-devel
mailing list