Re: [RFC] scripts: Include postprocessing script for memory allocation tracing

[Janani Ravichandran]

> On Sep 12, 2016, at 8:16 AM, Michal Hocko <mhocko@xxxxxxxxxx> wrote:
> 
> Hi,

Hello Michal,

> I am sorry I didn't follow up on the previous submission.

Thatâs alright :)

> I find this
> _really_ helpful. It is great that you could build on top of existing
> tracepoints but one thing is not entirely clear to me. Without a begin
> marker in __alloc_pages_nodemask we cannot really tell how long the
> whole allocation took, which would be extremely useful. Or do you use
> any graph tracer tricks to deduce that?

Iâm using the function graph tracer to see how long __alloc_pages_nodemask()
took.


> There is a note in your
> changelog but I cannot seem to find that in the changelog. And FWIW I
> would be open to adding a tracepoint like that. It would make our life
> so much easierâ

The line
echo __alloc_pages_nodemask > set_ftrace_filter in setup_alloc_trace.sh
sets __alloc_pages_nodemask as a function graph filter and this should help
us observe how long the function took.

> 
> On Sun 11-09-16 18:24:12, Janani Ravichandran wrote:
> [...]
>> allocation_postprocess.py is a script which reads from trace_pipe. It
>> does the following to filter out info from tracepoints that may not
>> be important:
>> 
>> 1. Displays mm_vmscan_direct_reclaim_begin and
>> mm_vmscan_direct_reclaim_end only when try_to_free_pages has
>> exceeded the threshold.
>> 2. Displays mm_compaction_begin and mm_compaction_end only when
>> compact_zone has exceeded the threshold.
>> 3. Displays mm_compaction_try_to_compat_pages only when
>> try_to_compact_pages has exceeded the threshold.
>> 4. Displays mm_shrink_slab_start and mm_shrink_slab_end only when
>> the time elapsed between them exceeds the threshold.
>> 5. Displays mm_vmscan_lru_shrink_inactive only when shrink_inactive_list
>> has exceeded the threshold.
>> 
>> When CTRL+C is pressed, the script shows the times taken by the
>> shrinkers. However, currently it is not possible to differentiate among
>> the
>> superblock shrinkers.
>> 
>> Sample output:
>> ^Ci915_gem_shrinker_scan : total time = 8.731000 ms, max latency =
>> 0.278000 ms
>> ext4_es_scan : total time = 0.970000 ms, max latency = 0.129000 ms
>> scan_shadow_nodes : total time = 1.150000 ms, max latency = 0.175000 ms
>> super_cache_scan : total time = 8.455000 ms, max latency = 0.466000 ms
>> deferred_split_scan : total time = 25.767000 ms, max latency = 25.485000
>> ms
> 
> Would it be possible to group those per the context?

Absolutely!
> I mean a single
> allocation/per-process drop down values rather than mixing all those
> values together? For example if I see that a process is talling due to
> direct reclaim I would love to see what is the worst case allocation
> stall and what is the most probable source of that stall. Mixing kswapd
> traces would be misleading here.
> 

True. Iâll do that and send a v2. Thanks for the suggestions!

Janani
>