[PATCH 0/3] Add names of shrinkers and have tracepoints display them

[PATCH 0/3] Add names of shrinkers and have tracepoints display them

[Janani Ravichandran]

Hello,

I'm an Outreachy intern working under Rik van Riel. My project is about
latency tracing during memory allocation. The idea is to use 
tracepoints, both existing and new, to derive higher level information
on memory allocation and identify where time was spent.
This patchset which

1, adds a new field to struct shrinker to hold names of shrinkers,
2, updates the newly added field in instances of the struct,
3, changes tracepoint definitions to have the field displayed,

would be useful when one wants to observe which shrinkers
contributed to excessive latencies.

A post processing script like the one here-

https://github.com/Jananiravichandran/Analyzing-tracepoints/blob/master/shrink_slab_latencies.py ,

can use the new information this patchset adds to see which shrinkers
were invoked and how long each of them took.

Sample output:

i915_gem_shrinker : 0.166 ms
ext4_es_shrinker : 0.954 ms
workingset_shadow_shrinker : 1.091 ms
deferred_split_shrinker : 6.043 ms
super_cache_shrinker : 84.218 ms

total time spent in shrinkers = 92.472 ms

This shows the various shrinkers called and the times spent.

Janani Ravichandran (3):
  Add a new field to struct shrinker
  Update name field for all shrinker instances
  Add name fields in shrinker tracepoint definitions

 arch/x86/kvm/mmu.c                                 |  1 +
 drivers/gpu/drm/i915/i915_gem_shrinker.c           |  1 +
 drivers/gpu/drm/ttm/ttm_page_alloc.c               |  1 +
 drivers/gpu/drm/ttm/ttm_page_alloc_dma.c           |  1 +
 drivers/md/bcache/btree.c                          |  1 +
 drivers/md/dm-bufio.c                              |  1 +
 drivers/md/raid5.c                                 |  1 +
 drivers/staging/android/ashmem.c                   |  1 +
 drivers/staging/android/ion/ion_heap.c             |  1 +
 drivers/staging/android/lowmemorykiller.c          |  1 +
 drivers/staging/lustre/lustre/ldlm/ldlm_pool.c     |  1 +
 drivers/staging/lustre/lustre/obdclass/lu_object.c |  1 +
 drivers/staging/lustre/lustre/ptlrpc/sec_bulk.c    |  1 +
 fs/ext4/extents_status.c                           |  1 +
 fs/f2fs/super.c                                    |  1 +
 fs/gfs2/glock.c                                    |  1 +
 fs/gfs2/quota.c                                    |  1 +
 fs/mbcache.c                                       |  1 +
 fs/nfs/super.c                                     |  1 +
 fs/nfsd/nfscache.c                                 |  1 +
 fs/quota/dquot.c                                   |  1 +
 fs/super.c                                         |  1 +
 fs/ubifs/super.c                                   |  1 +
 fs/xfs/xfs_buf.c                                   |  1 +
 fs/xfs/xfs_qm.c                                    |  1 +
 include/linux/shrinker.h                           |  1 +
 include/trace/events/vmscan.h                      | 10 ++++++++--
 mm/huge_memory.c                                   |  2 ++
 mm/workingset.c                                    |  1 +
 mm/zsmalloc.c                                      |  1 +
 net/sunrpc/auth.c                                  |  1 +
 31 files changed, 39 insertions(+), 2 deletions(-)

-- 
2.7.0

[PATCH 1/3] Add a new field to struct shrinker

[Janani Ravichandran]

Struct shrinker does not have a field to uniquely identify the shrinkers
it represents. It would be helpful to have a new field to hold names of
shrinkers. This information would be useful while analyzing their
behavior using tracepoints.

---
 include/linux/shrinker.h | 1 +
 1 file changed, 1 insertion(+)

diff --git a/include/linux/shrinker.h b/include/linux/shrinker.h
index 4fcacd9..431125c 100644
--- a/include/linux/shrinker.h
+++ b/include/linux/shrinker.h
@@ -52,6 +52,7 @@ struct shrinker {
 	unsigned long (*scan_objects)(struct shrinker *,
 				      struct shrink_control *sc);
 
+	const char *name;
 	int seeks;	/* seeks to recreate an obj */
 	long batch;	/* reclaim batch size, 0 = default */
 	unsigned long flags;
-- 
2.7.0

Re: [PATCH 1/3] Add a new field to struct shrinker

[Michal Hocko]

On Sat 09-07-16 04:43:31, Janani Ravichandran wrote:
> Struct shrinker does not have a field to uniquely identify the shrinkers
> it represents. It would be helpful to have a new field to hold names of
> shrinkers. This information would be useful while analyzing their
> behavior using tracepoints.

This will however increase the vmlinux size even when no tracing is
enabled. Why cannot we simply print the name of the shrinker callbacks?

> 
> ---
>  include/linux/shrinker.h | 1 +
>  1 file changed, 1 insertion(+)
> 
> diff --git a/include/linux/shrinker.h b/include/linux/shrinker.h
> index 4fcacd9..431125c 100644
> --- a/include/linux/shrinker.h
> +++ b/include/linux/shrinker.h
> @@ -52,6 +52,7 @@ struct shrinker {
>  	unsigned long (*scan_objects)(struct shrinker *,
>  				      struct shrink_control *sc);
>  
> +	const char *name;
>  	int seeks;	/* seeks to recreate an obj */
>  	long batch;	/* reclaim batch size, 0 = default */
>  	unsigned long flags;
> -- 
> 2.7.0
> 
> --
> To unsubscribe, send a message with 'unsubscribe linux-mm' in
> the body to majordomo@kvack.org.  For more info on Linux MM,
> see: http://www.linux-mm.org/ .
> Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

-- 
Michal Hocko
SUSE Labs

Re: [PATCH 1/3] Add a new field to struct shrinker

[Rik van Riel]

[-- Attachment #1: Type: text/plain, Size: 1504 bytes --]

On Mon, 2016-07-11 at 08:37 +0200, Michal Hocko wrote:
> On Sat 09-07-16 04:43:31, Janani Ravichandran wrote:
> > Struct shrinker does not have a field to uniquely identify the
> > shrinkers
> > it represents. It would be helpful to have a new field to hold
> > names of
> > shrinkers. This information would be useful while analyzing their
> > behavior using tracepoints.
> 
> This will however increase the vmlinux size even when no tracing is
> enabled. Why cannot we simply print the name of the shrinker
> callbacks?

What mechanism do you have in mind for obtaining the name,
Michal?

> > ---
> >  include/linux/shrinker.h | 1 +
> >  1 file changed, 1 insertion(+)
> > 
> > diff --git a/include/linux/shrinker.h b/include/linux/shrinker.h
> > index 4fcacd9..431125c 100644
> > --- a/include/linux/shrinker.h
> > +++ b/include/linux/shrinker.h
> > @@ -52,6 +52,7 @@ struct shrinker {
> >  	unsigned long (*scan_objects)(struct shrinker *,
> >  				      struct shrink_control *sc);
> >  
> > +	const char *name;
> >  	int seeks;	/* seeks to recreate an obj */
> >  	long batch;	/* reclaim batch size, 0 = default */
> >  	unsigned long flags;
> > -- 
> > 2.7.0
> > 
> > --
> > To unsubscribe, send a message with 'unsubscribe linux-mm' in
> > the body to majordomo@kvack.org.  For more info on Linux MM,
> > see: http://www.linux-mm.org/ .
> > Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
> 
-- 

All Rights Reversed.

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

Re: [PATCH 1/3] Add a new field to struct shrinker

[Michal Hocko]

On Mon 11-07-16 10:12:51, Rik van Riel wrote:
> On Mon, 2016-07-11 at 08:37 +0200, Michal Hocko wrote:
> > On Sat 09-07-16 04:43:31, Janani Ravichandran wrote:
> > > Struct shrinker does not have a field to uniquely identify the
> > > shrinkers
> > > it represents. It would be helpful to have a new field to hold
> > > names of
> > > shrinkers. This information would be useful while analyzing their
> > > behavior using tracepoints.
> > 
> > This will however increase the vmlinux size even when no tracing is
> > enabled. Why cannot we simply print the name of the shrinker
> > callbacks?
> 
> What mechanism do you have in mind for obtaining the name,
> Michal?

Not sure whether tracing infrastructure allows printk like %ps. If not
then it doesn't sound too hard to add.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH 1/3] Add a new field to struct shrinker

[Janani Ravichandran]

> On Jul 11, 2016, at 8:03 PM, Michal Hocko <mhocko@kernel.org> wrote:
> 
> On Mon 11-07-16 10:12:51, Rik van Riel wrote:
>> 
>> What mechanism do you have in mind for obtaining the name,
>> Michal?
> 
> Not sure whether tracing infrastructure allows printk like %ps. If not
> then it doesn't sound too hard to add.

It does allow %ps. Currently what is being printed is the function symbol 
of the callback using %pF. I’d like to know why %pF is used instead of
%ps in this case.

Michal, just to make sure I understand you correctly, do you mean that we
could infer the names of the shrinkers by looking at the names of their callbacks?

Janani.

Re: [PATCH 1/3] Add a new field to struct shrinker

[Michal Hocko]

On Wed 20-07-16 20:11:09, Janani Ravichandran wrote:
> 
> > On Jul 11, 2016, at 8:03 PM, Michal Hocko <mhocko@kernel.org> wrote:
> > 
> > On Mon 11-07-16 10:12:51, Rik van Riel wrote:
> >> 
> >> What mechanism do you have in mind for obtaining the name,
> >> Michal?
> > 
> > Not sure whether tracing infrastructure allows printk like %ps. If not
> > then it doesn't sound too hard to add.
> 
> It does allow %ps. Currently what is being printed is the function symbol 
> of the callback using %pF. I’d like to know why %pF is used instead of
> %ps in this case.

>From a quick look into the code %pF should be doing the same thing as
%ps in the end. Some architectures just need some magic to get a proper
address of the function.

> Michal, just to make sure I understand you correctly, do you mean that we
> could infer the names of the shrinkers by looking at the names of their callbacks?

Yes, %ps can then be used for the name of the shrinker structure
(assuming it is available).

-- 
Michal Hocko
SUSE Labs

Re: [PATCH 1/3] Add a new field to struct shrinker

[Tony Jones]

On 07/20/2016 07:54 AM, Michal Hocko wrote:

>> Michal, just to make sure I understand you correctly, do you mean that we
>> could infer the names of the shrinkers by looking at the names of their callbacks?
> 
> Yes, %ps can then be used for the name of the shrinker structure
> (assuming it is available).

This is fine for emitting via the ftrace /sys interface,  but in order to have the data [name] get 
marshalled thru to perf (for example) you need to add it to the TP_fast_assign entry.

tony

Re: [PATCH 1/3] Add a new field to struct shrinker

[Tony Jones]

On 07/22/2016 06:27 PM, Tony Jones wrote:
> On 07/20/2016 07:54 AM, Michal Hocko wrote:
> 
>>> Michal, just to make sure I understand you correctly, do you mean that we
>>> could infer the names of the shrinkers by looking at the names of their callbacks?
>>
>> Yes, %ps can then be used for the name of the shrinker structure
>> (assuming it is available).
> 
> This is fine for emitting via the ftrace /sys interface,  but in order to have the data [name] get 
> marshalled thru to perf (for example) you need to add it to the TP_fast_assign entry.
> 
> tony

Unfortunately, %ps/%pF doesn't do much (re:  Michal's comment "assuming it is available"):

-       TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
+       TP_printk("%pF %p(%ps): nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
                __entry->shrink,
                __entry->shr,
+               __entry->shr,
                __entry->nid,
                __entry->nr_objects_to_shrink,

# cat trace_pipe
            bash-1917  [003] ...1  2925.941062: mm_shrink_slab_start: super_cache_scan+0x0/0x1a0 ffff88042bb60cc0(0xffff88042bb60cc0): nid: 0 objects to shrink 0 gfp_flags GFP_KERNEL pgs_scanned 1000 lru_pgs 1000 cache items 4 delta 7 total_scan 7


Otherwise what I was suggesting was something like this to ensure it was correctly marshaled for perf/etc:

diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
--- a/include/trace/events/vmscan.h
+++ b/include/trace/events/vmscan.h
@@ -16,6 +16,8 @@
 #define RECLAIM_WB_SYNC		0x0004u /* Unused, all reclaim async */
 #define RECLAIM_WB_ASYNC	0x0008u
 
+#define SHRINKER_NAME_LEN 	(size_t)32
+
 #define show_reclaim_flags(flags)				\
 	(flags) ? __print_flags(flags, "|",			\
 		{RECLAIM_WB_ANON,	"RECLAIM_WB_ANON"},	\
@@ -191,6 +193,7 @@ TRACE_EVENT(mm_shrink_slab_start,
 	TP_STRUCT__entry(
 		__field(struct shrinker *, shr)
 		__field(void *, shrink)
+		__array(char, name, SHRINKER_NAME_LEN);
 		__field(int, nid)
 		__field(long, nr_objects_to_shrink)
 		__field(gfp_t, gfp_flags)
@@ -202,6 +205,11 @@ TRACE_EVENT(mm_shrink_slab_start,
 	),
 
 	TP_fast_assign(
+		char sym[KSYM_SYMBOL_LEN];
+
+		sprint_symbol(sym, (unsigned long)shr);
+		strlcpy(__entry->name, sym, SHRINKER_NAME_LEN);
+
 		__entry->shr = shr;
 		__entry->shrink = shr->scan_objects;
 		__entry->nid = sc->nid;
@@ -214,9 +222,10 @@ TRACE_EVENT(mm_shrink_slab_start,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
+	TP_printk("%pF %p(%s): nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
 		__entry->shrink,
 		__entry->shr,
+		__entry->name,
 		__entry->nid,
 		__entry->nr_objects_to_shrink,
 		show_gfp_flags(__entry->gfp_flags),
@@ -236,6 +245,7 @@ TRACE_EVENT(mm_shrink_slab_end,
 
 	TP_STRUCT__entry(
 		__field(struct shrinker *, shr)
+		__array(char, name, SHRINKER_NAME_LEN);
 		__field(int, nid)
 		__field(void *, shrink)
 		__field(long, unused_scan)
@@ -245,6 +255,11 @@ TRACE_EVENT(mm_shrink_slab_end,
 	),
 
 	TP_fast_assign(
+		char sym[KSYM_SYMBOL_LEN];
+
+		sprint_symbol(sym, (unsigned long)shr);
+		strlcpy(__entry->name, sym, SHRINKER_NAME_LEN);
+
 		__entry->shr = shr;
 		__entry->nid = nid;
 		__entry->shrink = shr->scan_objects;
@@ -254,9 +269,10 @@ TRACE_EVENT(mm_shrink_slab_end,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
+	TP_printk("%pF %p(%pF): nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
 		__entry->shrink,
 		__entry->shr,
+		__entry->shr,
 		__entry->nid,
 		__entry->unused_scan,
 		__entry->new_scan,

Re: [PATCH 1/3] Add a new field to struct shrinker

[Rik van Riel]

[-- Attachment #1: Type: text/plain, Size: 1989 bytes --]

On Fri, 2016-07-22 at 21:05 -0700, Tony Jones wrote:
> On 07/22/2016 06:27 PM, Tony Jones wrote:
> > On 07/20/2016 07:54 AM, Michal Hocko wrote:
> > 
> > > > Michal, just to make sure I understand you correctly, do you
> > > > mean that we
> > > > could infer the names of the shrinkers by looking at the names
> > > > of their callbacks?
> > > 
> > > Yes, %ps can then be used for the name of the shrinker structure
> > > (assuming it is available).
> > 
> > This is fine for emitting via the ftrace /sys interface,  but in
> > order to have the data [name] get 
> > marshalled thru to perf (for example) you need to add it to the
> > TP_fast_assign entry.
> > 
> > tony
> 
> Unfortunately, %ps/%pF doesn't do much (re:  Michal's comment
> "assuming it is available"):
> 
> -       TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s
> pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan
> %ld",
> +       TP_printk("%pF %p(%ps): nid: %d objects to shrink %ld
> gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld
> total_scan %ld",
>                 __entry->shrink,
>                 __entry->shr,
> +               __entry->shr,
>                 __entry->nid,
>                 __entry->nr_objects_to_shrink,
> 
> # cat trace_pipe
>             bash-1917  [003] ...1  2925.941062: mm_shrink_slab_start:
> super_cache_scan+0x0/0x1a0 ffff88042bb60cc0(0xffff88042bb60cc0): nid:
> 0 objects to shrink 0 gfp_flags GFP_KERNEL pgs_scanned 1000 lru_pgs
> 1000 cache items 4 delta 7 total_scan 7
> 
> 
> Otherwise what I was suggesting was something like this to ensure it
> was correctly marshaled for perf/etc:
> 
Janani,

it may make sense to have the code Tony posted be part of
your patch series. Just have both of your Signed-off-by:
lines on that patch.

-- 

All Rights Reversed.

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

Re: [PATCH 1/3] Add a new field to struct shrinker

[Tony Jones]

On 07/23/2016 12:43 PM, Rik van Riel wrote:

> Janani,

> it may make sense to have the code Tony posted be part of
> your patch series. Just have both of your Signed-off-by:
> lines on that patch.

Rik

Unfortunately the previous patch doesn't work on my system, which was the point I was trying to make. None of the shrinker symbols appear known so nothing usefully symbolic is displayed either with %ps 
or in the case of code I attached (calling sprint_symbol so it's visible to perf).   

Tony

Re: [PATCH 1/3] Add a new field to struct shrinker

[Tony Jones]

On 07/20/2016 07:54 AM, Michal Hocko wrote:
> On Wed 20-07-16 20:11:09, Janani Ravichandran wrote:
>>
>>> On Jul 11, 2016, at 8:03 PM, Michal Hocko <mhocko@kernel.org> wrote:
>>>
>>> On Mon 11-07-16 10:12:51, Rik van Riel wrote:
>>>>
>>>> What mechanism do you have in mind for obtaining the name,
>>>> Michal?
>>>
>>> Not sure whether tracing infrastructure allows printk like %ps. If not
>>> then it doesn't sound too hard to add.
>>
>> It does allow %ps. Currently what is being printed is the function symbol
>> of the callback using %pF. I’d like to know why %pF is used instead of
>> %ps in this case.
>
> From a quick look into the code %pF should be doing the same thing as
> %ps in the end. Some architectures just need some magic to get a proper
> address of the function.
>
>> Michal, just to make sure I understand you correctly, do you mean that we
>> could infer the names of the shrinkers by looking at the names of their callbacks?
>
> Yes, %ps can then be used for the name of the shrinker structure
> (assuming it is available).

The "shrinker structure" (struct shrinker) isn't a good candidate (as it's often embedded as thus no symbol name can be
resolved) but the callback seems to work fine in my testing.

I made an earlier suggestion to Janani that it was helpful to have the superblock shrinker name constructed to include
the fstype.   This level of specificity would be lost if just the callback is used.  I talked briefly to Michal and his view
is that more specific tracepoints can be added for this case.   This is certainly an option as the super_cache_scan callback
can access the superblock and thus the file_system_type via containing record.   It's just more work to later reconcile the
output of two tracepoints.

I talked briefly to Mel and we both think being able to have this level (of fstype) specificity would be useful and it would
be lost just using the callback.   Another option which would avoid the static overhead of the names would be to add a new
shrinker_name() callback.  If NULL,  the caller can just perform the default, in this case lookup the symbol for the callback,
if !NULL it would provide additional string information which the caller could use.   The per-sb shrinker could implement it
and return the fstype.   It's obviously still a +1 word growth of the struct shrinker but it avoids the text overhead of the
constructed names.

Opinions?

Tony

Re: [PATCH 1/3] Add a new field to struct shrinker

[Dave Chinner]

[line wrap text at 72 columns, please] 

On Tue, Jul 26, 2016 at 09:40:57AM -0700, Tony Jones wrote:
> On 07/20/2016 07:54 AM, Michal Hocko wrote:
> >On Wed 20-07-16 20:11:09, Janani Ravichandran wrote:
> >>>On Jul 11, 2016, at 8:03 PM, Michal Hocko <mhocko@kernel.org> wrote:
> >>>On Mon 11-07-16 10:12:51, Rik van Riel wrote:
> >>>>
> >>>>What mechanism do you have in mind for obtaining the name,
> >>>>Michal?
> >>>
> >>>Not sure whether tracing infrastructure allows printk like %ps.
> >>>If not then it doesn't sound too hard to add.
> >>
> >>It does allow %ps. Currently what is being printed is the
> >>function symbol of the callback using %pF. I’d like to know
> >>why %pF is used instead of %ps in this case.
> >
> >From a quick look into the code %pF should be doing the same
> >thing as %ps in the end. Some architectures just need some magic
> >to get a proper address of the function.
> >
> >>Michal, just to make sure I understand you correctly, do you
> >>mean that we could infer the names of the shrinkers by looking
> >>at the names of their callbacks?
> >
> >Yes, %ps can then be used for the name of the shrinker structure
> >(assuming it is available).
> 
> The "shrinker structure" (struct shrinker) isn't a good candidate
> (as it's often embedded as thus no symbol name can be resolved)
> but the callback seems to work fine in my testing.
> 
> I made an earlier suggestion to Janani that it was helpful to have
> the superblock shrinker name constructed to include the fstype.
> This level of specificity would be lost if just the callback is
> used.  I talked briefly to Michal and his view is that more
> specific tracepoints can be added for this case.   This is
> certainly an option as the super_cache_scan callback can access
> the superblock and thus the file_system_type via containing
> record.   It's just more work to later reconcile the output of two
> tracepoints.
> 
> I talked briefly to Mel and we both think being able to have this
> level (of fstype) specificity would be useful and it would be lost
> just using the callback.   Another option which would avoid the
> static overhead of the names would be to add a new shrinker_name()
> callback.  If NULL,  the caller can just perform the default, in
> this case lookup the symbol for the callback, if !NULL it would
> provide additional string information which the caller could use.
> The per-sb shrinker could implement it and return the fstype.
> It's obviously still a +1 word growth of the struct shrinker but
> it avoids the text overhead of the constructed names.
> 
> Opinions?

Seems you're all missing the obvious.

Add a tracepoint for a shrinker callback that includes a "name"
field, have the shrinker callback fill it out appropriately. e.g
in the superblock shrinker:


	trace_shrinker_callback(shrinker, shrink_control, sb->s_type->name);

And generic code that doesn't want to put a specific context name in
there can simply call:

	trace_shrinker_callback(shrinker, shrink_control, __func__);

And now you know exactly what shrinker is being run.

No need to add names to any structures, it's call site defined so is
flexible, and if you're not using tracepoints has no overhead.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH 1/3] Add a new field to struct shrinker

[Mel Gorman]

On Thu, Jul 28, 2016 at 03:49:47PM +1000, Dave Chinner wrote:
> Seems you're all missing the obvious.
> 
> Add a tracepoint for a shrinker callback that includes a "name"
> field, have the shrinker callback fill it out appropriately. e.g
> in the superblock shrinker:
> 
> 	trace_shrinker_callback(shrinker, shrink_control, sb->s_type->name);
> 

That misses capturing the latency of the call unless there is a begin/end
tracepoint. I was aware of the function graph tracer but I don't know how
to convince that to give the following information;

1. The length of time spent in a given function
2. The tracepoint information that might explain why the stall occurred

Take the compaction tracepoint for example

        trace_mm_compaction_begin(start_pfn, cc->migrate_pfn,
                                cc->free_pfn, end_pfn, sync);

	...

	trace_mm_compaction_end(start_pfn, cc->migrate_pfn,
                                cc->free_pfn, end_pfn, sync, ret);

The function graph tracer can say that X time is compact_zone() but it
cannot distinguish between a short time spent in that function because
compaction_suitable == false or compaction simply finished quickly.  While
the cc struct parameters could be extracted, end_pfn is much harder to figure
out because a user would have to parse zoneinfo to figure it out and even
*that* would only work if there are no overlapping nodes. Extracting sync
would require making assumptions about the implementation of compact_zone()
that could change.

> And now you know exactly what shrinker is being run.
> 

Sure and it's a good suggestion but does not say how long the shrinker
was running.

My understanding was the point of the tracepoints was to get detailed
information on points where the kernel is known to stall for long periods
of time. I don't actually know how to convince the function graph tracer
to get that type of information. Maybe it's possible and I just haven't
tried recently enough.

It potentially duration could be inferred from using a return probe on
the function but that requires that the function the tracepoint is running
is is known by the tool, has not been inlined and that there are no retry
loops that hit the begin tracepoint.

-- 
Mel Gorman
SUSE Labs

Re: [PATCH 1/3] Add a new field to struct shrinker

[Dave Chinner]

On Thu, Jul 28, 2016 at 11:25:13AM +0100, Mel Gorman wrote:
> On Thu, Jul 28, 2016 at 03:49:47PM +1000, Dave Chinner wrote:
> > Seems you're all missing the obvious.
> > 
> > Add a tracepoint for a shrinker callback that includes a "name"
> > field, have the shrinker callback fill it out appropriately. e.g
> > in the superblock shrinker:
> > 
> > 	trace_shrinker_callback(shrinker, shrink_control, sb->s_type->name);
> > 
> 
> That misses capturing the latency of the call unless there is a begin/end
> tracepoint.

Sure, but I didn't see that in the email talking about how to add a
name. Even if it is a requirement, it's not necessary as we've
already got shrinker runtime measurements from the
trace_mm_shrink_slab_start and trace_mm_shrink_slab_end trace
points. With the above callback event, shrinker call runtime is
simply the time between the calls to the same shrinker within
mm_shrink_slab start/end trace points.

We don't need tracepoint to measure everything - we just need enough
tracepoints that we can calculate everything we need by post
processing the trace report, and the above gives you shrinker
runtime latency. You need to look at the tracepoints in the wider
context of the code that is running, not just the individual
tracepoint itself.

IOWs, function runtime is obvious from the pattern of related tracepoints
and their timestamps.  Timing information is in the event traces, so
duration between two known tracepoints is a simple calculation.

	[0.0023]	mm_shrink_slab_start:	shrinker 0xblah ....
	[0.0025]	shrinker_callback:	shrinker 0xblah name xfs
	.....		[xfs events ignored]
	[0.0043]	shrinker_callback:	shrinker 0xblah name xfs
	.....		[xfs events ignored]
	[0.0176]	shrinker_callback:	shrinker 0xblah name xfs
	.....		[xfs events ignored]
	[0.0178]	mm_shrink_slab_end:	shrinker 0xblah .....


Now run awk to grab the '/shrinker 0xblah/ { .... } ' - That
information contains everything you need to calculate shrinker
runtime. i.e.  It ran 3 times, taking 1.8ms, 13ms and 0.2ms on each
of the calls.

That's exactly how I work out timings of various operations in XFS.
e.g. how long a specific metadata IO has taken, how long IO
completion has been queued on the endio workqueue before it got
processed, how long a process waited on a buffer lock, etc. Pick
your specific tracepoints from the haystack, post process with
grep/awk/sed/python to find the needle.

If you need more specific information than a tracepoint can give
you, then you can either add more tracepoints or craft a custom
tracer function to drill deeper.  Almost no-one will need anything
more than knowing what shrinker is running, as most shrinkers are
quite simple. Those that are more complex have their own internal
tracepoints that will tell you exactly where and why it is stalling
without the need for custom tracers....

> I was aware of the function graph tracer but I don't know how
> to convince that to give the following information;
>
> 1. The length of time spent in a given function
> 2. The tracepoint information that might explain why the stall occurred
> 
> Take the compaction tracepoint for example
> 
>         trace_mm_compaction_begin(start_pfn, cc->migrate_pfn,
>                                 cc->free_pfn, end_pfn, sync);
> 
> 	...
> 
> 	trace_mm_compaction_end(start_pfn, cc->migrate_pfn,
>                                 cc->free_pfn, end_pfn, sync, ret);
> 
> The function graph tracer can say that X time is compact_zone() but it
> cannot distinguish between a short time spent in that function because
> compaction_suitable == false or compaction simply finished quickly.

That information (i.e. value of compaction_suitable) should be in
the trace_mm_compaction_end() tracepoint, then. If you need context
information to make sense of the tracepoint then it should be in the
tracepoint.

> My understanding was the point of the tracepoints was to get detailed
> information on points where the kernel is known to stall for long periods
> of time.

First I've heard that's what tracepoints are supposed to be used
for. They are just debugging information points in the code and can
be used for any purpose you need as a developer....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH 1/3] Add a new field to struct shrinker

[Mel Gorman]

On Fri, Jul 29, 2016 at 10:13:40AM +1000, Dave Chinner wrote:
> On Thu, Jul 28, 2016 at 11:25:13AM +0100, Mel Gorman wrote:
> > On Thu, Jul 28, 2016 at 03:49:47PM +1000, Dave Chinner wrote:
> > > Seems you're all missing the obvious.
> > > 
> > > Add a tracepoint for a shrinker callback that includes a "name"
> > > field, have the shrinker callback fill it out appropriately. e.g
> > > in the superblock shrinker:
> > > 
> > > 	trace_shrinker_callback(shrinker, shrink_control, sb->s_type->name);
> > > 
> > 
> > That misses capturing the latency of the call unless there is a begin/end
> > tracepoint.
> 
> Sure, but I didn't see that in the email talking about how to add a
> name. Even if it is a requirement, it's not necessary as we've
> already got shrinker runtime measurements from the
> trace_mm_shrink_slab_start and trace_mm_shrink_slab_end trace
> points. With the above callback event, shrinker call runtime is
> simply the time between the calls to the same shrinker within
> mm_shrink_slab start/end trace points.
> 

Fair point. It's not that hard to correlate them.

> <SNIP>
> 
> > My understanding was the point of the tracepoints was to get detailed
> > information on points where the kernel is known to stall for long periods
> > of time.
> 
> First I've heard that's what tracepoints are supposed to be used
> for.

I meant the specific case of trace_X_begin followed by trace_X_end, not
tracepoints in general.

-- 
Mel Gorman
SUSE Labs

Re: [PATCH 1/3] Add a new field to struct shrinker

[Tony Jones]

On 07/29/2016 06:00 AM, Mel Gorman wrote:
> On Fri, Jul 29, 2016 at 10:13:40AM +1000, Dave Chinner wrote:
>> On Thu, Jul 28, 2016 at 11:25:13AM +0100, Mel Gorman wrote:
>>> On Thu, Jul 28, 2016 at 03:49:47PM +1000, Dave Chinner wrote:
>>>> Seems you're all missing the obvious.
>>>>
>>>> Add a tracepoint for a shrinker callback that includes a "name"
>>>> field, have the shrinker callback fill it out appropriately. e.g
>>>> in the superblock shrinker:
>>>>
>>>> 	trace_shrinker_callback(shrinker, shrink_control, sb->s_type->name);
>>>>
>>>
>>> That misses capturing the latency of the call unless there is a begin/end
>>> tracepoint.
>>
>> Sure, but I didn't see that in the email talking about how to add a
>> name. Even if it is a requirement, it's not necessary as we've
>> already got shrinker runtime measurements from the
>> trace_mm_shrink_slab_start and trace_mm_shrink_slab_end trace
>> points. With the above callback event, shrinker call runtime is
>> simply the time between the calls to the same shrinker within
>> mm_shrink_slab start/end trace points.
>>
> 
> Fair point. It's not that hard to correlate them.

True but the scan_objects callback is only called if we have >batch_size objects.

It's possible to accumulate quite some time without calling the callback and being able to obtain 
the s_type->name.   So this time all gets associated with just super_cache_scan.

[PATCH 2/3] Update name field for all shrinker instances

[Janani Ravichandran]

This patch makes changes to have all instances of struct shrinker update
the newly added name field. This name could then be passed to
tracepoints, which can help identify which shrinker was invoked.

---
 arch/x86/kvm/mmu.c                                 | 1 +
 drivers/gpu/drm/i915/i915_gem_shrinker.c           | 1 +
 drivers/gpu/drm/ttm/ttm_page_alloc.c               | 1 +
 drivers/gpu/drm/ttm/ttm_page_alloc_dma.c           | 1 +
 drivers/md/bcache/btree.c                          | 1 +
 drivers/md/dm-bufio.c                              | 1 +
 drivers/md/raid5.c                                 | 1 +
 drivers/staging/android/ashmem.c                   | 1 +
 drivers/staging/android/ion/ion_heap.c             | 1 +
 drivers/staging/android/lowmemorykiller.c          | 1 +
 drivers/staging/lustre/lustre/ldlm/ldlm_pool.c     | 1 +
 drivers/staging/lustre/lustre/obdclass/lu_object.c | 1 +
 drivers/staging/lustre/lustre/ptlrpc/sec_bulk.c    | 1 +
 fs/ext4/extents_status.c                           | 1 +
 fs/f2fs/super.c                                    | 1 +
 fs/gfs2/glock.c                                    | 1 +
 fs/gfs2/quota.c                                    | 1 +
 fs/mbcache.c                                       | 1 +
 fs/nfs/super.c                                     | 1 +
 fs/nfsd/nfscache.c                                 | 1 +
 fs/quota/dquot.c                                   | 1 +
 fs/super.c                                         | 1 +
 fs/ubifs/super.c                                   | 1 +
 fs/xfs/xfs_buf.c                                   | 1 +
 fs/xfs/xfs_qm.c                                    | 1 +
 mm/huge_memory.c                                   | 2 ++
 mm/workingset.c                                    | 1 +
 mm/zsmalloc.c                                      | 1 +
 net/sunrpc/auth.c                                  | 1 +
 29 files changed, 30 insertions(+)

diff --git a/arch/x86/kvm/mmu.c b/arch/x86/kvm/mmu.c
index def97b3..566b800 100644
--- a/arch/x86/kvm/mmu.c
+++ b/arch/x86/kvm/mmu.c
@@ -5025,6 +5025,7 @@ mmu_shrink_count(struct shrinker *shrink, struct shrink_control *sc)
 }
 
 static struct shrinker mmu_shrinker = {
+	.name = "mmu_shrinker",
 	.count_objects = mmu_shrink_count,
 	.scan_objects = mmu_shrink_scan,
 	.seeks = DEFAULT_SEEKS * 10,
diff --git a/drivers/gpu/drm/i915/i915_gem_shrinker.c b/drivers/gpu/drm/i915/i915_gem_shrinker.c
index 425e721..bb1953d 100644
--- a/drivers/gpu/drm/i915/i915_gem_shrinker.c
+++ b/drivers/gpu/drm/i915/i915_gem_shrinker.c
@@ -411,6 +411,7 @@ i915_gem_shrinker_vmap(struct notifier_block *nb, unsigned long event, void *ptr
  */
 void i915_gem_shrinker_init(struct drm_i915_private *dev_priv)
 {
+	dev_priv->mm.shrinker.name = "i915_gem_shrinker";
 	dev_priv->mm.shrinker.scan_objects = i915_gem_shrinker_scan;
 	dev_priv->mm.shrinker.count_objects = i915_gem_shrinker_count;
 	dev_priv->mm.shrinker.seeks = DEFAULT_SEEKS;
diff --git a/drivers/gpu/drm/ttm/ttm_page_alloc.c b/drivers/gpu/drm/ttm/ttm_page_alloc.c
index a37de5d..112a0c2 100644
--- a/drivers/gpu/drm/ttm/ttm_page_alloc.c
+++ b/drivers/gpu/drm/ttm/ttm_page_alloc.c
@@ -434,6 +434,7 @@ ttm_pool_shrink_count(struct shrinker *shrink, struct shrink_control *sc)
 
 static void ttm_pool_mm_shrink_init(struct ttm_pool_manager *manager)
 {
+	manager->mm_shrink.name = "ttm_pool_shrinker";
 	manager->mm_shrink.count_objects = ttm_pool_shrink_count;
 	manager->mm_shrink.scan_objects = ttm_pool_shrink_scan;
 	manager->mm_shrink.seeks = 1;
diff --git a/drivers/gpu/drm/ttm/ttm_page_alloc_dma.c b/drivers/gpu/drm/ttm/ttm_page_alloc_dma.c
index bef9f6f..4abd37c 100644
--- a/drivers/gpu/drm/ttm/ttm_page_alloc_dma.c
+++ b/drivers/gpu/drm/ttm/ttm_page_alloc_dma.c
@@ -1066,6 +1066,7 @@ ttm_dma_pool_shrink_count(struct shrinker *shrink, struct shrink_control *sc)
 
 static void ttm_dma_pool_mm_shrink_init(struct ttm_pool_manager *manager)
 {
+	manager->mm_shrink.name = "ttm_dma_pool_shrinker";
 	manager->mm_shrink.count_objects = ttm_dma_pool_shrink_count;
 	manager->mm_shrink.scan_objects = &ttm_dma_pool_shrink_scan;
 	manager->mm_shrink.seeks = 1;
diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
index eab505e..3f89272 100644
--- a/drivers/md/bcache/btree.c
+++ b/drivers/md/bcache/btree.c
@@ -803,6 +803,7 @@ int bch_btree_cache_alloc(struct cache_set *c)
 		c->verify_data = NULL;
 #endif
 
+	c->shrink.name = "bch_btree_shrinker";
 	c->shrink.count_objects = bch_mca_count;
 	c->shrink.scan_objects = bch_mca_scan;
 	c->shrink.seeks = 4;
diff --git a/drivers/md/dm-bufio.c b/drivers/md/dm-bufio.c
index cd77216..ff03854 100644
--- a/drivers/md/dm-bufio.c
+++ b/drivers/md/dm-bufio.c
@@ -1705,6 +1705,7 @@ struct dm_bufio_client *dm_bufio_client_create(struct block_device *bdev, unsign
 	__cache_size_refresh();
 	mutex_unlock(&dm_bufio_clients_lock);
 
+	c->shrinker.name = "dm_bufio_shrinker";
 	c->shrinker.count_objects = dm_bufio_shrink_count;
 	c->shrinker.scan_objects = dm_bufio_shrink_scan;
 	c->shrinker.seeks = 1;
diff --git a/drivers/md/raid5.c b/drivers/md/raid5.c
index 8959e6d..f0e04c2 100644
--- a/drivers/md/raid5.c
+++ b/drivers/md/raid5.c
@@ -6632,6 +6632,7 @@ static struct r5conf *setup_conf(struct mddev *mddev)
 	 * it reduces the queue depth and so can hurt throughput.
 	 * So set it rather large, scaled by number of devices.
 	 */
+	conf->shrinker.name = "raid5_shrinker";
 	conf->shrinker.seeks = DEFAULT_SEEKS * conf->raid_disks * 4;
 	conf->shrinker.scan_objects = raid5_cache_scan;
 	conf->shrinker.count_objects = raid5_cache_count;
diff --git a/drivers/staging/android/ashmem.c b/drivers/staging/android/ashmem.c
index ca9a53c..19dfeb9 100644
--- a/drivers/staging/android/ashmem.c
+++ b/drivers/staging/android/ashmem.c
@@ -487,6 +487,7 @@ ashmem_shrink_count(struct shrinker *shrink, struct shrink_control *sc)
 }
 
 static struct shrinker ashmem_shrinker = {
+	.name = "ashmem_shrinker",
 	.count_objects = ashmem_shrink_count,
 	.scan_objects = ashmem_shrink_scan,
 	/*
diff --git a/drivers/staging/android/ion/ion_heap.c b/drivers/staging/android/ion/ion_heap.c
index ca15a87..85f4110 100644
--- a/drivers/staging/android/ion/ion_heap.c
+++ b/drivers/staging/android/ion/ion_heap.c
@@ -308,6 +308,7 @@ static unsigned long ion_heap_shrink_scan(struct shrinker *shrinker,
 
 void ion_heap_init_shrinker(struct ion_heap *heap)
 {
+	heap->shrinker.name = "ion_heap_shrinker";
 	heap->shrinker.count_objects = ion_heap_shrink_count;
 	heap->shrinker.scan_objects = ion_heap_shrink_scan;
 	heap->shrinker.seeks = DEFAULT_SEEKS;
diff --git a/drivers/staging/android/lowmemorykiller.c b/drivers/staging/android/lowmemorykiller.c
index 24d2745..9c58ed4 100644
--- a/drivers/staging/android/lowmemorykiller.c
+++ b/drivers/staging/android/lowmemorykiller.c
@@ -188,6 +188,7 @@ static unsigned long lowmem_scan(struct shrinker *s, struct shrink_control *sc)
 }
 
 static struct shrinker lowmem_shrinker = {
+	.name = "lowmem_shrinker",
 	.scan_objects = lowmem_scan,
 	.count_objects = lowmem_count,
 	.seeks = DEFAULT_SEEKS * 16
diff --git a/drivers/staging/lustre/lustre/ldlm/ldlm_pool.c b/drivers/staging/lustre/lustre/ldlm/ldlm_pool.c
index b913ba9..89876c7 100644
--- a/drivers/staging/lustre/lustre/ldlm/ldlm_pool.c
+++ b/drivers/staging/lustre/lustre/ldlm/ldlm_pool.c
@@ -1081,6 +1081,7 @@ static void ldlm_pools_thread_stop(void)
 }
 
 static struct shrinker ldlm_pools_cli_shrinker = {
+	.name		= "ldlm_pools_cli_shrinker",
 	.count_objects	= ldlm_pools_cli_count,
 	.scan_objects	= ldlm_pools_cli_scan,
 	.seeks		= DEFAULT_SEEKS,
diff --git a/drivers/staging/lustre/lustre/obdclass/lu_object.c b/drivers/staging/lustre/lustre/obdclass/lu_object.c
index e043857..8f998a5 100644
--- a/drivers/staging/lustre/lustre/obdclass/lu_object.c
+++ b/drivers/staging/lustre/lustre/obdclass/lu_object.c
@@ -1803,6 +1803,7 @@ static unsigned long lu_cache_shrink_scan(struct shrinker *sk,
  * Debugging printer function using printk().
  */
 static struct shrinker lu_site_shrinker = {
+	.name		= "lu_site_shrinker",
 	.count_objects	= lu_cache_shrink_count,
 	.scan_objects	= lu_cache_shrink_scan,
 	.seeks 		= DEFAULT_SEEKS,
diff --git a/drivers/staging/lustre/lustre/ptlrpc/sec_bulk.c b/drivers/staging/lustre/lustre/ptlrpc/sec_bulk.c
index 02e6cda..c288b52 100644
--- a/drivers/staging/lustre/lustre/ptlrpc/sec_bulk.c
+++ b/drivers/staging/lustre/lustre/ptlrpc/sec_bulk.c
@@ -372,6 +372,7 @@ static inline void enc_pools_free(void)
 }
 
 static struct shrinker pools_shrinker = {
+	.name		= "ptlrpc_pools_shrinker",
 	.count_objects	= enc_pools_shrink_count,
 	.scan_objects	= enc_pools_shrink_scan,
 	.seeks		= DEFAULT_SEEKS,
diff --git a/fs/ext4/extents_status.c b/fs/ext4/extents_status.c
index 37e0592..a6534c6 100644
--- a/fs/ext4/extents_status.c
+++ b/fs/ext4/extents_status.c
@@ -1153,6 +1153,7 @@ int ext4_es_register_shrinker(struct ext4_sb_info *sbi)
 	if (err)
 		goto err1;
 
+	sbi->s_es_shrinker.name = "ext4_es_shrinker";
 	sbi->s_es_shrinker.scan_objects = ext4_es_scan;
 	sbi->s_es_shrinker.count_objects = ext4_es_count;
 	sbi->s_es_shrinker.seeks = DEFAULT_SEEKS;
diff --git a/fs/f2fs/super.c b/fs/f2fs/super.c
index 74cc852..9d0aac3 100644
--- a/fs/f2fs/super.c
+++ b/fs/f2fs/super.c
@@ -65,6 +65,7 @@ static void f2fs_build_fault_attr(unsigned int rate)
 
 /* f2fs-wide shrinker description */
 static struct shrinker f2fs_shrinker_info = {
+	.name = "f2fs_shrinker",
 	.scan_objects = f2fs_shrink_scan,
 	.count_objects = f2fs_shrink_count,
 	.seeks = DEFAULT_SEEKS,
diff --git a/fs/gfs2/glock.c b/fs/gfs2/glock.c
index 706fd93..5b3b7d6 100644
--- a/fs/gfs2/glock.c
+++ b/fs/gfs2/glock.c
@@ -1416,6 +1416,7 @@ static unsigned long gfs2_glock_shrink_count(struct shrinker *shrink,
 }
 
 static struct shrinker glock_shrinker = {
+	.name = "glock_shrinker",
 	.seeks = DEFAULT_SEEKS,
 	.count_objects = gfs2_glock_shrink_count,
 	.scan_objects = gfs2_glock_shrink_scan,
diff --git a/fs/gfs2/quota.c b/fs/gfs2/quota.c
index ce7d69a..2d13873 100644
--- a/fs/gfs2/quota.c
+++ b/fs/gfs2/quota.c
@@ -187,6 +187,7 @@ static unsigned long gfs2_qd_shrink_count(struct shrinker *shrink,
 }
 
 struct shrinker gfs2_qd_shrinker = {
+	.name = "gfs2_qd_shrinker",
 	.count_objects = gfs2_qd_shrink_count,
 	.scan_objects = gfs2_qd_shrink_scan,
 	.seeks = DEFAULT_SEEKS,
diff --git a/fs/mbcache.c b/fs/mbcache.c
index eccda3a..c58d727 100644
--- a/fs/mbcache.c
+++ b/fs/mbcache.c
@@ -363,6 +363,7 @@ struct mb_cache *mb_cache_create(int bucket_bits)
 	for (i = 0; i < bucket_count; i++)
 		INIT_HLIST_BL_HEAD(&cache->c_hash[i]);
 
+	cache->c_shrink.name = "mb_cache_shrinker";
 	cache->c_shrink.count_objects = mb_cache_count;
 	cache->c_shrink.scan_objects = mb_cache_scan;
 	cache->c_shrink.seeks = DEFAULT_SEEKS;
diff --git a/fs/nfs/super.c b/fs/nfs/super.c
index 2137e02..041873f 100644
--- a/fs/nfs/super.c
+++ b/fs/nfs/super.c
@@ -360,6 +360,7 @@ static void unregister_nfs4_fs(void)
 #endif
 
 static struct shrinker acl_shrinker = {
+	.name		= "nfs_shrinker",
 	.count_objects	= nfs_access_cache_count,
 	.scan_objects	= nfs_access_cache_scan,
 	.seeks		= DEFAULT_SEEKS,
diff --git a/fs/nfsd/nfscache.c b/fs/nfsd/nfscache.c
index 54cde9a..40d331e 100644
--- a/fs/nfsd/nfscache.c
+++ b/fs/nfsd/nfscache.c
@@ -69,6 +69,7 @@ static unsigned long nfsd_reply_cache_scan(struct shrinker *shrink,
 					   struct shrink_control *sc);
 
 static struct shrinker nfsd_reply_cache_shrinker = {
+	.name = "nfsd_reply_cache_shrinker",
 	.scan_objects = nfsd_reply_cache_scan,
 	.count_objects = nfsd_reply_cache_count,
 	.seeks	= 1,
diff --git a/fs/quota/dquot.c b/fs/quota/dquot.c
index ff21980..ca57560 100644
--- a/fs/quota/dquot.c
+++ b/fs/quota/dquot.c
@@ -730,6 +730,7 @@ dqcache_shrink_count(struct shrinker *shrink, struct shrink_control *sc)
 }
 
 static struct shrinker dqcache_shrinker = {
+	.name = "dqcache_shrinker",
 	.count_objects = dqcache_shrink_count,
 	.scan_objects = dqcache_shrink_scan,
 	.seeks = DEFAULT_SEEKS,
diff --git a/fs/super.c b/fs/super.c
index d78b984..051073c 100644
--- a/fs/super.c
+++ b/fs/super.c
@@ -241,6 +241,7 @@ static struct super_block *alloc_super(struct file_system_type *type, int flags)
 	s->s_time_gran = 1000000000;
 	s->cleancache_poolid = CLEANCACHE_NO_POOL;
 
+	s->s_shrink.name = "super_cache_shrinker";
 	s->s_shrink.seeks = DEFAULT_SEEKS;
 	s->s_shrink.scan_objects = super_cache_scan;
 	s->s_shrink.count_objects = super_cache_count;
diff --git a/fs/ubifs/super.c b/fs/ubifs/super.c
index 7034995..7fd4ac3 100644
--- a/fs/ubifs/super.c
+++ b/fs/ubifs/super.c
@@ -49,6 +49,7 @@ struct kmem_cache *ubifs_inode_slab;
 
 /* UBIFS TNC shrinker description */
 static struct shrinker ubifs_shrinker_info = {
+	.name = "ubifs_shrinker",
 	.scan_objects = ubifs_shrink_scan,
 	.count_objects = ubifs_shrink_count,
 	.seeks = DEFAULT_SEEKS,
diff --git a/fs/xfs/xfs_buf.c b/fs/xfs/xfs_buf.c
index e71cfbd..0fff60e 100644
--- a/fs/xfs/xfs_buf.c
+++ b/fs/xfs/xfs_buf.c
@@ -1691,6 +1691,7 @@ xfs_alloc_buftarg(
 	if (list_lru_init(&btp->bt_lru))
 		goto error;
 
+	btp->bt_shrinker.name = "xfs_buftarg_shrinker";
 	btp->bt_shrinker.count_objects = xfs_buftarg_shrink_count;
 	btp->bt_shrinker.scan_objects = xfs_buftarg_shrink_scan;
 	btp->bt_shrinker.seeks = DEFAULT_SEEKS;
diff --git a/fs/xfs/xfs_qm.c b/fs/xfs/xfs_qm.c
index a60d9e2..3c08c3b 100644
--- a/fs/xfs/xfs_qm.c
+++ b/fs/xfs/xfs_qm.c
@@ -687,6 +687,7 @@ xfs_qm_init_quotainfo(
 	if (XFS_IS_PQUOTA_RUNNING(mp))
 		xfs_qm_set_defquota(mp, XFS_DQ_PROJ, qinf);
 
+	qinf->qi_shrinker.name = "xfs_qm_shrinker";
 	qinf->qi_shrinker.count_objects = xfs_qm_shrink_count;
 	qinf->qi_shrinker.scan_objects = xfs_qm_shrink_scan;
 	qinf->qi_shrinker.seeks = DEFAULT_SEEKS;
diff --git a/mm/huge_memory.c b/mm/huge_memory.c
index 9ed5853..2c84d06 100644
--- a/mm/huge_memory.c
+++ b/mm/huge_memory.c
@@ -263,6 +263,7 @@ static unsigned long shrink_huge_zero_page_scan(struct shrinker *shrink,
 }
 
 static struct shrinker huge_zero_page_shrinker = {
+	.name = "huge_zero_page_shrinker",
 	.count_objects = shrink_huge_zero_page_count,
 	.scan_objects = shrink_huge_zero_page_scan,
 	.seeks = DEFAULT_SEEKS,
@@ -3471,6 +3472,7 @@ static unsigned long deferred_split_scan(struct shrinker *shrink,
 }
 
 static struct shrinker deferred_split_shrinker = {
+	.name = "deferred_split_shrinker",
 	.count_objects = deferred_split_count,
 	.scan_objects = deferred_split_scan,
 	.seeks = DEFAULT_SEEKS,
diff --git a/mm/workingset.c b/mm/workingset.c
index 8a75f8d..d180503 100644
--- a/mm/workingset.c
+++ b/mm/workingset.c
@@ -461,6 +461,7 @@ static unsigned long scan_shadow_nodes(struct shrinker *shrinker,
 }
 
 static struct shrinker workingset_shadow_shrinker = {
+	.name = "workingset_shadow_shrinker",
 	.count_objects = count_shadow_nodes,
 	.scan_objects = scan_shadow_nodes,
 	.seeks = DEFAULT_SEEKS,
diff --git a/mm/zsmalloc.c b/mm/zsmalloc.c
index b6d4f25..bba84e1 100644
--- a/mm/zsmalloc.c
+++ b/mm/zsmalloc.c
@@ -1864,6 +1864,7 @@ static void zs_unregister_shrinker(struct zs_pool *pool)
 
 static int zs_register_shrinker(struct zs_pool *pool)
 {
+	pool->shrinker.name = "zs_shrinker";
 	pool->shrinker.scan_objects = zs_shrinker_scan;
 	pool->shrinker.count_objects = zs_shrinker_count;
 	pool->shrinker.batch = 0;
diff --git a/net/sunrpc/auth.c b/net/sunrpc/auth.c
index 040ff62..3411778 100644
--- a/net/sunrpc/auth.c
+++ b/net/sunrpc/auth.c
@@ -861,6 +861,7 @@ rpcauth_uptodatecred(struct rpc_task *task)
 }
 
 static struct shrinker rpc_cred_shrinker = {
+	.name = "rpc_cred_shrinker",
 	.count_objects = rpcauth_cache_shrink_count,
 	.scan_objects = rpcauth_cache_shrink_scan,
 	.seeks = DEFAULT_SEEKS,
-- 
2.7.0

Re: [PATCH 2/3] Update name field for all shrinker instances

[Tony Jones]

On 07/09/2016 01:52 AM, Janani Ravichandran wrote:

> diff --git a/fs/super.c b/fs/super.c
> index d78b984..051073c 100644
> --- a/fs/super.c
> +++ b/fs/super.c
> @@ -241,6 +241,7 @@ static struct super_block *alloc_super(struct file_system_type *type, int flags)
>  	s->s_time_gran = 1000000000;
>  	s->cleancache_poolid = CLEANCACHE_NO_POOL;
>  
> +	s->s_shrink.name = "super_cache_shrinker";

my patchset made this a little more granular wrt superblock types by including type->name

[PATCH 3/3] Add name fields in shrinker tracepoint definitions

[Janani Ravichandran]

Currently, the mm_shrink_slab_start and mm_shrink_slab_end
tracepoints tell us how much time was spent in a shrinker, the number of
objects scanned, etc. But there is no information about the identity of
the shrinker. This patch enables the trace output to display names of
shrinkers.

---
 include/trace/events/vmscan.h | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
index 0101ef3..be4c5b0 100644
--- a/include/trace/events/vmscan.h
+++ b/include/trace/events/vmscan.h
@@ -189,6 +189,7 @@ TRACE_EVENT(mm_shrink_slab_start,
 		cache_items, delta, total_scan),
 
 	TP_STRUCT__entry(
+		__field(char *, name)
 		__field(struct shrinker *, shr)
 		__field(void *, shrink)
 		__field(int, nid)
@@ -202,6 +203,7 @@ TRACE_EVENT(mm_shrink_slab_start,
 	),
 
 	TP_fast_assign(
+		__entry->name = shr->name;
 		__entry->shr = shr;
 		__entry->shrink = shr->scan_objects;
 		__entry->nid = sc->nid;
@@ -214,7 +216,8 @@ TRACE_EVENT(mm_shrink_slab_start,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
+	TP_printk("name: %s %pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
+		__entry->name,
 		__entry->shrink,
 		__entry->shr,
 		__entry->nid,
@@ -235,6 +238,7 @@ TRACE_EVENT(mm_shrink_slab_end,
 		total_scan),
 
 	TP_STRUCT__entry(
+		__field(char *, name)
 		__field(struct shrinker *, shr)
 		__field(int, nid)
 		__field(void *, shrink)
@@ -245,6 +249,7 @@ TRACE_EVENT(mm_shrink_slab_end,
 	),
 
 	TP_fast_assign(
+		__entry->name = shr->name;
 		__entry->shr = shr;
 		__entry->nid = nid;
 		__entry->shrink = shr->scan_objects;
@@ -254,7 +259,8 @@ TRACE_EVENT(mm_shrink_slab_end,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
+	TP_printk("name: %s %pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
+		__entry->name,
 		__entry->shrink,
 		__entry->shr,
 		__entry->nid,
-- 
2.7.0

Re: [PATCH 3/3] Add name fields in shrinker tracepoint definitions

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 11412 bytes --]

Hi,

[auto build test WARNING on staging/staging-testing]
[also build test WARNING on v4.7-rc6 next-20160708]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Janani-Ravichandran/Add-names-of-shrinkers-and-have-tracepoints-display-them/20160709-170759
config: i386-defconfig (attached as .config)
compiler: gcc-6 (Debian 6.1.1-1) 6.1.1 20160430
reproduce:
        # save the attached .config to linux build tree
        make ARCH=i386 

All warnings (new ones prefixed by >>):

   In file included from include/trace/define_trace.h:95:0,
                    from include/trace/events/vmscan.h:395,
                    from mm/vmscan.c:60:
   include/trace/events/vmscan.h: In function 'trace_event_raw_event_mm_shrink_slab_start':
>> include/trace/events/vmscan.h:206:17: warning: assignment discards 'const' qualifier from pointer target type [-Wdiscarded-qualifiers]
      __entry->name = shr->name;
                    ^
   include/trace/trace_events.h:686:4: note: in definition of macro 'DECLARE_EVENT_CLASS'
     { assign; }       \
       ^~~~~~
   include/trace/trace_events.h:64:9: note: in expansion of macro 'PARAMS'
            PARAMS(assign),         \
            ^~~~~~
>> include/trace/events/vmscan.h:182:1: note: in expansion of macro 'TRACE_EVENT'
    TRACE_EVENT(mm_shrink_slab_start,
    ^~~~~~~~~~~
>> include/trace/events/vmscan.h:205:2: note: in expansion of macro 'TP_fast_assign'
     TP_fast_assign(
     ^~~~~~~~~~~~~~
   include/trace/events/vmscan.h: In function 'trace_event_raw_event_mm_shrink_slab_end':
   include/trace/events/vmscan.h:252:17: warning: assignment discards 'const' qualifier from pointer target type [-Wdiscarded-qualifiers]
      __entry->name = shr->name;
                    ^
   include/trace/trace_events.h:686:4: note: in definition of macro 'DECLARE_EVENT_CLASS'
     { assign; }       \
       ^~~~~~
   include/trace/trace_events.h:64:9: note: in expansion of macro 'PARAMS'
            PARAMS(assign),         \
            ^~~~~~
   include/trace/events/vmscan.h:233:1: note: in expansion of macro 'TRACE_EVENT'
    TRACE_EVENT(mm_shrink_slab_end,
    ^~~~~~~~~~~
   include/trace/events/vmscan.h:251:2: note: in expansion of macro 'TP_fast_assign'
     TP_fast_assign(
     ^~~~~~~~~~~~~~
   In file included from include/trace/define_trace.h:96:0,
                    from include/trace/events/vmscan.h:395,
                    from mm/vmscan.c:60:
   include/trace/events/vmscan.h: In function 'perf_trace_mm_shrink_slab_start':
>> include/trace/events/vmscan.h:206:17: warning: assignment discards 'const' qualifier from pointer target type [-Wdiscarded-qualifiers]
      __entry->name = shr->name;
                    ^
   include/trace/perf.h:65:4: note: in definition of macro 'DECLARE_EVENT_CLASS'
     { assign; }       \
       ^~~~~~
   include/trace/trace_events.h:64:9: note: in expansion of macro 'PARAMS'
            PARAMS(assign),         \
            ^~~~~~
>> include/trace/events/vmscan.h:182:1: note: in expansion of macro 'TRACE_EVENT'
    TRACE_EVENT(mm_shrink_slab_start,
    ^~~~~~~~~~~
>> include/trace/events/vmscan.h:205:2: note: in expansion of macro 'TP_fast_assign'
     TP_fast_assign(
     ^~~~~~~~~~~~~~
   include/trace/events/vmscan.h: In function 'perf_trace_mm_shrink_slab_end':
   include/trace/events/vmscan.h:252:17: warning: assignment discards 'const' qualifier from pointer target type [-Wdiscarded-qualifiers]
      __entry->name = shr->name;
                    ^
   include/trace/perf.h:65:4: note: in definition of macro 'DECLARE_EVENT_CLASS'
     { assign; }       \
       ^~~~~~
   include/trace/trace_events.h:64:9: note: in expansion of macro 'PARAMS'
            PARAMS(assign),         \
            ^~~~~~
   include/trace/events/vmscan.h:233:1: note: in expansion of macro 'TRACE_EVENT'
    TRACE_EVENT(mm_shrink_slab_end,
    ^~~~~~~~~~~
   include/trace/events/vmscan.h:251:2: note: in expansion of macro 'TP_fast_assign'
     TP_fast_assign(
     ^~~~~~~~~~~~~~

vim +/const +206 include/trace/events/vmscan.h

   176	
   177		TP_PROTO(unsigned long nr_reclaimed),
   178	
   179		TP_ARGS(nr_reclaimed)
   180	);
   181	
 > 182	TRACE_EVENT(mm_shrink_slab_start,
   183		TP_PROTO(struct shrinker *shr, struct shrink_control *sc,
   184			long nr_objects_to_shrink, unsigned long pgs_scanned,
   185			unsigned long lru_pgs, unsigned long cache_items,
   186			unsigned long long delta, unsigned long total_scan),
   187	
   188		TP_ARGS(shr, sc, nr_objects_to_shrink, pgs_scanned, lru_pgs,
   189			cache_items, delta, total_scan),
   190	
   191		TP_STRUCT__entry(
   192			__field(char *, name)
   193			__field(struct shrinker *, shr)
   194			__field(void *, shrink)
   195			__field(int, nid)
   196			__field(long, nr_objects_to_shrink)
   197			__field(gfp_t, gfp_flags)
   198			__field(unsigned long, pgs_scanned)
   199			__field(unsigned long, lru_pgs)
   200			__field(unsigned long, cache_items)
   201			__field(unsigned long long, delta)
   202			__field(unsigned long, total_scan)
   203		),
   204	
 > 205		TP_fast_assign(
 > 206			__entry->name = shr->name;
   207			__entry->shr = shr;
   208			__entry->shrink = shr->scan_objects;
   209			__entry->nid = sc->nid;
   210			__entry->nr_objects_to_shrink = nr_objects_to_shrink;
   211			__entry->gfp_flags = sc->gfp_mask;
   212			__entry->pgs_scanned = pgs_scanned;
   213			__entry->lru_pgs = lru_pgs;
   214			__entry->cache_items = cache_items;
   215			__entry->delta = delta;
   216			__entry->total_scan = total_scan;
   217		),
   218	
   219		TP_printk("name: %s %pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
   220			__entry->name,
   221			__entry->shrink,
   222			__entry->shr,
   223			__entry->nid,
   224			__entry->nr_objects_to_shrink,
   225			show_gfp_flags(__entry->gfp_flags),
   226			__entry->pgs_scanned,
   227			__entry->lru_pgs,
   228			__entry->cache_items,
   229			__entry->delta,
   230			__entry->total_scan)
   231	);
   232	
   233	TRACE_EVENT(mm_shrink_slab_end,
   234		TP_PROTO(struct shrinker *shr, int nid, int shrinker_retval,
   235			long unused_scan_cnt, long new_scan_cnt, long total_scan),
   236	
   237		TP_ARGS(shr, nid, shrinker_retval, unused_scan_cnt, new_scan_cnt,
   238			total_scan),
   239	
   240		TP_STRUCT__entry(
   241			__field(char *, name)
   242			__field(struct shrinker *, shr)
   243			__field(int, nid)
   244			__field(void *, shrink)
   245			__field(long, unused_scan)
   246			__field(long, new_scan)
   247			__field(int, retval)
   248			__field(long, total_scan)
   249		),
   250	
   251		TP_fast_assign(
   252			__entry->name = shr->name;
   253			__entry->shr = shr;
   254			__entry->nid = nid;
   255			__entry->shrink = shr->scan_objects;
   256			__entry->unused_scan = unused_scan_cnt;
   257			__entry->new_scan = new_scan_cnt;
   258			__entry->retval = shrinker_retval;
   259			__entry->total_scan = total_scan;
   260		),
   261	
   262		TP_printk("name: %s %pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
   263			__entry->name,
   264			__entry->shrink,
   265			__entry->shr,
   266			__entry->nid,
   267			__entry->unused_scan,
   268			__entry->new_scan,
   269			__entry->total_scan,
   270			__entry->retval)
   271	);
   272	
   273	DECLARE_EVENT_CLASS(mm_vmscan_lru_isolate_template,
   274	
   275		TP_PROTO(int order,
   276			unsigned long nr_requested,
   277			unsigned long nr_scanned,
   278			unsigned long nr_taken,
   279			isolate_mode_t isolate_mode,
   280			int file),
   281	
   282		TP_ARGS(order, nr_requested, nr_scanned, nr_taken, isolate_mode, file),
   283	
   284		TP_STRUCT__entry(
   285			__field(int, order)
   286			__field(unsigned long, nr_requested)
   287			__field(unsigned long, nr_scanned)
   288			__field(unsigned long, nr_taken)
   289			__field(isolate_mode_t, isolate_mode)
   290			__field(int, file)
   291		),
   292	
   293		TP_fast_assign(
   294			__entry->order = order;
   295			__entry->nr_requested = nr_requested;
   296			__entry->nr_scanned = nr_scanned;
   297			__entry->nr_taken = nr_taken;
   298			__entry->isolate_mode = isolate_mode;
   299			__entry->file = file;
   300		),
   301	
   302		TP_printk("isolate_mode=%d order=%d nr_requested=%lu nr_scanned=%lu nr_taken=%lu file=%d",
   303			__entry->isolate_mode,
   304			__entry->order,
   305			__entry->nr_requested,
   306			__entry->nr_scanned,
   307			__entry->nr_taken,
   308			__entry->file)
   309	);
   310	
   311	DEFINE_EVENT(mm_vmscan_lru_isolate_template, mm_vmscan_lru_isolate,
   312	
   313		TP_PROTO(int order,
   314			unsigned long nr_requested,
   315			unsigned long nr_scanned,
   316			unsigned long nr_taken,
   317			isolate_mode_t isolate_mode,
   318			int file),
   319	
   320		TP_ARGS(order, nr_requested, nr_scanned, nr_taken, isolate_mode, file)
   321	
   322	);
   323	
   324	DEFINE_EVENT(mm_vmscan_lru_isolate_template, mm_vmscan_memcg_isolate,
   325	
   326		TP_PROTO(int order,
   327			unsigned long nr_requested,
   328			unsigned long nr_scanned,
   329			unsigned long nr_taken,
   330			isolate_mode_t isolate_mode,
   331			int file),
   332	
   333		TP_ARGS(order, nr_requested, nr_scanned, nr_taken, isolate_mode, file)
   334	
   335	);
   336	
   337	TRACE_EVENT(mm_vmscan_writepage,
   338	
   339		TP_PROTO(struct page *page),
   340	
   341		TP_ARGS(page),
   342	
   343		TP_STRUCT__entry(
   344			__field(unsigned long, pfn)
   345			__field(int, reclaim_flags)
   346		),
   347	
   348		TP_fast_assign(
   349			__entry->pfn = page_to_pfn(page);
   350			__entry->reclaim_flags = trace_reclaim_flags(page);
   351		),
   352	
   353		TP_printk("page=%p pfn=%lu flags=%s",
   354			pfn_to_page(__entry->pfn),
   355			__entry->pfn,
   356			show_reclaim_flags(__entry->reclaim_flags))
   357	);
   358	
   359	TRACE_EVENT(mm_vmscan_lru_shrink_inactive,
   360	
   361		TP_PROTO(struct zone *zone,
   362			unsigned long nr_scanned, unsigned long nr_reclaimed,
   363			int priority, int file),
   364	
   365		TP_ARGS(zone, nr_scanned, nr_reclaimed, priority, file),
   366	
   367		TP_STRUCT__entry(
   368			__field(int, nid)
   369			__field(int, zid)
   370			__field(unsigned long, nr_scanned)
   371			__field(unsigned long, nr_reclaimed)
   372			__field(int, priority)
   373			__field(int, reclaim_flags)
   374		),
   375	
   376		TP_fast_assign(
   377			__entry->nid = zone_to_nid(zone);
   378			__entry->zid = zone_idx(zone);
   379			__entry->nr_scanned = nr_scanned;
   380			__entry->nr_reclaimed = nr_reclaimed;
   381			__entry->priority = priority;
   382			__entry->reclaim_flags = trace_shrink_flags(file);
   383		),
   384	
   385		TP_printk("nid=%d zid=%d nr_scanned=%ld nr_reclaimed=%ld priority=%d flags=%s",
   386			__entry->nid, __entry->zid,
   387			__entry->nr_scanned, __entry->nr_reclaimed,
   388			__entry->priority,
   389			show_reclaim_flags(__entry->reclaim_flags))
   390	);
   391	
   392	#endif /* _TRACE_VMSCAN_H */
   393	
   394	/* This part must be outside protection */
 > 395	#include <trace/define_trace.h>

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/octet-stream, Size: 24901 bytes --]

Re: [PATCH 3/3] Add name fields in shrinker tracepoint definitions

[Vlastimil Babka]

On 07/09/2016 11:05 AM, Janani Ravichandran wrote:
> Currently, the mm_shrink_slab_start and mm_shrink_slab_end
> tracepoints tell us how much time was spent in a shrinker, the number of
> objects scanned, etc. But there is no information about the identity of
> the shrinker. This patch enables the trace output to display names of
> shrinkers.
>
> ---
>  include/trace/events/vmscan.h | 10 ++++++++--
>  1 file changed, 8 insertions(+), 2 deletions(-)
>
> diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
> index 0101ef3..be4c5b0 100644
> --- a/include/trace/events/vmscan.h
> +++ b/include/trace/events/vmscan.h
> @@ -189,6 +189,7 @@ TRACE_EVENT(mm_shrink_slab_start,
>  		cache_items, delta, total_scan),
>
>  	TP_STRUCT__entry(
> +		__field(char *, name)
>  		__field(struct shrinker *, shr)
>  		__field(void *, shrink)
>  		__field(int, nid)
> @@ -202,6 +203,7 @@ TRACE_EVENT(mm_shrink_slab_start,
>  	),
>
>  	TP_fast_assign(
> +		__entry->name = shr->name;
>  		__entry->shr = shr;
>  		__entry->shrink = shr->scan_objects;
>  		__entry->nid = sc->nid;
> @@ -214,7 +216,8 @@ TRACE_EVENT(mm_shrink_slab_start,
>  		__entry->total_scan = total_scan;
>  	),
>
> -	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
> +	TP_printk("name: %s %pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
> +		__entry->name,

Is this legal to do when printing is not done via the /sys ... file 
itself, but raw data is collected and then printed by e.g. trace-cmd? 
How can it possibly interpret the "char *" kernel pointer?

>  		__entry->shrink,
>  		__entry->shr,
>  		__entry->nid,
> @@ -235,6 +238,7 @@ TRACE_EVENT(mm_shrink_slab_end,
>  		total_scan),
>
>  	TP_STRUCT__entry(
> +		__field(char *, name)
>  		__field(struct shrinker *, shr)
>  		__field(int, nid)
>  		__field(void *, shrink)
> @@ -245,6 +249,7 @@ TRACE_EVENT(mm_shrink_slab_end,
>  	),
>
>  	TP_fast_assign(
> +		__entry->name = shr->name;
>  		__entry->shr = shr;
>  		__entry->nid = nid;
>  		__entry->shrink = shr->scan_objects;
> @@ -254,7 +259,8 @@ TRACE_EVENT(mm_shrink_slab_end,
>  		__entry->total_scan = total_scan;
>  	),
>
> -	TP_printk("%pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
> +	TP_printk("name: %s %pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
> +		__entry->name,
>  		__entry->shrink,
>  		__entry->shr,
>  		__entry->nid,
>

Re: [PATCH 3/3] Add name fields in shrinker tracepoint definitions

[Tony Jones]

On 07/11/2016 07:18 AM, Vlastimil Babka wrote:
> On 07/09/2016 11:05 AM, Janani Ravichandran wrote:
>> Currently, the mm_shrink_slab_start and mm_shrink_slab_end
>> tracepoints tell us how much time was spent in a shrinker, the number of
>> objects scanned, etc. But there is no information about the identity of
>> the shrinker. This patch enables the trace output to display names of
>> shrinkers.
>>
>> ---
>>  include/trace/events/vmscan.h | 10 ++++++++--
>>  1 file changed, 8 insertions(+), 2 deletions(-)
>>
>> diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
>> index 0101ef3..be4c5b0 100644
>> --- a/include/trace/events/vmscan.h
>> +++ b/include/trace/events/vmscan.h
>> @@ -189,6 +189,7 @@ TRACE_EVENT(mm_shrink_slab_start,
>>  		cache_items, delta, total_scan),
>>
>>  	TP_STRUCT__entry(
>> +		__field(char *, name)
>>  		__field(struct shrinker *, shr)
>>  		__field(void *, shrink)
>>  		__field(int, nid)
>> @@ -202,6 +203,7 @@ TRACE_EVENT(mm_shrink_slab_start,
>>  	),
>>
>>  	TP_fast_assign(
>> +		__entry->name = shr->name;
>>  		__entry->shr = shr;
>>  		__entry->shrink = shr->scan_objects;
>>  		__entry->nid = sc->nid;
>> @@ -214,7 +216,8 @@ TRACE_EVENT(mm_shrink_slab_start,
>>  		__entry->total_scan = total_scan;
>>  	),
>>
>> -	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
>> +	TP_printk("name: %s %pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
>> +		__entry->name,
> 
> Is this legal to do when printing is not done via the /sys ... file 
> itself, but raw data is collected and then printed by e.g. trace-cmd? 
> How can it possibly interpret the "char *" kernel pointer?

I actually had a similar patch set to this,  I was going to post it but Janani beat me to it ;-)

Vlastimil is correct,  I'll attach my patch below so you can see the difference.  Otherwise you won't get correct behavior passing through perf.   

I also have a patch which adds a similar latency script (python) but interfaces it into the perf script setup.

Tony

---

Pass shrinker name in shrink slab tracepoints

Signed-off-by: Tony Jones <tonyj@suse.de>
---
 include/trace/events/vmscan.h | 12 ++++++++++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
index 0101ef3..0a15948 100644
--- a/include/trace/events/vmscan.h
+++ b/include/trace/events/vmscan.h
@@ -16,6 +16,8 @@
 #define RECLAIM_WB_SYNC		0x0004u /* Unused, all reclaim async */
 #define RECLAIM_WB_ASYNC	0x0008u
 
+#define SHRINKER_NAME_LEN 	(size_t)32
+
 #define show_reclaim_flags(flags)				\
 	(flags) ? __print_flags(flags, "|",			\
 		{RECLAIM_WB_ANON,	"RECLAIM_WB_ANON"},	\
@@ -190,6 +192,7 @@ TRACE_EVENT(mm_shrink_slab_start,
 
 	TP_STRUCT__entry(
 		__field(struct shrinker *, shr)
+		__array(char, name, SHRINKER_NAME_LEN)
 		__field(void *, shrink)
 		__field(int, nid)
 		__field(long, nr_objects_to_shrink)
@@ -203,6 +206,7 @@ TRACE_EVENT(mm_shrink_slab_start,
 
 	TP_fast_assign(
 		__entry->shr = shr;
+		strlcpy(__entry->name, shr->name, SHRINKER_NAME_LEN);
 		__entry->shrink = shr->scan_objects;
 		__entry->nid = sc->nid;
 		__entry->nr_objects_to_shrink = nr_objects_to_shrink;
@@ -214,9 +218,10 @@ TRACE_EVENT(mm_shrink_slab_start,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
+	TP_printk("%pF %p(%s): nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
 		__entry->shrink,
 		__entry->shr,
+		__entry->name,
 		__entry->nid,
 		__entry->nr_objects_to_shrink,
 		show_gfp_flags(__entry->gfp_flags),
@@ -236,6 +241,7 @@ TRACE_EVENT(mm_shrink_slab_end,
 
 	TP_STRUCT__entry(
 		__field(struct shrinker *, shr)
+		__array(char, name, SHRINKER_NAME_LEN)
 		__field(int, nid)
 		__field(void *, shrink)
 		__field(long, unused_scan)
@@ -246,6 +252,7 @@ TRACE_EVENT(mm_shrink_slab_end,
 
 	TP_fast_assign(
 		__entry->shr = shr;
+		strlcpy(__entry->name, shr->name, SHRINKER_NAME_LEN);
 		__entry->nid = nid;
 		__entry->shrink = shr->scan_objects;
 		__entry->unused_scan = unused_scan_cnt;
@@ -254,9 +261,10 @@ TRACE_EVENT(mm_shrink_slab_end,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
+	TP_printk("%pF %p(%s): nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
 		__entry->shrink,
 		__entry->shr,
+		__entry->name,
 		__entry->nid,
 		__entry->unused_scan,
 		__entry->new_scan,

Re: [PATCH 3/3] Add name fields in shrinker tracepoint definitions

[Janani Ravichandran]

> On Jul 13, 2016, at 6:05 AM, Tony Jones <tonyj@suse.de> wrote:
> 
> On 07/11/2016 07:18 AM, Vlastimil Babka wrote:
>> On 07/09/2016 11:05 AM, Janani Ravichandran wrote:
>>> 
>>> 	TP_fast_assign(
>>> +		__entry->name = shr->name;
>>> 		__entry->shr = shr;
>>> 		__entry->shrink = shr->scan_objects;
>>> 		__entry->nid = sc->nid;
>>> @@ -214,7 +216,8 @@ TRACE_EVENT(mm_shrink_slab_start,
>>> 		__entry->total_scan = total_scan;
>>> 	),
>>> 
>>> -	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
>>> +	TP_printk("name: %s %pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
>>> +		__entry->name,
>> 
>> Is this legal to do when printing is not done via the /sys ... file 
>> itself, but raw data is collected and then printed by e.g. trace-cmd? 
>> How can it possibly interpret the "char *" kernel pointer?
> 
> I actually had a similar patch set to this,  I was going to post it but Janani beat me to it ;-)
> 
> Vlastimil is correct,  I'll attach my patch below so you can see the difference.  Otherwise you won't get correct behavior passing through perf.

Thanks for that! I will have a look at it.
>   
> 
> I also have a patch which adds a similar latency script (python) but interfaces it into the perf script setup.

I’m looking for pointers for writing latency scripts using tracepoints as I’m new to it. Can I have a look at yours, please?

Thanks :)

Janani.
> 
> Tony
> 
> ---
> 
> Pass shrinker name in shrink slab tracepoints
> 
> Signed-off-by: Tony Jones <tonyj@suse.de>
> ---
> include/trace/events/vmscan.h | 12 ++++++++++--
> 1 file changed, 10 insertions(+), 2 deletions(-)
> 
> diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
> index 0101ef3..0a15948 100644
> --- a/include/trace/events/vmscan.h
> +++ b/include/trace/events/vmscan.h
> @@ -16,6 +16,8 @@
> #define RECLAIM_WB_SYNC		0x0004u /* Unused, all reclaim async */
> #define RECLAIM_WB_ASYNC	0x0008u
> 
> +#define SHRINKER_NAME_LEN 	(size_t)32
> +
> #define show_reclaim_flags(flags)				\
> 	(flags) ? __print_flags(flags, "|",			\
> 		{RECLAIM_WB_ANON,	"RECLAIM_WB_ANON"},	\
> @@ -190,6 +192,7 @@ TRACE_EVENT(mm_shrink_slab_start,
> 
> 	TP_STRUCT__entry(
> 		__field(struct shrinker *, shr)
> +		__array(char, name, SHRINKER_NAME_LEN)
> 		__field(void *, shrink)
> 		__field(int, nid)
> 		__field(long, nr_objects_to_shrink)
> @@ -203,6 +206,7 @@ TRACE_EVENT(mm_shrink_slab_start,
> 
> 	TP_fast_assign(
> 		__entry->shr = shr;
> +		strlcpy(__entry->name, shr->name, SHRINKER_NAME_LEN);
> 		__entry->shrink = shr->scan_objects;
> 		__entry->nid = sc->nid;
> 		__entry->nr_objects_to_shrink = nr_objects_to_shrink;
> @@ -214,9 +218,10 @@ TRACE_EVENT(mm_shrink_slab_start,
> 		__entry->total_scan = total_scan;
> 	),
> 
> -	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
> +	TP_printk("%pF %p(%s): nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
> 		__entry->shrink,
> 		__entry->shr,
> +		__entry->name,
> 		__entry->nid,
> 		__entry->nr_objects_to_shrink,
> 		show_gfp_flags(__entry->gfp_flags),
> @@ -236,6 +241,7 @@ TRACE_EVENT(mm_shrink_slab_end,
> 
> 	TP_STRUCT__entry(
> 		__field(struct shrinker *, shr)
> +		__array(char, name, SHRINKER_NAME_LEN)
> 		__field(int, nid)
> 		__field(void *, shrink)
> 		__field(long, unused_scan)
> @@ -246,6 +252,7 @@ TRACE_EVENT(mm_shrink_slab_end,
> 
> 	TP_fast_assign(
> 		__entry->shr = shr;
> +		strlcpy(__entry->name, shr->name, SHRINKER_NAME_LEN);
> 		__entry->nid = nid;
> 		__entry->shrink = shr->scan_objects;
> 		__entry->unused_scan = unused_scan_cnt;
> @@ -254,9 +261,10 @@ TRACE_EVENT(mm_shrink_slab_end,
> 		__entry->total_scan = total_scan;
> 	),
> 
> -	TP_printk("%pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
> +	TP_printk("%pF %p(%s): nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
> 		__entry->shrink,
> 		__entry->shr,
> +		__entry->name,
> 		__entry->nid,
> 		__entry->unused_scan,
> 		__entry->new_scan,
> 
> 

Re: [PATCH 3/3] Add name fields in shrinker tracepoint definitions

[Tony Jones]

On 07/12/2016 11:16 PM, Janani Ravichandran wrote:
>> I also have a patch which adds a similar latency script (python) but interfaces it into the perf script setup.
> 
> I’m looking for pointers for writing latency scripts using tracepoints as I’m new to it. Can I have a look at yours, please?

I was going to send it to you (off list email) last night but I seem to have misplaced the latest version.  I think it's on a diff test system.  I'll fire it off to you when I find it, hopefully in the next couple of days. I can also post it here if there is any interest.  I'd like to see it added to the builtin scripts under tools/perf.

tony

Re: [PATCH 3/3] Add name fields in shrinker tracepoint definitions

[Rik van Riel]

[-- Attachment #1: Type: text/plain, Size: 1550 bytes --]

On Wed, 2016-07-13 at 12:12 -0700, Tony Jones wrote:
> On 07/12/2016 11:16 PM, Janani Ravichandran wrote:
> > 
> > > 
> > > I also have a patch which adds a similar latency script (python)
> > > but interfaces it into the perf script setup.
> > I’m looking for pointers for writing latency scripts using
> > tracepoints as I’m new to it. Can I have a look at yours, please?
> I was going to send it to you (off list email) last night but I seem
> to have misplaced the latest version.  I think it's on a diff test
> system.  I'll fire it off to you when I find it, hopefully in the
> next couple of days. I can also post it here if there is any
> interest.  I'd like to see it added to the builtin scripts under
> tools/perf.

That is what Janani has been working on
as part of her Outreachy internship.

However, tools like this very much seem
to be subject to the 80/20 rule, and I
would expect that regardless of whether
Janani chooses to continue with her own
script, or continue working on yours,
there will be more than enough work left
to fill the remainder of the internship
period.

For one, chances are many of the things
inside vmscan.c (and compaction.c!) that
need to be instrumented currently are not.

Secondly, the tool will also need some
documentation.

Tony, Janani should be able to work on this
project full time for another month and a half
or so. This could be a good opportunity to get
something (1) upstream, and (2) refined, and
(3) documented :)

-- 
All rights reversed

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 473 bytes --]