Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1450680 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH 1/3] Add a new field to struct shrinker Tony Jones <tonyj@suse.de> - 2016-07-26 18:50 +0200
    Re: [PATCH 1/3] Add a new field to struct shrinker Dave Chinner <david@fromorbit.com> - 2016-07-28 07:50 +0200
      Re: [PATCH 1/3] Add a new field to struct shrinker Mel Gorman <mgorman@techsingularity.net> - 2016-07-28 12:30 +0200
        Re: [PATCH 1/3] Add a new field to struct shrinker Dave Chinner <david@fromorbit.com> - 2016-07-29 02:20 +0200
          Re: [PATCH 1/3] Add a new field to struct shrinker Mel Gorman <mgorman@techsingularity.net> - 2016-07-29 15:10 +0200

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

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

[toc] | [next] | [standalone]

#1451728

[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

[toc] | [prev] | [next] | [standalone]

#1451862

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

[toc] | [prev] | [next] | [standalone]

#1452183

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

[toc] | [prev] | [next] | [standalone]

#1452401

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

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web