Re: [RFC PATCH 1/2] add 99memdebug-ko dracut module

[Xunlei Pang <xpang-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org>]

On 2016/11/03 at 12:15, Xunlei Pang wrote:
> On 2016/11/03 at 11:01, Dave Young wrote:
>> Hi Xunlei,
>> On 11/02/16 at 05:03pm, Xunlei Pang wrote:
>>> The current method for memory debug is to use "rd.memdebug=[0-3]",
>>> it is not enough for debugging kernel modules. For example, when we
>>> want to find out which kernel module consumes a large amount of memory,
>>> "rd.memdebug=[0-3]" won't help too much.
>>>
>>> A better way is needed to achieve this requirement, this is useful for
>>> kdump OOM debugging.
>>>
>>> The principle of this patch is to use kernel trace to track slab and
>>> buddy allocation calls during kernel module loading(module_init), thus
>>> we can analyze all the trace data and get the total memory consumption.
>>> As for large slab allocation, it will probably fall into buddy allocation,
>>> thus tracing "mm_page_alloc" alone should be enough for the purpose(this
>>> saves quite some trace buffer memory, also large free is quite unlikey
>>> during module loading, we neglect those memory free events).
>>>
>>> The trace events include memory calls under "tracing/events/":
>>>   kmem/mm_page_alloc
>>>
>>> We also inpect the following events to detect the module loading:
>>>   module/module_load
>>>   module/module_put
>>>
>>> Since we use filters to trace events, the final trace data size won't
>>> be too big. Users can adjust the trace buffer size via "trace_buf_size"
>>> kernel boot command line as needed.
>>>
>>> We can get the module name and task pid from "module_load" event which
>>> also mark the beginning of the loading, and module_put called by the
>>> same task pid implies the end of the loading. So the memory events
>>> recorded in between by the same task pid are consumed by this module
>>> during loading(i.e. modprobe or module_init()).
>>>
>>> With these information, we can record the total memory(the larger, the
>>> more precise the result will be) consumption involved by each kernel
>>> module loading.
>>>
>>> Thus we introduce this dracut module to find out which kernel module
>>> consumes a large amount of memory during loading. It uses "rd.memdebug=4"
>>> as the tigger.
>>>
>>> After applying is patch and specifying "rd.memdebug=4", during booting
>>> it will print out something below:
>>> == debug_mem for kernel modules during loading begin ==
>>> 0 pages consumed by "pata_acpi"
>>> 0 pages consumed by "ata_generic"
>>> 1 pages consumed by "drm"
>>> 0 pages consumed by "ttm"
>>> 0 pages consumed by "drm_kms_helper"
>>> 835 pages consumed by "qxl"
>>> 0 pages consumed by "mii"
>>> 6 pages consumed by "8139cp"
>>> 0 pages consumed by "virtio"
>>> 0 pages consumed by "virtio_ring"
>>> 9 pages consumed by "virtio_pci"
>>> 1 pages consumed by "8139too"
>>> 0 pages consumed by "serio_raw"
>>> 0 pages consumed by "crc32c_intel"
>>> 199 pages consumed by "virtio_console"
>>> 0 pages consumed by "libcrc32c"
>>> 9 pages consumed by "xfs"
>>> == debug_mem for kernel modules during loading end ==
>>>
>>> From the print, we see clearly that "qxl" consumed lots of memory.
>>>
>>> Signed-off-by: Xunlei Pang <xlpang-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org>
>>> ---
>>>  dracut.spec                                    |  1 +
>>>  modules.d/99memdebug-ko/memdebug-ko-parse.sh   | 93 ++++++++++++++++++++++++++
>>>  modules.d/99memdebug-ko/memdebug-ko-prepare.sh | 60 +++++++++++++++++
>>>  modules.d/99memdebug-ko/module-setup.sh        | 25 +++++++
>>>  4 files changed, 179 insertions(+)
>>>  create mode 100755 modules.d/99memdebug-ko/memdebug-ko-parse.sh
>>>  create mode 100755 modules.d/99memdebug-ko/memdebug-ko-prepare.sh
>>>  create mode 100755 modules.d/99memdebug-ko/module-setup.sh
>>>
>>> diff --git a/dracut.spec b/dracut.spec
>>> index 7b9d675..3907b17 100644
>>> --- a/dracut.spec
>>> +++ b/dracut.spec
>>> @@ -407,6 +407,7 @@ rm -rf -- $RPM_BUILD_ROOT
>>>  %{dracutlibdir}/modules.d/98usrmount
>>>  %{dracutlibdir}/modules.d/99base
>>>  %{dracutlibdir}/modules.d/99fs-lib
>>> +%{dracutlibdir}/modules.d/99memdebug-ko
>>>  %{dracutlibdir}/modules.d/99shutdown
>>>  %attr(0644,root,root) %ghost %config(missingok,noreplace) %{_localstatedir}/log/dracut.log
>>>  %dir %{_sharedstatedir}/initramfs
>>> diff --git a/modules.d/99memdebug-ko/memdebug-ko-parse.sh b/modules.d/99memdebug-ko/memdebug-ko-parse.sh
>>> new file mode 100755
>>> index 0000000..1542658
>>> --- /dev/null
>>> +++ b/modules.d/99memdebug-ko/memdebug-ko-parse.sh
>>> @@ -0,0 +1,93 @@
>>> +# Parse the trace data to find out the modules consuming large amount of memory.
>>> +
>>> +is_trace_data_available() {
>>> +    # Only "rd.memdebug=4" is for the purpose.
>>> +    if [[ $(getargnum 0 0 4 rd.memdebug) != 4 ]]; then
>>> +        return 1
>>> +    fi
> Hi Dave,
>
> Firstly, thanks for your valuable comments.
>
>> The usage of rd.memdebug is different in other place, can we integrate
>> it to the original rd.memdbug code?
>>
>> One concern it in this patch only parse the trace data at pre-pivot
>> hook, so if oom happens earlier than that we will get nothing.
>>
>> Original rd.memdebug being added to several different point, if we
>> integrate this to the framework then we can get the out put early.
> Yes, they can be integrated together. My original thought is that to
> just output the memory information for all the modules at one stage
> where all modules are supposed to be loaded, as such can avoid printing
> redundant/partial information if at multiple stages(hooks).
>
> If OOM happens (mainly for kdump cases), we can enlarge the reserved
> crash memory and try again, because this feature itself might consume
> large trace buffer memory.
>
> But I can do in that way if you think it is fine.
>
>>> +
>>> +    TRACE_BASE="/sys/kernel/debug"
>>> +    # trace access through debugfs would be obsolete if "/sys/kernel/tracing" is available.
>>> +    if [[ -d "/sys/kernel/tracing" ]]; then
>>> +        TRACE_BASE="/sys/kernel"
>>> +    fi
>>> +
>>> +    if ! [[ -f "$TRACE_BASE/tracing/trace" ]]; then
>>> +        warn "Trace inactive, skipping kernel module memory analyzing."
>>> +        return 1
>>> +    fi
>> This function is only for checking if tracing is needed by checking
>> cmdline, so getting the TRACE_BASE logic can be moved to
>> parse_trace_data so that it can be a local variable..
> It is actually in a function, will change it to be a local definition.
>
>>> +
>>> +    return 0
>>> +}
>>> +
>>> +parse_trace_data() {
>>> +    # Indexed by task pid.
>>> +    declare -A current_module
>>> +    # Indexed by module name.
>>> +    declare -A module_loaded
>>> +    declare -A nr_alloc_pages
>>> +
>>> +    # For large trace data, parsing "tracing/trace" directly turns out to be time-consuming,
>>> +    # hence copy it out first, then parse the copy file instead.
>> Have you get any data about the time used via traceing/trace parsing, if
>> the time is still acceptable then it will be better to avoid the tmp
>> file.
> For large trace data(tested on rhel7, the filter doesn't work on rhel7, and will produce huge trace data),
> the time consumption is huge, I am afraid in minutes because I once suspected the script was in some
> dead loop when parsing "tracing/trace" directly. It is the same situation when turning off tracing_on and
> try again.

Although I don't know why, after I replaced the following scripts
1)
while read pid cpu flags ts function
do
    ... ...
done < "$TRACE_BASE/tracing/trace"

with

2)
cat "$TRACE_BASE/tracing/trace" | while read pid cpu flags ts function
do
    ... ...
done

2) became not time-consuming just like parsing the copied filename in 1) ...

Regards,
Xunlei

>
>>> +    TMPFILE=/tmp/kdump.trace.tmp.$$$$
>>> +    cp $TRACE_BASE/tracing/trace $TMPFILE -f
>>> +    while read pid cpu flags ts function ;
>>> +    do
>>> +        # Skip comment lines
>>> +        if [[ $pid = "#" ]]; then
>>> +            continue
>>> +        fi
>>> +
>>> +        if [[ $function = module_load* ]]; then
>>> +            # One module is being loaded, save the task pid for tracking.
>>> +            module_name=${function#*: }
>>> +            # Remove the trailing after whitespace, there may be the module flags.
>>> +            module_name=${module_name%% *}
>>> +            module_names+=" $module_name"
>>> +            current_module[$pid]="$module_name"
>>> +            [[ ${module_loaded[$module_name]} ]] && warn "\"$module_name\" was loaded multiple times!"
>>> +            unset module_loaded[$module_name]
>>> +            nr_alloc_pages[$module_name]=0
>>> +        fi
>>> +    
>>> +        if ! [[ ${current_module[$pid]} ]]; then
>>> +            continue
>>> +        fi
>>> +
>>> +        if [[ $function = module_put* ]]; then
>>> +            # Mark the module as loaded when the first module_put event happens after module_load.
>>> +            module_loaded[${current_module[$pid]}]=1
>>> +            # Module has been loaded when module_put is called, untrack the task
>>> +            unset current_module[$pid]
>>> +            continue
>>> +        fi
>>> +    
>>> +        # Once we get here, the task is being tracked(is loading a module).
>>> +        # Get the module name.
>>> +        module_name=${current_module[$pid]}
>>> +    
>>> +        if [[ $function = mm_page_alloc* ]]; then
>>> +            order=$(echo $function | sed -e 's/.*order=\([0-9]*\) .*/\1/')
>>> +            nr_alloc_pages[$module_name]=$((${nr_alloc_pages[$module_name]}+$((2 ** $order))))
>>> +        fi
>>> +    done < $TMPFILE
>>> +    
>>> +    # Print the result out.
>>> +    echo "== debug_mem for kernel modules during loading begin ==" >&2
>>> +    for i in $module_names; do
>>> +        status=""
>>> +        if ! [[ ${module_loaded[$i]} ]]; then
>>> +            status="[still loading]"
>>> +        fi
>>> +        echo "${nr_alloc_pages[$i]} pages consumed by \"$i\" $status" >&2
>>> +    done
>>> +    echo "== debug_mem for kernel modules during loading end ==" >&2
>>> +    
>>> +    unset module_names
>>> +    unset module_loaded
>> unset nr_alloc_pages?
> nr_alloc_pages will be set to be 0 when module_load hits, but I will update or try to change them to be local.
>
>
>>> +    rm $TMPFILE -f
>>> +}
>>> +
>>> +if is_trace_data_available ; then
>>> +    parse_trace_data
>>> +fi
>>> diff --git a/modules.d/99memdebug-ko/memdebug-ko-prepare.sh b/modules.d/99memdebug-ko/memdebug-ko-prepare.sh
>>> new file mode 100755
>>> index 0000000..134821a
>>> --- /dev/null
>>> +++ b/modules.d/99memdebug-ko/memdebug-ko-prepare.sh
>>> @@ -0,0 +1,60 @@
>>> +# Try to find out kernel modules with large total memory allocation during loading.
>>> +# For large slab allocation, it will fall into buddy, thus tracing "mm_page_alloc"
>>> +# alone should be enough for the purpose.
>>> +#
>>> +# Prepare for the trace setup.
>>> +
>>> +prepare_trace() {
>>> +    # Only "rd.memdebug=4" is for the purpose.
>>> +    if [[ $(getargnum 0 0 4 rd.memdebug) != 4 ]]; then
>>> +        return 0
>>> +    fi
>>> +
>>> +    TRACE_BASE="/sys/kernel/debug"
>>> +    # trace access through debugfs would be obsolete if "/sys/kernel/tracing" is available.
>>> +    if [[ -d "/sys/kernel/tracing" ]]; then
>>> +        TRACE_BASE="/sys/kernel"
>>> +    fi
>> Move TRACE_BASE as a local variable, maybe a function..
> It is in a function, will change it to be local.
>
>>> +    
>>> +    # old debugfs case.
>>> +    if ! [[ -d "$TRACE_BASE/tracing" ]]; then
>>> +        mount none -t debugfs $TRACE_BASE
>>> +    # new tracefs case.
>>> +    elif ! [[ -f "$TRACE_BASE/tracing/trace" ]]; then
>>> +        mount none -t tracefs "$TRACE_BASE/tracing"
>>> +    fi
>>> +    
>>> +    if ! [[ -f "$TRACE_BASE/tracing/trace" ]]; then
>>> +        warn "Mount trace failed for kernel module memory analyzing."
>>> +        return 1
>>> +    fi
>>> +    
>>> +    MATCH_EVENTS="module:module_put module:module_load kmem:mm_page_alloc"
>> Do we have module_init event? what is the difference between module_load
>> and module_init?
> module_load event is in some path of finit_module/init_module syscall, quite similar to
> module_init, after the event there is do_init_module()->do_one_initcall() to invoke the
> module init function, then module_put() immediately once finished which produces
> module_put event. So between the two events, there are all the needed page allocation
> events for us. I haven't see other better events.
>
> Regards,
> Xunlei
>
>>> +    SET_EVENTS=$(echo $(cat $TRACE_BASE/tracing/set_event))
>>> +    # Check if trace was properly setup, prepare it if not.
>>> +    if [[ $(cat $TRACE_BASE/tracing/tracing_on) != 1 ]] || \
>>> +        [[ "$SET_EVENTS" != "$MATCH_EVENTS" ]]; then
>>> +        # Set our trace events.
>>> +        echo $MATCH_EVENTS > $TRACE_BASE/tracing/set_event
>>> +    
>>> +        # There are three kinds of known applications for module loading:
>>> +        # "systemd-udevd", "modprobe" and "insmod".
>>> +        # Set them to the mm_page_alloc event filter.
>>> +        # NOTE: Some kernel may not support this format of filter, anyway
>>> +        #       the operation will fail and it doesn't matter.
>>> +        page_alloc_filter="comm == systemd-udevd || comm == modprobe || comm == insmod"
>>> +        echo $page_alloc_filter > $TRACE_BASE/tracing/events/kmem/mm_page_alloc/filter
>>> +        
>>> +        # Set the number of comm-pid.
>>> +        # Thanks to filters, 4096 is big enough(also well supported).
>>> +        echo 4096 > $TRACE_BASE/tracing/saved_cmdlines_size
>>> +
>>> +        # Enable and clear trace data for the first time.
>>> +        echo 1 > $TRACE_BASE/tracing/tracing_on
>>> +        echo > $TRACE_BASE/tracing/trace
>>> +    fi
>>> +
>>> +    return 0
>>> +}
>>> +
>>> +prepare_trace
>>> diff --git a/modules.d/99memdebug-ko/module-setup.sh b/modules.d/99memdebug-ko/module-setup.sh
>>> new file mode 100755
>>> index 0000000..d6a7f0c
>>> --- /dev/null
>>> +++ b/modules.d/99memdebug-ko/module-setup.sh
>>> @@ -0,0 +1,25 @@
>>> +#!/bin/bash
>>> +
>>> +# called by dracut
>>> +check() {
>>> +    # this is very small, always add it.
>>> +    # It has no effect if no "rd.memdebug=4" is specified, also
>>> +    # this stays consistent with "rd.memdebug=[0-3]".
>>> +    return 0
>>> +}
>>> +
>>> +# called by dracut
>>> +depends() {
>>> +    return 0
>>> +}
>>> +
>>> +# called by dracut
>>> +install() {
>>> +    # Prepare trace at the early stage before any ko modules is loaded.
>>> +    inst_hook cmdline 00 "$moddir/memdebug-ko-prepare.sh"
>>> +
>>> +    # Before switching root to the real root, rootfs should be mounted
>>> +    # and all dependent ko modules are expected to be loaded.
>>> +    # We can parse trace data at this stage.
>>> +    inst_hook pre-pivot 99 "$moddir/memdebug-ko-parse.sh"
>>> +}
>>> -- 
>>> 1.8.3.1
>>>
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe initramfs" in
>>> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>> --
>> To unsubscribe from this list: send the line "unsubscribe initramfs" in
>> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> --
> To unsubscribe from this list: send the line "unsubscribe initramfs" in
> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html