Having looked at that Google Doc it seems to just discuss "Plan A", or
there some multi-doc magic and there's a "Plan B", or...? I'm not very
familiar with Google Docs.
Anyway, I'd encourage you to just send this as an E-Mail to the mailing
list.
Having skimmed it I'm a bit confused about this in reference to
performance generally. I haven't looked into the case you're discussing,
but as I noted in
https://lore.kernel.org/git/87im1p6x34.fsf@evledraar.gmail.com/ the
profiling clearly shows that the main problem is that you've added
object lookups we skipped before.
I think any plan to improve performance should start with a perf test,
see which of your patches have performance regressions, if some don't
and are otherwise OK perhaps those can go in earlier.
Then we'll have the smallest possible set of changes that's correct, but
introduces performance regressions, and can look at what those are doing
to slow things down...
Having looked at that Google Doc it seems to just discuss "Plan A", or
there some multi-doc magic and there's a "Plan B", or...? I'm not very
familiar with Google Docs.
There may be several plan that have not been written to it for the time being.
Anyway, I'd encourage you to just send this as an E-Mail to the mailing
list.
Ok, I can migrate them here.
Having skimmed it I'm a bit confused about this in reference to
performance generally. I haven't looked into the case you're discussing,
but as I noted in
https://lore.kernel.org/git/87im1p6x34.fsf@evledraar.gmail.com/ the
profiling clearly shows that the main problem is that you've added
object lookups we skipped before.
Yeah, you showed me last time that lookup_object() took up a lot of time.
I think any plan to improve performance should start with a perf test,
see which of your patches have performance regressions, if some don't
and are otherwise OK perhaps those can go in earlier.
Then we'll have the smallest possible set of changes that's correct, but
introduces performance regressions, and can look at what those are doing
to slow things down...
Having skimmed it I'm a bit confused about this in reference to
performance generally. I haven't looked into the case you're discussing,
but as I noted in
https://lore.kernel.org/git/87im1p6x34.fsf@evledraar.gmail.com/ the
profiling clearly shows that the main problem is that you've added
object lookups we skipped before.
Yeah, you showed me last time that lookup_object() took up a lot of time.
Could the document explain with some details why there are more calls
to lookup_object()? For example it could take an example `git cat-file
--batch ...` command (if possible a simple one), and say which
functions like lookup_object() it was using (and how many times) to
get the data it needs before using the ref-filter logic, and then the
same information after using the ref-filter logic.
It could be nice if there were also some data about how much time used
to be spent in lookup_object() and how much time is now spent there,
and how this compares with the whole slowdown we are seeing. If Ævar
already showed that, you can of course reuse what he already did.
The GIT_TRACE_PERFORMANCE, GIT_TRACE2_PERF env variables and the
associated trace_*() and trace2_*() functions might help you with
measuring how much time is spent in different functions.
Having skimmed it I'm a bit confused about this in reference to
performance generally. I haven't looked into the case you're discussing,
but as I noted in
https://lore.kernel.org/git/87im1p6x34.fsf@evledraar.gmail.com/ the
profiling clearly shows that the main problem is that you've added
object lookups we skipped before.
Yeah, you showed me last time that lookup_object() took up a lot of time.
Could the document explain with some details why there are more calls
to lookup_object()? For example it could take an example `git cat-file
--batch ...` command (if possible a simple one), and say which
functions like lookup_object() it was using (and how many times) to
get the data it needs before using the ref-filter logic, and then the
same information after using the ref-filter logic.
Sorry but this time I use gprof but can’t observe the same effect as before.
lookup_object() is indeed a part of the time overhead, but its proportion is
not very large this time.
It could be nice if there were also some data about how much time used
to be spent in lookup_object() and how much time is now spent there,
and how this compares with the whole slowdown we are seeing. If Ævar
already showed that, you can of course reuse what he already did.
This is my test for git cat-file --batch --batch-all-objects >/dev/null:
daab8a564: The fifth batch (upstream/master)
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
38.13 0.61 0.61 1968866 0.00 0.00 patch_delta
13.75 0.83 0.22 6568488 0.00 0.00
unpack_object_header_buffer
11.25 1.01 0.18 344036 0.00 0.00 unpack_entry
7.50 1.13 0.12 1964667 0.00 0.00 hashmap_remove
6.88 1.24 0.11 6153182 0.00 0.00 hashmap_get
1.88 1.27 0.03 7746299 0.00 0.00 zlib_post_call
1.88 1.30 0.03 842731 0.00 0.00 bsearch_hash
1.88 1.33 0.03 827663 0.00 0.00 nth_packed_object_offset
1.25 1.35 0.02 15385422 0.00 0.00 use_pack
1.25 1.37 0.02 6236120 0.00 0.00 get_delta_base
1.25 1.39 0.02 2581859 0.00 0.00 git_inflate_end
1.25 1.41 0.02 826650 0.00 0.00
do_oid_object_info_extended
1.25 1.43 0.02 826650 0.00 0.00 find_pack_entry
1.25 1.45 0.02 825692 0.00 0.00 packed_to_object_type
1.25 1.47 0.02 378521 0.00 0.00 get_size_from_delta
d3b5272a94: [GSOC] cat-file: reuse ref-filter logic
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
27.06 0.59 0.59 1968866 0.00 0.00 patch_delta
16.51 0.95 0.36 2202293 0.00 0.00
unpack_object_header_buffer
13.76 1.25 0.30 5327015 0.00 0.00 hashmap_get
11.47 1.50 0.25 344036 0.00 0.00 unpack_entry
8.72 1.69 0.19 521278 0.00 0.00 lookup_object
4.13 1.78 0.09 1964667 0.00 0.00 hashmap_remove
2.75 1.84 0.06 348709 0.00 0.00 get_object
2.29 1.89 0.05 1 0.05 2.17 oid_array_for_each_unique
1.38 1.92 0.03 6373452 0.00 0.00 use_pack
0.92 1.94 0.02 2202293 0.00 0.00 unpack_compressed_entry
0.92 1.96 0.02 1394836 0.00 0.00 grab_sub_body_contents
0.92 1.98 0.02 348709 0.00 0.00 create_object
0.92 2.00 0.02 348709 0.00 0.00 format_ref_array_item
0.92 2.02 0.02 74557 0.00 0.00 fill_commit_graph_info
Because we called parse_object_buffer() in get_object(), lookup_object()
is called indirectly...
We can see that some functions are called the same times: patch_delta(),
unpack_entry(), hashmap_remove()... But after using my patch,
format_ref_array_item(), grab_sub_body_contents(), get_object(), lookup_object()
begin to occupy a certain proportion.
This is my test for git cat-file --batch-check --batch-all-objects >/dev/null:
daab8a564: The fifth batch (upstream/master)
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
47.83 0.11 0.11 3385670 0.00 0.00
unpack_object_header_buffer
13.04 0.14 0.03 6941590 0.00 0.00 use_pack
8.70 0.16 0.02 1046130 0.00 0.00 expand_format
4.35 0.17 0.01 349013 0.00 0.00 oid_array_append
4.35 0.18 0.01 348710 0.00 0.00 strbuf_expand
4.35 0.19 0.01 348709 0.00 0.00 find_pack_entry
4.35 0.20 0.01 348230 0.00 0.00 packed_to_object_type
4.35 0.21 0.01 259719 0.00 0.00 git_inflate
4.35 0.22 0.01 1 10.00 210.00 oid_array_for_each_unique
4.35 0.23 0.01 pack_basename
d3b5272a94: [GSOC] cat-file: reuse ref-filter logic
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
52.00 0.13 0.13 3385670 0.00 0.00
unpack_object_header_buffer
16.00 0.17 0.04 6941590 0.00 0.00 use_pack
8.00 0.19 0.02 3296680 0.00 0.00 get_delta_base
4.00 0.20 0.01 348709 0.00 0.00 find_pack_entry
4.00 0.21 0.01 348709 0.00 0.00 oid_to_hex
4.00 0.22 0.01 348709 0.00 0.00 populate_value
4.00 0.23 0.01 348230 0.00 0.00 packed_object_info
4.00 0.24 0.01 348230 0.00 0.00 packed_to_object_type
4.00 0.25 0.01 void_hashcmp
Similarly, unpack_object_header_buffer(), use_pack(),
find_pack_entry(), packed_to_object_type(), they are still called same
times as before; populate_value(),
packed_object_info(), oid_to_hex() are new.
The GIT_TRACE_PERFORMANCE, GIT_TRACE2_PERF env variables and the
associated trace_*() and trace2_*() functions might help you with
measuring how much time is spent in different functions.
Having skimmed it I'm a bit confused about this in reference to
performance generally. I haven't looked into the case you're discussing,
but as I noted in
https://lore.kernel.org/git/87im1p6x34.fsf@evledraar.gmail.com/ the
profiling clearly shows that the main problem is that you've added
object lookups we skipped before.
Yeah, you showed me last time that lookup_object() took up a lot of time.
Could the document explain with some details why there are more calls
to lookup_object()?
Please note that here we are looking for the number of times the
lookup_object() function is called. This means that to measure that
properly, it might actually be better to have some way to count this
number of times the lookup_object() function is called, rather than
count the time spent in the function.
For example you could add a trace_printf(...) call in the
lookup_object() function, set GIT_TRACE=/tmp/git_trace.log, and then
just run `git cat-file --batch ...` and count the number of times the
new trace from lookup_object() appears in the log file.
quoted
For example it could take an example `git cat-file
--batch ...` command (if possible a simple one), and say which
functions like lookup_object() it was using (and how many times) to
get the data it needs before using the ref-filter logic, and then the
same information after using the ref-filter logic.
Sorry but this time I use gprof but can’t observe the same effect as before.
lookup_object() is indeed a part of the time overhead, but its proportion is
not very large this time.
I am not sure gprof is a good tool for this. It looks like it tries to
attribute spent times to functions by splitting time between many low
level functions, and it doesn't seem like the right approach to me.
For example if lookup_object() is called 5% more often, it could be
that the excess time is attributed to some low level functions and not
to lookup_object() itself.
That's why we might get a more accurate view of what happens by just
counting the number of time the function is called.
quoted
It could be nice if there were also some data about how much time used
to be spent in lookup_object() and how much time is now spent there,
and how this compares with the whole slowdown we are seeing. If Ævar
already showed that, you can of course reuse what he already did.
Now I regret having wrote the above, sorry, as it might not be the
best way to look at this.
This is my test for git cat-file --batch --batch-all-objects >/dev/null:
[...]
Because we called parse_object_buffer() in get_object(), lookup_object()
is called indirectly...
It would be nice if you could add a bit more details about how
lookup_object() is called (both before and after the changes that
degrade performance).
We can see that some functions are called the same times:
When you say "the same times" I guess you mean that the same amount of
time is spent in these functions.
patch_delta(),
unpack_entry(), hashmap_remove()... But after using my patch,
format_ref_array_item(), grab_sub_body_contents(), get_object(), lookup_object()
begin to occupy a certain proportion.
Having skimmed it I'm a bit confused about this in reference to
performance generally. I haven't looked into the case you're discussing,
but as I noted in
https://lore.kernel.org/git/87im1p6x34.fsf@evledraar.gmail.com/ the
profiling clearly shows that the main problem is that you've added
object lookups we skipped before.
Yeah, you showed me last time that lookup_object() took up a lot of time.
Could the document explain with some details why there are more calls
to lookup_object()?
Please note that here we are looking for the number of times the
lookup_object() function is called. This means that to measure that
properly, it might actually be better to have some way to count this
number of times the lookup_object() function is called, rather than
count the time spent in the function.
Ok, therefore we need an accurate number of call times about lookup_object(),
although the conclusion is obvious: 0 (upstream/master) and a big
number (with my patch).
For example you could add a trace_printf(...) call in the
lookup_object() function, set GIT_TRACE=/tmp/git_trace.log, and then
just run `git cat-file --batch ...` and count the number of times the
new trace from lookup_object() appears in the log file.
After adding a trace_printf() in lookup_object(), here is the result:
Checkout to d3b5272a94 [GSOC] cat-file: reuse ref-filter logic
$ GIT_TRACE=/tmp/git_trace.log ggg cat-file --batch --batch-all-objects
$ cat /tmp/git_trace.log | wc -l
522710
Checkout to eb27b338a3e7 (upstream/master)
$ rm /tmp/git_trace.log
$ GIT_TRACE=/tmp/git_trace.log ggg cat-file --batch --batch-all-objects
$ cat /tmp/git_trace.log | wc -l
1
This is the only 1 time left is printed by git.c, which show that after using
my patch, we additionally call lookup_object() when we use --batch option.
According to the results of the previous gprof test: lookup_object()
occupies 8.72%
of the total time. (Though below you seem to think that the effect of
gprof is not
reliable enough.) This may be a place worthy of optimization.
quoted
quoted
For example it could take an example `git cat-file
--batch ...` command (if possible a simple one), and say which
functions like lookup_object() it was using (and how many times) to
get the data it needs before using the ref-filter logic, and then the
same information after using the ref-filter logic.
Sorry but this time I use gprof but can’t observe the same effect as before.
lookup_object() is indeed a part of the time overhead, but its proportion is
not very large this time.
I am not sure gprof is a good tool for this. It looks like it tries to
attribute spent times to functions by splitting time between many low
level functions, and it doesn't seem like the right approach to me.
For example if lookup_object() is called 5% more often, it could be
that the excess time is attributed to some low level functions and not
to lookup_object() itself.
Maybe you are talking about "cumulative seconds" part of gprof?
it's "self seconds" part is the number of seconds accounted for by
this function alone.
That's why we might get a more accurate view of what happens by just
counting the number of time the function is called.
According to https://sourceware.org/binutils/docs/gprof/Flat-Profile.html :
calls
This is the total number of times the function was called. If the
function was never called,
or the number of times it was called cannot be determined (probably
because the function
was not compiled with profiling enabled), the calls field is blank.
Therefore, there are accurate numbers in the previous gprof test results.
quoted
quoted
It could be nice if there were also some data about how much time used
to be spent in lookup_object() and how much time is now spent there,
and how this compares with the whole slowdown we are seeing. If Ævar
already showed that, you can of course reuse what he already did.
Now I regret having wrote the above, sorry, as it might not be the
best way to look at this.
Yes, because his previous results are based on a version of my patch set,
and some changes have taken place with my patch later.
quoted
This is my test for git cat-file --batch --batch-all-objects >/dev/null:
[...]
quoted
Because we called parse_object_buffer() in get_object(), lookup_object()
is called indirectly...
It would be nice if you could add a bit more details about how
lookup_object() is called (both before and after the changes that
degrade performance).
After we letting git cat-file --batch reuse the logic of ref-filter,
we will use get_object()
to grab the object's data. Since we used atom %(raw), it will require
us to grab the raw data
of the object, oi->info.contentp will be set, parse_object_buffer() in
get_object() will be
called, parse_object_buffer() calls lookup_commit(), lookup_blob(),
lookup_tree(),
and lookup_tag(), they call lookup_object(). As we have seen,
lookup_object() seems to
take a lot of time.
So let us think, can we skip this parse_object_buffer() in some scenarios?
parse_object_buffer() parses the data of the object into a "struct
object *obj", and then we use this
obj feed to grab_values(), and then grab_values() feed obj to
grab_tag_values() or grab_commit_values()
to handle some logic about %(tag), %(type), %(object), %(tree),
%(parent), %(numparent).
But git cat-file --batch can avaid handle there atoms with default format.
Therefore, maybe we can skip parsing object buffer if we really don't
care about these atoms.
quoted
We can see that some functions are called the same times:
When you say "the same times" I guess you mean that the same amount of
time is spent in these functions.
No... What I want to express is that the number of calls to these
functions is same,
see gprof "calls part" with "patch_delta()", both are 1968866.
quoted
patch_delta(),
unpack_entry(), hashmap_remove()... But after using my patch,
format_ref_array_item(), grab_sub_body_contents(), get_object(), lookup_object()
begin to occupy a certain proportion.
From: Christian Couder <hidden> Date: 2021-07-28 15:36:49
On Wed, Jul 28, 2021 at 3:38 PM ZheNing Hu [off-list ref] wrote:
Ok, therefore we need an accurate number of call times about lookup_object(),
although the conclusion is obvious: 0 (upstream/master) and a big
number (with my patch).
[...]
This is the only 1 time left is printed by git.c, which show that after using
my patch, we additionally call lookup_object() when we use --batch option.
According to the results of the previous gprof test: lookup_object()
occupies 8.72%
of the total time. (Though below you seem to think that the effect of
gprof is not
reliable enough.) This may be a place worthy of optimization.
First, yeah, I hadn't seen the "calls" columns in your gprof reports.
Sorry! It's nice to see that your manual check with a trace_printf()
function gives the same result as gprof about this though.
Anyway if you agree that it might be a place worthy of optimization,
then it might be a good idea to explain the reason for the numerous
lookup_object() calls when using the ref-filter code.
[...]
quoted
It would be nice if you could add a bit more details about how
lookup_object() is called (both before and after the changes that
degrade performance).
After we letting git cat-file --batch reuse the logic of ref-filter,
we will use get_object()
to grab the object's data. Since we used atom %(raw), it will require
us to grab the raw data
of the object, oi->info.contentp will be set, parse_object_buffer() in
get_object() will be
called, parse_object_buffer() calls lookup_commit(), lookup_blob(),
lookup_tree(),
and lookup_tag(), they call lookup_object(). As we have seen,
lookup_object() seems to
take a lot of time.
Not sure why you are talking about %(raw). Is the root of the issue
that we now use atom %(raw), or how we implemented it?
So let us think, can we skip this parse_object_buffer() in some scenarios?
parse_object_buffer() parses the data of the object into a "struct
object *obj", and then we use this
obj feed to grab_values(), and then grab_values() feed obj to
grab_tag_values() or grab_commit_values()
to handle some logic about %(tag), %(type), %(object), %(tree),
%(parent), %(numparent).
But git cat-file --batch can avaid handle there atoms with default format.
Therefore, maybe we can skip parsing object buffer if we really don't
care about these atoms.
Yeah, maybe oi->info.contentp should be set only if the user specified
one of the atoms that really needs the content provided by
parse_object_buffer().
Thanks!