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.

-- 
Jon Smirl
jonsmirl@gmail.com

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

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

How do you interpret the massif output?

  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.

-- 
·O·  Pierre Habouzit
··O                                                madcoder@debian.org
OOO                                                http://www.madism.org

On Tue, 11 Dec 2007, Jon Smirl wrote:

How do you interpret the massif output?

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:

On Tue, 11 Dec 2007, Jon Smirl wrote:

quoted

How do you interpret the massif output?

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, 

  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>

-- 
·O·  Pierre Habouzit
··O                                                madcoder@debian.org
OOO                                                http://www.madism.org

On 12/11/07, Pierre Habouzit [off-list ref] wrote:

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

quoted

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

How do you interpret the massif output?

  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.

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

--
·O·  Pierre Habouzit
··O                                                madcoder@debian.org
OOO                                                http://www.madism.org

-- 
Jon Smirl
jonsmirl@gmail.com

On Dec 11, 2007 7:45 PM, Jon Smirl [off-list ref] wrote:

On 12/11/07, Pierre Habouzit [off-list ref] wrote:

quoted

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

quoted

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

How do you interpret the massif output?

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,
-- 
[]s,
André Goddard