From: Arnaldo Carvalho de Melo <acme@kernel.org>
To: Steven Rostedt <rostedt@goodmis.org>, Namhyung Kim <namhyung@kernel.org>
Cc: Ingo Molnar <mingo@kernel.org>,
Peter Zijlstra <peterz@infradead.org>,
Jiri Olsa <jolsa@kernel.org>, LKML <linux-kernel@vger.kernel.org>,
David Ahern <dsahern@gmail.com>, Andi Kleen <andi@firstfloor.org>,
Stephane Eranian <eranian@google.com>,
Wang Nan <wangnan0@huawei.com>
Subject: Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy
Date: Fri, 26 Feb 2016 19:08:19 -0300 [thread overview]
Message-ID: <20160226220819.GZ8720@kernel.org> (raw)
In-Reply-To: <20160226214506.GY8720@kernel.org>
Em Fri, Feb 26, 2016 at 06:45:06PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Fri, Feb 26, 2016 at 06:43:07PM -0300, Arnaldo Carvalho de Melo escreveu:
> > Em Sat, Feb 27, 2016 at 03:52:46AM +0900, Namhyung Kim escreveu:
> > > 37.50% 0xffff8803f7669400
> > > 37.50% 448
> > > 37.50% 66080
> > > 10.42% 0xffff8803f766be00
> > > 8.33% 96
> > > 8.33% 66080
> > > 2.08% 512
> > > 2.08% 67280
> > >
> > > After:
> > >
> > > # Overhead ptr / bytes_req / gfp_flags
> > > # .............. ..........................................
> > > 37.50% 0xffff8803f7669400
> > > 37.50% 448
> > > 37.50% GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
> >
> > So, I'm not getting this translation, it looks just like before. So I
> > tried the non-hierarchy mode and got this [FAILED TO PARSE] on each
> > line:
> >
> > Samples: 107 of event 'kmem:kmalloc', Event count (approx.): 107
> > Overhead Trace output
> > 33.64% [FAILED TO PARSE] call_site=0xffffffff811a0747 ptr=0xffff880109c54000 bytes_req=4096 bytes_alloc=4096 gfp_flags=37748928 ▒
> >
> > Investigating...
>
> Further (lots of!) info:
>
> [root@jouet ~]# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format
> name: kmalloc
> ID: 424
> format:
> field:unsigned short common_type; offset:0; size:2; signed:0;
> field:unsigned char common_flags; offset:2; size:1; signed:0;
> field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
> field:int common_pid; offset:4; size:4; signed:1;
>
> field:unsigned long call_site; offset:8; size:8; signed:0;
> field:const void * ptr; offset:16; size:8; signed:0;
> field:size_t bytes_req; offset:24; size:8; signed:0;
> field:size_t bytes_alloc; offset:32; size:8; signed:0;
> field:gfp_t gfp_flags; offset:40; size:4; signed:0;
>
> print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)((((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) | (( gfp_t)0x1000u) | (( gfp_t)0x200u)) & ~(( gfp_t)0x2000000u)), "GFP_TRANSHUGE"}, {(unsigned long)((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)(((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)), "GFP_USER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x10u)), "GFP_TEMPORARY"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u)), "GFP_NOFS"}, {(unsigned long)((( gfp_t)0x20u)|(( gfp_t)0x80000u)|(( gfp_t)0x2000000u)), "GFP_ATOMIC"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u))), "GFP_NOIO"}, {(unsigned long)(( gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)(( gfp_t)0x80000u), "GFP_ATOMIC"}, {(unsigned long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)(( gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned long)(( gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"}, {(unsigned long)(( gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x2000u), "GFP_MEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u), "GFP_HARDWALL"}, {(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)(( gfp_t)0x10u), "GFP_RECLAIMABLE"}, {(unsigned long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0x200000u), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_DIRECT_RECLAIM"}, {(unsigned long)(( gfp_t)0x2000000u), "GFP_KSWAPD_RECLAIM"}, {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT"
> [root@jouet ~]# uname -a
> Linux jouet 4.5.0-rc4 #1 SMP Mon Feb 22 15:53:36 BRT 2016 x86_64 x86_64 x86_64 GNU/Linux
> [root@jouet ~]#
It is exploding at this depth, not liking how gfp_flags is described, problem
seems to be in this function, this __print_flags() long thing.
Steven, does this look familiar?
(gdb) bt
#0 process_fields (event=0x19b95e0, list=0x19bb0d0, tok=0x7fffffffa0e8) at event-parse.c:2527
#1 0x000000000058410d in process_flags (event=0x19b95e0, arg=0x19bb0b0, tok=0x7fffffffa178) at event-parse.c:2567
#2 0x0000000000584eba in process_function (event=0x19b95e0, arg=0x19bb0b0, token=0x19bb130 "gfp_flags", tok=0x7fffffffa178) at event-parse.c:2989
#3 0x0000000000585231 in process_arg_token (event=0x19b95e0, arg=0x19bb0b0, tok=0x7fffffffa218, type=EVENT_DELIM) at event-parse.c:3060
#4 0x0000000000581f2c in process_arg (event=0x19b95e0, arg=0x19bb0b0, tok=0x7fffffffa218) at event-parse.c:1698
#5 0x000000000058208a in process_cond (event=0x19b95e0, top=0x19bafd0, tok=0x7fffffffa308) at event-parse.c:1746
#6 0x0000000000582772 in process_op (event=0x19b95e0, arg=0x19bafd0, tok=0x7fffffffa308) at event-parse.c:1941
#7 0x0000000000585573 in event_read_print_args (event=0x19b95e0, list=0x19baf70) at event-parse.c:3153
#8 0x0000000000585778 in event_read_print (event=0x19b95e0) at event-parse.c:3225
#9 0x000000000058b402 in __pevent_parse_format (eventp=0x7fffffffa458, pevent=0x19b94c0,
buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at event-parse.c:5916
#10 0x000000000058b5bb in __pevent_parse_event (pevent=0x19b94c0, eventp=0x7fffffffa458,
buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at event-parse.c:5970
#11 0x000000000058b68f in pevent_parse_event (pevent=0x19b94c0,
buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at event-parse.c:6033
#12 0x00000000004f2c3c in parse_event_file (pevent=0x19b94c0,
buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at util/trace-event-parse.c:171
#13 0x0000000000502e16 in read_event_file (pevent=0x19b94c0, sys=0x19b96c0 "kmem", size=2983) at util/trace-event-read.c:293
#14 0x0000000000502f51 in read_event_files (pevent=0x19b94c0) at util/trace-event-read.c:336
#15 0x00000000005032e2 in trace_report (fd=3, tevent=0x19b5a80, __repipe=false) at util/trace-event-read.c:417
#16 0x00000000004d6303 in process_tracing_data (section=0x19b93b0, ph=0x19b57c0, fd=3, data=0x19b5a80) at util/header.c:1595
#17 0x00000000004d8f84 in perf_file_section__process (section=0x19b93b0, ph=0x19b57c0, feat=1, fd=3, data=0x19b5a80) at util/header.c:2704
#18 0x00000000004d8878 in perf_header__process_sections (header=0x19b57c0, fd=3, data=0x19b5a80, process=0x4d8e7e <perf_file_section__process>)
at util/header.c:2487
#19 0x00000000004d9860 in perf_session__read_header (session=0x19b57c0) at util/header.c:2922
#20 0x00000000004e8c59 in perf_session__open (session=0x19b57c0) at util/session.c:32
#21 0x00000000004e915c in perf_session__new (file=0x7fffffffc8a0, repipe=false, tool=0x7fffffffc990) at util/session.c:139
#22 0x0000000000436dfb in cmd_report (argc=0, argv=0x7fffffffe330, prefix=0x0) at builtin-report.c:878
#23 0x000000000049dbb3 in run_builtin (p=0x90d560 <commands+192>, argc=1, argv=0x7fffffffe330) at perf.c:390
#24 0x000000000049de1b in handle_internal_command (argc=1, argv=0x7fffffffe330) at perf.c:451
#25 0x000000000049df60 in run_argv (argcp=0x7fffffffe18c, argv=0x7fffffffe180) at perf.c:497
#26 0x000000000049e2f7 in main (argc=1, argv=0x7fffffffe330) at perf.c:622
(gdb)
next prev parent reply other threads:[~2016-02-26 22:08 UTC|newest]
Thread overview: 26+ messages / expand[flat|nested] mbox.gz Atom feed top
2016-02-26 18:52 [PATCH 1/5] perf report: Fix comparing of dynamic entries Namhyung Kim
2016-02-26 18:52 ` [PATCH 2/5] perf report: Fix indentation of dynamic entries in hierarchy Namhyung Kim
2016-02-27 9:43 ` [tip:perf/core] " tip-bot for Namhyung Kim
2016-02-26 18:52 ` [PATCH 3/5] perf report: Left align " Namhyung Kim
2016-02-27 9:43 ` [tip:perf/core] " tip-bot for Namhyung Kim
2016-02-26 18:52 ` [PATCH 4/5] perf report: Fix dynamic entry display " Namhyung Kim
2016-02-26 21:43 ` Arnaldo Carvalho de Melo
2016-02-26 21:45 ` Arnaldo Carvalho de Melo
2016-02-26 22:08 ` Arnaldo Carvalho de Melo [this message]
2016-02-26 22:24 ` Arnaldo Carvalho de Melo
2016-02-26 22:26 ` Steven Rostedt
2016-02-26 22:37 ` Arnaldo Carvalho de Melo
2016-02-26 23:12 ` Jiri Olsa
2016-02-26 23:13 ` Jiri Olsa
2016-02-26 23:13 ` [PATCH] tools lib traceevent: Add '~' operation within arg_num_eval() Steven Rostedt
2016-02-26 23:39 ` Arnaldo Carvalho de Melo
2016-02-26 23:45 ` David Ahern
2016-03-10 16:16 ` David Ahern
2016-03-10 19:28 ` Arnaldo Carvalho de Melo
2016-03-11 8:47 ` [tip:perf/core] " tip-bot for Steven Rostedt
2016-02-27 9:44 ` [tip:perf/core] perf hists: Fix dynamic entry display in hierarchy tip-bot for Namhyung Kim
2016-02-26 18:52 ` [PATCH 5/5] perf report: Update column width of dynamic entries Namhyung Kim
2016-02-26 22:43 ` Arnaldo Carvalho de Melo
2016-02-27 9:44 ` [tip:perf/core] " tip-bot for Namhyung Kim
2016-02-26 21:23 ` [PATCH 1/5] perf report: Fix comparing " Jiri Olsa
2016-02-27 9:43 ` [tip:perf/core] perf hists: " 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=20160226220819.GZ8720@kernel.org \
--to=acme@kernel.org \
--cc=andi@firstfloor.org \
--cc=dsahern@gmail.com \
--cc=eranian@google.com \
--cc=jolsa@kernel.org \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@kernel.org \
--cc=namhyung@kernel.org \
--cc=peterz@infradead.org \
--cc=rostedt@goodmis.org \
--cc=wangnan0@huawei.com \
/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.