All of lore.kernel.org
 help / color / mirror / Atom feed
From: Arnaldo Carvalho de Melo <acme@kernel.org>
To: Markus Trippelsdorf <markus@trippelsdorf.de>
Cc: Namhyung Kim <namhyung@kernel.org>,
	David Ahern <dsahern@gmail.com>,
	linux-kernel@vger.kernel.org,
	Peter Zijlstra <a.p.zijlstra@chello.nl>,
	Paul Mackerras <paulus@samba.org>, Ingo Molnar <mingo@redhat.com>
Subject: Re: "perf top -g" leaking ~300MB per second.
Date: Tue, 30 Dec 2014 20:04:25 -0300	[thread overview]
Message-ID: <20141230230425.GB14973@kernel.org> (raw)
In-Reply-To: <20141230083524.GA2143@x4>

Em Tue, Dec 30, 2014 at 09:35:24AM +0100, Markus Trippelsdorf escreveu:
> On 2014.12.30 at 14:38 +0900, Namhyung Kim wrote:
> > Hi David and Markus,
> > 
> > On Sat, Dec 13, 2014 at 11:16:43AM -0700, David Ahern wrote:
> > > On 12/13/14 8:26 AM, Arnaldo Carvalho de Melo wrote:
> > > >The callchain code was done initially for 'report' and when I made 'top'
> > > >reuse the hist_entry code allowing 'top' to collect callchains was too
> > > >easy, but then we need to go thru the callchain/hists/hist_entry code to
> > > >make sure that they don't leak, will try to do it...
> > > >
> > > 
> > > As I recall it is build up of the dead_threads list.
> > 
> > Maybe.  But I guess it's because of leak of callchains..
> > 
> > Markus, could you please test below patch how much it affects?
> 
> Thanks Namhyung. It leaks an order of magnitude less memory now:
> ~30MB/sec on my machine.
> 
> Valgrind shows (last entries of the list):
> ...
> ==20512== 7,225,920 bytes in 17,370 blocks are possibly lost in loss record 295 of 301
> ==20512==    at 0x402B000: calloc (vg_replace_malloc.c:623)
> ==20512==    by 0x4A6996: zalloc (util.h:189)
> ==20512==    by 0x4A6996: hist_entry__new (hist.c:309)
> ==20512==    by 0x4A8249: add_hist_entry (hist.c:431)
> ==20512==    by 0x4A8249: __hists__add_entry (hist.c:477)
> ==20512==    by 0x4A8902: iter_add_single_cumulative_entry (hist.c:730)
> ==20512==    by 0x4A8A64: hist_entry_iter__add (hist.c:876)
> ==20512==    by 0x43787A: perf_event__process_sample (builtin-top.c:787)
> ==20512==    by 0x43787A: perf_top__mmap_read_idx (builtin-top.c:854)
> ==20512==    by 0x4395EE: perf_top__mmap_read (builtin-top.c:871)
> ==20512==    by 0x4395EE: __cmd_top (builtin-top.c:974)
> ==20512==    by 0x4395EE: cmd_top (builtin-top.c:1266)
> ==20512==    by 0x41B702: run_builtin (perf.c:341)
> ==20512==    by 0x41AE51: handle_internal_command (perf.c:400)
> ==20512==    by 0x41AE51: run_argv (perf.c:444)
> ==20512==    by 0x41AE51: main (perf.c:559)

#1) Ok, those are the hist_entries that were not decayed, if top continued
they would eventually be decayed, freed, etc, i.e. the exit of top is
equivalent to the last decay.

> ==20512== 
> ==20512== 8,922,480 bytes in 159,330 blocks are possibly lost in loss record 296 of 301
> ==20512==    at 0x402B000: calloc (vg_replace_malloc.c:623)
> ==20512==    by 0x4821FE: zalloc (util.h:189)
> ==20512==    by 0x4821FE: fill_node (callchain.c:450)
> ==20512==    by 0x4821FE: add_child (callchain.c:473)
> ==20512==    by 0x4821FE: append_chain_children (callchain.c:596)
> ==20512==    by 0x48514E: callchain_append (callchain.c:672)
> ==20512==    by 0x4A8947: iter_add_single_cumulative_entry (hist.c:739)
> ==20512==    by 0x4A8A64: hist_entry_iter__add (hist.c:876)
> ==20512==    by 0x43787A: perf_event__process_sample (builtin-top.c:787)
> ==20512==    by 0x43787A: perf_top__mmap_read_idx (builtin-top.c:854)
> ==20512==    by 0x43967E: perf_top__mmap_read (builtin-top.c:871)
> ==20512==    by 0x43967E: __cmd_top (builtin-top.c:996)
> ==20512==    by 0x43967E: cmd_top (builtin-top.c:1266)
> ==20512==    by 0x41B702: run_builtin (perf.c:341)
> ==20512==    by 0x41AE51: handle_internal_command (perf.c:400)
> ==20512==    by 0x41AE51: run_argv (perf.c:444)
> ==20512==    by 0x41AE51: main (perf.c:559)
> ==20512== 

> ==20512== 11,050,136 bytes in 1,663 blocks are definitely lost in loss record 297 of 301
> ==20512==    at 0x402B000: calloc (vg_replace_malloc.c:623)
> ==20512==    by 0x44F7BF: zalloc (util.h:189)
> ==20512==    by 0x44F7BF: symbol__alloc_hist (annotate.c:455)
> ==20512==    by 0x44F7BF: symbol__inc_addr_samples (annotate.c:507)
> ==20512==    by 0x44F7BF: hist_entry__inc_addr_samples (annotate.c:521)
> ==20512==    by 0x437A65: perf_top__record_precise_ip (builtin-top.c:195)
> ==20512==    by 0x437A65: hist_iter__top_callback (builtin-top.c:688)
> ==20512==    by 0x4A8AC8: hist_entry_iter__add (hist.c:892)
> ==20512==    by 0x43787A: perf_event__process_sample (builtin-top.c:787)
> ==20512==    by 0x43787A: perf_top__mmap_read_idx (builtin-top.c:854)
> ==20512==    by 0x43967E: perf_top__mmap_read (builtin-top.c:871)
> ==20512==    by 0x43967E: __cmd_top (builtin-top.c:996)
> ==20512==    by 0x43967E: cmd_top (builtin-top.c:1266)
> ==20512==    by 0x41B702: run_builtin (perf.c:341)
> ==20512==    by 0x41AE51: handle_internal_command (perf.c:400)
> ==20512==    by 0x41AE51: run_argv (perf.c:444)
> ==20512==    by 0x41AE51: main (perf.c:559)

These (symbol__alloc_hist) we need to free up the decaying of per RIP
annotation gets to zero... Will check where to do this...

> ==20512== 
> ==20512== 24,920,064 bytes in 59,904 blocks are possibly lost in loss record 298 of 301
> ==20512==    at 0x402B000: calloc (vg_replace_malloc.c:623)
> ==20512==    by 0x4A6996: zalloc (util.h:189)
> ==20512==    by 0x4A6996: hist_entry__new (hist.c:309)
> ==20512==    by 0x4A8249: add_hist_entry (hist.c:431)
> ==20512==    by 0x4A8249: __hists__add_entry (hist.c:477)
> ==20512==    by 0x4A8902: iter_add_single_cumulative_entry (hist.c:730)
> ==20512==    by 0x4A8A64: hist_entry_iter__add (hist.c:876)
> ==20512==    by 0x43787A: perf_event__process_sample (builtin-top.c:787)
> ==20512==    by 0x43787A: perf_top__mmap_read_idx (builtin-top.c:854)
> ==20512==    by 0x43967E: perf_top__mmap_read (builtin-top.c:871)
> ==20512==    by 0x43967E: __cmd_top (builtin-top.c:996)
> ==20512==    by 0x43967E: cmd_top (builtin-top.c:1266)
> ==20512==    by 0x41B702: run_builtin (perf.c:341)
> ==20512==    by 0x41AE51: handle_internal_command (perf.c:400)
> ==20512==    by 0x41AE51: run_argv (perf.c:444)
> ==20512==    by 0x41AE51: main (perf.c:559)

Same thing as #1.

> ==20512== 
> ==20512== 26,147,680 bytes in 62,855 blocks are possibly lost in loss record 299 of 301
> ==20512==    at 0x402B000: calloc (vg_replace_malloc.c:623)
> ==20512==    by 0x4A6996: zalloc (util.h:189)
> ==20512==    by 0x4A6996: hist_entry__new (hist.c:309)
> ==20512==    by 0x4A8249: add_hist_entry (hist.c:431)
> ==20512==    by 0x4A8249: __hists__add_entry (hist.c:477)
> ==20512==    by 0x4A8728: iter_add_next_cumulative_entry (hist.c:803)
> ==20512==    by 0x4A8AA5: hist_entry_iter__add (hist.c:887)
> ==20512==    by 0x43787A: perf_event__process_sample (builtin-top.c:787)
> ==20512==    by 0x43787A: perf_top__mmap_read_idx (builtin-top.c:854)
> ==20512==    by 0x43967E: perf_top__mmap_read (builtin-top.c:871)
> ==20512==    by 0x43967E: __cmd_top (builtin-top.c:996)
> ==20512==    by 0x43967E: cmd_top (builtin-top.c:1266)
> ==20512==    by 0x41B702: run_builtin (perf.c:341)
> ==20512==    by 0x41AE51: handle_internal_command (perf.c:400)
> ==20512==    by 0x41AE51: run_argv (perf.c:444)
> ==20512==    by 0x41AE51: main (perf.c:559)
> ==20512== 
> ==20512== 44,939,792 bytes in 3,788 blocks are definitely lost in loss record 300 of 301
> ==20512==    at 0x402B000: calloc (vg_replace_malloc.c:623)
> ==20512==    by 0x44F7BF: zalloc (util.h:189)
> ==20512==    by 0x44F7BF: symbol__alloc_hist (annotate.c:455)
> ==20512==    by 0x44F7BF: symbol__inc_addr_samples (annotate.c:507)
> ==20512==    by 0x44F7BF: hist_entry__inc_addr_samples (annotate.c:521)
> ==20512==    by 0x437A65: perf_top__record_precise_ip (builtin-top.c:195)
> ==20512==    by 0x437A65: hist_iter__top_callback (builtin-top.c:688)
> ==20512==    by 0x4A8AC8: hist_entry_iter__add (hist.c:892)
> ==20512==    by 0x43787A: perf_event__process_sample (builtin-top.c:787)
> ==20512==    by 0x43787A: perf_top__mmap_read_idx (builtin-top.c:854)
> ==20512==    by 0x4395EE: perf_top__mmap_read (builtin-top.c:871)
> ==20512==    by 0x4395EE: __cmd_top (builtin-top.c:974)
> ==20512==    by 0x4395EE: cmd_top (builtin-top.c:1266)
> ==20512==    by 0x41B702: run_builtin (perf.c:341)
> ==20512==    by 0x41AE51: handle_internal_command (perf.c:400)
> ==20512==    by 0x41AE51: run_argv (perf.c:444)
> ==20512==    by 0x41AE51: main (perf.c:559)
> ==20512== 
> ==20512== 81,248,440 bytes in 1,450,865 blocks are possibly lost in loss record 301 of 301
> ==20512==    at 0x402B000: calloc (vg_replace_malloc.c:623)
> ==20512==    by 0x4821FE: zalloc (util.h:189)
> ==20512==    by 0x4821FE: fill_node (callchain.c:450)
> ==20512==    by 0x4821FE: add_child (callchain.c:473)
> ==20512==    by 0x4821FE: append_chain_children (callchain.c:596)
> ==20512==    by 0x48514E: callchain_append (callchain.c:672)
> ==20512==    by 0x4A8768: iter_add_next_cumulative_entry (hist.c:812)
> ==20512==    by 0x4A8AA5: hist_entry_iter__add (hist.c:887)
> ==20512==    by 0x43787A: perf_event__process_sample (builtin-top.c:787)
> ==20512==    by 0x43787A: perf_top__mmap_read_idx (builtin-top.c:854)
> ==20512==    by 0x43967E: perf_top__mmap_read (builtin-top.c:871)
> ==20512==    by 0x43967E: __cmd_top (builtin-top.c:996)
> ==20512==    by 0x43967E: cmd_top (builtin-top.c:1266)
> ==20512==    by 0x41B702: run_builtin (perf.c:341)
> ==20512==    by 0x41AE51: handle_internal_command (perf.c:400)
> ==20512==    by 0x41AE51: run_argv (perf.c:444)
> ==20512==    by 0x41AE51: main (perf.c:559)
> ==20512== 
> ==20512== LEAK SUMMARY:
> ==20512==    definitely lost: 56,810,427 bytes in 5,479 blocks
> ==20512==    indirectly lost: 4,000 bytes in 125 blocks
> ==20512==      possibly lost: 210,493,048 bytes in 2,552,578 blocks
> ==20512==    still reachable: 18,258 bytes in 242 blocks
> ==20512==         suppressed: 0 bytes in 0 blocks
> 
> -- 
> Markus

  reply	other threads:[~2014-12-30 23:04 UTC|newest]

Thread overview: 9+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2014-12-13  8:48 "perf top -g" leaking ~300MB per second Markus Trippelsdorf
2014-12-13  9:03 ` Markus Trippelsdorf
2014-12-13 15:26   ` Arnaldo Carvalho de Melo
2014-12-13 18:16     ` David Ahern
2014-12-30  5:38       ` Namhyung Kim
2014-12-30  8:35         ` Markus Trippelsdorf
2014-12-30 23:04           ` Arnaldo Carvalho de Melo [this message]
2015-01-08 15:09         ` Arnaldo Carvalho de Melo
2015-01-09 12:31         ` [tip:perf/urgent] perf callchain: Free callchains when hist entries are deleted tip-bot for Namhyung Kim

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20141230230425.GB14973@kernel.org \
    --to=acme@kernel.org \
    --cc=a.p.zijlstra@chello.nl \
    --cc=dsahern@gmail.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=markus@trippelsdorf.de \
    --cc=mingo@redhat.com \
    --cc=namhyung@kernel.org \
    --cc=paulus@samba.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.