Re: [PATCH] Add a gfp-translate script to help understand page allocation failure reports

[Minchan Kim]

Let's CCed Steven Rostedt :)

On Tue, Jun 9, 2009 at 7:29 AM, Mel Gorman<mel@xxxxxxxxx> wrote:
> On Mon, Jun 08, 2009 at 09:59:06AM -0400, Christoph Hellwig wrote:
>> On Mon, Jun 08, 2009 at 02:29:50PM +0100, Mel Gorman wrote:
>> > The page allocation failure messages include a line that looks like
>> >
>> > page allocation failure. order:1, mode:0x4020
>> >
>> > The mode is easy to translate but irritating for the lazy and a bit error
>> > prone. This patch adds a very simple helper script gfp-translate for the mode:
>> > portion of the page allocation failure messages. An example usage looks like
>>
>> Maybe we just just print the symbolic flags directly?
>
> It'd be nice if it was possible, not ugly and didn't involve declaring
> maps twice.
>
> Even with such hypothetical support, I believe there is scope for having
> the script readily available for use with reports from older kernels,
> particularly distro kernels.
>
>> The even tracer
>> in the for-2.6.23 queue now has a __print_flags helper to translate the
>> bitmask back into symbolic flags, and we even have a kmalloc tracer
>> using it for the GFP flags. ÂMaybe we should add a printk_flags variant
>> for regular printks and just do the right thing?
>>
>
> The problem I found with a printk_flags variant was that there was no
> buffer for it to easily print to for use with printk("%s"). We can't "see"
> the printk buffer, we can't kmalloc() one and I suspect it's too large to
> place on the stack. What had you in mind?
>
> I haven't looked at the trace implementation before so I have very little
> idea as to how best approach this problem. That didn't stop me attempting a
> hatchet-job on the implementation of printk support for the bitflags->string
> maps declared within ftrace - particularly the GFP flags.
>
> The following patch is what it ended up looking like. I recommend goggles
> because even if we go with printk support, this could be implemented better.
>
> === CUT HERE ===
>
> Add support for %f for the printing of string representation of bit flags
>
> This patch is a prototype to see if the tracing infrastructure used for
> the outputting of symbolic representation of bits set in a flag can be
> reused for printk. With it applied, a page allocation failure report
> looks like
>
> [ Â171.284889] cat: page allocation failure. order:9, mode:0xd1
> [ Â171.284948] mode:|GFP_KERNEL|0x1
> [ Â171.295114] Pid: 2383, comm: cat Not tainted 2.6.30-rc8-tip-02066-g800cfbb-dirty #38
>
> Not-signed-off-yet-by: Mel Gorman <mel@xxxxxxxxx>
>
> diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
> index 5c093ff..8f8e86c 100644
> --- a/include/linux/ftrace_event.h
> +++ b/include/linux/ftrace_event.h
> @@ -16,6 +16,11 @@ struct trace_print_flags {
>    Âconst char       Â*name;
> Â};
>
> +struct trace_printf_spec {
> +    unsigned long          flags;
> +    struct trace_print_flags    Â*flag_array;
> +};
> +
> Âconst char *ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â unsigned long flags,
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â const struct trace_print_flags *flag_array);
> diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
> index 9baba50..e2404ad 100644
> --- a/include/trace/events/kmem.h
> +++ b/include/trace/events/kmem.h
> @@ -17,8 +17,7 @@
> Â*
> Â* Thus most bits set go first.
> Â*/
> -#define show_gfp_flags(flags) Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â\
> - Â Â Â (flags) ? __print_flags(flags, "|", Â Â Â Â Â Â Â Â Â Â Â Â Â Â \
> +#define gfp_flags_printf_map                      \
> Â Â Â Â{(unsigned long)GFP_HIGHUSER_MOVABLE, Â "GFP_HIGHUSER_MOVABLE"}, \
> Â Â Â Â{(unsigned long)GFP_HIGHUSER, Â Â Â Â Â "GFP_HIGHUSER"}, Â Â Â Â\
> Â Â Â Â{(unsigned long)GFP_USER, Â Â Â Â Â Â Â "GFP_USER"}, Â Â Â Â Â Â\
> @@ -42,6 +41,11 @@
> Â Â Â Â{(unsigned long)__GFP_THISNODE, Â Â Â Â "GFP_THISNODE"}, Â Â Â Â\
> Â Â Â Â{(unsigned long)__GFP_RECLAIMABLE, Â Â Â"GFP_RECLAIMABLE"}, Â Â \
> Â Â Â Â{(unsigned long)__GFP_MOVABLE, Â Â Â Â Â"GFP_MOVABLE"} Â Â Â Â Â\
> +
> +
> +#define show_gfp_flags(flags, map) Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â \
> + Â Â Â (flags) ? __print_flags(flags, "|", Â Â Â Â Â Â Â Â Â Â Â Â Â Â \
> +    map                               \
> Â Â Â Â) : "GFP_NOWAIT"
>
> ÂTRACE_EVENT(kmalloc,
> @@ -75,7 +79,7 @@ TRACE_EVENT(kmalloc,
> Â Â Â Â Â Â Â Â__entry->ptr,
> Â Â Â Â Â Â Â Â__entry->bytes_req,
> Â Â Â Â Â Â Â Â__entry->bytes_alloc,
> - Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags))
> + Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags, gfp_flags_printf_map))
> Â);
>
> ÂTRACE_EVENT(kmem_cache_alloc,
> @@ -109,7 +113,7 @@ TRACE_EVENT(kmem_cache_alloc,
> Â Â Â Â Â Â Â Â__entry->ptr,
> Â Â Â Â Â Â Â Â__entry->bytes_req,
> Â Â Â Â Â Â Â Â__entry->bytes_alloc,
> - Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags))
> + Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags, gfp_flags_printf_map))
> Â);
>
> ÂTRACE_EVENT(kmalloc_node,
> @@ -146,7 +150,7 @@ TRACE_EVENT(kmalloc_node,
> Â Â Â Â Â Â Â Â__entry->ptr,
> Â Â Â Â Â Â Â Â__entry->bytes_req,
> Â Â Â Â Â Â Â Â__entry->bytes_alloc,
> - Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags),
> + Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags, gfp_flags_printf_map),
> Â Â Â Â Â Â Â Â__entry->node)
> Â);
>
> @@ -184,7 +188,7 @@ TRACE_EVENT(kmem_cache_alloc_node,
> Â Â Â Â Â Â Â Â__entry->ptr,
> Â Â Â Â Â Â Â Â__entry->bytes_req,
> Â Â Â Â Â Â Â Â__entry->bytes_alloc,
> - Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags),
> + Â Â Â Â Â Â Â show_gfp_flags(__entry->gfp_flags, gfp_flags_printf_map),
> Â Â Â Â Â Â Â Â__entry->node)
> Â);
>
> diff --git a/lib/vsprintf.c b/lib/vsprintf.c
> index 756ccaf..acb20e0 100644
> --- a/lib/vsprintf.c
> +++ b/lib/vsprintf.c
> @@ -25,6 +25,7 @@
> Â#include <linux/kallsyms.h>
> Â#include <linux/uaccess.h>
> Â#include <linux/ioport.h>
> +#include <linux/ftrace_event.h>
>
> Â#include <asm/page.h> Â Â Â Â Â/* for PAGE_SIZE */
> Â#include <asm/div64.h>
> @@ -403,6 +404,7 @@ enum format_type {
> Â Â Â ÂFORMAT_TYPE_CHAR,
> Â Â Â ÂFORMAT_TYPE_STR,
> Â Â Â ÂFORMAT_TYPE_PTR,
> + Â Â Â FORMAT_TYPE_TRACE_FLAGS,
> Â Â Â ÂFORMAT_TYPE_PERCENT_CHAR,
> Â Â Â ÂFORMAT_TYPE_INVALID,
> Â Â Â ÂFORMAT_TYPE_LONG_LONG,
> @@ -574,6 +576,44 @@ static char *string(char *buf, char *end, char *s, struct printf_spec spec)
> Â Â Â Âreturn buf;
> Â}
>
> +/*
> + * Support a %f thing storing a struct trace_print_flags
> + */
> +static char *trace_flags(char *buf, char *end,
> + Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â struct trace_printf_spec *trace_flags_spec,
> + Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â struct printf_spec spec)
> +{
> + Â Â Â unsigned long mask;
> + Â Â Â unsigned long flags = trace_flags_spec->flags;
> + Â Â Â struct trace_print_flags *flag_array = trace_flags_spec->flag_array;
> + Â Â Â char *str;
> + Â Â Â char *delim = "|";
> + Â Â Â char *ret = buf;
> + Â Â Â int i;
> +
> + Â Â Â for (i = 0; Âflag_array[i].name && flags; i++) {
> +
> + Â Â Â Â Â Â Â mask = flag_array[i].mask;
> + Â Â Â Â Â Â Â if ((flags & mask) != mask)
> + Â Â Â Â Â Â Â Â Â Â Â continue;
> +
> + Â Â Â Â Â Â Â str = (char *)flag_array[i].name;
> + Â Â Â Â Â Â Â flags &= ~mask;
> + Â Â Â Â Â Â Â if (ret < end && delim)
> + Â Â Â Â Â Â Â Â Â Â Â ret = string(ret, end, delim, spec);
> + Â Â Â Â Â Â Â ret = string(ret, end, str, spec);
> + Â Â Â }
> +
> + Â Â Â if (flags) {
> + Â Â Â Â Â Â Â ret = string(ret, end, delim, spec);
> + Â Â Â Â Â Â Â spec.flags |= SPECIAL|SMALL;
> + Â Â Â Â Â Â Â spec.base = 16;
> + Â Â Â Â Â Â Â ret = number(ret, end, flags, spec);
> + Â Â Â }
> +
> + Â Â Â return ret;
> +}
> +
> Âstatic char *symbol_string(char *buf, char *end, void *ptr,
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Âstruct printf_spec spec, char ext)
> Â{
> @@ -888,6 +928,11 @@ qualifier:
> Â Â Â Â Â Â Â Âreturn fmt - start;
> Â Â Â Â Â Â Â Â/* skip alnum */
>
> + Â Â Â case 'f':
> + Â Â Â Â Â Â Â spec->qualifier = 'l';
> + Â Â Â Â Â Â Â spec->type = FORMAT_TYPE_TRACE_FLAGS;
> + Â Â Â Â Â Â Â return ++fmt - start;
> +
> Â Â Â Âcase 'n':
> Â Â Â Â Â Â Â Âspec->type = FORMAT_TYPE_NRCHARS;
> Â Â Â Â Â Â Â Âreturn ++fmt - start;
> @@ -1058,6 +1103,12 @@ int vsnprintf(char *buf, size_t size, const char *fmt, va_list args)
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Âfmt++;
> Â Â Â Â Â Â Â Â Â Â Â Âbreak;
>
> + Â Â Â Â Â Â Â case FORMAT_TYPE_TRACE_FLAGS:
> + Â Â Â Â Â Â Â Â Â Â Â str = trace_flags(str, end,
> + Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â va_arg(args, struct trace_printf_spec *),
> + Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â spec);
> + Â Â Â Â Â Â Â Â Â Â Â break;
> +
> Â Â Â Â Â Â Â Âcase FORMAT_TYPE_PERCENT_CHAR:
> Â Â Â Â Â Â Â Â Â Â Â Âif (str < end)
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â*str = '%';
> diff --git a/mm/page_alloc.c b/mm/page_alloc.c
> index ed766b5..714b5c2 100644
> --- a/mm/page_alloc.c
> +++ b/mm/page_alloc.c
> @@ -47,6 +47,7 @@
> Â#include <linux/page-isolation.h>
> Â#include <linux/page_cgroup.h>
> Â#include <linux/debugobjects.h>
> +#include <linux/ftrace_event.h>
>
> Â#include <asm/tlbflush.h>
> Â#include <asm/div64.h>
> @@ -172,6 +173,11 @@ static void set_pageblock_migratetype(struct page *page, int migratetype)
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â ÂPB_migrate, PB_migrate_end);
> Â}
>
> +struct trace_print_flags trace_print_flags_gfp[] = {
> + Â Â Â gfp_flags_printf_map,
> + Â Â Â { -1, NULL }
> +};
> +
> Â#ifdef CONFIG_DEBUG_VM
> Âstatic int page_outside_zone_boundaries(struct zone *zone, struct page *page)
> Â{
> @@ -1675,9 +1681,15 @@ nofail_alloc:
>
> Ânopage:
> Â Â Â Âif (!(gfp_mask & __GFP_NOWARN) && printk_ratelimit()) {
> + Â Â Â Â Â Â Â static struct trace_printf_spec gfpmask_printspec;
> + Â Â Â Â Â Â Â gfpmask_printspec.flags = gfp_mask;
> + Â Â Â Â Â Â Â gfpmask_printspec.flag_array = trace_print_flags_gfp;
> +
> Â Â Â Â Â Â Â Âprintk(KERN_WARNING "%s: page allocation failure."
> - Â Â Â Â Â Â Â Â Â Â Â " order:%d, mode:0x%x\n",
> - Â Â Â Â Â Â Â Â Â Â Â p->comm, order, gfp_mask);
> + Â Â Â Â Â Â Â Â Â Â Â " order:%d, mode:0x%x\nmode:%f\n",
> + Â Â Â Â Â Â Â Â Â Â Â p->comm, order, gfp_mask,
> + Â Â Â Â Â Â Â Â Â Â Â &gfpmask_printspec);
> +
> Â Â Â Â Â Â Â Âdump_stack();
> Â Â Â Â Â Â Â Âshow_mem();
> Â Â Â Â}
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at Âhttp://vger.kernel.org/majordomo-info.html
> Please read the FAQ at Âhttp://www.tux.org/lkml/
>



-- 
Kinds regards,
Minchan Kim
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/