git blame with valgrind massif

I ran:
 valgrind --tool=massif --heap=yes git blame gcc/ChangeLog
it used about 2.25GB

How do you interpret the massif output?

Command: git blame gcc/ChangeLog

== 0 =========================== Heap allocation functions accounted for 98.2% of measured spacetime

Called from:
  34.3% : 0x44EFC2: patch_delta (git-compat-util.h:235)

  24.7% : 0x45DD38: cache_or_unpack_entry (git-compat-util.h:235)

  13.1% : 0x4909FC: xdl_cha_alloc (xutils.c:113)

  12.0% : 0x461277: strbuf_grow (git-compat-util.h:268)

   5.9% : 0x40EF5A: cmd_blame (git-compat-util.h:235)

   2.6% : 0x48FA5E: xdl_prepare_env (xprepare.c:79)

   1.9% : 0x45D775: unpack_compressed_entry (git-compat-util.h:235)

   1.5% : 0x452FE5: read_index_from (git-compat-util.h:284)

   1.3% : 0x48F672: xdl_prepare_ctx (xprepare.c:162)

  and 61 other insignificant places

== 1 ===========================
Context accounted for 34.3% of measured spacetime
  0x44EFC2: patch_delta (git-compat-util.h:235)

Called from:
  34.3% : 0x45DA03: unpack_entry (sha1_file.c:1578)

---------------------------------
Context accounted for 24.7% of measured spacetime
  0x45DD38: cache_or_unpack_entry (git-compat-util.h:235)

Called from:
  24.7% : 0x45F175: read_packed_sha1 (sha1_file.c:1815)

---------------------------------
Context accounted for 13.1% of measured spacetime
  0x4909FC: xdl_cha_alloc (xutils.c:113)

Called from:
   6.6% : 0x48F75B: xdl_prepare_ctx (xprepare.c:192)

   4.0% : 0x48F83A: xdl_prepare_ctx (xprepare.c:115)

---------------------------------
Context accounted for 12.0% of measured spacetime
  0x461277: strbuf_grow (git-compat-util.h:268)

Called from:
  12.0% : 0x4617F4: strbuf_read (strbuf.c:192)

  and 2 other insignificant places

---------------------------------
Context accounted for  5.9% of measured spacetime
  0x40EF5A: cmd_blame (git-compat-util.h:235)

Called from:
   5.9% : 0x40405A: handle_internal_command (git.c:266)

---------------------------------
Context accounted for  2.6% of measured spacetime
  0x48FA5E: xdl_prepare_env (xprepare.c:79)

Called from:
   2.6% : 0x48F21A: xdl_do_diff (xdiffi.c:332)

---------------------------------
Context accounted for  1.9% of measured spacetime
  0x45D775: unpack_compressed_entry (git-compat-util.h:235)

Called from:
   1.9% : 0x45D945: unpack_entry (sha1_file.c:1606)

  and 1 other insignificant place

---------------------------------
Context accounted for  1.5% of measured spacetime
  0x452FE5: read_index_from (git-compat-util.h:284)

Called from:
   1.5% : 0x40FAD7: cmd_blame (builtin-blame.c:2075)

---------------------------------
Context accounted for  1.3% of measured spacetime
  0x48F672: xdl_prepare_ctx (xprepare.c:162)

Called from:
   0.6% : 0x48FAAB: xdl_prepare_env (xprepare.c:280)

  and 1 other insignificant place

== 2 ===========================
Context accounted for 34.3% of measured spacetime
  0x44EFC2: patch_delta (git-compat-util.h:235)
  0x45DA03: unpack_entry (sha1_file.c:1578)

Called from:
  41.7% : 0x45D9BE: unpack_entry (sha1_file.c:1567)

  33.3% : 0x45F175: read_packed_sha1 (sha1_file.c:1815)

---------------------------------
Context accounted for 24.7% of measured spacetime
  0x45DD38: cache_or_unpack_entry (git-compat-util.h:235)
  0x45F175: read_packed_sha1 (sha1_file.c:1815)

Called from:
  24.7% : 0x45F55D: read_sha1_file (sha1_file.c:1881)

---------------------------------
Context accounted for  6.6% of measured spacetime
  0x4909FC: xdl_cha_alloc (xutils.c:113)
  0x48F75B: xdl_prepare_ctx (xprepare.c:192)

Called from:
   2.9% : 0x48FAAB: xdl_prepare_env (xprepare.c:280)

   1.6% : 0x48FAD0: xdl_prepare_env (xprepare.c:285)

---------------------------------
Context accounted for  4.0% of measured spacetime
  0x4909FC: xdl_cha_alloc (xutils.c:113)
  0x48F83A: xdl_prepare_ctx (xprepare.c:115)

Called from:
   4.0% : 0x48FAAB: xdl_prepare_env (xprepare.c:280)

  and 1 other insignificant place

---------------------------------
Context accounted for 12.0% of measured spacetime
  0x461277: strbuf_grow (git-compat-util.h:268)
  0x4617F4: strbuf_read (strbuf.c:192)

Called from:
  12.0% : 0x461881: strbuf_read_file (strbuf.c:228)

---------------------------------
Context accounted for  5.9% of measured spacetime
  0x40EF5A: cmd_blame (git-compat-util.h:235)
  0x40405A: handle_internal_command (git.c:266)

Called from:
   5.9% : 0x4045C9: main (git.c:456)

---------------------------------
Context accounted for  2.6% of measured spacetime
  0x48FA5E: xdl_prepare_env (xprepare.c:79)
  0x48F21A: xdl_do_diff (xdiffi.c:332)

Called from:
   2.6% : 0x48F3B0: xdl_diff (xdiffi.c:542)

---------------------------------
Context accounted for  1.9% of measured spacetime
  0x45D775: unpack_compressed_entry (git-compat-util.h:235)
  0x45D945: unpack_entry (sha1_file.c:1606)

Called from:
   2.4% : 0x45F175: read_packed_sha1 (sha1_file.c:1815)

  and 1 other insignificant place

---------------------------------
Context accounted for  1.5% of measured spacetime
  0x452FE5: read_index_from (git-compat-util.h:284)
  0x40FAD7: cmd_blame (builtin-blame.c:2075)

Called from:
   1.5% : 0x40405A: handle_internal_command (git.c:266)

---------------------------------
Context accounted for  0.6% of measured spacetime
  0x48F672: xdl_prepare_ctx (xprepare.c:162)
  0x48FAAB: xdl_prepare_env (xprepare.c:280)

Called from:
   0.6% : 0x48F21A: xdl_do_diff (xdiffi.c:332)

=================================

End of information.  Rerun with a bigger --depth value for more.

On Tue, Dec 11, 2007 at 08:57:24PM +0000, Jon Smirl wrote:

  would you mind putting the postscript it generated somewhere too ?
it's usually pretty informative, because the amount of data allocated is
not all, its liveness is an important information too.

On 12/11/07, Pierre Habouzit <madcoder@debian.org> wrote:

It was very boring. A diagonal line from 0 to 2GB.

On Dec 11, 2007 7:45 PM, Jon Smirl <jonsmirl@gmail.com> wrote:

A bit unrelated, but there's a new valgrind release: http://www.valgrind.org/docs/manual/dist.news.html

"The main excitement in 3.3.0 is new and improved tools. Helgrind works again, Massif has been completely overhauled and much improved, Cachegrind now does branch-misprediction profiling, and a new category of experimental tools has been created, containing two new tools: Omega and DRD. There are many other smaller improvements."

Best regards,

On Tue, 11 Dec 2007, Jon Smirl wrote:

Not very easy, since massif will tell you what *allocated* it, but then trying to see who was supposed to free it is another issue altogether.

I also find the textual output to be very confusing. But what massif is really good at is to look at the memory usage over time in the postscript file it generates, and that gives you a much better feel for what particular allocation is a problem.

In this case, it's patch_delta that generates all the memory usage (well, 98% of it ;^), but that's not that helpful unless you know git internals, and realize that with deep delta chains, that only means that the memory is kept around just for random object data. The question is why that object data stays around and isn't free'd.

There's two answers to that:
 - the non-buggy use of the object data in the delta base cache (limited 
   by the delta_base_cache_limit, which defaults to 16MB, although you can 
   tweak it with core.deltabasecachelimit)
 - the (possibly buggy) callers that keep the data.

See my previous email with a patch to "git blame" to make it release the object data. That should fix it, I think.

		Linus

On Tue, Dec 11, 2007 at 09:22:53PM +0000, Linus Torvalds wrote:

  No 37%, the 98% list is the list of calls that generate 98% of the
total allocations git blame does, and then massif lists each individual
call, and patch_delta generates 37% of the total.

  Though it's meaningless without knowing how much time this memory
stayed allocated>