Christian Couder <christian.couder@xxxxxxxxx> 于2021年7月26日周一 下午5:38写道： > > On Sun, Jul 25, 2021 at 2:04 PM ZheNing Hu <adlternative@xxxxxxxxx> wrote: > > Ævar Arnfjörð Bjarmason <avarab@xxxxxxxxx> 于2021年7月25日周日 上午5:23写道： > > > > 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@xxxxxxxxxxxxxxxxxxx/ 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. Thanks. -- ZheNing Hu
