{"thread":{"id":"44089","subject":"[PATCH] object: measure time needed for resolving hash collisions","startedAt":"2016-09-15T02:01:53Z","lastAt":"2016-09-15T18:49:15Z","messageCount":7,"participants":["Stefan Beller","Jeff King","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"301951","messageId":"20160915020141.32000-1-sbeller@google.com","threadId":"44089","inReplyTo":null,"subject":"[PATCH] object: measure time needed for resolving hash collisions","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2016-09-15T02:01:41Z","receivedAt":"2016-09-15T02:01:53Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"$ time ./git rev-list HEAD --count\n44271\nprint_time_spent_object: measure time needed for resolving hash collisions\n\nThis shows that we roughly spent a third of the time in resolving\nhash collisions:\n\nI am using linux.git to measure:\n\n$ time git rev-list --objects --count HEAD >/dev/null\nprint_time_spent_resolving_hash_collisions 9:445591664\n\nreal\t0m31.733s\nuser\t0m31.220s\nsys\t0m0.463s\n\nFor fun I reverted 9a414486d9f0:\n\n$ time git rev-list --objects --count HEAD >/dev/null\nprint_time_spent_resolving_hash_collisions 14:338605504\n\nreal\t0m37.008s\nuser\t0m36.524s\nsys\t0m0.423s\n\nThe 17% that Jeff measured in there, equals to 1-31.733/37.008 = 0.14\nin these measurements.\nThe time spent in collision resolving went down by 1/3 on itself\n(14.33s to 9.44s), so there is still room for improvement.\n\nSigned-off-by: Stefan Beller <sbeller@google.com>\n---\n\n According to Jeff, sending patches that don't get accepted is the new hype!\n\n builtin/rev-list.c |  2 ++\n object.c           | 36 ++++++++++++++++++++++++++++++++++++\n object.h           |  2 ++\n 3 files changed, 40 insertions(+)\n\ndiff --git a/builtin/rev-list.c b/builtin/rev-list.c\nindex 8479f6e..d0e5922 100644\n--- a/builtin/rev-list.c\n+++ b/builtin/rev-list.c\n@@ -412,5 +412,7 @@ int cmd_rev_list(int argc, const char **argv, const char *prefix)\n \t\t\tprintf(\"%d\\n\", revs.count_left + revs.count_right);\n \t}\n \n+\tprint_time_spent_resolving_hash_collisions();\n+\n \treturn 0;\n }\ndiff --git a/object.c b/object.c\nindex 67d9a9e..e9e73e0 100644\n--- a/object.c\n+++ b/object.c\n@@ -5,9 +5,40 @@\n #include \"commit.h\"\n #include \"tag.h\"\n \n+#include <time.h>\n+\n static struct object **obj_hash;\n static int nr_objs, obj_hash_size;\n \n+struct timespec caching = {0, 0};\n+\n+void diff(struct timespec *start, struct timespec *end, struct timespec *dst)\n+{\n+\tif ((end->tv_nsec-start->tv_nsec)<0) {\n+\t\tdst->tv_sec = end->tv_sec-start->tv_sec-1;\n+\t\tdst->tv_nsec = 1000000000+end->tv_nsec-start->tv_nsec;\n+\t} else {\n+\t\tdst->tv_sec = end->tv_sec-start->tv_sec;\n+\t\tdst->tv_nsec = end->tv_nsec-start->tv_nsec;\n+\t}\n+}\n+\n+void add_time_to(struct timespec *dst, struct timespec *addend)\n+{\n+\tdst->tv_sec += addend->tv_sec;\n+\tdst->tv_nsec += addend->tv_nsec;\n+\twhile (dst->tv_nsec > 1000000000) {\n+\t\tdst->tv_nsec -= 1000000000;\n+\t\tdst->tv_sec ++;\n+\t}\n+}\n+\n+void print_time_spent_resolving_hash_collisions(void)\n+{\n+\tfprintf(stderr, \"print_time_spent_resolving_hash_collisions %ld:%9ld\\n\",\n+\t\t(long)caching.tv_sec, (long)caching.tv_nsec);\n+}\n+\n unsigned int get_max_object_index(void)\n {\n \treturn obj_hash_size;\n@@ -86,11 +117,13 @@ struct object *lookup_object(const unsigned char *sha1)\n {\n \tunsigned int i, first;\n \tstruct object *obj;\n+\tstruct timespec time1, time2, t_diff;\n \n \tif (!obj_hash)\n \t\treturn NULL;\n \n \tfirst = i = hash_obj(sha1, obj_hash_size);\n+\tclock_gettime(CLOCK_MONOTONIC, &time1);\n \twhile ((obj = obj_hash[i]) != NULL) {\n \t\tif (!hashcmp(sha1, obj->oid.hash))\n \t\t\tbreak;\n@@ -98,6 +131,9 @@ struct object *lookup_object(const unsigned char *sha1)\n \t\tif (i == obj_hash_size)\n \t\t\ti = 0;\n \t}\n+\tclock_gettime(CLOCK_MONOTONIC, &time2);\n+\tdiff(&time1, &time2, &t_diff);\n+\tadd_time_to(&caching, &t_diff);\n \tif (obj && i != first) {\n \t\t/*\n \t\t * Move object to where we started to look for it so\ndiff --git a/object.h b/object.h\nindex f8b6442..ee6ab3a 100644\n--- a/object.h\n+++ b/object.h\n@@ -56,6 +56,8 @@ extern const char *typename(unsigned int type);\n extern int type_from_string_gently(const char *str, ssize_t, int gentle);\n #define type_from_string(str) type_from_string_gently(str, -1, 0)\n \n+void print_time_spent_resolving_hash_collisions(void);\n+\n /*\n  * Return the current number of buckets in the object hashmap.\n  */\n-- \n2.10.0.130.gef2bcd7.dirty\n\n"},{"id":"301955","messageId":"20160915064701.c4ishixuynbzpgwx@sigill.intra.peff.net","threadId":"44089","inReplyTo":"20160915020141.32000-1-sbeller@google.com","subject":"Re: [PATCH] object: measure time needed for resolving hash collisions","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-09-15T06:47:02Z","receivedAt":"2016-09-15T06:47:12Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Sep 14, 2016 at 07:01:41PM -0700, Stefan Beller wrote:\n\n>  According to Jeff, sending patches that don't get accepted is the new hype!\n\nIt is what all the cool kids are doing. Unfortunately, it does not save\nyou from nitpicky reviews...;)\n\n>  \tfirst = i = hash_obj(sha1, obj_hash_size);\n> +\tclock_gettime(CLOCK_MONOTONIC, &time1);\n>  \twhile ((obj = obj_hash[i]) != NULL) {\n>  \t\tif (!hashcmp(sha1, obj->oid.hash))\n>  \t\t\tbreak;\n> @@ -98,6 +131,9 @@ struct object *lookup_object(const unsigned char *sha1)\n>  \t\tif (i == obj_hash_size)\n>  \t\t\ti = 0;\n>  \t}\n> +\tclock_gettime(CLOCK_MONOTONIC, &time2);\n> +\tdiff(&time1, &time2, &t_diff);\n> +\tadd_time_to(&caching, &t_diff);\n>  \tif (obj && i != first) {\n\nI don't think this is actually measuring the time spent on collisions.\nIt's measuring the time we spend in hashcmp(), but that includes the\nnon-collision case where we find it in the first hashcmp.\n\nMeasuring _just_ the collisions is more like the patch below. In my\nmeasurements it's more like 30ms, compared to 10s for all of the\nhashcmps.\n\nSo we really aren't dealing with collisions, but rather just verifying\nthat our hash landed at the right spot. And _any_ data structure is\ngoing to have to do that. If you want to make it faster, I'd try\noptimizing hashcmp (and you can see why the critbit tree was slower; if\nwe spend so much time just on hashcmp() to make sure we're at the right\nkey, then making that slower with a bunch of branching is not going to\nhelp).\n\nI notice we still open-code hashcmp. I get a slight speedup by switching\nit to memcmp(). About 2.5%, which is similar to what I showed in\n\n  http://public-inbox.org/git/20130318073229.GA5551@sigill.intra.peff.net/\n\na few years ago (though it's more pronounced as a portion of the whole\nnow, because we've optimized some of the other bits).\n\nThe main driver there was memcmp() improvements that went into glibc\n2.13 several years ago. It might be time to start assuming that memcmp()\nbeats our open-coded loop.\n\nIt may also be possible to really micro-optimize it on some platforms,\nbecause we know the size in advance (I'd kind of expect the compiler to\ndo that, but if we're ending up in glibc memcmp then it sounds like it\nis not the case).\n\n-Peff\n"},{"id":"301956","messageId":"20160915070129.w66dxntm45qngceo@sigill.intra.peff.net","threadId":"44089","inReplyTo":"20160915064701.c4ishixuynbzpgwx@sigill.intra.peff.net","subject":"Re: [PATCH] object: measure time needed for resolving hash collisions","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-09-15T07:01:30Z","receivedAt":"2016-09-15T07:08:19Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Sep 14, 2016 at 11:47:01PM -0700, Jeff King wrote:\n\n> >  \tfirst = i = hash_obj(sha1, obj_hash_size);\n> > +\tclock_gettime(CLOCK_MONOTONIC, &time1);\n> >  \twhile ((obj = obj_hash[i]) != NULL) {\n> >  \t\tif (!hashcmp(sha1, obj->oid.hash))\n> >  \t\t\tbreak;\n> > @@ -98,6 +131,9 @@ struct object *lookup_object(const unsigned char *sha1)\n> >  \t\tif (i == obj_hash_size)\n> >  \t\t\ti = 0;\n> >  \t}\n> > +\tclock_gettime(CLOCK_MONOTONIC, &time2);\n> > +\tdiff(&time1, &time2, &t_diff);\n> > +\tadd_time_to(&caching, &t_diff);\n> >  \tif (obj && i != first) {\n> \n> I don't think this is actually measuring the time spent on collisions.\n> It's measuring the time we spend in hashcmp(), but that includes the\n> non-collision case where we find it in the first hashcmp.\n> \n> Measuring _just_ the collisions is more like the patch below. In my\n> measurements it's more like 30ms, compared to 10s for all of the\n> hashcmps.\n\nI forgot to send the patch. Which is just as well, because I realized it\nwas totally buggy.\n\nHere's a patch that I believe is correct (it counts only times when we\nmove past the first hash slot). It spends about 280ms. Which is still a\nlot less than 10s, so I think my other comments stand.\n\n---\ndiff --git a/object.c b/object.c\nindex e9e73e0..7a74a1d 100644\n--- a/object.c\n+++ b/object.c\n@@ -123,17 +123,20 @@ struct object *lookup_object(const unsigned char *sha1)\n \t\treturn NULL;\n \n \tfirst = i = hash_obj(sha1, obj_hash_size);\n-\tclock_gettime(CLOCK_MONOTONIC, &time1);\n \twhile ((obj = obj_hash[i]) != NULL) {\n \t\tif (!hashcmp(sha1, obj->oid.hash))\n \t\t\tbreak;\n+\t\tif (first == i)\n+\t\t\tclock_gettime(CLOCK_MONOTONIC, &time1);\n \t\ti++;\n \t\tif (i == obj_hash_size)\n \t\t\ti = 0;\n \t}\n-\tclock_gettime(CLOCK_MONOTONIC, &time2);\n-\tdiff(&time1, &time2, &t_diff);\n-\tadd_time_to(&caching, &t_diff);\n+\tif (i != first) {\n+\t\tclock_gettime(CLOCK_MONOTONIC, &time2);\n+\t\tdiff(&time1, &time2, &t_diff);\n+\t\tadd_time_to(&caching, &t_diff);\n+\t}\n \tif (obj && i != first) {\n \t\t/*\n \t\t * Move object to where we started to look for it so\n"},{"id":"301979","messageId":"CAGZ79kZ-rLVijKj31uYgYrLkSCCOaLKWrr8u=6LXnd=gmma+xQ@mail.gmail.com","threadId":"44089","inReplyTo":"20160915064701.c4ishixuynbzpgwx@sigill.intra.peff.net","subject":"Re: [PATCH] object: measure time needed for resolving hash collisions","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2016-09-15T16:26:22Z","receivedAt":"2016-09-15T16:26:30Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"On Wed, Sep 14, 2016 at 11:47 PM, Jeff King <peff@peff.net> wrote:\n> On Wed, Sep 14, 2016 at 07:01:41PM -0700, Stefan Beller wrote:\n>\n>>  According to Jeff, sending patches that don't get accepted is the new hype!\n>\n> It is what all the cool kids are doing. Unfortunately, it does not save\n> you from nitpicky reviews...;)\n>\n>>       first = i = hash_obj(sha1, obj_hash_size);\n>> +     clock_gettime(CLOCK_MONOTONIC, &time1);\n>>       while ((obj = obj_hash[i]) != NULL) {\n>>               if (!hashcmp(sha1, obj->oid.hash))\n>>                       break;\n>> @@ -98,6 +131,9 @@ struct object *lookup_object(const unsigned char *sha1)\n>>               if (i == obj_hash_size)\n>>                       i = 0;\n>>       }\n>> +     clock_gettime(CLOCK_MONOTONIC, &time2);\n>> +     diff(&time1, &time2, &t_diff);\n>> +     add_time_to(&caching, &t_diff);\n>>       if (obj && i != first) {\n>\n> I don't think this is actually measuring the time spent on collisions.\n> It's measuring the time we spend in hashcmp(), but that includes the\n> non-collision case where we find it in the first hashcmp.\n\nRight. I measured all lookup times, i.e. this function accounts for\n1/3 of the run\ntime.\n\n>\n> Measuring _just_ the collisions is more like the patch below. In my\n> measurements it's more like 30ms, compared to 10s for all of the\n> hashcmps.\n\nSo off by a few orders of magnitude, i.e. we don't have to worry about\nthe time spent in resolving collisions.\n\n>\n> So we really aren't dealing with collisions, but rather just verifying\n> that our hash landed at the right spot. And _any_ data structure is\n> going to have to do that. If you want to make it faster, I'd try\n> optimizing hashcmp (and you can see why the critbit tree was slower; if\n> we spend so much time just on hashcmp() to make sure we're at the right\n> key, then making that slower with a bunch of branching is not going to\n> help).\n>\n> I notice we still open-code hashcmp. I get a slight speedup by switching\n> it to memcmp(). About 2.5%, which is similar to what I showed in\n>\n>   http://public-inbox.org/git/20130318073229.GA5551@sigill.intra.peff.net/\n>\n> a few years ago (though it's more pronounced as a portion of the whole\n> now, because we've optimized some of the other bits).\n>\n> The main driver there was memcmp() improvements that went into glibc\n> 2.13 several years ago. It might be time to start assuming that memcmp()\n> beats our open-coded loop.\n\nhttp://stackoverflow.com/questions/21106801/why-is-memcmp-so-much-faster-than-a-for-loop-check\n\nseems to agree with you; so I'd think I'll agree with switching over.\n\n>\n> It may also be possible to really micro-optimize it on some platforms,\n> because we know the size in advance (I'd kind of expect the compiler to\n> do that, but if we're ending up in glibc memcmp then it sounds like it\n> is not the case).\n\nThat stackoverflow link suggests that glibc already has microoptimisations\nfor a variety of platforms.\n\n>\n> -Peff\n"},{"id":"301984","messageId":"xmqq60pxoy4h.fsf@gitster.mtv.corp.google.com","threadId":"44089","inReplyTo":"20160915064701.c4ishixuynbzpgwx@sigill.intra.peff.net","subject":"Re: [PATCH] object: measure time needed for resolving hash collisions","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2016-09-15T17:45:34Z","receivedAt":"2016-09-15T17:45:43Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King <peff@peff.net> writes:\n\n> Measuring _just_ the collisions is more like the patch below. In my\n> measurements it's more like 30ms, compared to 10s for all of the\n> hashcmps.\n>\n> So we really aren't dealing with collisions, but rather just verifying\n> that our hash landed at the right spot. And _any_ data structure is\n> going to have to do that.\n\nThe reverse side of the coin may be if we can shrink the hashtable\nsmaller and load it more heavily without sacrificing performance by\nmaking the necessary \"have we landed at the right spot\" check cheap\nenough, I guess.\n\n"},{"id":"301996","messageId":"20160915184737.2vcarwyhdp7xl3mg@sigill.intra.peff.net","threadId":"44089","inReplyTo":"xmqq60pxoy4h.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH] object: measure time needed for resolving hash collisions","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-09-15T18:47:38Z","receivedAt":"2016-09-15T18:47:46Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Sep 15, 2016 at 10:45:34AM -0700, Junio C Hamano wrote:\n\n> Jeff King <peff@peff.net> writes:\n> \n> > Measuring _just_ the collisions is more like the patch below. In my\n> > measurements it's more like 30ms, compared to 10s for all of the\n> > hashcmps.\n> >\n> > So we really aren't dealing with collisions, but rather just verifying\n> > that our hash landed at the right spot. And _any_ data structure is\n> > going to have to do that.\n> \n> The reverse side of the coin may be if we can shrink the hashtable\n> smaller and load it more heavily without sacrificing performance by\n> making the necessary \"have we landed at the right spot\" check cheap\n> enough, I guess.\n\nI think that's where things like cuckoo hashing come into play. They\ndidn't have any effect for us because we already keep the table very\nunloaded. But you could _probably_ increase the load factor without\nsacrificing performance using a more clever scheme.\n\nIt's not clear to me that the current table size is a big problem,\nthough. It might be hurting us with cache effects, but I think the only\nway we'd know is to measure.\n\n-Peff\n"},{"id":"301998","messageId":"20160915184906.hocai2ho4mkx6n6s@sigill.intra.peff.net","threadId":"44089","inReplyTo":"CAGZ79kZ-rLVijKj31uYgYrLkSCCOaLKWrr8u=6LXnd=gmma+xQ@mail.gmail.com","subject":"Re: [PATCH] object: measure time needed for resolving hash collisions","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-09-15T18:49:07Z","receivedAt":"2016-09-15T18:49:15Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Sep 15, 2016 at 09:26:22AM -0700, Stefan Beller wrote:\n\n> > It may also be possible to really micro-optimize it on some platforms,\n> > because we know the size in advance (I'd kind of expect the compiler to\n> > do that, but if we're ending up in glibc memcmp then it sounds like it\n> > is not the case).\n> \n> That stackoverflow link suggests that glibc already has microoptimisations\n> for a variety of platforms.\n\nIt's definitely micro-optimized in glibc. What I was trying to say is\nthat if we are hitting the glibc implementation, then we know we are\nhandling the \"20\" at runtime. Whereas the compiler should know that \"20\"\nis a constant, and could in theory skip the memcmp() call entirely in\nfavor of something like an unrolled loop.\n\n-Peff\n"}]}