Re: [PATCH 5/5] slab, documentation: add description of debugfs files for SLUB caches

[Hyeonggon Yoo <42.hyeyoo@gmail.com>]

On Fri, Feb 25, 2022 at 07:03:18PM +0100, Vlastimil Babka wrote:
> From: Oliver Glitta <glittao@gmail.com>
> 
> Add description of debugfs files alloc_traces and free_traces
> to SLUB cache documentation.
> 
> [ vbabka@suse.cz: some rewording ]
> 
> Signed-off-by: Oliver Glitta <glittao@gmail.com>
> Signed-off-by: Vlastimil Babka <vbabka@suse.cz>
> Cc: Jonathan Corbet <corbet@lwn.net>
> Cc: Randy Dunlap <rdunlap@infradead.org>
> Cc: linux-doc@vger.kernel.org
> ---
>  Documentation/vm/slub.rst | 61 +++++++++++++++++++++++++++++++++++++++
>  1 file changed, 61 insertions(+)
> 
> diff --git a/Documentation/vm/slub.rst b/Documentation/vm/slub.rst
> index d3028554b1e9..2b2b931e59fc 100644
> --- a/Documentation/vm/slub.rst
> +++ b/Documentation/vm/slub.rst
> @@ -384,5 +384,66 @@ c) Execute ``slabinfo-gnuplot.sh`` in '-t' mode, passing all of the
>        40,60`` range will plot only samples collected between 40th and
>        60th seconds).
>  
> +
> +DebugFS files for SLUB
> +======================
> +
> +For more information about current state of SLUB caches with the user tracking
> +debug option enabled, debugfs files are available, typically under
> +/sys/kernel/debug/slab/<cache>/ (created only for caches with enabled user
> +tracking). There are 2 types of these files with the following debug
> +information:
> +
> +1. alloc_traces::
> +
> +    Prints information about unique allocation traces of the currently
> +    allocated objects. The output is sorted by frequency of each trace.
> +
> +    Information in the output:
> +    Number of objects, allocating function, minimal/average/maximal jiffies since alloc,
> +    pid range of the allocating processes, cpu mask of allocating cpus, and stack trace.
> +
> +    Example:::
> +
> +    1085 populate_error_injection_list+0x97/0x110 age=166678/166680/166682 pid=1 cpus=1::
> +	__slab_alloc+0x6d/0x90
> +	kmem_cache_alloc_trace+0x2eb/0x300
> +	populate_error_injection_list+0x97/0x110
> +	init_error_injection+0x1b/0x71
> +	do_one_initcall+0x5f/0x2d0
> +	kernel_init_freeable+0x26f/0x2d7
> +	kernel_init+0xe/0x118
> +	ret_from_fork+0x22/0x30
> +
> +
> +2. free_traces::
> +
> +    Prints information about unique free traces of the currently free objects,
> +    sorted by their frequency.
> +

I'm not sure that it's traces of the "currently free objects".

static int slab_debug_trace_open(struct inode *inode, struct file *filep)
{
	[...]
        
	obj_map = bitmap_alloc(oo_objects(s->oo), GFP_KERNEL);
	
	[...]

        for_each_kmem_cache_node(s, node, n) {
                unsigned long flags;
                struct slab *slab;

                if (!atomic_long_read(&n->nr_slabs))
                        continue;

                spin_lock_irqsave(&n->list_lock, flags);
                list_for_each_entry(slab, &n->partial, slab_list)
                        process_slab(t, s, slab, alloc, obj_map);
                list_for_each_entry(slab, &n->full, slab_list)
                        process_slab(t, s, slab, alloc, obj_map);
                spin_unlock_irqrestore(&n->list_lock, flags);
        }

	[...]

}

static void __fill_map(unsigned long *obj_map, struct kmem_cache *s,
                       struct slab *slab)
{
        void *addr = slab_address(slab);
        void *p;

        bitmap_zero(obj_map, slab->objects);

        for (p = slab->freelist; p; p = get_freepointer(s, p))
                set_bit(__obj_to_index(s, addr, p), obj_map);
}

static void process_slab(struct loc_track *t, struct kmem_cache *s,
                struct slab *slab, enum track_item alloc,
                unsigned long *obj_map)
{
        void *addr = slab_address(slab);
        void *p;

        __fill_map(obj_map, s, slab);

        for_each_object(p, s, addr, slab->objects)
                if (!test_bit(__obj_to_index(s, addr, p), obj_map))
                        add_location(t, s, get_track(s, p, alloc));
}

I think it's not traces of "currently free objects"
because index bit of free objects are set in obj_map bitmap?

It's weird but it's traces of allocated objects that have been freed at
least once (or <not available>)

I think we can fix the code or doc?

Please tell me if I'm missing something :)

> +    Information in the output:
> +    Number of objects, freeing function, minimal/average/maximal jiffies since free,
> +    pid range of the freeing processes, cpu mask of freeing cpus, and stack trace.
> +
> +    Example:::
> +
> +    51 acpi_ut_update_ref_count+0x6a6/0x782 age=236886/237027/237772 pid=1 cpus=1
> +	kfree+0x2db/0x420
> +	acpi_ut_update_ref_count+0x6a6/0x782
> +	acpi_ut_update_object_reference+0x1ad/0x234
> +	acpi_ut_remove_reference+0x7d/0x84
> +	acpi_rs_get_prt_method_data+0x97/0xd6
> +	acpi_get_irq_routing_table+0x82/0xc4
> +	acpi_pci_irq_find_prt_entry+0x8e/0x2e0
> +	acpi_pci_irq_lookup+0x3a/0x1e0
> +	acpi_pci_irq_enable+0x77/0x240
> +	pcibios_enable_device+0x39/0x40
> +	do_pci_enable_device.part.0+0x5d/0xe0
> +	pci_enable_device_flags+0xfc/0x120
> +	pci_enable_device+0x13/0x20
> +	virtio_pci_probe+0x9e/0x170
> +	local_pci_probe+0x48/0x80
> +	pci_device_probe+0x105/0x1c0
> +

Everything else looks nice!

>  Christoph Lameter, May 30, 2007
>  Sergey Senozhatsky, October 23, 2015
> -- 
> 2.35.1
> 
> 

-- 
Thank you, You are awesome!
Hyeonggon :-)