Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy

From: Arnaldo Carvalho de Melo
Date: Fri Feb 26 2016 - 17:08:30 EST

Next message: Andrew Lunn: "Re: [PATCH net-next 7/9] net: dsa: mv88e6xxx: restore VLANTable map control"
Previous message: Al Viro: "Re: fs: NULL deref in atime_needs_update"
In reply to: Arnaldo Carvalho de Melo: "Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy"
Next in thread: Arnaldo Carvalho de Melo: "Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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)0x400
00u), "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 message: Andrew Lunn: "Re: [PATCH net-next 7/9] net: dsa: mv88e6xxx: restore VLANTable map control"
Previous message: Al Viro: "Re: fs: NULL deref in atime_needs_update"
In reply to: Arnaldo Carvalho de Melo: "Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy"
Next in thread: Arnaldo Carvalho de Melo: "Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]