[WISH] Store also tag dereferences in packed-refs

[WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

Time needed to execute git-peek-remote in my box with cold cache currently is:

- git tree 2.347 ms
- linux tree 2.144 ms

And refs are *already* packed in both repos.

Looking at packed-refs file, it contains something like:

d9b0f913ce0508fcc83e642e0241f373428368e5 refs/tags/v1.4.3
4314f5982d2aac08001a977fc0b1b611e858e025 refs/tags/v1.4.3-rc1

while I would need something like git-peek-remote output,

d9b0f913ce0508fcc83e642e0241f373428368e5        refs/tags/v1.4.3
e0b0830726286287744cc9e1a629a534bbe75452        refs/tags/v1.4.3^{}
4314f5982d2aac08001a977fc0b1b611e858e025        refs/tags/v1.4.3-rc1
1965efb1599f59b8e3380335d1fa395e2008a30b        refs/tags/v1.4.3-rc1^{}

Because the sha value a tag points to is needed to match against
git-rev-list output so to identify tagged revisions.

Would be possible to store in packed-refs also the dereferenced tag
info, so that cold opening of a repository would be much faster?

Just to give an idea, with warmed up cache, refs reading times are:

- git tree 43 ms
- linux tree 28 ms

Thanks
Marco

P.S: In case it's not clear I don't suggest to read directly the
packed-refs file with the added info, but always to use

Re: [WISH] Store also tag dereferences in packed-refs

[Junio C Hamano]

"Marco Costalba" <mcostalba@gmail.com> writes:

> Time needed to execute git-peek-remote in my box with cold cache currently is:
>
> - git tree 2.347 ms
> - linux tree 2.144 ms
>
> And refs are *already* packed in both repos.
>
> Looking at packed-refs file, it contains something like:
>
> d9b0f913ce0508fcc83e642e0241f373428368e5 refs/tags/v1.4.3
> 4314f5982d2aac08001a977fc0b1b611e858e025 refs/tags/v1.4.3-rc1
>
> while I would need something like git-peek-remote output,
>
> d9b0f913ce0508fcc83e642e0241f373428368e5        refs/tags/v1.4.3
> e0b0830726286287744cc9e1a629a534bbe75452        refs/tags/v1.4.3^{}
> 4314f5982d2aac08001a977fc0b1b611e858e025        refs/tags/v1.4.3-rc1
> 1965efb1599f59b8e3380335d1fa395e2008a30b        refs/tags/v1.4.3-rc1^{}
>
> Because the sha value a tag points to is needed to match against
> git-rev-list output so to identify tagged revisions.
>
> Would be possible to store in packed-refs also the dereferenced tag
> info, so that cold opening of a repository would be much faster?
>
> Just to give an idea, with warmed up cache, refs reading times are:
>
> - git tree 43 ms
> - linux tree 28 ms
>
> Thanks
> Marco
>
> P.S: In case it's not clear I don't suggest to read directly the
> packed-refs file with the added info, but always to use
> git-peek-remote that _would_ became much faster.

I think the question is why you would want to run peek-remote.
Do you use the ^{} peeled-onion information and if so how and
why?

Re: [WISH] Store also tag dereferences in packed-refs

[Petr Baudis]

On Sat, Nov 18, 2006 at 07:38:11PM CET, Junio C Hamano wrote:
> "Marco Costalba" <mcostalba@gmail.com> writes:
> 
> > Time needed to execute git-peek-remote in my box with cold cache currently is:
> >
> > - git tree 2.347 ms
> > - linux tree 2.144 ms
> >
> > And refs are *already* packed in both repos.
> >
> > Looking at packed-refs file, it contains something like:
> >
> > d9b0f913ce0508fcc83e642e0241f373428368e5 refs/tags/v1.4.3
> > 4314f5982d2aac08001a977fc0b1b611e858e025 refs/tags/v1.4.3-rc1
> >
> > while I would need something like git-peek-remote output,
> >
> > d9b0f913ce0508fcc83e642e0241f373428368e5        refs/tags/v1.4.3
> > e0b0830726286287744cc9e1a629a534bbe75452        refs/tags/v1.4.3^{}
> > 4314f5982d2aac08001a977fc0b1b611e858e025        refs/tags/v1.4.3-rc1
> > 1965efb1599f59b8e3380335d1fa395e2008a30b        refs/tags/v1.4.3-rc1^{}
> >
> > Because the sha value a tag points to is needed to match against
> > git-rev-list output so to identify tagged revisions.
> >
> > Would be possible to store in packed-refs also the dereferenced tag
> > info, so that cold opening of a repository would be much faster?
> >
> > Just to give an idea, with warmed up cache, refs reading times are:
> >
> > - git tree 43 ms
> > - linux tree 28 ms
> >
> > Thanks
> > Marco
> >
> > P.S: In case it's not clear I don't suggest to read directly the
> > packed-refs file with the added info, but always to use
> > git-peek-remote that _would_ became much faster.
> 
> I think the question is why you would want to run peek-remote.
> Do you use the ^{} peeled-onion information and if so how and
> why?

My wild guess would be to attach tags to the right commits in qgit?

-- 
				Petr "Pasky" Baudis
Stuff: http://pasky.or.cz/
The meaning of Stonehenge in Traflamadorian, when viewed from above, is:
"Replacement part being rushed with all possible speed."

Re: [WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

On 11/18/06, Petr Baudis <pasky@suse.cz> wrote:
> On Sat, Nov 18, 2006 at 07:38:11PM CET, Junio C Hamano wrote:
> > "Marco Costalba" <mcostalba@gmail.com> writes:
> >
> > > Time needed to execute git-peek-remote in my box with cold cache currently is:
> > >
> > > - git tree 2.347 ms
> > > - linux tree 2.144 ms
> > >
> > > And refs are *already* packed in both repos.
> > >
> > > Looking at packed-refs file, it contains something like:
> > >
> > > d9b0f913ce0508fcc83e642e0241f373428368e5 refs/tags/v1.4.3
> > > 4314f5982d2aac08001a977fc0b1b611e858e025 refs/tags/v1.4.3-rc1
> > >
> > > while I would need something like git-peek-remote output,
> > >
> > > d9b0f913ce0508fcc83e642e0241f373428368e5        refs/tags/v1.4.3
> > > e0b0830726286287744cc9e1a629a534bbe75452        refs/tags/v1.4.3^{}
> > > 4314f5982d2aac08001a977fc0b1b611e858e025        refs/tags/v1.4.3-rc1
> > > 1965efb1599f59b8e3380335d1fa395e2008a30b        refs/tags/v1.4.3-rc1^{}
> > >
> > > Because the sha value a tag points to is needed to match against
> > > git-rev-list output so to identify tagged revisions.
> > >
> > > Would be possible to store in packed-refs also the dereferenced tag
> > > info, so that cold opening of a repository would be much faster?
> > >
> > > Just to give an idea, with warmed up cache, refs reading times are:
> > >
> > > - git tree 43 ms
> > > - linux tree 28 ms
> > >
> > > Thanks
> > > Marco
> > >
> > > P.S: In case it's not clear I don't suggest to read directly the
> > > packed-refs file with the added info, but always to use
> > > git-peek-remote that _would_ became much faster.
> >
> > I think the question is why you would want to run peek-remote.
> > Do you use the ^{} peeled-onion information and if so how and
> > why?
>
> My wild guess would be to attach tags to the right commits in qgit?
>
Yes. It is. From a list like

> > > d9b0f913ce0508fcc83e642e0241f373428368e5        refs/tags/v1.4.3
> > > e0b0830726286287744cc9e1a629a534bbe75452        refs/tags/v1.4.3^{}
> > > 4314f5982d2aac08001a977fc0b1b611e858e025        refs/tags/v1.4.3-rc1
> > > 1965efb1599f59b8e3380335d1fa395e2008a30b        refs/tags/v1.4.3-rc1^{}
>
qgit (but also gitk FWIK) extracts

e0b0830726286287744cc9e1a629a534bbe75452
1965efb1599f59b8e3380335d1fa395e2008a30b

Stores in a quick look-up container and then checks against loaded
commits to, as Pasky says, attach the nice green markers to tags.

Re: [WISH] Store also tag dereferences in packed-refs

[Junio C Hamano]

"Marco Costalba" <mcostalba@gmail.com> writes:

> On 11/18/06, Petr Baudis <pasky@suse.cz> wrote:
>> On Sat, Nov 18, 2006 at 07:38:11PM CET, Junio C Hamano wrote:
>> >
>> > I think the question is why you would want to run peek-remote.
>> > Do you use the ^{} peeled-onion information and if so how and
>> > why?
>>..
> Yes. It is. From a list like
>
>> > > d9b0f913ce0508fcc83e642e0241f373428368e5        refs/tags/v1.4.3
>> > > e0b0830726286287744cc9e1a629a534bbe75452        refs/tags/v1.4.3^{}
>> > > 4314f5982d2aac08001a977fc0b1b611e858e025        refs/tags/v1.4.3-rc1
>> > > 1965efb1599f59b8e3380335d1fa395e2008a30b        refs/tags/v1.4.3-rc1^{}
>>
> qgit (but also gitk FWIK) extracts
>
> e0b0830726286287744cc9e1a629a534bbe75452
> 1965efb1599f59b8e3380335d1fa395e2008a30b
>
> Stores in a quick look-up container and then checks against loaded
> commits to, as Pasky says, attach the nice green markers to tags.

Two answers.

A quick one that is to the point to solve "your" problem.

	show-ref -d

Not a quick one but that may lead to solution of a similar issue
for wider audiences is...

I wonder how fast update-server-info is under the same condition
with your earlier timing.

I am not suggesting you to use update-server-info.  The reason I
am wondering about it are:

 (1) traditionally, "peek-remote ." has been the only way to get
     to that information, so you have every right to keep doing
     so;

 (2) however, even with presense of packed-refs, upload-pack
     that is invoked by peek-remote needs to consult unpacked
     refs first and then fall back to packed-refs, and only
     using the ^{} information "cached" in packed-refs file and
     computing ^{} itself when dealing with unpacked refs means
     more code, which we need to assess the pros-and-cons.

 (3) another inefficiency of using "peek-remote ." is that it
     spawns another process in the "remote" repo and talks with
     it.

So storing this information making upload-pack to reuse it when
it can might make things go faster for other applications but
first I wanted to know how much overhead is incurred in the
extra upload-pack process, and time update-server-info needs to
prepare the info in .git/info/refs would be a way to get a rough
estimate for that (you subtract that from "peek-remote ." time).

Re: [WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

>
> A quick one that is to the point to solve "your" problem.
>
>         show-ref -d
>

I was out for dinner, just come back home.

Some quick tests with show-ref -d instead of peek-remote:

- git tree 2374ms
- linux tree 2225ms

Not a big change. I reboot before each test to have a guaranteed cold cache.

Tested also with show-ref only, not useful to me, but just as a comparison.

- git tree 1420ms
- linux tree 1021ms

Better, but still slower then what I would expected.

In both case CPU load is low, processes are heavily I/O bound, so
avoiding some fork does not save the day.

Please, tell me if you want me to run some kind of additional test.

> I wonder how fast update-server-info is under the same condition
> with your earlier timing.
>
> I am not suggesting you to use update-server-info.  The reason I
> am wondering about it are:
>
>  (1) traditionally, "peek-remote ." has been the only way to get
>      to that information, so you have every right to keep doing
>      so;
>
>  (2) however, even with presense of packed-refs, upload-pack
>      that is invoked by peek-remote needs to consult unpacked
>      refs first and then fall back to packed-refs, and only
>      using the ^{} information "cached" in packed-refs file and
>      computing ^{} itself when dealing with unpacked refs means
>      more code, which we need to assess the pros-and-cons.
>
>  (3) another inefficiency of using "peek-remote ." is that it
>      spawns another process in the "remote" repo and talks with
>      it.
>
> So storing this information making upload-pack to reuse it when
> it can might make things go faster for other applications but
> first I wanted to know how much overhead is incurred in the
> extra upload-pack process, and time update-server-info needs to
> prepare the info in .git/info/refs would be a way to get a rough
> estimate for that (you subtract that from "peek-remote ." time).
>

It's to late to understand this part of your e-mail ;-) I will read
better tomorrow.

Thanks

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Marco Costalba wrote:
> 
> Tested also with show-ref only, not useful to me, but just as a comparison.
> 
> - git tree 1420ms
> - linux tree 1021ms
> 
> Better, but still slower then what I would expected.

MUCH slower than expected.

Can you do

	strace -o tracefile -Ttt git show-ref

and send out the tracefile?

What I _suspect_ is going on is that when you packed your refs, you either 
didn't prune them (which means that packing didn't actually help you), or 
if you did prune them, since we don't seem to remove the refs 
_directories_ when packing, you still have an old and big directory for 
.git/refs/tags, and just reading that (empty, but non-shrunken) directory 
takes time.

The -Ttt thing should show quite clearly what takes time.

(This, btw, is one _huge_ reason why the old shell script things with 
piping sucked. Doing things like performance analysis is so much easier 
with a builtin thing and really shows what's going on).

Re: [WISH] Store also tag dereferences in packed-refs

[Junio C Hamano]

Linus Torvalds <torvalds@osdl.org> writes:

> On Sun, 19 Nov 2006, Marco Costalba wrote:
>> 
>> Tested also with show-ref only, not useful to me, but just as a comparison.
>> 
>> - git tree 1420ms
>> - linux tree 1021ms
>> 
>> Better, but still slower then what I would expected.
>
> MUCH slower than expected.

This is still a WIP and for discussion only (I have to leave to
pick up my wife now so I won't be making any further progress
tonight), but I think parse_object() in show-ref is costing us.

One worry is that existing git will misinterpret packed-refs
file prepared with this version.

If you say "git show-ref -d --tags" to this version, it takes
the fast path which seems to shave about 1/3 of the runtime.

---

diff --git a/builtin-pack-refs.c b/builtin-pack-refs.c
index 042d271..0c770f5 100644
--- a/builtin-pack-refs.c
+++ b/builtin-pack-refs.c
@@ -1,5 +1,7 @@
 #include "cache.h"
 #include "refs.h"
+#include "object.h"
+#include "tag.h"
 
 static const char builtin_pack_refs_usage[] =
 "git-pack-refs [--all] [--prune]";
@@ -29,12 +31,24 @@ static int handle_one_ref(const char *pa
 			  int flags, void *cb_data)
 {
 	struct pack_refs_cb_data *cb = cb_data;
+	int is_tag_ref;
 
-	if (!cb->all && strncmp(path, "refs/tags/", 10))
-		return 0;
 	/* Do not pack the symbolic refs */
-	if (!(flags & REF_ISSYMREF))
-		fprintf(cb->refs_file, "%s %s\n", sha1_to_hex(sha1), path);
+	if ((flags & REF_ISSYMREF))
+		return 0;
+	is_tag_ref = !strncmp(path, "refs/tags/", 10);
+	if (!cb->all && !is_tag_ref)
+		return 0;
+
+	fprintf(cb->refs_file, "%s %s\n", sha1_to_hex(sha1), path);
+	if (is_tag_ref) {
+		struct object *o = parse_object(sha1);
+		o = deref_tag(o, path, 0);
+		if (o)
+			fprintf(cb->refs_file, "%s %s^{}\n",
+				sha1_to_hex(o->sha1), path);
+	}
+
 	if (cb->prune && !do_not_prune(flags)) {
 		int namelen = strlen(path) + 1;
 		struct ref_to_prune *n = xcalloc(1, sizeof(*n) + namelen);
diff --git a/builtin-show-ref.c b/builtin-show-ref.c
index 06ec400..32cbcb8 100644
--- a/builtin-show-ref.c
+++ b/builtin-show-ref.c
@@ -13,6 +13,7 @@ static int show_ref(const char *refname,
 {
 	struct object *obj;
 	const char *hex;
+	unsigned char peeled[20];
 
 	if (tags_only || heads_only) {
 		int match;
@@ -44,6 +45,17 @@ static int show_ref(const char *refname,
 
 match:
 	found_match++;
+
+	/* Fastpath for demonstration only */
+	if (deref_tags && (flag & REF_ISPACKED) &&
+	    !peel_ref(refname, peeled) && !quiet && !hash_only) {
+		hex = find_unique_abbrev(sha1, abbrev);
+		printf("%s %s\n", hex, refname);
+		hex = find_unique_abbrev(peeled, abbrev);
+		printf("%s %s^{}\n", hex, refname);
+		return 0;
+	}
+
 	obj = parse_object(sha1);
 	if (!obj) {
 		if (quiet)
@@ -59,8 +71,13 @@ match:
 	else
 		printf("%s %s\n", hex, refname);
 	if (deref_tags && obj->type == OBJ_TAG) {
-		obj = deref_tag(obj, refname, 0);
-		hex = find_unique_abbrev(obj->sha1, abbrev);
+		unsigned char sha1[20];
+		if ((flag & REF_ISPACKED) && !peel_ref(refname, sha1))
+			hex = find_unique_abbrev(sha1, abbrev);
+		else {
+			obj = deref_tag(obj, refname, 0);
+			hex = find_unique_abbrev(obj->sha1, abbrev);
+		}
 		printf("%s %s^{}\n", hex, refname);
 	}
 	return 0;
diff --git a/refs.c b/refs.c
index f003a0b..347c9b7 100644
--- a/refs.c
+++ b/refs.c
@@ -1,16 +1,18 @@
 #include "refs.h"
 #include "cache.h"
+#include "object.h"
+#include "tag.h"
 
 #include <errno.h>
 
 struct ref_list {
 	struct ref_list *next;
-	unsigned char flag; /* ISSYMREF? ISPACKED? */
+	unsigned char flag; /* ISSYMREF? ISPACKED? ISPEELED? */
 	unsigned char sha1[20];
 	char name[FLEX_ARRAY];
 };
 
-static const char *parse_ref_line(char *line, unsigned char *sha1)
+static const char *parse_ref_line(char *line, unsigned char *sha1, int *flag)
 {
 	/*
 	 * 42: the answer to everything.
@@ -34,6 +36,10 @@ static const char *parse_ref_line(char *
 	if (line[len] != '\n')
 		return NULL;
 	line[len] = 0;
+	if (len < 3 || strcmp(line + len - 3, "^{}"))
+	    *flag &= ~REF_ISPEELED;
+	else
+	    *flag |= REF_ISPEELED;
 	return line;
 }
 
@@ -108,10 +114,12 @@ static struct ref_list *get_packed_refs(
 			char refline[PATH_MAX];
 			while (fgets(refline, sizeof(refline), f)) {
 				unsigned char sha1[20];
-				const char *name = parse_ref_line(refline, sha1);
+				int flag = REF_ISPACKED;
+				const char *name =
+					parse_ref_line(refline, sha1, &flag);
 				if (!name)
 					continue;
-				list = add_ref(name, sha1, REF_ISPACKED, list);
+				list = add_ref(name, sha1, flag, list);
 			}
 			fclose(f);
 			refs = list;
@@ -207,7 +215,8 @@ const char *resolve_ref(const char *ref,
 		if (lstat(path, &st) < 0) {
 			struct ref_list *list = get_packed_refs();
 			while (list) {
-				if (!strcmp(ref, list->name)) {
+				if (!(list->flag & REF_ISPEELED) &&
+				    !strcmp(ref, list->name)) {
 					hashcpy(sha1, list->sha1);
 					if (flag)
 						*flag |= REF_ISPACKED;
@@ -322,6 +331,41 @@ int read_ref(const char *ref, unsigned c
 	return -1;
 }
 
+int peel_ref(const char *ref, unsigned char *sha1)
+{
+	int flag;
+	unsigned char base[20];
+	struct object *o;
+
+	if (!resolve_ref(ref, base, 1, &flag))
+		return -1;
+
+	if ((flag & REF_ISPACKED)) {
+		struct ref_list *list = get_packed_refs();		
+		int len = strlen(ref);
+		while (list) {
+			if ((list->flag & REF_ISPEELED) &&
+			    !strncmp(list->name, ref, len) &&
+			    strlen(list->name) == len + 3 &&
+			    !strcmp(list->name + len, "^{}")) {
+				hashcpy(sha1, list->sha1);
+				return 0;
+			}
+			list = list->next;
+		}
+		/* older pack-refs did not leave peeled ones in */
+	}
+
+	/* otherwise ... */
+	o = parse_object(sha1);
+	o = deref_tag(o, ref, 0);
+	if (o) {
+		hashcpy(sha1, o->sha1);
+		return 0;
+	}
+	return -1;
+}
+
 static int do_for_each_ref(const char *base, each_ref_fn fn, int trim,
 			   void *cb_data)
 {
@@ -347,6 +391,8 @@ static int do_for_each_ref(const char *b
 			continue;
 		if (is_null_sha1(entry->sha1))
 			continue;
+		if (entry->flag & REF_ISPEELED)
+			continue;
 		if (!has_sha1_file(entry->sha1)) {
 			error("%s does not point to a valid object!", entry->name);
 			continue;
@@ -357,15 +403,22 @@ static int do_for_each_ref(const char *b
 			return retval;
 	}
 
-	packed = packed ? packed : loose;
-	while (packed) {
-		if (!strncmp(base, packed->name, trim)) {
-			retval = fn(packed->name + trim, packed->sha1,
-				    packed->flag, cb_data);
-			if (retval)
-				return retval;
+	for (packed = packed ? packed : loose; packed; packed = packed->next) {
+		if (strncmp(base, packed->name, trim))
+			continue;
+		if (is_null_sha1(packed->sha1))
+			continue;
+		if (packed->flag & REF_ISPEELED)
+			continue;
+		if (!has_sha1_file(packed->sha1)) {
+			error("%s does not point to a valid object!",
+			      packed->name);
+			continue;
 		}
-		packed = packed->next;
+		retval = fn(packed->name + trim, packed->sha1,
+			    packed->flag, cb_data);
+		if (retval)
+			return retval;
 	}
 	return 0;
 }
diff --git a/refs.h b/refs.h
index a57d437..40048a6 100644
--- a/refs.h
+++ b/refs.h
@@ -16,6 +16,8 @@ struct ref_lock {
  */
 #define REF_ISSYMREF 01
 #define REF_ISPACKED 02
+#define REF_ISPEELED 04 /* internal use */
+
 typedef int each_ref_fn(const char *refname, const unsigned char *sha1, int flags, void *cb_data);
 extern int head_ref(each_ref_fn, void *);
 extern int for_each_ref(each_ref_fn, void *);
@@ -23,6 +25,8 @@ extern int for_each_tag_ref(each_ref_fn,
 extern int for_each_branch_ref(each_ref_fn, void *);
 extern int for_each_remote_ref(each_ref_fn, void *);
 
+extern int peel_ref(const char *, unsigned char *);
+
 /** Reads the refs file specified into sha1 **/
 extern int get_ref_sha1(const char *ref, unsigned char *sha1);
 

Re: [WISH] Store also tag dereferences in packed-refs

[Junio C Hamano]

Junio C Hamano <junkio@cox.net> writes:

> Linus Torvalds <torvalds@osdl.org> writes:
>
>> On Sun, 19 Nov 2006, Marco Costalba wrote:
>>> 
>>> Tested also with show-ref only, not useful to me, but just as a comparison.
>>> 
>>> - git tree 1420ms
>>> - linux tree 1021ms
>>> 
>>> Better, but still slower then what I would expected.
>>
>> MUCH slower than expected.

There is something seriously wrong about Marco's number with or
without my patch.  I am getting something like this from
linux-2.6 with fully packed and pruned refs;

$ /usr/bin/time git-show-ref -d >/dev/null
0.08user 0.00system 0:00.08elapsed 97%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+3314minor)pagefaults 0swaps

$ /usr/bin/time ../git.junio/git-show-ref -d >/dev/null
0.05user 0.01system 0:00.06elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+2724minor)pagefaults 0swaps

The second one is with the patch, the first one is from
yesterday's master.

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sat, 18 Nov 2006, Junio C Hamano wrote:
> 
> There is something seriously wrong about Marco's number with or
> without my patch.  I am getting something like this from
> linux-2.6 with fully packed and pruned refs;

Well, Marco is testing cold-cache numbers. But I agree, even with 
cold-cache, it shouldn't be anywhere close to that bad. 

Re: [WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

[-- Attachment #1: Type: text/plain, Size: 1167 bytes --]

>
> Can you do
>
>         strace -o tracefile -Ttt git show-ref
>
> and send out the tracefile?
>

Sure. File ran against git tree attached.

> What I _suspect_ is going on is that when you packed your refs, you either
> didn't prune them (which means that packing didn't actually help you), or
> if you did prune them, since we don't seem to remove the refs
> _directories_ when packing, you still have an old and big directory for
> .git/refs/tags, and just reading that (empty, but non-shrunken) directory
> takes time.

Indeed it is not empty, it has 4 refs, all the remaining are in packed-refs:

$ ls .git/refs/tags
v1.4.3.4  v1.4.3.5  v1.4.4  v1.4.4-rc1  v1.4.4-rc2

$ ls -l .git/packed-refs
-rw-r--r-- 1 marco marco 6469 nov  3 21:03 .git/packed-refs

$ cat .git/packed-refs  |wc
    109     218    6469

If you want I can repack and prune, but for now I just wait to avoid
to corrupt this test case.

IMHO if just 4 entry in a directory out of 109 could slow down in this
way, at least should be documented/warned in some place. Also because
this it seems to me, perhaps wrongly, a quite common scenario of an
user that repacks the tags seldom.


    Marco

[-- Attachment #2: tracefile_git_tree.txt --]
[-- Type: text/plain, Size: 37982 bytes --]

10:19:02.935227 execve("/home/marco/bin/git", ["git", "show-ref"], [/* 75 vars */]) = 0 <0.045394>
10:19:02.981333 brk(0)                  = 0x80de000 <0.000011>
10:19:02.981498 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fcb000 <0.000014>
10:19:02.981618 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000015>
10:19:02.981760 open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000020>
10:19:02.981849 fstat64(3, {st_mode=S_IFREG|0644, st_size=79652, ...}) = 0 <0.000011>
10:19:02.981975 mmap2(NULL, 79652, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fb7000 <0.000016>
10:19:02.982056 close(3)                = 0 <0.000011>
10:19:02.982166 open("/lib/libz.so.1", O_RDONLY) = 3 <0.000019>
10:19:02.982253 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20\27\0"..., 512) = 512 <0.000015>
10:19:02.982368 fstat64(3, {st_mode=S_IFREG|0755, st_size=73156, ...}) = 0 <0.000011>
10:19:02.982474 mmap2(NULL, 75980, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7fa4000 <0.000014>
10:19:02.982558 mmap2(0xb7fb6000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x11) = 0xb7fb6000 <0.000025>
10:19:02.982666 close(3)                = 0 <0.000010>
10:19:02.982762 open("/usr/lib/libcrypto.so.0.9.8", O_RDONLY) = 3 <0.000017>
10:19:02.982851 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0@U\3\000"..., 512) = 512 <0.000014>
10:19:02.982958 fstat64(3, {st_mode=S_IFREG|0755, st_size=1353744, ...}) = 0 <0.000011>
10:19:02.983062 mmap2(NULL, 1370456, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e55000 <0.000014>
10:19:02.983146 mmap2(0xb7f8c000, 86016, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x136) = 0xb7f8c000 <0.000020>
10:19:02.983254 mmap2(0xb7fa1000, 10584, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7fa1000 <0.000015>
10:19:02.983354 close(3)                = 0 <0.000011>
10:19:02.983441 open("/lib/i686/libc.so.6", O_RDONLY) = 3 <0.000019>
10:19:02.983530 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\240X\1"..., 512) = 512 <0.000013>
10:19:02.983635 fstat64(3, {st_mode=S_IFREG|0644, st_size=1220244, ...}) = 0 <0.000011>
10:19:02.983745 mmap2(NULL, 1230204, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7d28000 <0.000014>
10:19:02.983828 mmap2(0xb7e4f000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x126) = 0xb7e4f000 <0.000022>
10:19:02.983936 mmap2(0xb7e52000, 9596, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7e52000 <0.000015>
10:19:02.984161 close(3)                = 0 <0.000012>
10:19:02.984261 open("/lib/libdl.so.2", O_RDONLY) = 3 <0.000020>
10:19:02.984350 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0p\f\0\000"..., 512) = 512 <0.000014>
10:19:02.984457 fstat64(3, {st_mode=S_IFREG|0755, st_size=9700, ...}) = 0 <0.000011>
10:19:02.984562 mmap2(NULL, 12412, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7d24000 <0.000016>
10:19:02.984647 mmap2(0xb7d26000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1) = 0xb7d26000 <0.000020>
10:19:02.984766 close(3)                = 0 <0.000011>
10:19:02.984883 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7d23000 <0.000016>
10:19:02.984995 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7d22000 <0.000012>
10:19:02.985086 set_thread_area({entry_number:-1 -> 6, base_addr:0xb7d226c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 <0.000011>
10:19:02.985642 mprotect(0xb7e4f000, 4096, PROT_READ) = 0 <0.000019>
10:19:02.986216 mprotect(0xb7fe5000, 4096, PROT_READ) = 0 <0.000021>
10:19:02.986324 munmap(0xb7fb7000, 79652) = 0 <0.000027>
10:19:02.988091 brk(0)                  = 0x80de000 <0.000012>
10:19:02.988180 brk(0x80ff000)          = 0x80ff000 <0.000015>
10:19:02.988343 getcwd("/home/marco/programmi/git", 4097) = 26 <0.000025>
10:19:02.988456 access(".git/refs/", X_OK) = 0 <0.016158>
10:19:03.004751 access(".git/objects/", X_OK) = 0 <0.008759>
10:19:03.013670 lstat64(".git/HEAD", {st_mode=S_IFREG|0644, st_size=23, ...}) = 0 <0.000023>
10:19:03.013812 open(".git/HEAD", O_RDONLY) = 3 <0.000021>
10:19:03.013910 read(3, "ref: refs/heads/origin\n", 255) = 23 <0.008989>
10:19:03.023027 close(3)                = 0 <0.000015>
10:19:03.023257 access("/home/marco/.gitconfig", R_OK) = -1 ENOENT (No such file or directory) <0.000030>
10:19:03.023401 open(".git/config", O_RDONLY) = 3 <0.000027>
10:19:03.023527 fstat64(3, {st_mode=S_IFREG|0664, st_size=84, ...}) = 0 <0.000012>
10:19:03.023639 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fca000 <0.000019>
10:19:03.023730 read(3, "[core]\n\trepositoryformatversion "..., 4096) = 84 <0.004629>
10:19:03.028488 read(3, "", 4096)       = 0 <0.000012>
10:19:03.028583 close(3)                = 0 <0.000014>
10:19:03.028659 munmap(0xb7fca000, 4096) = 0 <0.000023>
10:19:03.029585 open(".git/packed-refs", O_RDONLY) = 3 <0.000031>
10:19:03.029711 fstat64(3, {st_mode=S_IFREG|0644, st_size=6469, ...}) = 0 <0.000011>
10:19:03.029818 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fca000 <0.000015>
10:19:03.029903 read(3, "dcc22ee22803fe091761047d69d92529"..., 4096) = 4096 <0.013330>
10:19:03.043674 read(3, "f416f8f2bc74d6d0a refs/tags/v1.1"..., 4096) = 2373 <0.003832>
10:19:03.047952 read(3, "", 4096)       = 0 <0.000012>
10:19:03.048142 close(3)                = 0 <0.000013>
10:19:03.048221 munmap(0xb7fca000, 4096) = 0 <0.000022>
10:19:03.048343 open(".git/refs", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 3 <0.000018>
10:19:03.048436 fstat64(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000011>
10:19:03.048541 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0 <0.000012>
10:19:03.048641 getdents(3, /* 4 entries */, 4096) = 68 <0.011642>
10:19:03.060486 stat64(".git/refs/heads", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000034>
10:19:03.060658 open(".git/refs/heads", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 4 <0.000021>
10:19:03.060752 fstat64(4, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000011>
10:19:03.060854 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 <0.000012>
10:19:03.060946 getdents(4, /* 10 entries */, 4096) = 172 <0.000179>
10:19:03.061242 stat64(".git/refs/heads/pu", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.006570>
10:19:03.067925 lstat64(".git/refs/heads/pu", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.068152 open(".git/refs/heads/pu", O_RDONLY) = 5 <0.000019>
10:19:03.068248 read(5, "69e98b538aeb47f1a5602b00f1972bfd"..., 255) = 41 <0.007676>
10:19:03.076003 close(5)                = 0 <0.000541>
10:19:03.076680 stat64(".git/refs/heads/man", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000030>
10:19:03.076831 lstat64(".git/refs/heads/man", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.076944 open(".git/refs/heads/man", O_RDONLY) = 5 <0.000019>
10:19:03.077031 read(5, "d0f877fb601ac0076fd69ec4f48f71f9"..., 255) = 41 <0.009018>
10:19:03.086137 close(5)                = 0 <0.000013>
10:19:03.086232 stat64(".git/refs/heads/todo", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000025>
10:19:03.086361 lstat64(".git/refs/heads/todo", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.086475 open(".git/refs/heads/todo", O_RDONLY) = 5 <0.000017>
10:19:03.086562 read(5, "16a4568a8292605cb688d0e26c65aea8"..., 255) = 41 <0.008006>
10:19:03.094684 close(5)                = 0 <0.000013>
10:19:03.094782 stat64(".git/refs/heads/maint", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000028>
10:19:03.094916 lstat64(".git/refs/heads/maint", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000016>
10:19:03.095030 open(".git/refs/heads/maint", O_RDONLY) = 5 <0.000017>
10:19:03.095118 read(5, "fe142b3a4577a6692a39e2386ed64966"..., 255) = 41 <0.006822>
10:19:03.102017 close(5)                = 0 <0.000013>
10:19:03.102103 stat64(".git/refs/heads/next", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000031>
10:19:03.102236 lstat64(".git/refs/heads/next", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.102382 open(".git/refs/heads/next", O_RDONLY) = 5 <0.000017>
10:19:03.102471 read(5, "8f89a06b2529346f2b05bd44bd6a61a7"..., 255) = 41 <0.008473>
10:19:03.111052 close(5)                = 0 <0.000013>
10:19:03.111150 stat64(".git/refs/heads/v1.4.0", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000029>
10:19:03.111284 lstat64(".git/refs/heads/v1.4.0", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.111398 open(".git/refs/heads/v1.4.0", O_RDONLY) = 5 <0.000018>
10:19:03.111485 read(5, "41292ddd37202ff6dce34986c87a6000"..., 255) = 41 <0.008847>
10:19:03.120410 close(5)                = 0 <0.000012>
10:19:03.120495 stat64(".git/refs/heads/html", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000023>
10:19:03.120621 lstat64(".git/refs/heads/html", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.120734 open(".git/refs/heads/html", O_RDONLY) = 5 <0.000017>
10:19:03.120821 read(5, "fb2ead308920336d55720031034442c1"..., 255) = 41 <0.015274>
10:19:03.136258 close(5)                = 0 <0.000016>
10:19:03.136383 stat64(".git/refs/heads/origin", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000033>
10:19:03.136524 lstat64(".git/refs/heads/origin", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.136638 open(".git/refs/heads/origin", O_RDONLY) = 5 <0.000020>
10:19:03.136728 read(5, "e267c2f6f0784e242883b7d3fe5f36ef"..., 255) = 41 <0.000725>
10:19:03.137529 close(5)                = 0 <0.000013>
10:19:03.137611 getdents(4, /* 0 entries */, 4096) = 0 <0.000013>
10:19:03.137702 close(4)                = 0 <0.000012>
10:19:03.137781 stat64(".git/refs/tags", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000025>
10:19:03.137909 open(".git/refs/tags", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 4 <0.000016>
10:19:03.137997 fstat64(4, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000012>
10:19:03.138098 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 <0.000013>
10:19:03.138177 getdents(4, /* 7 entries */, 4096) = 140 <0.010973>
10:19:03.149276 stat64(".git/refs/tags/v1.4.3.4", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.004994>
10:19:03.154448 lstat64(".git/refs/tags/v1.4.3.4", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000017>
10:19:03.154585 open(".git/refs/tags/v1.4.3.4", O_RDONLY) = 5 <0.000022>
10:19:03.154677 read(5, "100490cfcd50d0f9ddadeb90cf5d95b2"..., 255) = 41 <0.005124>
10:19:03.159877 close(5)                = 0 <0.000015>
10:19:03.159966 stat64(".git/refs/tags/v1.4.4-rc1", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.006757>
10:19:03.166861 lstat64(".git/refs/tags/v1.4.4-rc1", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000017>
10:19:03.166995 open(".git/refs/tags/v1.4.4-rc1", O_RDONLY) = 5 <0.000019>
10:19:03.167085 read(5, "3a41a48d139d1425c1d27e3fbe4f511f"..., 255) = 41 <0.005877>
10:19:03.173113 close(5)                = 0 <0.000015>
10:19:03.173236 stat64(".git/refs/tags/v1.4.3.5", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.006382>
10:19:03.179730 lstat64(".git/refs/tags/v1.4.3.5", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.179846 open(".git/refs/tags/v1.4.3.5", O_RDONLY) = 5 <0.000019>
10:19:03.179936 read(5, "a8d8dc4c6cd6d4681746fd6919318640"..., 255) = 41 <0.007536>
10:19:03.187558 close(5)                = 0 <0.000013>
10:19:03.187655 stat64(".git/refs/tags/v1.4.4-rc2", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000026>
10:19:03.187785 lstat64(".git/refs/tags/v1.4.4-rc2", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.187899 open(".git/refs/tags/v1.4.4-rc2", O_RDONLY) = 5 <0.000018>
10:19:03.187988 read(5, "b9b0b3d0020c3559d4d9e6d07e3316c3"..., 255) = 41 <0.010095>
10:19:03.198218 close(5)                = 0 <0.000015>
10:19:03.198330 stat64(".git/refs/tags/v1.4.4", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.003882>
10:19:03.202322 lstat64(".git/refs/tags/v1.4.4", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0 <0.000015>
10:19:03.202437 open(".git/refs/tags/v1.4.4", O_RDONLY) = 5 <0.000019>
10:19:03.202527 read(5, "fab4f17015ccb2c6ea978b45386d45dd"..., 255) = 41 <0.014246>
10:19:03.216949 close(5)                = 0 <0.000014>
10:19:03.217063 getdents(4, /* 0 entries */, 4096) = 0 <0.000013>
10:19:03.217140 close(4)                = 0 <0.000012>
10:19:03.217213 getdents(3, /* 0 entries */, 4096) = 0 <0.000011>
10:19:03.217287 close(3)                = 0 <0.000011>
10:19:03.217397 open(".git/objects/pack", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 3 <0.015266>
10:19:03.232796 fstat64(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000011>
10:19:03.232928 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0 <0.000012>
10:19:03.233009 getdents(3, /* 4 entries */, 4096) = 160 <0.000216>
10:19:03.233356 open(".git/objects/pack/pack-a587adeec6a06edc539cc73c0a526e93b2982022.idx", O_RDONLY) = 4 <0.000032>
10:19:03.233486 fstat64(4, {st_mode=S_IFREG|0444, st_size=431864, ...}) = 0 <0.000011>
10:19:03.233598 mmap2(NULL, 431864, PROT_READ, MAP_PRIVATE, 4, 0) = 0xb7cb8000 <0.000022>
10:19:03.233687 close(4)                = 0 <0.000012>
10:19:03.252324 stat64(".git/objects/pack/pack-a587adeec6a06edc539cc73c0a526e93b2982022.pack", {st_mode=S_IFREG|0444, st_size=7118252, ...}) = 0 <0.000057>
10:19:03.252570 getdents(3, /* 0 entries */, 4096) = 0 <0.000013>
10:19:03.252652 close(3)                = 0 <0.000014>
10:19:03.252741 open(".git/objects/info/alternates", O_RDONLY) = -1 ENOENT (No such file or directory) <0.006948>
10:19:03.271644 stat64(".git/objects/fb/2ead308920336d55720031034442c1ff3a2088", {st_mode=S_IFREG|0444, st_size=193, ...}) = 0 <0.029404>
10:19:03.301358 stat64(".git/objects/fb/2ead308920336d55720031034442c1ff3a2088", {st_mode=S_IFREG|0444, st_size=193, ...}) = 0 <0.000018>
10:19:03.301514 open(".git/objects/fb/2ead308920336d55720031034442c1ff3a2088", O_RDONLY|O_NOATIME) = 3 <0.000023>
10:19:03.301620 mmap2(NULL, 193, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fca000 <0.000019>
10:19:03.301706 close(3)                = 0 <0.000012>
10:19:03.310337 munmap(0xb7fca000, 193) = 0 <0.000030>
10:19:03.310740 open(".git/info/grafts", O_RDONLY) = -1 ENOENT (No such file or directory) <0.008295>
10:19:03.319252 fstat64(1, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000013>
10:19:03.319386 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fca000 <0.000018>
10:19:03.319500 stat64(".git/objects/fe/142b3a4577a6692a39e2386ed649664ad8bd20", {st_mode=S_IFREG|0444, st_size=316, ...}) = 0 <0.010379>
10:19:03.330019 stat64(".git/objects/fe/142b3a4577a6692a39e2386ed649664ad8bd20", {st_mode=S_IFREG|0444, st_size=316, ...}) = 0 <0.000016>
10:19:03.330156 open(".git/objects/fe/142b3a4577a6692a39e2386ed649664ad8bd20", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:03.330260 mmap2(NULL, 316, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000018>
10:19:03.330344 close(3)                = 0 <0.000011>
10:19:03.342077 munmap(0xb7fc9000, 316) = 0 <0.000058>
10:19:03.355754 stat64(".git/objects/d0/f877fb601ac0076fd69ec4f48f71f9247771c8", {st_mode=S_IFREG|0444, st_size=190, ...}) = 0 <0.046244>
10:19:03.402234 stat64(".git/objects/d0/f877fb601ac0076fd69ec4f48f71f9247771c8", {st_mode=S_IFREG|0444, st_size=190, ...}) = 0 <0.000019>
10:19:03.402392 open(".git/objects/d0/f877fb601ac0076fd69ec4f48f71f9247771c8", O_RDONLY|O_NOATIME) = 3 <0.000023>
10:19:03.402498 mmap2(NULL, 190, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000021>
10:19:03.402586 close(3)                = 0 <0.000012>
10:19:03.408581 munmap(0xb7fc9000, 190) = 0 <0.000022>
10:19:03.427950 stat64(".git/objects/8f/89a06b2529346f2b05bd44bd6a61a76898c639", {st_mode=S_IFREG|0444, st_size=262, ...}) = 0 <0.018769>
10:19:03.446963 stat64(".git/objects/8f/89a06b2529346f2b05bd44bd6a61a76898c639", {st_mode=S_IFREG|0444, st_size=262, ...}) = 0 <0.000017>
10:19:03.447109 open(".git/objects/8f/89a06b2529346f2b05bd44bd6a61a76898c639", O_RDONLY|O_NOATIME) = 3 <0.000018>
10:19:03.447209 mmap2(NULL, 262, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000020>
10:19:03.447297 close(3)                = 0 <0.000010>
10:19:03.455682 munmap(0xb7fc9000, 262) = 0 <0.000023>
10:19:03.455835 stat64(".git/objects/e2/67c2f6f0784e242883b7d3fe5f36ef63d6950d", {st_mode=S_IFREG|0444, st_size=179, ...}) = 0 <0.033849>
10:19:03.489904 stat64(".git/objects/e2/67c2f6f0784e242883b7d3fe5f36ef63d6950d", {st_mode=S_IFREG|0444, st_size=179, ...}) = 0 <0.000018>
10:19:03.490059 open(".git/objects/e2/67c2f6f0784e242883b7d3fe5f36ef63d6950d", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:03.490162 mmap2(NULL, 179, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:03.490249 close(3)                = 0 <0.000011>
10:19:03.504780 munmap(0xb7fc9000, 179) = 0 <0.000023>
10:19:03.504931 stat64(".git/objects/69/e98b538aeb47f1a5602b00f1972bfd05ac27cc", {st_mode=S_IFREG|0444, st_size=517, ...}) = 0 <0.026898>
10:19:03.531966 stat64(".git/objects/69/e98b538aeb47f1a5602b00f1972bfd05ac27cc", {st_mode=S_IFREG|0444, st_size=517, ...}) = 0 <0.000016>
10:19:03.532337 open(".git/objects/69/e98b538aeb47f1a5602b00f1972bfd05ac27cc", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:03.532458 mmap2(NULL, 517, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:03.532542 close(3)                = 0 <0.000012>
10:19:03.542325 munmap(0xb7fc9000, 517) = 0 <0.000022>
10:19:03.542485 stat64(".git/objects/16/a4568a8292605cb688d0e26c65aea8850f22d4", {st_mode=S_IFREG|0444, st_size=184, ...}) = 0 <0.015860>
10:19:03.558508 stat64(".git/objects/16/a4568a8292605cb688d0e26c65aea8850f22d4", {st_mode=S_IFREG|0444, st_size=184, ...}) = 0 <0.000017>
10:19:03.558654 open(".git/objects/16/a4568a8292605cb688d0e26c65aea8850f22d4", O_RDONLY|O_NOATIME) = 3 <0.000019>
10:19:03.558755 mmap2(NULL, 184, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000018>
10:19:03.558839 close(3)                = 0 <0.000012>
10:19:03.566339 munmap(0xb7fc9000, 184) = 0 <0.000024>
10:19:03.566511 stat64(".git/objects/41/292ddd37202ff6dce34986c87a6000c5d3fbfa", {st_mode=S_IFREG|0444, st_size=180, ...}) = 0 <0.020396>
10:19:03.587058 stat64(".git/objects/41/292ddd37202ff6dce34986c87a6000c5d3fbfa", {st_mode=S_IFREG|0444, st_size=180, ...}) = 0 <0.000016>
10:19:03.587197 open(".git/objects/41/292ddd37202ff6dce34986c87a6000c5d3fbfa", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:03.587299 mmap2(NULL, 180, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:03.587383 close(3)                = 0 <0.000012>
10:19:03.600927 munmap(0xb7fc9000, 180) = 0 <0.000022>
10:19:03.601072 open(".git/objects/pack/pack-a587adeec6a06edc539cc73c0a526e93b2982022.pack", O_RDONLY) = 3 <0.000022>
10:19:03.601180 fstat64(3, {st_mode=S_IFREG|0444, st_size=7118252, ...}) = 0 <0.000011>
10:19:03.601284 mmap2(NULL, 7118252, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb75ee000 <0.000018>
10:19:03.601365 close(3)                = 0 <0.000011>
10:19:03.645053 brk(0x8124000)          = 0x8124000 <0.000019>
10:19:03.662737 write(1, "fb2ead308920336d55720031034442c1"..., 4096) = 4096 <0.000054>
10:19:03.663479 stat64(".git/objects/b0/517166ae2ad92f3b17638cbdee0f04b8170d99", {st_mode=S_IFREG|0444, st_size=277, ...}) = 0 <0.022552>
10:19:03.686177 stat64(".git/objects/b0/517166ae2ad92f3b17638cbdee0f04b8170d99", {st_mode=S_IFREG|0444, st_size=277, ...}) = 0 <0.000017>
10:19:03.686315 open(".git/objects/b0/517166ae2ad92f3b17638cbdee0f04b8170d99", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:03.686418 mmap2(NULL, 277, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000021>
10:19:03.686504 close(3)                = 0 <0.000012>
10:19:03.690535 munmap(0xb7fc9000, 277) = 0 <0.000026>
10:19:03.690897 stat64(".git/objects/86/a9bf69164090c91474bb7bcdde7d76966b7d40", {st_mode=S_IFREG|0444, st_size=282, ...}) = 0 <0.015918>
10:19:03.706991 stat64(".git/objects/86/a9bf69164090c91474bb7bcdde7d76966b7d40", {st_mode=S_IFREG|0444, st_size=282, ...}) = 0 <0.000017>
10:19:03.707140 open(".git/objects/86/a9bf69164090c91474bb7bcdde7d76966b7d40", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:03.707243 mmap2(NULL, 282, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000020>
10:19:03.707328 close(3)                = 0 <0.000012>
10:19:03.721897 munmap(0xb7fc9000, 282) = 0 <0.000026>
10:19:03.722067 stat64(".git/objects/fa/7bd724f61bcdcd71ef579f7b94b72bda1298cf", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.007090>
10:19:03.729292 stat64(".git/objects/fa/7bd724f61bcdcd71ef579f7b94b72bda1298cf", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.000017>
10:19:03.729456 open(".git/objects/fa/7bd724f61bcdcd71ef579f7b94b72bda1298cf", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:03.729560 mmap2(NULL, 279, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:03.729645 close(3)                = 0 <0.000012>
10:19:03.730857 munmap(0xb7fc9000, 279) = 0 <0.000019>
10:19:03.730979 stat64(".git/objects/43/2567e79be81bc91f4af5bcfe5ac51330d2d349", {st_mode=S_IFREG|0444, st_size=281, ...}) = 0 <0.035298>
10:19:03.766440 stat64(".git/objects/43/2567e79be81bc91f4af5bcfe5ac51330d2d349", {st_mode=S_IFREG|0444, st_size=281, ...}) = 0 <0.000018>
10:19:03.766586 open(".git/objects/43/2567e79be81bc91f4af5bcfe5ac51330d2d349", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:03.766687 mmap2(NULL, 281, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:03.766771 close(3)                = 0 <0.000012>
10:19:03.780679 munmap(0xb7fc9000, 281) = 0 <0.000023>
10:19:03.780829 stat64(".git/objects/ff/a22c1601a782de4f54c7667d772936da123ef0", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.020505>
10:19:03.801496 stat64(".git/objects/ff/a22c1601a782de4f54c7667d772936da123ef0", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.000017>
10:19:03.801642 open(".git/objects/ff/a22c1601a782de4f54c7667d772936da123ef0", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:03.801744 mmap2(NULL, 279, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000020>
10:19:03.801829 close(3)                = 0 <0.000011>
10:19:03.811789 munmap(0xb7fc9000, 279) = 0 <0.000022>
10:19:03.811920 stat64(".git/objects/12/0530fb2e10679d9095e278c95c0e98c96f3080", {st_mode=S_IFREG|0444, st_size=277, ...}) = 0 <0.008756>
10:19:03.820801 stat64(".git/objects/12/0530fb2e10679d9095e278c95c0e98c96f3080", {st_mode=S_IFREG|0444, st_size=277, ...}) = 0 <0.000015>
10:19:03.820927 open(".git/objects/12/0530fb2e10679d9095e278c95c0e98c96f3080", O_RDONLY|O_NOATIME) = 3 <0.000019>
10:19:03.821027 mmap2(NULL, 277, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000017>
10:19:03.821109 close(3)                = 0 <0.000011>
10:19:03.838061 munmap(0xb7fc9000, 277) = 0 <0.000029>
10:19:03.838263 stat64(".git/objects/92/d7605b6d9312a29efa30b1baa4d7c880a0be41", {st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.032662>
10:19:03.871093 stat64(".git/objects/92/d7605b6d9312a29efa30b1baa4d7c880a0be41", {st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.000017>
10:19:03.871238 open(".git/objects/92/d7605b6d9312a29efa30b1baa4d7c880a0be41", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:03.871339 mmap2(NULL, 280, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000021>
10:19:03.871426 close(3)                = 0 <0.000012>
10:19:03.885472 munmap(0xb7fc9000, 280) = 0 <0.000046>
10:19:03.885707 stat64(".git/objects/58/9ee4d580d34a76238e90795a070a7372de18a2", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.021423>
10:19:03.907288 stat64(".git/objects/58/9ee4d580d34a76238e90795a070a7372de18a2", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.000017>
10:19:03.907429 open(".git/objects/58/9ee4d580d34a76238e90795a070a7372de18a2", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:03.907531 mmap2(NULL, 279, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000020>
10:19:03.907617 close(3)                = 0 <0.000012>
10:19:03.912980 munmap(0xb7fc9000, 279) = 0 <0.000020>
10:19:03.913107 stat64(".git/objects/4c/e643674c24dbda1d0fa0a0da60163ff9ea666f", {st_mode=S_IFREG|0444, st_size=275, ...}) = 0 <0.013600>
10:19:03.926830 stat64(".git/objects/4c/e643674c24dbda1d0fa0a0da60163ff9ea666f", {st_mode=S_IFREG|0444, st_size=275, ...}) = 0 <0.000016>
10:19:03.926958 open(".git/objects/4c/e643674c24dbda1d0fa0a0da60163ff9ea666f", O_RDONLY|O_NOATIME) = 3 <0.000019>
10:19:03.927056 mmap2(NULL, 275, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000016>
10:19:03.927137 close(3)                = 0 <0.000011>
10:19:03.939741 munmap(0xb7fc9000, 275) = 0 <0.000023>
10:19:03.939895 stat64(".git/objects/73/8dec0ead6a96f87cf71989a1dad7bb5d1faba4", {st_mode=S_IFREG|0444, st_size=747, ...}) = 0 <0.020027>
10:19:03.960098 stat64(".git/objects/73/8dec0ead6a96f87cf71989a1dad7bb5d1faba4", {st_mode=S_IFREG|0444, st_size=747, ...}) = 0 <0.000292>
10:19:03.960542 open(".git/objects/73/8dec0ead6a96f87cf71989a1dad7bb5d1faba4", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:03.960649 mmap2(NULL, 747, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:03.960734 close(3)                = 0 <0.000012>
10:19:03.965837 munmap(0xb7fc9000, 747) = 0 <0.000027>
10:19:03.966016 stat64(".git/objects/33/c9db007159db11c1ad5fa7101ea95853740acf", {st_mode=S_IFREG|0444, st_size=469, ...}) = 0 <0.015332>
10:19:03.981493 stat64(".git/objects/33/c9db007159db11c1ad5fa7101ea95853740acf", {st_mode=S_IFREG|0444, st_size=469, ...}) = 0 <0.000016>
10:19:03.981629 open(".git/objects/33/c9db007159db11c1ad5fa7101ea95853740acf", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:03.981730 mmap2(NULL, 469, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:03.981815 close(3)                = 0 <0.000012>
10:19:03.988857 munmap(0xb7fc9000, 469) = 0 <0.000023>
10:19:03.989010 stat64(".git/objects/84/19a453dc088b25b63ab1746d3d7e679caf686d", {st_mode=S_IFREG|0444, st_size=382, ...}) = 0 <0.020436>
10:19:04.009621 stat64(".git/objects/84/19a453dc088b25b63ab1746d3d7e679caf686d", {st_mode=S_IFREG|0444, st_size=382, ...}) = 0 <0.000016>
10:19:04.009759 open(".git/objects/84/19a453dc088b25b63ab1746d3d7e679caf686d", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:04.009860 mmap2(NULL, 382, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.009944 close(3)                = 0 <0.000012>
10:19:04.017654 munmap(0xb7fc9000, 382) = 0 <0.000021>
10:19:04.017786 stat64(".git/objects/85/ba32e27db65314ad4ea25f5afcaad684d68811", {st_mode=S_IFREG|0444, st_size=275, ...}) = 0 <0.013548>
10:19:04.031456 stat64(".git/objects/85/ba32e27db65314ad4ea25f5afcaad684d68811", {st_mode=S_IFREG|0444, st_size=275, ...}) = 0 <0.000015>
10:19:04.031583 open(".git/objects/85/ba32e27db65314ad4ea25f5afcaad684d68811", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:04.031681 mmap2(NULL, 275, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000016>
10:19:04.031763 close(3)                = 0 <0.000011>
10:19:04.043476 munmap(0xb7fc9000, 275) = 0 <0.000022>
10:19:04.043619 stat64(".git/objects/91/82013b4241fefc455f07fc78a922c9c149a38b", {st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.008078>
10:19:04.051857 stat64(".git/objects/91/82013b4241fefc455f07fc78a922c9c149a38b", {st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.000017>
10:19:04.052001 open(".git/objects/91/82013b4241fefc455f07fc78a922c9c149a38b", O_RDONLY|O_NOATIME) = 3 <0.000019>
10:19:04.052102 mmap2(NULL, 280, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000097>
10:19:04.052284 close(3)                = 0 <0.000011>
10:19:04.058917 munmap(0xb7fc9000, 280) = 0 <0.000022>
10:19:04.059041 stat64(".git/objects/d2/d79edaf81ec78ad11c8daeb91ee3e82a4aaa19", {st_mode=S_IFREG|0444, st_size=282, ...}) = 0 <0.013396>
10:19:04.072584 stat64(".git/objects/d2/d79edaf81ec78ad11c8daeb91ee3e82a4aaa19", {st_mode=S_IFREG|0444, st_size=282, ...}) = 0 <0.000016>
10:19:04.072725 open(".git/objects/d2/d79edaf81ec78ad11c8daeb91ee3e82a4aaa19", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:04.072827 mmap2(NULL, 282, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.072911 close(3)                = 0 <0.000012>
10:19:04.084973 munmap(0xb7fc9000, 282) = 0 <0.000024>
10:19:04.085140 stat64(".git/objects/bc/3aec1567d09218d319e8053d58fd740e3f6d4a", {st_mode=S_IFREG|0444, st_size=281, ...}) = 0 <0.005028>
10:19:04.090289 stat64(".git/objects/bc/3aec1567d09218d319e8053d58fd740e3f6d4a", {st_mode=S_IFREG|0444, st_size=281, ...}) = 0 <0.000016>
10:19:04.090414 open(".git/objects/bc/3aec1567d09218d319e8053d58fd740e3f6d4a", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:04.090515 mmap2(NULL, 281, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000017>
10:19:04.090597 close(3)                = 0 <0.000011>
10:19:04.101560 munmap(0xb7fc9000, 281) = 0 <0.000019>
10:19:04.101683 stat64(".git/objects/8c/7a107d8eeba18ae56befb6142daaba91aa3ecf", {st_mode=S_IFREG|0444, st_size=378, ...}) = 0 <0.014772>
10:19:04.116612 stat64(".git/objects/8c/7a107d8eeba18ae56befb6142daaba91aa3ecf", {st_mode=S_IFREG|0444, st_size=378, ...}) = 0 <0.000016>
10:19:04.116745 open(".git/objects/8c/7a107d8eeba18ae56befb6142daaba91aa3ecf", O_RDONLY|O_NOATIME) = 3 <0.000019>
10:19:04.116845 mmap2(NULL, 378, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.116928 close(3)                = 0 <0.000011>
10:19:04.117185 munmap(0xb7fc9000, 378) = 0 <0.000019>
10:19:04.117305 stat64(".git/objects/ad/86a7fc13a820a56957f41f81c4763f734676f4", {st_mode=S_IFREG|0444, st_size=324, ...}) = 0 <0.029156>
10:19:04.146625 stat64(".git/objects/ad/86a7fc13a820a56957f41f81c4763f734676f4", {st_mode=S_IFREG|0444, st_size=324, ...}) = 0 <0.000017>
10:19:04.146769 open(".git/objects/ad/86a7fc13a820a56957f41f81c4763f734676f4", O_RDONLY|O_NOATIME) = 3 <0.000018>
10:19:04.146868 mmap2(NULL, 324, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.146952 close(3)                = 0 <0.000011>
10:19:04.156903 munmap(0xb7fc9000, 324) = 0 <0.000023>
10:19:04.157043 stat64(".git/objects/27/da5785a8fec4e462aeee4dc41281ac89233675", {st_mode=S_IFREG|0444, st_size=397, ...}) = 0 <0.027180>
10:19:04.184386 stat64(".git/objects/27/da5785a8fec4e462aeee4dc41281ac89233675", {st_mode=S_IFREG|0444, st_size=397, ...}) = 0 <0.000017>
10:19:04.184532 open(".git/objects/27/da5785a8fec4e462aeee4dc41281ac89233675", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:04.184635 mmap2(NULL, 397, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.184720 close(3)                = 0 <0.000011>
10:19:04.189421 munmap(0xb7fc9000, 397) = 0 <0.000025>
10:19:04.189583 stat64(".git/objects/32/578a62ce8469465504509360aed5f1a6dc5b2b", {st_mode=S_IFREG|0444, st_size=319, ...}) = 0 <0.011685>
10:19:04.201394 stat64(".git/objects/32/578a62ce8469465504509360aed5f1a6dc5b2b", {st_mode=S_IFREG|0444, st_size=319, ...}) = 0 <0.000016>
10:19:04.201521 open(".git/objects/32/578a62ce8469465504509360aed5f1a6dc5b2b", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:04.201621 mmap2(NULL, 319, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000018>
10:19:04.201702 close(3)                = 0 <0.000012>
10:19:04.216765 munmap(0xb7fc9000, 319) = 0 <0.000027>
10:19:04.216944 stat64(".git/objects/ab/71dde01e310ed582e86446d216531f792468bf", {st_mode=S_IFREG|0444, st_size=325, ...}) = 0 <0.004873>
10:19:04.221941 stat64(".git/objects/ab/71dde01e310ed582e86446d216531f792468bf", {st_mode=S_IFREG|0444, st_size=325, ...}) = 0 <0.000016>
10:19:04.222067 open(".git/objects/ab/71dde01e310ed582e86446d216531f792468bf", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:04.222169 mmap2(NULL, 325, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000018>
10:19:04.222253 close(3)                = 0 <0.000012>
10:19:04.230433 munmap(0xb7fc9000, 325) = 0 <0.000019>
10:19:04.230556 stat64(".git/objects/d9/b0f913ce0508fcc83e642e0241f373428368e5", {st_mode=S_IFREG|0444, st_size=275, ...}) = 0 <0.014431>
10:19:04.245143 stat64(".git/objects/d9/b0f913ce0508fcc83e642e0241f373428368e5", {st_mode=S_IFREG|0444, st_size=275, ...}) = 0 <0.000017>
10:19:04.245282 open(".git/objects/d9/b0f913ce0508fcc83e642e0241f373428368e5", O_RDONLY|O_NOATIME) = 3 <0.000018>
10:19:04.245380 mmap2(NULL, 275, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.245464 close(3)                = 0 <0.000011>
10:19:04.259086 munmap(0xb7fc9000, 275) = 0 <0.000021>
10:19:04.259218 stat64(".git/objects/43/14f5982d2aac08001a977fc0b1b611e858e025", {st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.012914>
10:19:04.272282 stat64(".git/objects/43/14f5982d2aac08001a977fc0b1b611e858e025", {st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.000017>
10:19:04.272425 open(".git/objects/43/14f5982d2aac08001a977fc0b1b611e858e025", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:04.272528 mmap2(NULL, 280, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000018>
10:19:04.272611 close(3)                = 0 <0.000011>
10:19:04.284930 munmap(0xb7fc9000, 280) = 0 <0.000028>
10:19:04.285142 stat64(".git/objects/87/30a82b9f00b8debab717ec384eedbd0f36a54f", {st_mode=S_IFREG|0444, st_size=294, ...}) = 0 <0.006320>
10:19:04.291672 stat64(".git/objects/87/30a82b9f00b8debab717ec384eedbd0f36a54f", {st_mode=S_IFREG|0444, st_size=294, ...}) = 0 <0.000017>
10:19:04.291825 open(".git/objects/87/30a82b9f00b8debab717ec384eedbd0f36a54f", O_RDONLY|O_NOATIME) = 3 <0.000023>
10:19:04.291929 mmap2(NULL, 294, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000020>
10:19:04.292015 close(3)                = 0 <0.000012>
10:19:04.303292 munmap(0xb7fc9000, 294) = 0 <0.000023>
10:19:04.303442 stat64(".git/objects/a4/97d102d6961ded91b60dc3524eb63679d7dc08", {st_mode=S_IFREG|0444, st_size=282, ...}) = 0 <0.012219>
10:19:04.315813 stat64(".git/objects/a4/97d102d6961ded91b60dc3524eb63679d7dc08", {st_mode=S_IFREG|0444, st_size=282, ...}) = 0 <0.000016>
10:19:04.315955 open(".git/objects/a4/97d102d6961ded91b60dc3524eb63679d7dc08", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:04.316057 mmap2(NULL, 282, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.316141 close(3)                = 0 <0.000082>
10:19:04.316530 munmap(0xb7fc9000, 282) = 0 <0.000021>
10:19:04.316655 stat64(".git/objects/95/f1e36cc34e8738e5c431aac47d6fea18913db0", {st_mode=S_IFREG|0444, st_size=395, ...}) = 0 <0.023411>
10:19:04.340297 stat64(".git/objects/95/f1e36cc34e8738e5c431aac47d6fea18913db0", {st_mode=S_IFREG|0444, st_size=395, ...}) = 0 <0.000017>
10:19:04.340444 open(".git/objects/95/f1e36cc34e8738e5c431aac47d6fea18913db0", O_RDONLY|O_NOATIME) = 3 <0.000022>
10:19:04.340547 mmap2(NULL, 395, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:04.340632 close(3)                = 0 <0.000012>
10:19:04.349413 munmap(0xb7fc9000, 395) = 0 <0.000024>
10:19:04.349568 stat64(".git/objects/84/13d9ffefd1fde6d8a04f9e22503ab910fc36de", {st_mode=S_IFREG|0444, st_size=1061, ...}) = 0 <0.015285>
10:19:04.365008 stat64(".git/objects/84/13d9ffefd1fde6d8a04f9e22503ab910fc36de", {st_mode=S_IFREG|0444, st_size=1061, ...}) = 0 <0.000017>
10:19:04.365150 open(".git/objects/84/13d9ffefd1fde6d8a04f9e22503ab910fc36de", O_RDONLY|O_NOATIME) = 3 <0.000021>
10:19:04.365252 mmap2(NULL, 1061, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000018>
10:19:04.365335 close(3)                = 0 <0.000012>
10:19:04.369839 munmap(0xb7fc9000, 1061) = 0 <0.000021>
10:19:04.369984 stat64(".git/objects/d1/eebeecb839749b1559ec7d44b9a31b2513cfb3", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.011146>
10:19:04.381282 stat64(".git/objects/d1/eebeecb839749b1559ec7d44b9a31b2513cfb3", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.000017>
10:19:04.381422 open(".git/objects/d1/eebeecb839749b1559ec7d44b9a31b2513cfb3", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:04.381523 mmap2(NULL, 279, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000018>
10:19:04.381607 close(3)                = 0 <0.000011>
10:19:04.381899 munmap(0xb7fc9000, 279) = 0 <0.000020>
10:19:04.382020 stat64(".git/objects/10/0490cfcd50d0f9ddadeb90cf5d95b28e2397ce", {st_mode=S_IFREG|0444, st_size=1641, ...}) = 0 <0.023306>
10:19:04.405476 open(".git/objects/10/0490cfcd50d0f9ddadeb90cf5d95b28e2397ce", O_RDONLY|O_NOATIME) = 3 <0.000023>
10:19:04.405599 mmap2(NULL, 1641, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000020>
10:19:04.405684 close(3)                = 0 <0.000012>
10:19:04.420508 munmap(0xb7fc9000, 1641) = 0 <0.000025>
10:19:04.420725 stat64(".git/objects/a8/d8dc4c6cd6d4681746fd6919318640ee97a059", {st_mode=S_IFREG|0444, st_size=279, ...}) = 0 <0.007644>
10:19:04.428492 open(".git/objects/a8/d8dc4c6cd6d4681746fd6919318640ee97a059", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:04.428599 mmap2(NULL, 279, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000017>
10:19:04.428681 close(3)                = 0 <0.000011>
10:19:04.439591 munmap(0xb7fc9000, 279) = 0 <0.000022>
10:19:04.439727 stat64(".git/objects/fa/b4f17015ccb2c6ea978b45386d45dd008df42d", {st_mode=S_IFREG|0444, st_size=278, ...}) = 0 <0.000039>
10:19:04.439879 open(".git/objects/fa/b4f17015ccb2c6ea978b45386d45dd008df42d", O_RDONLY|O_NOATIME) = 3 <0.000020>
10:19:04.439978 mmap2(NULL, 278, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000016>
10:19:04.440060 close(3)                = 0 <0.000012>
10:19:04.449022 munmap(0xb7fc9000, 278) = 0 <0.000028>
10:19:04.449236 stat64(".git/objects/3a/41a48d139d1425c1d27e3fbe4f511fb7e09e94", {st_mode=S_IFREG|0444, st_size=278, ...}) = 0 <0.817989>
10:19:05.267499 open(".git/objects/3a/41a48d139d1425c1d27e3fbe4f511fb7e09e94", O_RDONLY|O_NOATIME) = 3 <0.000027>
10:19:05.267643 mmap2(NULL, 278, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000019>
10:19:05.267730 close(3)                = 0 <0.000012>
10:19:05.298154 munmap(0xb7fc9000, 278) = 0 <0.000024>
10:19:05.298362 stat64(".git/objects/b9/b0b3d0020c3559d4d9e6d07e3316c3ebcd6e85", {st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.025652>
10:19:05.324191 open(".git/objects/b9/b0b3d0020c3559d4d9e6d07e3316c3ebcd6e85", O_RDONLY|O_NOATIME) = 3 <0.000095>
10:19:05.324395 mmap2(NULL, 280, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fc9000 <0.000020>
10:19:05.324483 close(3)                = 0 <0.000011>
10:19:05.336149 munmap(0xb7fc9000, 280) = 0 <0.000025>
10:19:05.336371 write(1, "f416f8f2bc74d6d0a refs/tags/v1.1"..., 2675) = 2675 <0.000049>
10:19:05.336516 exit_group(0)           = ?

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Marco Costalba wrote:
> 
> Sure. File ran against git tree attached.

Ok. Nothing really strange stands out - it's a nice trace with just over 
400 system calls. I'd expect it to finish in no time at all (tracing will 
add some overhead, since you context switch back and forth between the 
tracer and the tracee, but it's really not doing a lot, so even with 
tracing it should execute almost instantaneously).

So it all looks _almost_ fine..

Except for this one:

   10:19:04.449236 stat64(".git/objects/3a/41a48d139d1425c1d27e3fbe4f511fb7e09e94", {st_mode=S_IFREG|0444, st_size=278, ...}) = 0 <0.817989>

That's a _single_ "stat64()" system call that takes almost a second to 
execute. All the rest are in the millisecond range, and sometimes a 
hundreth of a second or two. Ie doing

	grep -v ' <0.0[012]' tracefile_git_tree.txt

on your tracefile, there's really not a lot of system calls that take a 
long time, and that one stat _really_ stands out (the others are 3 or four 
hundredths of a second, and then suddenly you have one that is 20 times 
longer than even the slowest other ones.

Basically, you seem to have a _single_ object access that takes up half 
the time of the whole program.

It's the object for 'refs/tags/v1.4.4-rc1' in case you care, btw. 

> If you want I can repack and prune, but for now I just wait to avoid
> to corrupt this test case.

What you could try to do is to re-run it a few times (cold-cache) and see 
if those numbers really are stable, and if it's always the same object 
that takes that long.

In fact, you could even do a simple

	time ls -l .git/objects/3a/41a48d139d1425c1d27e3fbe4f511fb7e09e94

for the cold-cache case, and see if just even _that_ takes almost a 
second.

If it _is_ stable, there's two possibilities:

 - you have a large and slow disk, and that one object really is way out 
   there on the other side of the disk, and seeking really takes almost a 
   second.

   Quite frankly, I expected that the time when a single stat() took 
   almost a second was a decade or more in the past, back in the days of 
   floppy-disks. But what do I know?

 - your disk is failing, and ends up doing error recovery etc.

   Maybe worth running "smartctl -a /dev/hda" or whatever, to see if the 
   disk already knows it is having problems.

Anyway, repacking will fix this, but quite frankly, you might have a 
reason to be a bit nervous about that disk if I were you.

(NOTE NOTE NOTE! There could be other reasons for that second delay. If 
the machine was under heavy load, or was running low on memory, maybe the 
long delay was just due to havign to swap things out or run other things 
instead. That's why it might be interesting to see if the number is 
"stable" in that it's always that same object..)

Re: [WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

On 11/19/06, Linus Torvalds <torvalds@osdl.org> wrote:
>
> So it all looks _almost_ fine..
>
> Except for this one:
>
>    10:19:04.449236 stat64(".git/objects/3a/41a48d139d1425c1d27e3fbe4f511fb7e09e94", {st_mode=S_IFREG|0444, st_size=278, ...}) = 0 <0.817989>
>
> That's a _single_ "stat64()" system call that takes almost a second to
> execute. All the rest are in the millisecond range, and sometimes a
> hundreth of a second or two. Ie doing
>
>         grep -v ' <0.0[012]' tracefile_git_tree.txt
>
> on your tracefile, there's really not a lot of system calls that take a
> long time, and that one stat _really_ stands out (the others are 3 or four
> hundredths of a second, and then suddenly you have one that is 20 times
> longer than even the slowest other ones.
>
> Basically, you seem to have a _single_ object access that takes up half
> the time of the whole program.
>

But why my numbers are bad both in git, in Linux and also qgit (not
posted) local repo? If it is a single case other repos should load
fast.

> It's the object for 'refs/tags/v1.4.4-rc1' in case you care, btw.
>
> > If you want I can repack and prune, but for now I just wait to avoid
> > to corrupt this test case.
>
> What you could try to do is to re-run it a few times (cold-cache) and see
> if those numbers really are stable, and if it's always the same object
> that takes that long.
>

Right now I'm running smartctl -t long  /dev/hda, I was a little bit scared ;-)

When finished I will do additional cold chache (reboot) tests.

> In fact, you could even do a simple
>
>         time ls -l .git/objects/3a/41a48d139d1425c1d27e3fbe4f511fb7e09e94
>
> for the cold-cache case, and see if just even _that_ takes almost a
> second.
>
> If it _is_ stable, there's two possibilities:
>
>  - you have a large and slow disk, and that one object really is way out
>    there on the other side of the disk, and seeking really takes almost a
>    second.
>

Its a Thinkpad 2.5 inches HD, 2 years old (IBM/Hitachi Travelstar 40GNX family)

>    Quite frankly, I expected that the time when a single stat() took
>    almost a second was a decade or more in the past, back in the days of
>    floppy-disks. But what do I know?
>
>  - your disk is failing, and ends up doing error recovery etc.
>

No recent errors are reported:

Stripped from smartctl -a /dev/hda

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE
UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000b   100   100   062    Pre-fail
Always       -       0
  2 Throughput_Performance  0x0005   100   100   040    Pre-fail
Offline      -       0
  3 Spin_Up_Time            0x0007   165   165   033    Pre-fail
Always       -       1
  4 Start_Stop_Count        0x0012   097   097   000    Old_age
Always       -       4928
  5 Reallocated_Sector_Ct   0x0033   100   100   005    Pre-fail
Always       -       0
  7 Seek_Error_Rate         0x000b   100   100   067    Pre-fail
Always       -       0
  8 Seek_Time_Performance   0x0005   100   100   040    Pre-fail
Offline      -       0
  9 Power_On_Hours          0x0012   073   073   000    Old_age
Always       -       11832
 10 Spin_Retry_Count        0x0013   100   100   060    Pre-fail
Always       -       0
 12 Power_Cycle_Count       0x0032   099   099   000    Old_age
Always       -       2563
191 G-Sense_Error_Rate      0x000a   100   100   000    Old_age
Always       -       0
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age
Always       -       117
193 Load_Cycle_Count        0x0012   045   045   000    Old_age
Always       -       558210
194 Temperature_Celsius     0x0002   130   130   000    Old_age
Always       -       42 (Lifetime Min/Max 5/59)
196 Reallocated_Event_Count 0x0032   100   100   000    Old_age
Always       -       1
197 Current_Pending_Sector  0x0022   100   100   000    Old_age
Always       -       0
198 Offline_Uncorrectable   0x0008   100   100   000    Old_age
Offline      -       0
199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age
Always       -       0
210 Unknown_Attribute       0x0023   100   100   001    Pre-fail
Always       -       0

SMART Error Log Version: 1
ATA Error Count: 2
        CR = Command Register [HEX]
        FR = Features Register [HEX]
        SC = Sector Count Register [HEX]
        SN = Sector Number Register [HEX]
        CL = Cylinder Low Register [HEX]
        CH = Cylinder High Register [HEX]
        DH = Device/Head Register [HEX]
        DC = Device Command Register [HEX]
        ER = Error register [HEX]
        ST = Status register [HEX]
Powered_Up_Time is measured from power on, and printed as
DDd+hh:mm:SS.sss where DD=days, hh=hours, mm=minutes,
SS=sec, and sss=millisec. It "wraps" after 49.710 days.

Error 2 occurred at disk power-on lifetime: 0 hours (0 days + 0 hours)
  When the command that caused the error occurred, the device was
active or idle.

  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  10 51 01 0f 8e a8 e4  Error: IDNF at LBA = 0x04a88e0f = 78155279

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  20 ff 01 0f 8e a8 e4 00      00:05:26.850  READ SECTOR(S)
  c8 ff 01 0f 8e a8 e4 00      00:05:26.775  READ DMA
  c8 ff 01 00 00 00 e0 00      00:05:26.625  READ DMA
  ca 04 01 ff 52 a8 e4 00      00:03:40.575  WRITE DMA
  c8 04 01 ff 52 a8 e4 00      00:03:40.275  READ DMA

Error 1 occurred at disk power-on lifetime: 0 hours (0 days + 0 hours)
  When the command that caused the error occurred, the device was
active or idle.

  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  10 51 01 0f 8e a8 e4  Error: IDNF 1 sectors at LBA = 0x04a88e0f = 78155279

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  c8 ff 01 0f 8e a8 e4 00      00:05:26.775  READ DMA
  c8 ff 01 00 00 00 e0 00      00:05:26.625  READ DMA
  ca 04 01 ff 52 a8 e4 00      00:03:40.575  WRITE DMA
  c8 04 01 ff 52 a8 e4 00      00:03:40.275  READ DMA
  ca 04 7d 73 49 02 e0 00      00:03:40.275  WRITE DMA

SMART Self-test log structure revision number 1
No self-tests have been logged.  [To run self-tests, use: smartctl -t]

>
> (NOTE NOTE NOTE! There could be other reasons for that second delay. If
> the machine was under heavy load, or was running low on memory, maybe the
> long delay was just due to havign to swap things out or run other things
> instead. That's why it might be interesting to see if the number is
> "stable" in that it's always that same object..)
>

No load, no low memory: I quitted everything before to test. I will
test again as soon smartctl finishes.

Re: [WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

On 11/19/06, Marco Costalba <mcostalba@gmail.com> wrote:
>
> When finished I will do additional cold chache (reboot) tests.
>

Previous delay was not reproduced. This time I tested also with git
show-ref -d (dereferencing tags), always with cold-cache.

It does not seems there are strange delays, but total time it's high
(very I/O bound)


- LINUX TREE

$ pwd
/git/linux-2.6

$ time strace -o tracefile -Ttt git show-ref -d >> /dev/null
0.02user 0.01system 0:02.39elapsed 1%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (127major+894minor)pagefaults 0swaps

$ grep -v ' <0.0[012]' tracefile >> tracefile_slowest.txt
$ cat tracefile_slowest.txt
20:51:49.695511 execve("/home/marco/bin/git", ["git", "show-ref",
"-d"], [/* 78 vars */]) = 0 <0.065006>
20:51:49.946258 open(".git/objects/info/alternates", O_RDONLY) = -1
ENOENT (No such file or directory) <0.091447>
20:51:50.070555
stat64(".git/objects/e0/30f8294a5b9f8179dae10cdbf9dcf32aa64110",
{st_mode=S_IFREG|0444, st_size=284, ...}) = 0 <0.037669>
20:51:51.822469
stat64(".git/objects/7a/9d289b6650bf78df77ab463bedc2919df89833",
{st_mode=S_IFREG|0444, st_size=285, ...}) = 0 <0.048868>
20:51:51.930582
stat64(".git/objects/80/c218812786f619c9a1ce50d0e7c32c7afde4de",
{st_mode=S_IFREG|0444, st_size=210, ...}) = 0 <0.030057>
20:51:51.981951
stat64(".git/objects/44/597f65f6af3c692560a639f61d25398d13d1b6",
{st_mode=S_IFREG|0444, st_size=249, ...}) = 0 <0.037440>
20:51:52.023469 exit_group(0)           = ?


- GIT TREE

$cd /home/marco/programmi/git
$ time strace -o tracefile -Ttt git show-ref -d >> /dev/null
0.04user 0.04system 0:02.47elapsed 3%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (91major+794minor)pagefaults 0swaps

$ grep -v ' <0.0[012]' tracefile >> tracefile_slowest.txt
$ cat tracefile_slowest.txt
20:55:04.844584
stat64(".git/objects/d0/f877fb601ac0076fd69ec4f48f71f9247771c8",
{st_mode=S_IFREG|0444, st_size=190, ...}) = 0 <0.046100>
20:55:04.944839
stat64(".git/objects/e2/67c2f6f0784e242883b7d3fe5f36ef63d6950d",
{st_mode=S_IFREG|0444, st_size=179, ...}) = 0 <0.033536>
20:55:05.057966
stat64(".git/objects/41/292ddd37202ff6dce34986c87a6000c5d3fbfa",
{st_mode=S_IFREG|0444, st_size=180, ...}) = 0 <0.072937>
20:55:05.432107
stat64(".git/objects/7d/09fbe4ab7f080a8f8f5dcef7e0f3edf5e26019",
{st_mode=S_IFREG|0444, st_size=396, ...}) = 0 <0.035952>
20:55:05.592877
stat64(".git/objects/92/d7605b6d9312a29efa30b1baa4d7c880a0be41",
{st_mode=S_IFREG|0444, st_size=280, ...}) = 0 <0.032139>
20:55:05.738173
stat64(".git/objects/05/56a11a0df6b4119e01aa77dfb795561e62eb34",
{st_mode=S_IFREG|0444, st_size=557, ...}) = 0 <0.031572>
20:55:06.176786
stat64(".git/objects/88/3653babd8ee7ea23e6a5c392bb739348b1eb61",
{st_mode=S_IFREG|0444, st_size=442, ...}) = 0 <0.030382>
20:55:06.549025
stat64(".git/objects/95/f1e36cc34e8738e5c431aac47d6fea18913db0",
{st_mode=S_IFREG|0444, st_size=395, ...}) = 0 <0.031731>
20:55:06.844432
stat64(".git/objects/ba/f0bfcb4b335438e9359835f2c27cccf20e54a3",
{st_mode=S_IFREG|0444, st_size=182, ...}) = 0 <0.033688>
20:55:06.922993 exit_group(0)           = ?

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Marco Costalba wrote:
> 
> It does not seems there are strange delays, but total time it's high
> (very I/O bound)

This looks more normal. No truly horrid IO times. With your disk, having 
an uncached "stat64()" taking ~50ms is not at all impossible, if you just 
end up having to do a few seeks for directory/inode information.

> $ time strace -o tracefile -Ttt git show-ref -d >> /dev/null
> 0.02user 0.01system 0:02.39elapsed 1%CPU (0avgtext+0avgdata 0maxresident)k
> 0inputs+0outputs (127major+894minor)pagefaults 0swaps

So in addition to the "stat()" calls on all the objects you have 
referenced, you also had 127 page faults that needed to do IO (probably a 
combination of executable and pack-file accesses). 

I think the only way to avoid this is likely to try to either not do the 
object lookups at all (which you really cannot currently avoid with "-d", 
since the whole point is to dereference the objects if they are tags), or 
to do some silly optimizations like fsck does.

For example, it's often (but not always) faster to do all the readdir's 
separately, and then sort the thing by inode number, and try to avoid 
back-and-forth movement. But quite frankly, that kind of stuff probably 
isn't sane to do in "git show-refs".

So the optimizations that _can_ be done are:

 - add dereference info to .git/packed-refs

   This would allow us to simply not do the expensive object lookup for 
   every single tag. We'd still have to do it for non-packed objects, of 
   course, but the cost here tends to be that over time you might have 
   hundreds of tags, and even if each tag only takes 0.02s to look up, 
   you're going to be slow.

 - avoid the references for "heads/" (which we know are supposed to be 
   commits, and cannot be tags) and when not specifying "-d". This won't 
   help your case very much, though. If you want "-d", you want it, and 
   the _big_ number of refs tends to be in tags, not branches, anyway.

 - using a filesystem wih nicer locality behaviour for directory entries 
   and inodes. This can cut down costs of cold-cache case by a factor of 
   two, but right now there are no good filesystems that do this (but see 
   for example "spadfs" that Mikulas Patocka announced a few weeks ago on 
   linux-kernel - it would seem to have the possibility of being better in 
   this area. I looked at the code and it looked like it could become 
   very reasonable, but I've not actually _tested_ it, soo...)

Anyway, I think that if we really want to make "git show-refs" go fast 
when things are cold in the cache, and with lots ot tags and "-d" (which 
is a reasonable case to optimize for: it's probably exactly what we end up 
doing both for gitweb _and_ for "git-send-pack"), we'd need to expand the 
packed-refs file with the deref cache.

Junio?

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Linus Torvalds wrote:
> 
> So the optimizations that _can_ be done are:

Of course, doing a "git repack -a -d && git prune" is always the #1 
optimization. It will still look up the objects, but it will be a lot 
faster about it, and avoid a lot of the really bad IO patterns.

If you don't want to repack, you could try just doing a "git clone" and 
then doing the "git pack-refs --prune" in the clone too. And compare 
cold-cache times between the two "identical" repositories.

Re: [WISH] Store also tag dereferences in packed-refs

[Junio C Hamano]

Linus Torvalds <torvalds@osdl.org> writes:

> So the optimizations that _can_ be done are:
>
>  - add dereference info to .git/packed-refs
>
>    This would allow us to simply not do the expensive object lookup for 
>    every single tag. We'd still have to do it for non-packed objects, of 
>    course, but the cost here tends to be that over time you might have 
>    hundreds of tags, and even if each tag only takes 0.02s to look up, 
>    you're going to be slow.
>
>  - avoid the references for "heads/" (which we know are supposed to be 
>    commits, and cannot be tags) and when not specifying "-d". This won't 
>    help your case very much, though. If you want "-d", you want it, and 
>    the _big_ number of refs tends to be in tags, not branches, anyway.
>
>  - using a filesystem wih nicer locality behaviour for directory entries 
>    and inodes. This can cut down costs of cold-cache case by a factor of 
>    two, but right now there are no good filesystems that do this (but see 
>    for example "spadfs" that Mikulas Patocka announced a few weeks ago on 
>    linux-kernel - it would seem to have the possibility of being better in 
>    this area. I looked at the code and it looked like it could become 
>    very reasonable, but I've not actually _tested_ it, soo...)
>
> Anyway, I think that if we really want to make "git show-refs" go fast 
> when things are cold in the cache, and with lots ot tags and "-d" (which 
> is a reasonable case to optimize for: it's probably exactly what we end up 
> doing both for gitweb _and_ for "git-send-pack"), we'd need to expand the 
> packed-refs file with the deref cache.
>
> Junio?

Yes; the "for discussion only" WIP patch from yesterday was
about the first point and half of the second point.

One downside about storing the peeled refs in .git/packed-refs
is that the code in the wild does not have safety guard against
them, so the version of show-ref from v1.4.4 recently released
will list tags/v2.6.19^{} as if it is a true tag and worse yet
it might even show tags/v2.6.19^{}^{} under -d option after the
repository's refs are packed in the new format.

But I think we can avoid that problem by using a format slightly
different from the WIP patch.  We can for example use two spaces
between SHA-1 and the name for them.  refs.c::parse_ref_line()
in existing code will say "oh, this line is nonsense" and skip
them, while the updated code can say "ok, this is a peeled ref",
since it has a seemingly incomplete "check for valid refname"
there that only checks "isspace(*line)".

Did you do this "if (isspace(*line)) return NULL" to have
extensibility later, I wonder...

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Junio C Hamano wrote:
> 
> Did you do this "if (isspace(*line)) return NULL" to have
> extensibility later, I wonder...

No, but I try to have a policy of not accepting anything that is even 
slightly questionable, so it was unintentional in the details but a result 
of a higher-level principle..

Of course, even when I wrote it I _also_ knew that I should check 
everything else too (not just the first character), but I was lazy. That 
would have been even better - then we could have made the thing be 
something like

	<sha1><space><name>[<space><sha1-of-deref>]*

instead.

Re: [WISH] Store also tag dereferences in packed-refs

[Jakub Narebski]

Linus Torvalds wrote:

> On Sun, 19 Nov 2006, Junio C Hamano wrote:
>> 
>> Did you do this "if (isspace(*line)) return NULL" to have
>> extensibility later, I wonder...
> 
> No, but I try to have a policy of not accepting anything that is even 
> slightly questionable, so it was unintentional in the details but a result 
> of a higher-level principle..
> 
> Of course, even when I wrote it I _also_ knew that I should check 
> everything else too (not just the first character), but I was lazy. That 
> would have been even better - then we could have made the thing be 
> something like
> 
>       <sha1><space><name>[<space><sha1-of-deref>]*
> 
> instead.

So the only reason against this format (IMHO more reasonable, more readable
and more readable, and even easy extendable to the whole chain of derefs)
is code in the wild? 

By the way, do we copy packed refs literaly when fetching or cloning?
-- 
Jakub Narebski
Warsaw, Poland
ShadeHawk on #git

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Jakub Narebski wrote:
> 
> So the only reason against this format (IMHO more reasonable, more readable
> and more readable, and even easy extendable to the whole chain of derefs)
> is code in the wild? 
> 
> By the way, do we copy packed refs literaly when fetching or cloning?

The packed refs format is _purely_ a local format. So in that sense, we 
can change it any way we want, and nobody really cares.

HOWEVER, even on a local machine, we generally want to be able to upgrade 
and downgrade git versions without having to worry about things like this, 
and having to convert one format to another. So using a format that "just 
works" with any version of git that understands packed refs is _wildly_ 
more preferable over changing the format.

Btw, the simplest and best format is probably to make the new extension 
look something like

	8ba130df4b67fa40878ccf80d54615132d24bc68 refs/tags/v2.6.17
	^427abfa28afedffadfca9dd8b067eb6d36bac53f
	d882e0c80e6e3c60640492b83395e6fbbae04276 refs/tags/v2.6.17-rc1
	^6246b6128bbe34d0752f119cf7c5111c85fe481d

which is basically almost as dense as having a space on the same line, and 
will also trigger the old "that's not a valid line, just ignore it" 
reaction from older versions.

So the parsing rules for that would simply be:

 - if you see a line that starts with a "^<sha1>", then that is the 
   "unpeeling" of the previous packed entry (which in turn might have been 
   an unpeeling itself)

So if you were to have tags pointing to tags, you migt have

	<sha1> refs/tags/tagname
	^<sha1-unpeeled>
	^<sha1-unpeeled-of-unpeeled>
	...
	<sha1> refs/tags/othertag

In addition, we'd need a line at the top of the file that says "this has 
unpeeled information", because otherwise we have no way to distinguish 
between the case of "no actual tag objects" and "old-fashioned ref-pack 
file without any unpeeling info" - since they'd look identical.

So I'd suggest adding - at the very top of the ref-pack file - a line line

	# Ref-pack version 2

which will be ignored by the current ref-pack reader (again, because it's 
not a valid ref line), but we can use it in the future to specify further 
extensions if we want to.

Now somebody would just need to implement that ;)

Re: [WISH] Store also tag dereferences in packed-refs

[Junio C Hamano]

Linus Torvalds <torvalds@osdl.org> writes:

> So I'd suggest adding - at the very top of the ref-pack file - a line line
>
> 	# Ref-pack version 2
>
> which will be ignored by the current ref-pack reader (again, because it's 
> not a valid ref line), but we can use it in the future to specify further 
> extensions if we want to.
>
> Now somebody would just need to implement that ;)

For this particular one, there is no need for version 2.

My current wip does:

	SHA-1 SP name LF
	SHA-1 SP SP name^{} LF

the latter of which is ignored by code in the wild and the new
code can take advantage of (and fall back the usual deref_tag
when it is not available).

I need to rebase it on top of a minor update to refs.c before
pushing it out.

Re: [WISH] Store also tag dereferences in packed-refs

[Jakub Narebski]

Junio C Hamano wrote:

> Linus Torvalds <torvalds@osdl.org> writes:
> 
>> So I'd suggest adding - at the very top of the ref-pack file - a line line
>>
>>      # Ref-pack version 2
>>
>> which will be ignored by the current ref-pack reader (again, because it's 
>> not a valid ref line), but we can use it in the future to specify further 
>> extensions if we want to.
>>
>> Now somebody would just need to implement that ;)
> 
> For this particular one, there is no need for version 2.

Actually, I think it is both true and untrue. True, because we need some
indicator that we trust packed-refs file to provide tag dereferences to
distinguish between the case when there are no tag objects at all, so there
are no tag dereferences in packed-refs, and the situation where we use
packed-refs generated by older git, and there are no tag dereferences in
packed-refs because git didn't saved it.

Untrue, because it is not enough. In the case[*1*] when packed-refs was
created with tag dereferences, then some "heavyweight" tags were added
by older version of git (adding references doesn't rewrite packed-refs
if I understand correctly), then we use new git again and trust that there
are no derefs...

[*1*] For example when git repository is on the network filesystem, but
programs are installed locally, and perhaps computers in the network are
heterogenic (perhaps even different architectures: PC vs. Sun and/or
different operating systems: Linux vs. FreeBSD vs. Solaris vs.
Windows+Cygwin) and have different versions of git installed (perhaps
one of them is "your" machine, where you have admin rights, and you have
newest git installed there). Or for example using git repository on USB
stick, again on different computers with different version of git installed.
 
---------------------------------------------------------------------

To summarize, we have the following proposals of the packed-refs format
extension


The unusable Linux Torvalds proposal (unusable because of requiring
newer packed-refs work with older git, for example in the case [*1*]
or the case of git downgrade):

lt>    <sha1><space><name>[<space><sha1-of-deref>]*


Linus Torvalds "Now somebody would just need to implement that ;)"
proposal:

lt>    <sha1> refs/tags/tagname
lt>    ^<sha1-unpeeled>
lt>    ^<sha1-unpeeled-of-unpeeled>
lt>    ...
lt>    <sha1> refs/tags/othertag


Junio C Hamano proposal _with code_ (proposal with code usually wins).
Less elegant IMVHO, but perhaps better.

jc> My current wip does:
jc> 
jc>     SHA-1 SP name LF
jc>     SHA-1 SP SP name^{} LF
jc> 
jc> the latter of which is ignored by code in the wild and the new
jc> code can take advantage of (and fall back the usual deref_tag
jc> when it is not available).

-- 
Jakub Narebski
Warsaw, Poland
ShadeHawk on #git

Re: [WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

> >
> > For this particular one, there is no need for version 2.
>
> Actually, I think it is both true and untrue. True, because we need some
> indicator that we trust packed-refs file to provide tag dereferences to
> distinguish between the case when there are no tag objects at all, so there
> are no tag dereferences in packed-refs, and the situation where we use
> packed-refs generated by older git, and there are no tag dereferences in
> packed-refs because git didn't saved it.
>

We should be able to handle the ambiguous/malformed lines correctly
and gracefully _always_, without 'trust' a version number to avoid to
be prone to attacks with a malicious malformed file.

Anyway document versioning it's a common and savy practice.

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Junio C Hamano wrote:

> Linus Torvalds <torvalds@osdl.org> writes:
> 
> > So I'd suggest adding - at the very top of the ref-pack file - a line line
> >
> > 	# Ref-pack version 2
> >
> > which will be ignored by the current ref-pack reader (again, because it's 
> > not a valid ref line), but we can use it in the future to specify further 
> > extensions if we want to.
> >
> > Now somebody would just need to implement that ;)
> 
> For this particular one, there is no need for version 2.

I don't think you understand.

> My current wip does:
> 
> 	SHA-1 SP name LF
> 	SHA-1 SP SP name^{} LF

I think that's ugly and redundant (if "name" is ever different from the 
lien above it, that would be a bug), but that's not the real problem.

The real problem is (go back to the mail that you answered, and snipped 
the explanation from) this:

 - you have a thousand tags

 - NONE of them are "tag objects".

 - as a result your ref-pack file doesn't have a _single_ of the ^{} lines

Think about it. How do you know whether you should look up the tag objects 
for "-d" or not?

The answer is: you don't. You can't tell a "version 1" and "version 2" 
file apart. It might be an old "version 1" file that simply doesn't _have_ 
dereference information. Or it might be a "version 2" file that _does_ 
have dereference information, but nothing to dereference.

So you either have to:

 - look up each object again to see if it's a tag that should be 
   dereferenced

OR:

 - add a "# ref-pack version 2" flag at the top of the file.

So it's not about "parsing" the new file structure. I realize that parsing 
it is trivial. It's simply about knowing whether the new information 
_could_ be there or not.

And once you have that flag, your _future_ extensions can add their own 
version, which is an added bonus. But that means that "version 2" parsing 
should _also_ ignore lines that it cannot match, so you'd better have an 
escape from the new format. I personally think that using

	^<sha1><lf>

instead of "<sha1><space><space><name>^{}<lf>" is better partly for that 
reason: it's not only denser, it is "stricter" in the sense that there's 
less room for some future extended version that could be mistaken for a 
"version 2 unpeeling" line. 

(But you can do the same thing with your version too. You should:
 - check that there is just _one_ extra space
 - verify that the name matches the previous one
 - verify that it ends exactly with "^{}", so that any future extension 
   could add their own flags at the end.)

But regardless of which format chosen, you need the flag of "this format 
is in use", exactly because the extended unpeeling information might not 
_exist_.

Oh, and regardless of which format chosen, you'd need to verify that the 
unpeeled object in the pack wasn't overridden, of course. 

		Linus

Re: [WISH] Store also tag dereferences in packed-refs

[Junio C Hamano]

Linus Torvalds <torvalds@osdl.org> writes:

>> For this particular one, there is no need for version 2.
>
> I don't think you understand.

That is true.  I was not thinking about optimizing the
lightweight tag case -- we would want to be able to tell that
they are not tag objects and skip peel_ref altogether, and in
order to do that we do need a way to tell us that we can trust
the absense of peeled representation in the packed-refs file.

It is my day job day so I do not expect I can continue til later
today, though...

Re: [WISH] Store also tag dereferences in packed-refs

[Marco Costalba]

On 11/19/06, Linus Torvalds <torvalds@osdl.org> wrote:
>
>
>
> For example, it's often (but not always) faster to do all the readdir's
> separately, and then sort the thing by inode number, and try to avoid
> back-and-forth movement. But quite frankly, that kind of stuff probably
> isn't sane to do in "git show-refs".

Excuse me for my ignorance, but isn' it the job of OS disk schedulers?

>
> Anyway, I think that if we really want to make "git show-refs" go fast
> when things are cold in the cache, and with lots ot tags and "-d" (which
> is a reasonable case to optimize for: it's probably exactly what we end up
> doing both for gitweb _and_ for "git-send-pack"), we'd need to expand the
> packed-refs file with the deref cache.
>

Probably also gitk, currently it uses (the slower) "git ls-remote"
instead of "git peek-remote" or "git show-refs" but the concept seems
the same.

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Marco Costalba wrote:
> 
> Excuse me for my ignorance, but isn' it the job of OS disk schedulers?

The OS disk scheduler does exactly that but

	ONLY IF IT'S GIVEN DATA TO WORK ON IN PARALLEL

If an application gives it read requests one by one, the OS has no choice 
but to just do the accesses one by one.

Writes are easier, since you can just buffer them. But you can't "buffer" 
a read. When the user asks for a readdir(), you'd better give it to the 
user, and there's not anything you can do about it.

So disk schedulers only work for 
 - parallel workloads
 - writes

(where "parallel workloads" can be asynchronous reads - where the user 
says "I will _start_ this read, notify me when it's done" and then gives 
multiple independent reads to do in parallel).

So the OS cannot add parallelism - it can only take advantage of what 
parallelism the application gives it.

Re: [WISH] Store also tag dereferences in packed-refs

[Linus Torvalds]

On Sun, 19 Nov 2006, Marco Costalba wrote:
> 
> But why my numbers are bad both in git, in Linux and also qgit (not
> posted) local repo? If it is a single case other repos should load
> fast.

Well, it's almost guaranteed to not really be a "single" case.

An inode on disk is usually ~128 bytes or so, which means that you'll be 
able to fit quite a number of inodes in a page-sized allocation of disk 
cache. If _any_ of the sectors was slow to access (because of IO retries, 
disk sector remapping, whatever), all those inodes will be slow to access.

(It might also be a specific area on the disk, or something).

> Its a Thinkpad 2.5 inches HD, 2 years old (IBM/Hitachi Travelstar 40GNX
> family)

That's a 5400rpm disk with an average seektime of 12ms, and full stroke 
typical seek of 23ms.

A "stat64()" will do more than a single IO when it's cold-cache (the 
kernel will have to look up the directory entry and the inode, of course), 
but you _should_ see just a few IO's (2-3), so quite frankly, normally I'd 
expect to see times in the 0.03s - 0.05s range _maximum_. You'd see less 
if even just part of it was cached (which is normal, exactly because 
things like directory entries are contiguous on disk etc).

And that seems to match your other numbers.

The 0.8s number really is an outlier. It sounds like the drive didn't find 
the sector at first, perhaps had to go to its remapping table, seek around 
a bit more, take a break just to calm down, and then perhaps recalibrate 
itself (or write a SMART record entry).

> >  - your disk is failing, and ends up doing error recovery etc.
> 
> No recent errors are reported:
> 
> Stripped from smartctl -a /dev/hda

Ok, I'm not actually all that familiar with all the SMART error codes, but 
it _looks_ healthy. You do have one Spin_Up_Time event (that is 
marked pre-fail), and those two IDNF errors you have:

>  10 51 01 0f 8e a8 e4  Error: IDNF at LBA = 0x04a88e0f = 78155279
>  10 51 01 0f 8e a8 e4  Error: IDNF 1 sectors at LBA = 0x04a88e0f = 78155279

makes me wonder a bit, but for all I know, it's not actually serious. I 
_think_ the IDNF error means that it couldn't find a sector, but..

Re: [WISH] Store also tag dereferences in packed-refs

[Jakub Narebski]

Junio C Hamano wrote:
> Jakub Narebski <jnareb@gmail.com> writes:
> 
>> ... I mean you trust (use) reference
>> info from packed-refs, but don't trust lack of dereference in
>> packed-refs.
> 
> That is exactly what the code does (at least that was the intent;
> there could be bugs since I am not Linus ;-).

The question is: is it more common case to have very large number
of heavyweight tags, or is it more common case to have very large
number of lightweight tags (refs to commit objects).

In the latter case the solution to not trust lack of dereference
means no gain in performance (although for the core checking type
of object is faster (much faster?) than depeeling tag, so the gain
wouldn't be large), although the solution is probably safer.

Still, the decision: do not trust the lack of dereference in
packed-refs, or mark packed-refs as having dereferences and trust
lack of dereferences, is fairly orthogonal to the format for depeel
in packed-refs.


P.S. I have just noticed that you have taken the discussion
off-list...
-- 
Jakub Narebski