From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752372AbcG2ANs (ORCPT ); Thu, 28 Jul 2016 20:13:48 -0400 Received: from ipmail04.adl6.internode.on.net ([150.101.137.141]:17592 "EHLO ipmail04.adl6.internode.on.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751530AbcG2ANq (ORCPT ); Thu, 28 Jul 2016 20:13:46 -0400 X-IronPort-Anti-Spam-Filtered: true X-IronPort-Anti-Spam-Result: Ah8aAGyemld5LLN+EGdsb2JhbABdg0WBUoZxnREBAQEGjFuGCoQMhhcEAgKBM00BAQEBAQEHAQEBAQEDNkBBDgGEDAEBBAEnExwjBQsIAw4KCSUPBSUDBxoTiCkHvB0BAQgCJR6FRIUVhBIRAYV3BY4WixyOc49JjC6DeIRgKjKFM4IZgTUBAQE Date: Fri, 29 Jul 2016 10:13:40 +1000 From: Dave Chinner To: Mel Gorman Cc: Tony Jones , Michal Hocko , Janani Ravichandran , Rik van Riel , linux-mm@kvack.org, linux-kernel@vger.kernel.org, akpm@linux-foundation.org, hannes@cmpxchg.org, vdavydov@virtuozzo.com, vbabka@suse.cz, kirill.shutemov@linux.intel.com, bywxiaobai@163.com Subject: Re: [PATCH 1/3] Add a new field to struct shrinker Message-ID: <20160729001340.GM12670@dastard> References: <85a9712f3853db5d9bc14810b287c23776235f01.1468051281.git.janani.rvchndrn@gmail.com> <20160711063730.GA5284@dhcp22.suse.cz> <1468246371.13253.63.camel@surriel.com> <20160711143342.GN1811@dhcp22.suse.cz> <20160720145405.GP11249@dhcp22.suse.cz> <5e6e4f2d-ae94-130e-198d-fa402a9eef50@suse.de> <20160728054947.GL12670@dastard> <20160728102513.GA2799@techsingularity.net> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20160728102513.GA2799@techsingularity.net> User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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