Hello,
It seems to me that a generic way to dynamically control the printing
of certain messages to the console during kernel boot is required.
Systems that really need this are large SMP systems or NUMA machines
with a large number of nodes. The number of messages that appear
per-node or per-cpu is huge in these machines.
I've created a small macro called printk_verbose() and a kernel command
line option to decide if these messages should be printed. The
command line option is:
printk_verbose=no or =yes
To deal with the very early messages, which are printed before the
kernel command line is processed, i've added a config option to set
whether printk_verbose is turned on by default.
The attached patch implements printk_verbose, and changes certain
printk's to printk_verbose. The ones that I changed were just to
illustrate my envisioned use of the facility. Specifically, I tried to
suppress the per-cpu, and per-node memory messages as well as the very
verbose IO APIC debug output. If some of these printk->printk_verbose
changes are deemed inappropriate that's fine.
Patch is against latest 2.5 bk and only effects x86 pc-compatible
for now.
Any comments?
mh
--
Wild Open Source Inc. [email protected]
# This is a BitKeeper generated patch for the following project:
# Project Name: Linux kernel tree
# This patch format is intended for GNU patch command version 2.5 or higher.
# This patch includes the following deltas:
# ChangeSet 1.1187 -> 1.1188
# include/linux/kernel.h 1.34 -> 1.35
# arch/i386/kernel/cpu/common.c 1.20 -> 1.21
# mm/page_alloc.c 1.148 -> 1.149
# arch/i386/Kconfig 1.49 -> 1.50
# arch/i386/kernel/cpu/intel.c 1.16 -> 1.17
# arch/i386/kernel/io_apic.c 1.58 -> 1.59
# arch/i386/kernel/smpboot.c 1.54 -> 1.55
# arch/i386/kernel/cpu/mcheck/p6.c 1.1 -> 1.2
# kernel/printk.c 1.23 -> 1.24
# include/asm-i386/mach-default/mach_apic.h 1.22 -> 1.23
#
# The following is the BitKeeper ChangeSet Log
# --------------------------------------------
# 03/03/21 [email protected] 1.1188
# Adds a new option called PRINTK_VERBOSE. This option allows certain printk's
# to be marked as purely extra debug info by using printk_verbose().
# This is useful for quieting certain boot messages that are not
# terribly important, except while debugging. This is especially true
# on large SMP systems, where each processor or node prints out large
# quantities of debug info.
# --------------------------------------------
#
diff -Nru a/arch/i386/Kconfig b/arch/i386/Kconfig
--- a/arch/i386/Kconfig Fri Mar 21 17:23:15 2003
+++ b/arch/i386/Kconfig Fri Mar 21 17:23:15 2003
@@ -1525,6 +1525,25 @@
If you don't debug the kernel, you can say N, but we may not be able
to solve problems without frame pointers.
+config PRINTK_VERBOSE
+ bool "Verbose printk during kernel bootup"
+ help
+ If you say Y here you will be able to control how verbose certain
+ early boot messages are with a kernel command line option. All
+ but the earliest messages can be controlled with this option.
+ If you don't need a lot of early debug info about CPUs and memory
+ say N here. This is especially helpful on large SMP systems.
+
+config PRINTK_VERBOSE_DEFAULT
+ bool "Turn verbose printk on by default"
+ depends on PRINTK_VERBOSE
+ help
+ The earliest messages that are controlled by PRINTK_VERBOSE cannot
+ be switched on and off with a kernel command line option. Saying
+ Y to this option turns verbose printk on by default for the earliest
+ stages of the kernel. The command line option can be used to turn
+ verbose printk off for the later stages of the boot.
+
config X86_EXTRA_IRQS
bool
depends on X86_LOCAL_APIC || X86_VOYAGER
diff -Nru a/arch/i386/kernel/cpu/common.c b/arch/i386/kernel/cpu/common.c
--- a/arch/i386/kernel/cpu/common.c Fri Mar 21 17:23:15 2003
+++ b/arch/i386/kernel/cpu/common.c Fri Mar 21 17:23:15 2003
@@ -83,7 +83,7 @@
if (n >= 0x80000005) {
cpuid(0x80000005, &dummy, &dummy, &ecx, &edx);
- printk(KERN_INFO "CPU: L1 I Cache: %dK (%d bytes/line), D cache %dK (%d bytes/line)\n",
+ printk_verbose(KERN_INFO "CPU: L1 I Cache: %dK (%d bytes/line), D cache %dK (%d bytes/line)\n",
edx>>24, edx&0xFF, ecx>>24, ecx&0xFF);
c->x86_cache_size=(ecx>>24)+(edx>>24);
}
@@ -107,7 +107,7 @@
c->x86_cache_size = l2size;
- printk(KERN_INFO "CPU: L2 Cache: %dK (%d bytes/line)\n",
+ printk_verbose(KERN_INFO "CPU: L2 Cache: %dK (%d bytes/line)\n",
l2size, ecx & 0xFF);
}
@@ -337,7 +337,7 @@
/* Now the feature flags better reflect actual CPU features! */
- printk(KERN_DEBUG "CPU: After generic, caps: %08lx %08lx %08lx %08lx\n",
+ printk_verbose(KERN_DEBUG "CPU: After generic, caps: %08lx %08lx %08lx %08lx\n",
c->x86_capability[0],
c->x86_capability[1],
c->x86_capability[2],
@@ -382,17 +382,17 @@
vendor = c->x86_vendor_id;
if (vendor && strncmp(c->x86_model_id, vendor, strlen(vendor)))
- printk("%s ", vendor);
+ printk_verbose("%s ", vendor);
if (!c->x86_model_id[0])
- printk("%d86", c->x86);
+ printk_verbose("%d86", c->x86);
else
- printk("%s", c->x86_model_id);
+ printk_verbose("%s", c->x86_model_id);
if (c->x86_mask || c->cpuid_level >= 0)
- printk(" stepping %02x\n", c->x86_mask);
+ printk_verbose(" stepping %02x\n", c->x86_mask);
else
- printk("\n");
+ printk_verbose("\n");
}
unsigned long cpu_initialized __initdata = 0;
diff -Nru a/arch/i386/kernel/cpu/intel.c b/arch/i386/kernel/cpu/intel.c
--- a/arch/i386/kernel/cpu/intel.c Fri Mar 21 17:23:15 2003
+++ b/arch/i386/kernel/cpu/intel.c Fri Mar 21 17:23:15 2003
@@ -134,8 +134,8 @@
if ((c->x86 == 15) && (c->x86_model == 1) && (c->x86_mask == 1)) {
rdmsr (MSR_IA32_MISC_ENABLE, lo, hi);
if ((lo & (1<<9)) == 0) {
- printk (KERN_INFO "CPU: C0 stepping P4 Xeon detected.\n");
- printk (KERN_INFO "CPU: Disabling hardware prefetching (Errata 037)\n");
+ printk_verbose(KERN_INFO "CPU: C0 stepping P4 Xeon detected.\n");
+ printk_verbose(KERN_INFO "CPU: Disabling hardware prefetching (Errata 037)\n");
lo |= (1<<9); /* Disable hw prefetching */
wrmsr (MSR_IA32_MISC_ENABLE, lo, hi);
}
diff -Nru a/arch/i386/kernel/cpu/mcheck/p6.c b/arch/i386/kernel/cpu/mcheck/p6.c
--- a/arch/i386/kernel/cpu/mcheck/p6.c Fri Mar 21 17:23:15 2003
+++ b/arch/i386/kernel/cpu/mcheck/p6.c Fri Mar 21 17:23:15 2003
@@ -95,7 +95,7 @@
machine_check_vector = intel_machine_check;
wmb();
- printk (KERN_INFO "Intel machine check architecture supported.\n");
+ printk_verbose(KERN_INFO "Intel machine check architecture supported.\n");
rdmsr (MSR_IA32_MCG_CAP, l, h);
if (l & (1<<8)) /* Control register present ? */
wrmsr(MSR_IA32_MCG_CTL, 0xffffffff, 0xffffffff);
@@ -108,6 +108,6 @@
}
set_in_cr4 (X86_CR4_MCE);
- printk (KERN_INFO "Intel machine check reporting enabled on CPU#%d.\n",
+ printk_verbose(KERN_INFO "Intel machine check reporting enabled on CPU#%d.\n",
smp_processor_id());
}
diff -Nru a/arch/i386/kernel/io_apic.c b/arch/i386/kernel/io_apic.c
--- a/arch/i386/kernel/io_apic.c Fri Mar 21 17:23:15 2003
+++ b/arch/i386/kernel/io_apic.c Fri Mar 21 17:23:15 2003
@@ -1278,16 +1278,16 @@
spin_unlock_irqrestore(&ioapic_lock, flags);
printk("\n");
- printk(KERN_DEBUG "IO APIC #%d......\n", mp_ioapics[apic].mpc_apicid);
- printk(KERN_DEBUG ".... register #00: %08X\n", *(int *)®_00);
- printk(KERN_DEBUG "....... : physical APIC id: %02X\n", reg_00.ID);
- printk(KERN_DEBUG "....... : Delivery Type: %X\n", reg_00.delivery_type);
- printk(KERN_DEBUG "....... : LTS : %X\n", reg_00.LTS);
+ printk_verbose(KERN_DEBUG "IO APIC #%d......\n", mp_ioapics[apic].mpc_apicid);
+ printk_verbose(KERN_DEBUG ".... register #00: %08X\n", *(int *)®_00);
+ printk_verbose(KERN_DEBUG "....... : physical APIC id: %02X\n", reg_00.ID);
+ printk_verbose(KERN_DEBUG "....... : Delivery Type: %X\n", reg_00.delivery_type);
+ printk_verbose(KERN_DEBUG "....... : LTS : %X\n", reg_00.LTS);
if (reg_00.__reserved_0 || reg_00.__reserved_1 || reg_00.__reserved_2)
UNEXPECTED_IO_APIC();
- printk(KERN_DEBUG ".... register #01: %08X\n", *(int *)®_01);
- printk(KERN_DEBUG "....... : max redirection entries: %04X\n", reg_01.entries);
+ printk_verbose(KERN_DEBUG ".... register #01: %08X\n", *(int *)®_01);
+ printk_verbose(KERN_DEBUG "....... : max redirection entries: %04X\n", reg_01.entries);
if ( (reg_01.entries != 0x0f) && /* older (Neptune) boards */
(reg_01.entries != 0x17) && /* typical ISA+PCI boards */
(reg_01.entries != 0x1b) && /* Compaq Proliant boards */
@@ -1298,8 +1298,8 @@
)
UNEXPECTED_IO_APIC();
- printk(KERN_DEBUG "....... : PRQ implemented: %X\n", reg_01.PRQ);
- printk(KERN_DEBUG "....... : IO APIC version: %04X\n", reg_01.version);
+ printk_verbose(KERN_DEBUG "....... : PRQ implemented: %X\n", reg_01.PRQ);
+ printk_verbose(KERN_DEBUG "....... : IO APIC version: %04X\n", reg_01.version);
if ( (reg_01.version != 0x01) && /* 82489DX IO-APICs */
(reg_01.version != 0x10) && /* oldest IO-APICs */
(reg_01.version != 0x11) && /* Pentium/Pro IO-APICs */
@@ -1311,15 +1311,15 @@
UNEXPECTED_IO_APIC();
if (reg_01.version >= 0x10) {
- printk(KERN_DEBUG ".... register #02: %08X\n", *(int *)®_02);
- printk(KERN_DEBUG "....... : arbitration: %02X\n", reg_02.arbitration);
+ printk_verbose(KERN_DEBUG ".... register #02: %08X\n", *(int *)®_02);
+ printk_verbose(KERN_DEBUG "....... : arbitration: %02X\n", reg_02.arbitration);
if (reg_02.__reserved_1 || reg_02.__reserved_2)
UNEXPECTED_IO_APIC();
}
- printk(KERN_DEBUG ".... IRQ redirection table:\n");
+ printk_verbose(KERN_DEBUG ".... IRQ redirection table:\n");
- printk(KERN_DEBUG " NR Log Phy Mask Trig IRR Pol"
+ printk_verbose(KERN_DEBUG " NR Log Phy Mask Trig IRR Pol"
" Stat Dest Deli Vect: \n");
for (i = 0; i <= reg_01.entries; i++) {
@@ -1330,13 +1330,13 @@
*(((int *)&entry)+1) = io_apic_read(apic, 0x11+i*2);
spin_unlock_irqrestore(&ioapic_lock, flags);
- printk(KERN_DEBUG " %02x %03X %02X ",
+ printk_verbose(KERN_DEBUG " %02x %03X %02X ",
i,
entry.dest.logical.logical_dest,
entry.dest.physical.physical_dest
);
- printk("%1d %1d %1d %1d %1d %1d %1d %02X\n",
+ printk_verbose("%1d %1d %1d %1d %1d %1d %1d %02X\n",
entry.mask,
entry.trigger,
entry.irr,
@@ -1348,19 +1348,19 @@
);
}
}
- printk(KERN_DEBUG "IRQ to pin mappings:\n");
+ printk_verbose(KERN_DEBUG "IRQ to pin mappings:\n");
for (i = 0; i < NR_IRQS; i++) {
struct irq_pin_list *entry = irq_2_pin + i;
if (entry->pin < 0)
continue;
- printk(KERN_DEBUG "IRQ%d ", i);
+ printk_verbose(KERN_DEBUG "IRQ%d ", i);
for (;;) {
- printk("-> %d:%d", entry->apic, entry->pin);
+ printk_verbose("-> %d:%d", entry->apic, entry->pin);
if (!entry->next)
break;
entry = irq_2_pin + entry->next;
}
- printk("\n");
+ printk_verbose("\n");
}
printk(KERN_INFO ".................................... done.\n");
diff -Nru a/arch/i386/kernel/smpboot.c b/arch/i386/kernel/smpboot.c
--- a/arch/i386/kernel/smpboot.c Fri Mar 21 17:23:15 2003
+++ b/arch/i386/kernel/smpboot.c Fri Mar 21 17:23:15 2003
@@ -856,7 +856,7 @@
if (test_bit(cpu, &cpu_callin_map)) {
/* number CPUs logically, starting from 1 (BSP is 0) */
Dprintk("OK.\n");
- printk("CPU%d: ", cpu);
+ printk_verbose("CPU%d: ", cpu);
print_cpu_info(&cpu_data[cpu]);
Dprintk("CPU has booted.\n");
} else {
diff -Nru a/include/asm-i386/mach-default/mach_apic.h b/include/asm-i386/mach-default/mach_apic.h
--- a/include/asm-i386/mach-default/mach_apic.h Fri Mar 21 17:23:15 2003
+++ b/include/asm-i386/mach-default/mach_apic.h Fri Mar 21 17:23:15 2003
@@ -82,7 +82,7 @@
static inline int mpc_apic_id(struct mpc_config_processor *m,
struct mpc_config_translation *translation_record)
{
- printk("Processor #%d %ld:%ld APIC version %d\n",
+ printk_verbose("Processor #%d %ld:%ld APIC version %d\n",
m->mpc_apicid,
(m->mpc_cpufeature & CPU_FAMILY_MASK) >> 8,
(m->mpc_cpufeature & CPU_MODEL_MASK) >> 4,
diff -Nru a/include/linux/kernel.h b/include/linux/kernel.h
--- a/include/linux/kernel.h Fri Mar 21 17:23:15 2003
+++ b/include/linux/kernel.h Fri Mar 21 17:23:15 2003
@@ -91,6 +91,16 @@
asmlinkage int printk(const char * fmt, ...)
__attribute__ ((format (printf, 1, 2)));
+extern int printk_verbose_flag;
+#ifdef CONFIG_PRINTK_VERBOSE
+# define printk_verbose(args...) do { \
+ if (printk_verbose_flag) \
+ printk(args); \
+} while (0)
+#else
+# define printk_verbose(args...)
+#endif
+
static inline void console_silent(void)
{
console_loglevel = 0;
diff -Nru a/kernel/printk.c b/kernel/printk.c
--- a/kernel/printk.c Fri Mar 21 17:23:15 2003
+++ b/kernel/printk.c Fri Mar 21 17:23:15 2003
@@ -51,6 +51,12 @@
DEFAULT_CONSOLE_LOGLEVEL, /* default_console_loglevel */
};
+#ifdef CONFIG_PRINTK_VERBOSE_DEFAULT
+int printk_verbose_flag = 1;
+#else
+int printk_verbose_flag = 0;
+#endif
+
int oops_in_progress;
/*
@@ -140,6 +146,20 @@
}
__setup("console=", console_setup);
+
+/*
+ * Check if we want to do verbose printk messages during kernel boot.
+ * Called from init/main.c during parse_options.
+ */
+static void __init printk_verbose_setup(char *str)
+{
+ if (!strncmp(str, "yes", 3))
+ printk_verbose_flag = 1;
+ if (!strncmp(str, "no", 2))
+ printk_verbose_flag = 0;
+}
+
+__setup("printk_verbose=", printk_verbose_setup);
/*
* Commands to do_syslog:
diff -Nru a/mm/page_alloc.c b/mm/page_alloc.c
--- a/mm/page_alloc.c Fri Mar 21 17:23:15 2003
+++ b/mm/page_alloc.c Fri Mar 21 17:23:15 2003
@@ -1125,7 +1125,7 @@
if (zholes_size)
for (i = 0; i < MAX_NR_ZONES; i++)
realtotalpages -= zholes_size[i];
- printk("On node %d totalpages: %lu\n", pgdat->node_id, realtotalpages);
+ printk_verbose("On node %d totalpages: %lu\n", pgdat->node_id, realtotalpages);
}
/*
@@ -1214,7 +1214,7 @@
pcp->batch = 1 * batch;
INIT_LIST_HEAD(&pcp->list);
}
- printk(" %s zone: %lu pages, LIFO batch:%lu\n",
+ printk_verbose(" %s zone: %lu pages, LIFO batch:%lu\n",
zone_names[j], realsize, batch);
INIT_LIST_HEAD(&zone->active_list);
INIT_LIST_HEAD(&zone->inactive_list);
Followup to: <[email protected]>
By author: Martin Hicks <[email protected]>
In newsgroup: linux.dev.kernel
>
> It seems to me that a generic way to dynamically control the printing
> of certain messages to the console during kernel boot is required.
> Systems that really need this are large SMP systems or NUMA machines
> with a large number of nodes. The number of messages that appear
> per-node or per-cpu is huge in these machines.
>
See KERN_EMERG, KERN_ALERT, KERN_CRIT, KERN_ERR, KERN_WARNING,
KERN_NOTICE, KERN_INFO, KERN_DEBUG.
-hpa
--
<[email protected]> at work, <[email protected]> in private!
"Unix gives you enough rope to shoot yourself in the foot."
Architectures needed: ia64 m68k mips64 ppc ppc64 s390 s390x sh v850 x86-64
On Fri, Mar 21, 2003 at 06:15:06PM -0800, H. Peter Anvin wrote:
> Followup to: <[email protected]>
> By author: Martin Hicks <[email protected]>
> In newsgroup: linux.dev.kernel
> >
> > It seems to me that a generic way to dynamically control the printing
> > of certain messages to the console during kernel boot is required.
> > Systems that really need this are large SMP systems or NUMA machines
> > with a large number of nodes. The number of messages that appear
> > per-node or per-cpu is huge in these machines.
> >
>
> See KERN_EMERG, KERN_ALERT, KERN_CRIT, KERN_ERR, KERN_WARNING,
> KERN_NOTICE, KERN_INFO, KERN_DEBUG.
Okay, perhaps I didn't clearly identify the problem last time. The
problem is the number of messages that go into the log_buf. On
large systems we can certainly just crank up the size of log_buf, but I
don't see this as a terribly elegant solution.
I think there should be some facility, mirroring the way we can set a
threshold for console messages, to decide if a message is logged at all.
For example, setting console_loglevel and log_loglevel (the new
threshold) to 7 results in no KERN_DEBUG messages begin printed to the
console or the log.
I'm testing a patch now, but are there any comments on the basic idea?
Is it preferrable to just crank up the size of log_buf?
mh
--
Martin Hicks || [email protected] || PGP/GnuPG: 0x4C7F2BEE
plato up 2 days, 22:44, 14 users, load average: 2.64, 0.94, 0.34
Great Spirits have always encountered opposition from mediocre minds
-Albert Einstein
Martin Hicks wrote:
>
> Okay, perhaps I didn't clearly identify the problem last time. The
> problem is the number of messages that go into the log_buf. On
> large systems we can certainly just crank up the size of log_buf, but I
> don't see this as a terribly elegant solution.
>
> I think there should be some facility, mirroring the way we can set a
> threshold for console messages, to decide if a message is logged at all.
> For example, setting console_loglevel and log_loglevel (the new
> threshold) to 7 results in no KERN_DEBUG messages begin printed to the
> console or the log.
>
> I'm testing a patch now, but are there any comments on the basic idea?
> Is it preferrable to just crank up the size of log_buf?
>
This is probably a good idea. It might also be worthwhile to implement
per-subsystem filtering similar to what syslog has; the network
subsystem is particular is notoriously noisy when it comes to telling me
that someone else sent bad packets. If you're a public Internet server,
that happens *all the time*...
-hpa