The existed pGp shows the names of page flags only, rather than the full
information including section, node, zone, last cpuipid and kasan tag.
While it is not easy to parse these information manually because there
are so many flavors. We'd better interpret them in printf.
To avoid breaking some tools which parsing pGp via debugfs or affecting
the printf buffer, other new formats are introduced, so the user can choose
what and in which order they want, suggested by Andy. These new introduced
format as follows,
pGpb: print other information first and then the names of page flags
pGpl: print the names of page flags first and then the other info
The differece between them looks like the difference between big-endian and
little-endian, that's why they are named like that. The examples of the
output as follows,
%pGpb 0x17ffffc0010200(node=0|zone=2|lastcpupid=0x1fffff|slab|head)
%pGpl 0x17ffffc0010200(slab|head|node=0|zone=2|lastcpupid=0x1fffff)
To be compitable with the existed format of pGp, the new introduced ones
also use '|' as the separator, then the user tools parsing pGp won't
need to make change, suggested by Matthew.
The doc and test cases are also updated. Below is the output of the
test cases,
[ 4299.847655] test_printf: loaded.
[ 4299.848301] test_printf: all 404 tests passed
[ 4299.850371] test_printf: unloaded.
This patchset also includes some code cleanup in mm/slub.c.
v3:
- coding improvement, per Joe and Andy
- the possible impact on debugfs and the fix of it, per Joe and Matthew
- introduce new format instead of changing pGp, per Andy
v2:
- various coding improvement, per Joe, Miaohe, Vlastimil and Andy
- remove the prefix completely in patch #2, per Vlastimil
- Update the test cases, per Andy
Yafang Shao (3):
mm, slub: use pGp to print page flags
mm, slub: don't combine pr_err with INFO
vsprintf: introduce new format to dump full information of page flags
Documentation/core-api/printk-formats.rst | 2 +
lib/test_printf.c | 126 +++++++++++++++++++---
lib/vsprintf.c | 115 +++++++++++++++++++-
mm/slub.c | 13 +--
4 files changed, 233 insertions(+), 23 deletions(-)
--
2.17.1
It is strange to combine "pr_err" with "INFO", so let's remove the
prefix completely.
This patch is motivated by David's comment[1].
- before the patch
[ 8846.517809] INFO: Slab 0x00000000f42a2c60 objects=33 used=3 fp=0x0000000060d32ca8 flags=0x17ffffc0010200(slab|head)
- after the patch
[ 6343.396602] Slab 0x000000004382e02b objects=33 used=3 fp=0x000000009ae06ffc flags=0x17ffffc0010200(slab|head)
[1]. https://lore.kernel.org/linux-mm/[email protected]/#t
Suggested-by: Vlastimil Babka <[email protected]>
Cc: David Hildenbrand <[email protected]>
Signed-off-by: Yafang Shao <[email protected]>
---
mm/slub.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)
diff --git a/mm/slub.c b/mm/slub.c
index 87ff086e68a4..2514c37ab4e4 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -612,7 +612,7 @@ static void print_track(const char *s, struct track *t, unsigned long pr_time)
if (!t->addr)
return;
- pr_err("INFO: %s in %pS age=%lu cpu=%u pid=%d\n",
+ pr_err("%s in %pS age=%lu cpu=%u pid=%d\n",
s, (void *)t->addr, pr_time - t->when, t->cpu, t->pid);
#ifdef CONFIG_STACKTRACE
{
@@ -638,7 +638,7 @@ void print_tracking(struct kmem_cache *s, void *object)
static void print_page_info(struct page *page)
{
- pr_err("INFO: Slab 0x%p objects=%u used=%u fp=0x%p flags=%#lx(%pGp)\n",
+ pr_err("Slab 0x%p objects=%u used=%u fp=0x%p flags=%#lx(%pGp)\n",
page, page->objects, page->inuse, page->freelist,
page->flags, &page->flags);
@@ -695,7 +695,7 @@ static void print_trailer(struct kmem_cache *s, struct page *page, u8 *p)
print_page_info(page);
- pr_err("INFO: Object 0x%p @offset=%tu fp=0x%p\n\n",
+ pr_err("Object 0x%p @offset=%tu fp=0x%p\n\n",
p, p - addr, get_freepointer(s, p));
if (s->flags & SLAB_RED_ZONE)
@@ -788,7 +788,7 @@ static int check_bytes_and_report(struct kmem_cache *s, struct page *page,
end--;
slab_bug(s, "%s overwritten", what);
- pr_err("INFO: 0x%p-0x%p @offset=%tu. First byte 0x%x instead of 0x%x\n",
+ pr_err("0x%p-0x%p @offset=%tu. First byte 0x%x instead of 0x%x\n",
fault, end - 1, fault - addr,
fault[0], value);
print_trailer(s, page, object);
@@ -3854,7 +3854,7 @@ static void list_slab_objects(struct kmem_cache *s, struct page *page,
for_each_object(p, s, addr, page->objects) {
if (!test_bit(__obj_to_index(s, addr, p), map)) {
- pr_err("INFO: Object 0x%p @offset=%tu\n", p, p - addr);
+ pr_err("Object 0x%p @offset=%tu\n", p, p - addr);
print_tracking(s, p);
}
}
--
2.17.1
On Mon, Feb 08, 2021 at 06:14:36PM +0800, Yafang Shao wrote:
> To avoid breaking some tools which parsing pGp via debugfs or affecting
> the printf buffer, other new formats are introduced, so the user can choose
> what and in which order they want, suggested by Andy. These new introduced
> format as follows,
> pGpb: print other information first and then the names of page flags
> pGpl: print the names of page flags first and then the other info
This is overengineering things. We already print in little-endian order,
and the other information should be tacked onto the end. Just extend
%pGp. Andy's suggestion to add another flag was a bad one.
On Mon, Feb 8, 2021 at 2:37 PM Matthew Wilcox <[email protected]> wrote:
>
> On Mon, Feb 08, 2021 at 06:14:36PM +0800, Yafang Shao wrote:
> > To avoid breaking some tools which parsing pGp via debugfs or affecting
> > the printf buffer, other new formats are introduced, so the user can choose
> > what and in which order they want, suggested by Andy. These new introduced
> > format as follows,
> > pGpb: print other information first and then the names of page flags
> > pGpl: print the names of page flags first and then the other info
>
> This is overengineering things. We already print in little-endian order,
> and the other information should be tacked onto the end. Just extend
> %pGp. Andy's suggestion to add another flag was a bad one.
Fair enough, I can admit this because I don't know the mm specifics.
However, my initial point was about the long message which might be
cut into pieces during Oops or whatever and the user will get the
first parts only. Depends on what you consider as a higher priority
to print the order might be different. Initial patch suggested to
print the new fields first.
--
With Best Regards,
Andy Shevchenko
On Mon, Feb 8, 2021 at 8:20 PM Matthew Wilcox <[email protected]> wrote:
>
> On Mon, Feb 08, 2021 at 06:14:36PM +0800, Yafang Shao wrote:
> > To avoid breaking some tools which parsing pGp via debugfs or affecting
> > the printf buffer, other new formats are introduced, so the user can choose
> > what and in which order they want, suggested by Andy. These new introduced
> > format as follows,
> > pGpb: print other information first and then the names of page flags
> > pGpl: print the names of page flags first and then the other info
>
> This is overengineering things. We already print in little-endian order,
> and the other information should be tacked onto the end. Just extend
> %pGp. Andy's suggestion to add another flag was a bad one.
>
All right. I will do it in the next version.
--
Thanks
Yafang
On 2/8/21 11:14 AM, Yafang Shao wrote:
> It is strange to combine "pr_err" with "INFO", so let's remove the
> prefix completely.
> This patch is motivated by David's comment[1].
>
> - before the patch
> [ 8846.517809] INFO: Slab 0x00000000f42a2c60 objects=33 used=3 fp=0x0000000060d32ca8 flags=0x17ffffc0010200(slab|head)
>
> - after the patch
> [ 6343.396602] Slab 0x000000004382e02b objects=33 used=3 fp=0x000000009ae06ffc flags=0x17ffffc0010200(slab|head)
>
> [1]. https://lore.kernel.org/linux-mm/[email protected]/#t
>
> Suggested-by: Vlastimil Babka <[email protected]>
> Cc: David Hildenbrand <[email protected]>
> Signed-off-by: Yafang Shao <[email protected]>
Acked-by: Vlastimil Babka <[email protected]>
> ---
> mm/slub.c | 10 +++++-----
> 1 file changed, 5 insertions(+), 5 deletions(-)
>
> diff --git a/mm/slub.c b/mm/slub.c
> index 87ff086e68a4..2514c37ab4e4 100644
> --- a/mm/slub.c
> +++ b/mm/slub.c
> @@ -612,7 +612,7 @@ static void print_track(const char *s, struct track *t, unsigned long pr_time)
> if (!t->addr)
> return;
>
> - pr_err("INFO: %s in %pS age=%lu cpu=%u pid=%d\n",
> + pr_err("%s in %pS age=%lu cpu=%u pid=%d\n",
> s, (void *)t->addr, pr_time - t->when, t->cpu, t->pid);
> #ifdef CONFIG_STACKTRACE
> {
> @@ -638,7 +638,7 @@ void print_tracking(struct kmem_cache *s, void *object)
>
> static void print_page_info(struct page *page)
> {
> - pr_err("INFO: Slab 0x%p objects=%u used=%u fp=0x%p flags=%#lx(%pGp)\n",
> + pr_err("Slab 0x%p objects=%u used=%u fp=0x%p flags=%#lx(%pGp)\n",
> page, page->objects, page->inuse, page->freelist,
> page->flags, &page->flags);
>
> @@ -695,7 +695,7 @@ static void print_trailer(struct kmem_cache *s, struct page *page, u8 *p)
>
> print_page_info(page);
>
> - pr_err("INFO: Object 0x%p @offset=%tu fp=0x%p\n\n",
> + pr_err("Object 0x%p @offset=%tu fp=0x%p\n\n",
> p, p - addr, get_freepointer(s, p));
>
> if (s->flags & SLAB_RED_ZONE)
> @@ -788,7 +788,7 @@ static int check_bytes_and_report(struct kmem_cache *s, struct page *page,
> end--;
>
> slab_bug(s, "%s overwritten", what);
> - pr_err("INFO: 0x%p-0x%p @offset=%tu. First byte 0x%x instead of 0x%x\n",
> + pr_err("0x%p-0x%p @offset=%tu. First byte 0x%x instead of 0x%x\n",
> fault, end - 1, fault - addr,
> fault[0], value);
> print_trailer(s, page, object);
> @@ -3854,7 +3854,7 @@ static void list_slab_objects(struct kmem_cache *s, struct page *page,
> for_each_object(p, s, addr, page->objects) {
>
> if (!test_bit(__obj_to_index(s, addr, p), map)) {
> - pr_err("INFO: Object 0x%p @offset=%tu\n", p, p - addr);
> + pr_err("Object 0x%p @offset=%tu\n", p, p - addr);
> print_tracking(s, p);
> }
> }
>
On Mon, Feb 08, 2021 at 06:14:38PM +0800, Yafang Shao wrote:
> It is strange to combine "pr_err" with "INFO", so let's remove the
> prefix completely.
So is this the right thing to do? Should it be pr_info() instead?
Many of these messages do not appear to be error messages, but
rather informational messages.
On 2/8/21 6:26 PM, Matthew Wilcox wrote:
> On Mon, Feb 08, 2021 at 06:14:38PM +0800, Yafang Shao wrote:
>> It is strange to combine "pr_err" with "INFO", so let's remove the
>> prefix completely.
>
> So is this the right thing to do? Should it be pr_info() instead?
> Many of these messages do not appear to be error messages, but
> rather informational messages.
They are all part of longer error reports. See
https://lore.kernel.org/linux-mm/[email protected]/
On 2021/2/8 18:14, Yafang Shao wrote:
> It is strange to combine "pr_err" with "INFO", so let's remove the
> prefix completely.
> This patch is motivated by David's comment[1].
>
> - before the patch
> [ 8846.517809] INFO: Slab 0x00000000f42a2c60 objects=33 used=3 fp=0x0000000060d32ca8 flags=0x17ffffc0010200(slab|head)
>
> - after the patch
> [ 6343.396602] Slab 0x000000004382e02b objects=33 used=3 fp=0x000000009ae06ffc flags=0x17ffffc0010200(slab|head)
>
> [1]. https://lore.kernel.org/linux-mm/[email protected]/#t
>
> Suggested-by: Vlastimil Babka <[email protected]>
> Cc: David Hildenbrand <[email protected]>
> Signed-off-by: Yafang Shao <[email protected]>
Looks good,thanks.
Reviewed-by: Miaohe Lin <[email protected]>
> ---
> mm/slub.c | 10 +++++-----
> 1 file changed, 5 insertions(+), 5 deletions(-)
>
> diff --git a/mm/slub.c b/mm/slub.c
> index 87ff086e68a4..2514c37ab4e4 100644
> --- a/mm/slub.c
> +++ b/mm/slub.c
> @@ -612,7 +612,7 @@ static void print_track(const char *s, struct track *t, unsigned long pr_time)
> if (!t->addr)
> return;
>
> - pr_err("INFO: %s in %pS age=%lu cpu=%u pid=%d\n",
> + pr_err("%s in %pS age=%lu cpu=%u pid=%d\n",
> s, (void *)t->addr, pr_time - t->when, t->cpu, t->pid);
> #ifdef CONFIG_STACKTRACE
> {
> @@ -638,7 +638,7 @@ void print_tracking(struct kmem_cache *s, void *object)
>
> static void print_page_info(struct page *page)
> {
> - pr_err("INFO: Slab 0x%p objects=%u used=%u fp=0x%p flags=%#lx(%pGp)\n",
> + pr_err("Slab 0x%p objects=%u used=%u fp=0x%p flags=%#lx(%pGp)\n",
> page, page->objects, page->inuse, page->freelist,
> page->flags, &page->flags);
>
> @@ -695,7 +695,7 @@ static void print_trailer(struct kmem_cache *s, struct page *page, u8 *p)
>
> print_page_info(page);
>
> - pr_err("INFO: Object 0x%p @offset=%tu fp=0x%p\n\n",
> + pr_err("Object 0x%p @offset=%tu fp=0x%p\n\n",
> p, p - addr, get_freepointer(s, p));
>
> if (s->flags & SLAB_RED_ZONE)
> @@ -788,7 +788,7 @@ static int check_bytes_and_report(struct kmem_cache *s, struct page *page,
> end--;
>
> slab_bug(s, "%s overwritten", what);
> - pr_err("INFO: 0x%p-0x%p @offset=%tu. First byte 0x%x instead of 0x%x\n",
> + pr_err("0x%p-0x%p @offset=%tu. First byte 0x%x instead of 0x%x\n",
> fault, end - 1, fault - addr,
> fault[0], value);
> print_trailer(s, page, object);
> @@ -3854,7 +3854,7 @@ static void list_slab_objects(struct kmem_cache *s, struct page *page,
> for_each_object(p, s, addr, page->objects) {
>
> if (!test_bit(__obj_to_index(s, addr, p), map)) {
> - pr_err("INFO: Object 0x%p @offset=%tu\n", p, p - addr);
> + pr_err("Object 0x%p @offset=%tu\n", p, p - addr);
> print_tracking(s, p);
> }
> }
>