Re: [RFC PATCH 1/2] memdebug-ko: add dracut-memdebug-ko.sh to debug kernel module memory consumption

[Xunlei Pang]

On 2016/10/17 at 18:06, Pratyush Anand wrote:
> Hi Xunlei,
>
> Thanks for this work. It would be a great help in debugging kdump oom memory issues.
>
> On Monday 10 October 2016 01:13 PM, Xunlei Pang wrote:
> > Add dracut-memdebug-ko.sh, install it to the dracut kdump module.
> >
> > The principle 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.
> >
> > One major flaw of this method is that it consumes a lot of memory,
> > users should increase the crash kernel memory reservation as needed.
> > Signed-off-by: Xunlei Pang
> >
> > dracut-memdebug-ko.sh | 151 ++++++++++++++++++++++++++++++++++++++++++++++++++
> >  kexec-tools.spec      |   2 +
> >  2 files changed, 153 insertions(+)
> >  create mode 100755 dracut-memdebug-ko.sh
> >
> > diff --git a/dracut-memdebug-ko.sh b/dracut-memdebug-ko.sh
> > new file mode 100755
> > index 0000000..bb404ce
> > --- /dev/null
> > +++ b/dracut-memdebug-ko.sh
> > @@ -0,0 +1,151 @@
> > +#Debug the number of memory through alloc_pages and kmalloc consumed
> > +#by kernel modules during loading(i.e. modprobe).
> > +#NOTE: kmalloc may trigger alloc_pages, thus resulting in double account.
> >
> > +if ! [[ -e /sys/kernel/debug/tracing ]]; then
> > mount none -t debugfs /sys/kernel/debug
>
> May be you can also check if tracefs is mounted on /sys/kernel/tracing? trace access through debugfs would be obsolete soon.

ok, thanks for the information.
> > if ! [[ -d /sys/kernel/debug/tracing ]]; then
> >    warn "Mount debugfs failed, can't activate trace, skip kernel module memory analyzing!"
> >    return 0
> > fi
> > # 10MB should be big enough for most cases?
> > # If the current ring buffer size is the default one(contains "expanded" keyword),
> > # set it to 10MB. Users can set other size via "trace_buf_size" kernel boot command.
> > cat /proc/cmdline  | grep -q "trace_buf_size="
> > if [[ $? -ne 0 ]]; then
> >    echo 10240 > /sys/kernel/debug/tracing/buffer_size_kb
> > fi
> > # Prepare trace for the first time
>
> What if /sys/kernel/debug/tracing did exist , but kmem events were not enabled?

correct, we always need to set these events.
> > echo 1 > /sys/kernel/debug/tracing/events/kmem/mm_page_alloc/enable
> > echo 1 > /sys/kernel/debug/tracing/events/kmem/mm_page_free/enable
> > echo 1 > /sys/kernel/debug/tracing/events/kmem/kmalloc/enable
> > echo 1 > /sys/kernel/debug/tracing/events/kmem/kmalloc_node/enable
> > echo 1 > /sys/kernel/debug/tracing/events/kmem/kmem_cache_alloc/enable
> > echo 1 > /sys/kernel/debug/tracing/events/kmem/kmem_cache_alloc_node/enable
> > echo 1 > /sys/kernel/debug/tracing/events/module/module_load/enable
> > echo 1 > /sys/kernel/debug/tracing/events/module/module_put/enable
>
> would be better to clear old trace data at this point, just to make sure that its empty.

I will improve the logic.
> > echo 1 > /sys/kernel/debug/tracing/tracing_on
> > return 0
> >
> > +fi
> >
> > +echo 0 > /sys/kernel/debug/tracing/tracing_on
> > +TMPFILE=/tmp/tmp$$$$
> > +cp /sys/kernel/debug/tracing/trace $TMPFILE -f
> > +# Clear old trace data after copied away
> > +echo > /sys/kernel/debug/tracing/trace
> >
> > +#Indexed by task pid.
> > +declare -A current_module
> >
> > +#Indexed by module name.
> > +declare -A module_loaded
> > +declare -A nr_alloc_pages
> > +declare -A nr_alloc_pages_peak
> > +declare -A nr_kmalloc
> > +#For x86: If the request size of kmalloc is greater than 2*PAGE_SIZE, SLUB will use buddy instead.
> > +#So we maintain the statistics of the large kmalloc requests. For ppc64, PAGE_SIZE is not 4096,
> > +#but the large kmalloc request is not very common, this information is just to give some tips.
> > +declare -A nr_kmalloc_above8192
> >
> > +declare -A nr_kmem_cache_alloc
> >
> > +# $1: order of pages
> > +order_to_pages()
> > +{
> > local pages=1
> > local order=$1
> > while [[ $order != 0 ]]; do
> >    order=$((order-1))
> >    pages=$(($pages*2))
> > done
> > echo $pages
> >
> > +}
> >
> > +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#*: }
> >    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
> >    nr_alloc_pages_peak[$module_name]=0
> >    nr_kmalloc[$module_name]=0
> >    nr_kmalloc_above8192[$module_name]=0
> >    nr_kmem_cache_alloc[$module_name]=0
> > fi
> > if ! [[ ${current_module[$pid]} ]]; then
> >    continue
> > fi
> > if [[ $function = module_put* ]]; then
> >    #Mark the module as loaded
> >    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]}+$(order_to_pages $order)))
>
> May be I am missing..since we do not track mm_page_free(), so wouldn't nr_alloc_pages[$module_name] be always growing? In that case, how can it provide correct peak memory usage?

We do track mm_page_free here(see code below), but will consider to remove it later.
> >    if [[ ${nr_alloc_pages[$module_name]} -gt ${nr_alloc_pages_peak[$module_name]} ]]; then
> >        nr_alloc_pages_peak[$module_name]=${nr_alloc_pages[$module_name]}
> >    fi
> > fi
> > if [[ $function = mm_page_free* ]]; then
> >    order=$(echo $function | sed -e 's/.*order=\([0-9]*\)/\1/')
> >    nr_alloc_pages[$module_name]=$((${nr_alloc_pages[$module_name]}-$(order_to_pages $order)))
> > fi
> > if [[ $function = kmalloc* ]]; then
> >    bytes_alloc=$(echo $function | sed -e 's/.*bytes_alloc=\([0-9]*\).*/\1/')
> >    nr_kmalloc[$module_name]=$((${nr_kmalloc[$module_name]}+$bytes_alloc))
> >    if [[ $bytes_alloc -gt 8192 ]]; then
> >        nr_kmalloc_above8192[$module_name]=$((${nr_kmalloc_above8192[$module_name]}+$bytes_alloc))
> >    fi
> > fi
> > if [[ $function = kmem_cache_alloc* ]]; then
> >    bytes_alloc=$(echo $function | sed -e 's/.*bytes_alloc=\([0-9]*\).*/\1/')
> >    nr_kmem_cache_alloc[$module_name]=$((${nr_kmem_cache_alloc[$module_name]}+$bytes_alloc))
> > fi
> >
> > +done < $TMPFILE
> >
> > +echo -e "\n\n== debug_mem for kernel modules during loading begin ==" >&2
> > +for i in $module_names; do
> > status="finished"
> > if ! [[ ${module_loaded[$i]} ]]; then
> >    status="loading"
> > fi
> > echo -e "[Module Name] "$i" (loading status: $status)" >&2
> > echo -e "alloc_pages: consumed ${nr_alloc_pages[$i]} pages (peak: ${nr_alloc_pages_peak[$i]} pages)" >&2
> > echo -e "kmalloc: consumed ${nr_kmalloc[$i]} bytes (above8192: ${nr_kmalloc_above8192[$i]} bytes)\n" >&2
> > echo -e "kmem_cache_alloc: consumed ${nr_kmem_cache_alloc[$i]} bytes\n" >&2
> >
> > +done
> > +echo -e "== debug_mem for kernel modules during loading end ==\n\n" >&2
> >
> > +unset module_names
> > +unset module_loaded
> >
> > +rm $TMPFILE -f
> > +echo 1 > /sys/kernel/debug/tracing/tracing_on
> >
> > +return 0
> > diff --git a/kexec-tools.spec b/kexec-tools.spec
> > index 0bbaf72..1f0b7f5 100644
> > --- a/kexec-tools.spec
> > +++ b/kexec-tools.spec
> > @@ -40,6 +40,7 @@ Source103: dracut-kdump-error-handler.sh
> >  Source104: dracut-kdump-emergency.service
> >  Source105: dracut-kdump-error-handler.service
> >  Source106: dracut-kdump-capture.service
> > +Source107: dracut-memdebug-ko.sh
> >
> > Requires(post): systemd-units
> >  Requires(preun): systemd-units
> > @@ -203,6 +204,7 @@ cp %{SOURCE103} $RPM_BUILD_ROOT/etc/kdump-adv-conf/kdump_dracut_modules/99kdumpb
> >  cp %{SOURCE104} $RPM_BUILD_ROOT/etc/kdump-adv-conf/kdump_dracut_modules/99kdumpbase/%{remove_dracut_prefix %{SOURCE104}}
> >  cp %{SOURCE105} $RPM_BUILD_ROOT/etc/kdump-adv-conf/kdump_dracut_modules/99kdumpbase/%{remove_dracut_prefix %{SOURCE105}}
> >  cp %{SOURCE106} $RPM_BUILD_ROOT/etc/kdump-adv-conf/kdump_dracut_modules/99kdumpbase/%{remove_dracut_prefix %{SOURCE106}}
> > +cp %{SOURCE107} $RPM_BUILD_ROOT/etc/kdump-adv-conf/kdump_dracut_modules/99kdumpbase/%{remove_dracut_prefix %{SOURCE107}}
> >  chmod 755 $RPM_BUILD_ROOT/etc/kdump-adv-conf/kdump_dracut_modules/99kdumpbase/%{remove_dracut_prefix %{SOURCE100}}
> >  chmod 755 $RPM_BUILD_ROOT/etc/kdump-adv-conf/kdump_dracut_modules/99kdumpbase/%{remove_dracut_prefix %{SOURCE101}}
>
> Couple of thing I am still trying to understand. Will comment if I find something.

Thanks,
Xunlei
> ~Pratyush