[PATCH] Print sysrq-m messages with KERN_INFO priority

[PATCH] Print sysrq-m messages with KERN_INFO priority

[Theodore Ts'o]

Print messages resulting from sysrq-m with a KERN_INFO instead of the
default KERN_WARNING priority

Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>

Index: linux-2.6/mm/page_alloc.c
===================================================================
--- linux-2.6.orig/mm/page_alloc.c	2006-12-25 09:21:54.000000000 -0500
+++ linux-2.6/mm/page_alloc.c	2006-12-29 17:19:11.000000000 -0500
@@ -1505,7 +1505,7 @@
 static inline void show_node(struct zone *zone)
 {
 	if (NUMA_BUILD)
-		printk("Node %d ", zone_to_nid(zone));
+		printk(KERN_INFO, "Node %d ", zone_to_nid(zone));
 }
 
 void si_meminfo(struct sysinfo *val)
@@ -1566,8 +1566,8 @@
 
 			pageset = zone_pcp(zone, cpu);
 
-			printk("CPU %4d: Hot: hi:%5d, btch:%4d usd:%4d   "
-			       "Cold: hi:%5d, btch:%4d usd:%4d\n",
+			printk(KERN_INFO "CPU %4d: Hot: hi:%5d, btch:%4d "
+			       "usd:%4d   Cold: hi:%5d, btch:%4d usd:%4d\n",
 			       cpu, pageset->pcp[0].high,
 			       pageset->pcp[0].batch, pageset->pcp[0].count,
 			       pageset->pcp[1].high, pageset->pcp[1].batch,
@@ -1577,7 +1577,7 @@
 
 	get_zone_counts(&active, &inactive, &free);
 
-	printk("Active:%lu inactive:%lu dirty:%lu writeback:%lu "
+	printk(KERN_INFO "Active:%lu inactive:%lu dirty:%lu writeback:%lu "
 		"unstable:%lu free:%u slab:%lu mapped:%lu pagetables:%lu\n",
 		active,
 		inactive,
@@ -1619,7 +1619,7 @@
 			zone->pages_scanned,
 			(zone->all_unreclaimable ? "yes" : "no")
 			);
-		printk("lowmem_reserve[]:");
+		printk(KERN_INFO "lowmem_reserve[]:");
 		for (i = 0; i < MAX_NR_ZONES; i++)
 			printk(" %lu", zone->lowmem_reserve[i]);
 		printk("\n");
@@ -1875,7 +1875,7 @@
 		/* cpuset refresh routine should be here */
 	}
 	vm_total_pages = nr_free_pagecache_pages();
-	printk("Built %i zonelists.  Total pages: %ld\n",
+	printk(KERN_INFO "Built %i zonelists.  Total pages: %ld\n",
 			num_online_nodes(), vm_total_pages);
 }
 
Index: linux-2.6/mm/swap_state.c
===================================================================
--- linux-2.6.orig/mm/swap_state.c	2006-07-04 18:38:19.000000000 -0400
+++ linux-2.6/mm/swap_state.c	2006-12-29 17:18:42.000000000 -0500
@@ -57,12 +57,14 @@
 
 void show_swap_cache_info(void)
 {
-	printk("Swap cache: add %lu, delete %lu, find %lu/%lu, race %lu+%lu\n",
+	printk(KERN_INFO "Swap cache: add %lu, delete %lu, find %lu/%lu, race %lu+%lu\n",
 		swap_cache_info.add_total, swap_cache_info.del_total,
 		swap_cache_info.find_success, swap_cache_info.find_total,
 		swap_cache_info.noent_race, swap_cache_info.exist_race);
-	printk("Free swap  = %lukB\n", nr_swap_pages << (PAGE_SHIFT - 10));
-	printk("Total swap = %lukB\n", total_swap_pages << (PAGE_SHIFT - 10));
+	printk(KERN_INFO "Free swap  = %lukB\n",
+	       nr_swap_pages << (PAGE_SHIFT - 10));
+	printk(KERN_INFO "Total swap = %lukB\n",
+	       total_swap_pages << (PAGE_SHIFT - 10));
 }
 
 /*

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Andrew Morton]

On Fri, 29 Dec 2006 22:24:53 -0500
"Theodore Ts'o" <tytso@mit.edu> wrote:

> Print messages resulting from sysrq-m with a KERN_INFO instead of the
> default KERN_WARNING priority

hm, I wonder why.  If someone does sysrq-<whatever> then they presumably want
to display the result?  Tricky.

Is this patch a consistency thing?

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Dave Jones]

On Fri, Dec 29, 2006 at 08:42:47PM -0800, Andrew Morton wrote:
 > On Fri, 29 Dec 2006 22:24:53 -0500
 > "Theodore Ts'o" <tytso@mit.edu> wrote:
 > 
 > > Print messages resulting from sysrq-m with a KERN_INFO instead of the
 > > default KERN_WARNING priority
 > 
 > hm, I wonder why.  If someone does sysrq-<whatever> then they presumably want
 > to display the result?  Tricky.

I looked at this and got even more puzzled.
__handle_sysrq temporarily sets the loglevel to 7 (KERN_DEBUG) for the
duration of the sysrq-<whatever> output.

Which is odd, as KERN_DEBUG stuff is usually hidden, yet the
printk's that lack loglevels still seem to end up onscreen.

Ted's patch also misses a few of the printk's in show_free_areas()
which seems inconsistent, or am I just confused?

		Dave

-- 
http://www.codemonkey.org.uk

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[* *]

Was this patch tested?

On 12/29/06, Theodore Ts'o <tytso@mit.edu> wrote:
> Print messages resulting from sysrq-m with a KERN_INFO instead of the
> default KERN_WARNING priority
>
> Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
>
> Index: linux-2.6/mm/page_alloc.c
> ===================================================================
> --- linux-2.6.orig/mm/page_alloc.c      2006-12-25 09:21:54.000000000 -0500
> +++ linux-2.6/mm/page_alloc.c   2006-12-29 17:19:11.000000000 -0500
> @@ -1505,7 +1505,7 @@
>  static inline void show_node(struct zone *zone)
>  {
>         if (NUMA_BUILD)
> -               printk("Node %d ", zone_to_nid(zone));
> +               printk(KERN_INFO, "Node %d ", zone_to_nid(zone));

Here there is a comma after KERN_INFO, which does not occur elsewhere.

>  }
>
>  void si_meminfo(struct sysinfo *val)
> @@ -1566,8 +1566,8 @@
>
>                         pageset = zone_pcp(zone, cpu);
>
> -                       printk("CPU %4d: Hot: hi:%5d, btch:%4d usd:%4d   "
> -                              "Cold: hi:%5d, btch:%4d usd:%4d\n",
> +                       printk(KERN_INFO "CPU %4d: Hot: hi:%5d, btch:%4d "
> +                              "usd:%4d   Cold: hi:%5d, btch:%4d usd:%4d\n",
>                                cpu, pageset->pcp[0].high,
>                                pageset->pcp[0].batch, pageset->pcp[0].count,
>                                pageset->pcp[1].high, pageset->pcp[1].batch,
> @@ -1577,7 +1577,7 @@
>
>         get_zone_counts(&active, &inactive, &free);
>
> -       printk("Active:%lu inactive:%lu dirty:%lu writeback:%lu "
> +       printk(KERN_INFO "Active:%lu inactive:%lu dirty:%lu writeback:%lu "
>                 "unstable:%lu free:%u slab:%lu mapped:%lu pagetables:%lu\n",
>                 active,
>                 inactive,
> @@ -1619,7 +1619,7 @@
>                         zone->pages_scanned,
>                         (zone->all_unreclaimable ? "yes" : "no")
>                         );
> -               printk("lowmem_reserve[]:");
> +               printk(KERN_INFO "lowmem_reserve[]:");
>                 for (i = 0; i < MAX_NR_ZONES; i++)
>                         printk(" %lu", zone->lowmem_reserve[i]);
>                 printk("\n");
> @@ -1875,7 +1875,7 @@
>                 /* cpuset refresh routine should be here */
>         }
>         vm_total_pages = nr_free_pagecache_pages();
> -       printk("Built %i zonelists.  Total pages: %ld\n",
> +       printk(KERN_INFO "Built %i zonelists.  Total pages: %ld\n",
>                         num_online_nodes(), vm_total_pages);
>  }
>
> Index: linux-2.6/mm/swap_state.c
> ===================================================================
> --- linux-2.6.orig/mm/swap_state.c      2006-07-04 18:38:19.000000000 -0400
> +++ linux-2.6/mm/swap_state.c   2006-12-29 17:18:42.000000000 -0500
> @@ -57,12 +57,14 @@
>
>  void show_swap_cache_info(void)
>  {
> -       printk("Swap cache: add %lu, delete %lu, find %lu/%lu, race %lu+%lu\n",
> +       printk(KERN_INFO "Swap cache: add %lu, delete %lu, find %lu/%lu, race %lu+%lu\n",
>                 swap_cache_info.add_total, swap_cache_info.del_total,
>                 swap_cache_info.find_success, swap_cache_info.find_total,
>                 swap_cache_info.noent_race, swap_cache_info.exist_race);
> -       printk("Free swap  = %lukB\n", nr_swap_pages << (PAGE_SHIFT - 10));
> -       printk("Total swap = %lukB\n", total_swap_pages << (PAGE_SHIFT - 10));
> +       printk(KERN_INFO "Free swap  = %lukB\n",
> +              nr_swap_pages << (PAGE_SHIFT - 10));
> +       printk(KERN_INFO "Total swap = %lukB\n",
> +              total_swap_pages << (PAGE_SHIFT - 10));
>  }
>
>  /*
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Theodore Tso]

On Fri, Dec 29, 2006 at 11:19:49PM -0600, * * wrote:
> Was this patch tested?
> 
> > static inline void show_node(struct zone *zone)
> > {
> >        if (NUMA_BUILD)
> >-               printk("Node %d ", zone_to_nid(zone));
> >+               printk(KERN_INFO, "Node %d ", zone_to_nid(zone));
> 
> Here there is a comma after KERN_INFO, which does not occur elsewhere.

Thanks for noticing the typo.  Yes, it's been tested and in my tree
for a while, but not on a NUMA system, so I didn't notice the problem.  :-)

						- Ted

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Theodore Tso]

On Fri, Dec 29, 2006 at 08:42:47PM -0800, Andrew Morton wrote:
> On Fri, 29 Dec 2006 22:24:53 -0500
> "Theodore Ts'o" <tytso@mit.edu> wrote:
> 
> > Print messages resulting from sysrq-m with a KERN_INFO instead of the
> > default KERN_WARNING priority
> 
> hm, I wonder why.  If someone does sysrq-<whatever> then they presumably want
> to display the result?  Tricky.
> 
> Is this patch a consistency thing?

The goal of the patch was to avoid filling /var/log/messages huge
amounts of sysrq text.  Some of the sysrq commands, especially sysrq-m
and sysrq-t emit a truly vast amount of information, and it's not
really nice to have that filling up /var/log/messages.  

						- Ted

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Alan]

On Mon, 1 Jan 2007 23:37:43 -0500
Theodore Tso <tytso@mit.edu> wrote:
> > Is this patch a consistency thing?
> 
> The goal of the patch was to avoid filling /var/log/messages huge
> amounts of sysrq text.  Some of the sysrq commands, especially sysrq-m
> and sysrq-t emit a truly vast amount of information, and it's not
> really nice to have that filling up /var/log/messages.  

I find it extremely useful that it ends up in /var/log/messages so that I
can review the dump later. Often the first glance through a set of dumps
on things like a process deadlock don't reveal the right information and
you need to go back and look again.

Alan

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Dave Jones]

On Tue, Jan 02, 2007 at 10:33:32AM +0000, Alan Cox wrote:
 > On Mon, 1 Jan 2007 23:37:43 -0500
 > Theodore Tso <tytso@mit.edu> wrote:
 > > > Is this patch a consistency thing?
 > > 
 > > The goal of the patch was to avoid filling /var/log/messages huge
 > > amounts of sysrq text.  Some of the sysrq commands, especially sysrq-m
 > > and sysrq-t emit a truly vast amount of information, and it's not
 > > really nice to have that filling up /var/log/messages.  
 > 
 > I find it extremely useful that it ends up in /var/log/messages so that I
 > can review the dump later. Often the first glance through a set of dumps
 > on things like a process deadlock don't reveal the right information and
 > you need to go back and look again.

Seconded.  And with the limited scrollback of the ringbuffer, sometimes
looking through the logs is the only way to get the info.

		Dave

-- 
http://www.codemonkey.org.uk

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Theodore Tso]

On Tue, Jan 02, 2007 at 10:33:32AM +0000, Alan wrote:
> On Mon, 1 Jan 2007 23:37:43 -0500
> Theodore Tso <tytso@mit.edu> wrote:
> > > Is this patch a consistency thing?
> > 
> > The goal of the patch was to avoid filling /var/log/messages huge
> > amounts of sysrq text.  Some of the sysrq commands, especially sysrq-m
> > and sysrq-t emit a truly vast amount of information, and it's not
> > really nice to have that filling up /var/log/messages.  
> 
> I find it extremely useful that it ends up in /var/log/messages so that I
> can review the dump later. Often the first glance through a set of dumps
> on things like a process deadlock don't reveal the right information and
> you need to go back and look again.

Maybe it's something that should be configurable?

Usually I end up configuring a separate line in /etc/syslog.conf so
that it gets logged to a file --- but not one which is subject to the
same retention period as /var/log/messages.  The reason why this
becomes an issue for me is that unfortunately, there is some
information displayed by alt-sysrq-m that can't be found any other way
--- it's not available in /proc/slabinfo, /proc/meminfo, etc.  So I
have a script which I use when I'm trying to debug obscure customer
problems which does an "echo m > /proc/sysrq-trigger" every 15
minutes, so I can gather information that might help point towards the
problem. 

Granted, most of the time the additional information shown by sysrq-m
isn't necessary, but I usually get called in after the other Level 3
support folks haven't been able to solve the problem, so like the
Richard Feymenn story, it's a tool that everyone else doesn't have in
their toolbox, so it often solves problems that others haven't been
able to figure out.

So maybe the right solution is either to make the priority level
configurable, or perhaps better, making the sysrq-m information
available via either /proc or /sys?

						- Ted

Re: [PATCH] Print sysrq-m messages with KERN_INFO priority

[Dave Jones]

On Tue, Jan 02, 2007 at 01:03:54PM -0500, Theodore Tso wrote:

 > or perhaps better, making the sysrq-m information
 > available via either /proc or /sys?

or debugfs ?

		Dave


-- 
http://www.codemonkey.org.uk