[PATCH 0/7] Limit console output by suppressing repetitious messages

[Mike Travis]

Second version...

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

[Mike Travis]

With a large number of processors in a system there is an excessive amount
of messages sent to the system console.  It's estimated that with 4096
processors in a system, and the console baudrate set to 56K, the startup
messages will take about 84 minutes to clear the serial port.

This set of patches limits the number of repetitious messages which contain
no additional information.  Much of this information is obtainable from the
/proc and /sysfs.   Most of the messages are also sent to the kernel log
buffer as KERN_DEBUG messages so it can be used to examine more closely any
details specific to a processor.

The list of message transformations....

For system_state == SYSTEM_BOOTING:

[   18.669304] Booting Node   0, Processors  1 2 3 4 5 6 7 Ok.
[   19.321065] Booting Node   1, Processors  8 9 10 11 12 13 14 15 Ok.
[   20.065325] Booting Node   2, Processors  16 17 18 19 20 21 22 23 Ok.
..
[  117.153053] Booting Node  63, Processors  1016 1017 1018 1019 1020 1021 1022 1023 Ok.
[  117.952235] Brought up 1024 CPUs

Timing shows that with NO bootup messages, it takes only slightly less time
so printing adds very little overhead:

[   18.670219] Booting all processors
[  117.180248] Brought up 1024 CPUs

For Processor Information printout, the specifics of CPU0 are printed and
then at the end of the bootup sequence, a summary is printed:

[  117.957682] Processor Information for CPUS: 0-191,208-223,256-271,...
[  117.968034] Genuine Intel(R) CPU             0000 @ 2.13GHz stepping 04
[  117.977406] BogoMIPS: MIN 3989.01 (7978031) AVG 4266.62 (8533249) MAX 4537.51 (9075028)
[  117.984496] Processor Information for CPUS: 192-207,240-255,272-287,...
[  117.996032] Genuine Intel(R) CPU             0000 @ 2.13GHz stepping 03
[  118.001404] BogoMIPS: MIN 4021.49 (8042995) AVG 4265.91 (8531833) MAX 4479.79 (8959584)
[  118.012373] Processor Information for CPUS: 224-239,736-751
[  118.020032] Genuine Intel(R) CPU             0000 @ 1.87GHz stepping 03
[  118.028033] BogoMIPS: MIN 3733.92 (7467855) AVG 3746.96 (7493933) MAX 3939.52 (7879056)
[  118.036360] Processor Information for CPUS: 320-335,384-415,432-447,...
[  118.044032] Intel(R) Xeon(R) CPU           X7560  @ 2.27GHz stepping 05
[  118.053404] BogoMIPS: MIN 4244.65 (8489318) AVG 4532.45 (9064917) MAX 4666.80 (9333604)
[  118.060644] Total of 1024 processors activated (4386353.46 BogoMIPS).


The following lines have been removed:

        CPU: Physical Processor ID:
        CPU: Processor Core ID:
        CPU %d/0x%x -> Node %d

The following lines will only be printed if unusual (state):

        CPU %d is now offline  (system_state == RUNNING)

The following lines will only be printed in debug mode:

        Initializing CPU#%d

The following lines are only printed for the first cpu:

        CPU0: Hyper-Threading is disabled
        CPU0: Thermal monitoring enabled
        CPU0: <cache line sizes>


Signed-off-by: Mike Travis <travis@...>
---
 arch/x86/kernel/cpu/addon_cpuid_features.c |    6 -
 arch/x86/kernel/cpu/amd.c                  |    2
 arch/x86/kernel/cpu/common.c               |   20 +---
 arch/x86/kernel/cpu/intel.c                |    2
 arch/x86/kernel/cpu/intel_cacheinfo.c      |   28 +++---
 arch/x86/kernel/cpu/mcheck/therm_throt.c   |    5 -
 arch/x86/kernel/smpboot.c                  |  118 +++++++++++++++++++++++++----
 7 files changed, 129 insertions(+), 52 deletions(-)

--- linux.orig/arch/x86/kernel/cpu/addon_cpuid_features.c
+++ linux/arch/x86/kernel/cpu/addon_cpuid_features.c
@@ -127,12 +127,6 @@
 
  c->x86_max_cores = (core_level_siblings / smp_num_siblings);
 
-
- printk(KERN_INFO  "CPU: Physical Processor ID: %d\n",
-       c->phys_proc_id);
- if (c->x86_max_cores > 1)
- printk(KERN_INFO  "CPU: Processor Core ID: %d\n",
-       c->cpu_core_id);
  return;
 #endif
 }
--- linux.orig/arch/x86/kernel/cpu/amd.c
+++ linux/arch/x86/kernel/cpu/amd.c
@@ -375,8 +375,6 @@
  node = nearby_node(apicid);
  }
  numa_set_node(cpu, node);
-
- printk(KERN_INFO "CPU %d/0x%x -> Node %d\n", cpu, apicid, node);
 #endif
 }
 
--- linux.orig/arch/x86/kernel/cpu/common.c
+++ linux/arch/x86/kernel/cpu/common.c
@@ -437,7 +437,7 @@
  return;
 
  if (cpu_has(c, X86_FEATURE_CMP_LEGACY))
- goto out;
+ return;
 
  if (cpu_has(c, X86_FEATURE_XTOPOLOGY))
  return;
@@ -446,13 +446,13 @@
 
  smp_num_siblings = (ebx & 0xff0000) >> 16;
 
- if (smp_num_siblings == 1) {
- printk(KERN_INFO  "CPU: Hyper-Threading is disabled\n");
- goto out;
+ if (smp_num_siblings == 1 && c->cpu_index == 0) {
+ pr_info("CPU0: Hyper-Threading is disabled\n");
+ return;
  }
 
  if (smp_num_siblings <= 1)
- goto out;
+ return;
 
  if (smp_num_siblings > nr_cpu_ids) {
  pr_warning("CPU: Unsupported number of siblings %d",
@@ -472,14 +472,6 @@
 
  c->cpu_core_id = apic->phys_pkg_id(c->initial_apicid, index_msb) &
        ((1 << core_bits) - 1);
-
-out:
- if ((c->x86_max_cores * smp_num_siblings) > 1) {
- printk(KERN_INFO  "CPU: Physical Processor ID: %d\n",
-       c->phys_proc_id);
- printk(KERN_INFO  "CPU: Processor Core ID: %d\n",
-       c->cpu_core_id);
- }
 #endif
 }
 
@@ -1115,7 +1107,7 @@
  if (cpumask_test_and_set_cpu(cpu, cpu_initialized_mask))
  panic("CPU#%d already initialized!\n", cpu);
 
- printk(KERN_INFO "Initializing CPU#%d\n", cpu);
+ pr_debug("Initializing CPU#%d\n", cpu);
 
  clear_in_cr4(X86_CR4_VME|X86_CR4_PVI|X86_CR4_TSD|X86_CR4_DE);
 
--- linux.orig/arch/x86/kernel/cpu/intel.c
+++ linux/arch/x86/kernel/cpu/intel.c
@@ -266,8 +266,6 @@
  if (node == NUMA_NO_NODE || !node_online(node))
  node = first_node(node_online_map);
  numa_set_node(cpu, node);
-
- printk(KERN_INFO "CPU %d/0x%x -> Node %d\n", cpu, apicid, node);
 #endif
 }
 
--- linux.orig/arch/x86/kernel/cpu/intel_cacheinfo.c
+++ linux/arch/x86/kernel/cpu/intel_cacheinfo.c
@@ -488,21 +488,23 @@
 #endif
  }
 
- if (trace)
- printk(KERN_INFO "CPU: Trace cache: %dK uops", trace);
- else if (l1i)
- printk(KERN_INFO "CPU: L1 I cache: %dK", l1i);
-
- if (l1d)
- printk(KERN_CONT ", L1 D cache: %dK\n", l1d);
- else
- printk(KERN_CONT "\n");
+ if (c->cpu_index == 0) {
+ if (trace)
+ pr_info("CPU0: Trace cache: %dK uops", trace);
+ else if (l1i)
+ pr_info("CPU0: L1 I cache: %dK", l1i);
+
+ if (l1d)
+ pr_cont(", L1 D cache: %dK\n", l1d);
+ else
+ pr_cont("\n");
 
- if (l2)
- printk(KERN_INFO "CPU: L2 cache: %dK\n", l2);
+ if (l2)
+ pr_info("CPU0: L2 cache: %dK\n", l2);
 
- if (l3)
- printk(KERN_INFO "CPU: L3 cache: %dK\n", l3);
+ if (l3)
+ pr_info("CPU0: L3 cache: %dK\n", l3);
+ }
 
  c->x86_cache_size = l3 ? l3 : (l2 ? l2 : (l1i+l1d));
 
--- linux.orig/arch/x86/kernel/cpu/mcheck/therm_throt.c
+++ linux/arch/x86/kernel/cpu/mcheck/therm_throt.c
@@ -312,8 +312,9 @@
  l = apic_read(APIC_LVTTHMR);
  apic_write(APIC_LVTTHMR, l & ~APIC_LVT_MASKED);
 
- printk(KERN_INFO "CPU%d: Thermal monitoring enabled (%s)\n",
-       cpu, tm2 ? "TM2" : "TM1");
+ if (cpu == 0)
+ printk(KERN_INFO "CPU0: Thermal monitoring enabled (%s)\n",
+       tm2 ? "TM2" : "TM1");
 
  /* enable thermal throttle processing */
  atomic_set(&therm_throt_en, 1);
--- linux.orig/arch/x86/kernel/smpboot.c
+++ linux/arch/x86/kernel/smpboot.c
@@ -442,6 +442,84 @@
  return c->llc_shared_map;
 }
 
+/* Summarize Processor Information */
+static void __init summarize_cpu_info(void)
+{
+ cpumask_var_t cpulist, cpusdone;
+ int cpu;
+ int err = 0;
+
+ if (!alloc_cpumask_var(&cpulist, GFP_KERNEL))
+ err = 1;
+ else if (!alloc_cpumask_var(&cpusdone, GFP_KERNEL)) {
+ free_cpumask_var(cpulist);
+ err = 1;
+ }
+ if (err) {
+ printk(KERN_INFO "Can't print processor summaries\n");
+ return;
+ }
+
+ cpumask_clear(cpusdone);
+ for (cpu = 0; cpu < nr_cpu_ids; cpu++) {
+ struct cpuinfo_x86 *c;
+ char buf[128];
+ int ncpu, len;
+ unsigned long minlpj, maxlpj, avglpj = 0;
+
+ /* skip if cpu has already been displayed */
+ if (cpumask_test_cpu(cpu, cpusdone))
+ continue;
+
+ c = &cpu_data(cpu);
+ minlpj = ULONG_MAX;
+ maxlpj = 0;
+
+ cpumask_clear(cpulist);
+
+ /* collate all cpus with same specifics */
+ for (ncpu = cpu; ncpu < nr_cpu_ids; ncpu++) {
+ struct cpuinfo_x86 *n = &cpu_data(ncpu);
+
+ if (c->x86 != n->x86 ||
+    c->x86_vendor != n->x86_vendor ||
+    c->x86_model  != n->x86_model  ||
+    c->x86_mask   != n->x86_mask   ||
+    strcmp(c->x86_model_id, n->x86_model_id))
+ continue;
+
+ cpumask_set_cpu(ncpu, cpulist);
+ cpumask_set_cpu(ncpu, cpusdone);
+
+ if (cpu_data(ncpu).loops_per_jiffy < minlpj)
+ minlpj = cpu_data(ncpu).loops_per_jiffy;
+
+ if (cpu_data(ncpu).loops_per_jiffy > maxlpj)
+ maxlpj = cpu_data(ncpu).loops_per_jiffy;
+
+ avglpj += cpu_data(ncpu).loops_per_jiffy;
+ }
+
+ len = cpulist_scnprintf(buf, sizeof(buf), cpulist);
+ printk(KERN_INFO
+ "Processor Information for CPUS: %s%s\n",
+ buf, (len == sizeof(buf)-1) ? "..." : "");
+
+ printk(KERN_INFO);
+ print_cpu_info(c);
+
+ avglpj /= cpumask_weight(cpulist);
+ printk(KERN_INFO "BogoMIPS: MIN %lu.%02lu (%lu) "
+ "AVG %lu.%02lu (%lu) MAX %lu.%02lu (%lu)\n",
+ minlpj/(500000/HZ), (minlpj/(5000/HZ)) % 100, minlpj,
+ avglpj/(500000/HZ), (avglpj/(5000/HZ)) % 100, avglpj,
+ maxlpj/(500000/HZ), (maxlpj/(5000/HZ)) % 100, maxlpj);
+ }
+
+ free_cpumask_var(cpusdone);
+ free_cpumask_var(cpulist);
+}
+
 static void impress_friends(void)
 {
  int cpu;
@@ -737,8 +815,21 @@
  start_ip = setup_trampoline();
 
  /* So we see what's up   */
- printk(KERN_INFO "Booting processor %d APIC 0x%x ip 0x%lx\n",
-  cpu, apicid, start_ip);
+#ifdef CONFIG_NUMA
+ if (system_state == SYSTEM_BOOTING) {
+ static int current_node = -1;
+ int node = cpu_to_node(cpu);
+
+ if (node != current_node) {
+ if (current_node > (-1))
+ pr_cont(" Ok.\n");
+ current_node = node;
+ pr_info("Booting Node %3d, Processors ", node);
+ }
+ pr_cont(" %d%s", cpu, cpu == (nr_cpu_ids - 1) ? " Ok.\n" : "");
+ } else
+#endif
+ pr_info("Booting Processor %d APIC 0x%x\n", cpu, apicid);
 
  /*
  * This grunge runs the startup process for
@@ -787,21 +878,17 @@
  udelay(100);
  }
 
- if (cpumask_test_cpu(cpu, cpu_callin_mask)) {
- /* number CPUs logically, starting from 1 (BSP is 0) */
- pr_debug("OK.\n");
- printk(KERN_INFO "CPU%d: ", cpu);
- print_cpu_info(&cpu_data(cpu));
- pr_debug("CPU has booted.\n");
- } else {
+ if (cpumask_test_cpu(cpu, cpu_callin_mask))
+ pr_debug("CPU%d: has booted.\n", cpu);
+ else {
  boot_error = 1;
  if (*((volatile unsigned char *)trampoline_base)
  == 0xA5)
  /* trampoline started but...? */
- printk(KERN_ERR "Stuck ??\n");
+ pr_err("CPU%d: Stuck ??\n", cpu);
  else
  /* trampoline code not run */
- printk(KERN_ERR "Not responding.\n");
+ pr_err("CPU%d: Not responding.\n", cpu);
  if (apic->inquire_remote_apic)
  apic->inquire_remote_apic(apicid);
  }
@@ -1147,6 +1234,9 @@
 {
  pr_debug("Boot done.\n");
 
+ /* print processor data summaries */
+ summarize_cpu_info();
+
  impress_friends();
 #ifdef CONFIG_X86_IO_APIC
  setup_ioapic_dest();
@@ -1300,14 +1390,16 @@
  for (i = 0; i < 10; i++) {
  /* They ack this in play_dead by setting CPU_DEAD */
  if (per_cpu(cpu_state, cpu) == CPU_DEAD) {
- printk(KERN_INFO "CPU %d is now offline\n", cpu);
+ if (system_state == SYSTEM_RUNNING)
+ pr_info("CPU %u is now offline\n", cpu);
+
  if (1 == num_online_cpus())
  alternatives_smp_switch(0);
  return;
  }
  msleep(100);
  }
- printk(KERN_ERR "CPU %u didn't die...\n", cpu);
+ pr_err("CPU %u didn't die...\n", cpu);
 }
 
 void play_dead_common(void)

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

[Mike Travis]

Limit the number of per cpu ACPI messages when system is booting to
prevent clogging up the console output with repetitious messages.

Signed-off-by: Mike Travis <travis@...>
---
 drivers/acpi/fan.c            |    2 +-
 drivers/acpi/processor_core.c |    2 +-
 drivers/acpi/tables.c         |   28 +++++++++++++++++++---------
 3 files changed, 21 insertions(+), 11 deletions(-)

--- linux.orig/drivers/acpi/fan.c
+++ linux/drivers/acpi/fan.c
@@ -267,7 +267,7 @@
  goto end;
  }
 
- dev_info(&device->dev, "registered as cooling_device%d\n", cdev->id);
+ dev_dbg(&device->dev, "registered as cooling_device%d\n", cdev->id);
 
  device->driver_data = cdev;
  result = sysfs_create_link(&device->dev.kobj,
--- linux.orig/drivers/acpi/processor_core.c
+++ linux/drivers/acpi/processor_core.c
@@ -845,7 +845,7 @@
  goto err_power_exit;
  }
 
- dev_info(&device->dev, "registered as cooling_device%d\n",
+ dev_dbg(&device->dev, "registered as cooling_device%d\n",
  pr->cdev->id);
 
  result = sysfs_create_link(&device->dev.kobj,
--- linux.orig/drivers/acpi/tables.c
+++ linux/drivers/acpi/tables.c
@@ -66,11 +66,15 @@
  {
  struct acpi_madt_local_x2apic *p =
     (struct acpi_madt_local_x2apic *)header;
- printk(KERN_INFO PREFIX
-       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
-       p->local_apic_id, p->uid,
-       (p->lapic_flags & ACPI_MADT_ENABLED) ?
-       "enabled" : "disabled");
+ /*
+ * Per cpu tracing clogs console output when NR_CPUS
+ * is large.  Send only to kernel log buffer.
+ */
+ printk(KERN_DEBUG PREFIX
+ "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
+ p->local_apic_id, p->uid,
+ (p->lapic_flags & ACPI_MADT_ENABLED) ?
+ "enabled" : "disabled");
  }
  break;
 
@@ -171,10 +175,16 @@
  {
  struct acpi_madt_local_sapic *p =
     (struct acpi_madt_local_sapic *)header;
- printk(KERN_INFO PREFIX
-       "LSAPIC (acpi_id[0x%02x] lsapic_id[0x%02x] lsapic_eid[0x%02x] %s)\n",
-       p->processor_id, p->id, p->eid,
-       (p->lapic_flags & ACPI_MADT_ENABLED) ? "enabled" : "disabled");
+ /*
+ * Per cpu tracing clogs console output when NR_CPUS
+ * is large.  Send only to kernel log buffer.
+ */
+ printk(KERN_DEBUG PREFIX
+ "LSAPIC (acpi_id[0x%02x] lsapic_id[0x%02x] "
+ "lsapic_eid[0x%02x] %s)\n",
+ p->processor_id, p->id, p->eid,
+ (p->lapic_flags & ACPI_MADT_ENABLED) ?
+ "enabled" : "disabled");
  }
  break;
 

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

[Mike Travis]

Limit the number of per cpu INIT messages when system is booting to
prevent clogging up the console output with repetitious messages.

Signed-off-by: Mike Travis <travis@...>
---
 init/calibrate.c |   22 +++++++++++++---------
 kernel/cpu.c     |    5 ++---
 2 files changed, 15 insertions(+), 12 deletions(-)

--- linux.orig/init/calibrate.c
+++ linux/init/calibrate.c
@@ -123,23 +123,26 @@
 {
  unsigned long ticks, loopbit;
  int lps_precision = LPS_PREC;
+ bool boot_cpu = (smp_processor_id() == 0);
 
  if (preset_lpj) {
  loops_per_jiffy = preset_lpj;
- printk(KERN_INFO
- "Calibrating delay loop (skipped) preset value.. ");
- } else if ((smp_processor_id() == 0) && lpj_fine) {
+ if (boot_cpu)
+ pr_info("Calibrating delay loop (skipped) "
+ "preset value.. ");
+ } else if ((boot_cpu) && lpj_fine) {
  loops_per_jiffy = lpj_fine;
- printk(KERN_INFO
- "Calibrating delay loop (skipped), "
+ pr_info("Calibrating delay loop (skipped), "
  "value calculated using timer frequency.. ");
  } else if ((loops_per_jiffy = calibrate_delay_direct()) != 0) {
- printk(KERN_INFO
- "Calibrating delay using timer specific routine.. ");
+ if (boot_cpu)
+ pr_info("Calibrating delay using timer "
+ "specific routine.. ");
  } else {
  loops_per_jiffy = (1<<12);
 
- printk(KERN_INFO "Calibrating delay loop... ");
+ if (boot_cpu)
+ pr_info("Calibrating delay loop... ");
  while ((loops_per_jiffy <<= 1) != 0) {
  /* wait for "start of" clock tick */
  ticks = jiffies;
@@ -170,7 +173,8 @@
  loops_per_jiffy &= ~loopbit;
  }
  }
- printk(KERN_CONT "%lu.%02lu BogoMIPS (lpj=%lu)\n",
+ if (boot_cpu)
+ pr_cont("%lu.%02lu BogoMIPS (lpj=%lu)\n",
  loops_per_jiffy/(500000/HZ),
  (loops_per_jiffy/(5000/HZ)) % 100, loops_per_jiffy);
 }
--- linux.orig/kernel/cpu.c
+++ linux/kernel/cpu.c
@@ -392,10 +392,9 @@
  if (cpu == first_cpu)
  continue;
  error = _cpu_down(cpu, 1);
- if (!error) {
+ if (!error)
  cpumask_set_cpu(cpu, frozen_cpus);
- printk("CPU%d is down\n", cpu);
- } else {
+ else {
  printk(KERN_ERR "Error taking CPU%d down: %d\n",
  cpu, error);
  break;

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

[Mike Travis]

Limit the number of per cpu firmware: messages when system is booting to
prevent clogging up the console output with repetitious messages.

[  170.643130] firmware: requesting intel-ucode/06-2e-0

Signed-off-by: Mike Travis <travis@...>
---
 drivers/base/firmware_class.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

--- linux.orig/drivers/base/firmware_class.c
+++ linux/drivers/base/firmware_class.c
@@ -495,7 +495,7 @@
  }
 
  if (uevent)
- dev_info(device, "firmware: requesting %s\n", name);
+ dev_dbg(device, "firmware: requesting %s\n", name);
 
  retval = fw_setup_device(firmware, &f_dev, name, device, uevent);
  if (retval)

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

[Mike Travis]

Limit the number of per cpu MCE messages when system is booting to
prevent clogging up the console output with repetitious messages.

Signed-off-by: Mike Travis <travis@...>
---
 arch/x86/kernel/cpu/mcheck/mce.c       |    4 ++--
 arch/x86/kernel/cpu/mcheck/mce_intel.c |    2 +-
 2 files changed, 3 insertions(+), 3 deletions(-)

--- linux.orig/arch/x86/kernel/cpu/mcheck/mce.c
+++ linux/arch/x86/kernel/cpu/mcheck/mce.c
@@ -1215,10 +1215,10 @@
 
  b = cap & MCG_BANKCNT_MASK;
  if (!banks)
- printk(KERN_INFO "mce: CPU supports %d MCE banks\n", b);
+ pr_debug("mce: CPU supports %d MCE banks\n", b);
 
  if (b > MAX_NR_BANKS) {
- printk(KERN_WARNING
+ pr_warning(
        "MCE: Using only %u machine check banks out of %u\n",
  MAX_NR_BANKS, b);
  b = MAX_NR_BANKS;
--- linux.orig/arch/x86/kernel/cpu/mcheck/mce_intel.c
+++ linux/arch/x86/kernel/cpu/mcheck/mce_intel.c
@@ -67,7 +67,7 @@
 static void print_update(char *type, int *hdr, int num)
 {
  if (*hdr == 0)
- printk(KERN_INFO "CPU %d MCA banks", smp_processor_id());
+ printk(KERN_DEBUG "CPU %d MCA banks", smp_processor_id());
  *hdr = 1;
  printk(KERN_CONT " %s:%d", type, num);
 }

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

[Mike Travis]

Limit number of sched debug messages for MAXSMP systems.

Signed-off-by: Mike Travis <travis@...>
---
 lib/Kconfig.debug |    5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

--- linux.orig/lib/Kconfig.debug
+++ linux/lib/Kconfig.debug
@@ -235,11 +235,12 @@
 config SCHED_DEBUG
  bool "Collect scheduler debugging info"
  depends on DEBUG_KERNEL && PROC_FS
- default y
+ default !MAXSMP
  help
   If you say Y here, the /proc/sched_debug file will be provided
   that can help debug the scheduler. The runtime overhead of this
-  option is minimal.
+  option is minimal unless there are a large number of CPUs in
+  the system.
 
 config SCHEDSTATS
  bool "Collect scheduler statistics"

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

[Mike Travis]

Limit the number of per cpu TSC sync messages when system is booting to
prevent clogging up the console output with repetitious messages.

Signed-off-by: Mike Travis <travis@...>
---
 arch/x86/kernel/tsc_sync.c |    8 +++-----
 1 file changed, 3 insertions(+), 5 deletions(-)

--- linux.orig/arch/x86/kernel/tsc_sync.c
+++ linux/arch/x86/kernel/tsc_sync.c
@@ -118,9 +118,6 @@
  return;
  }
 
- pr_info("checking TSC synchronization [CPU#%d -> CPU#%d]:",
- smp_processor_id(), cpu);
-
  /*
  * Reset it - in case this is a second bootup:
  */
@@ -142,12 +139,13 @@
  cpu_relax();
 
  if (nr_warps) {
- printk("\n");
+ pr_warning("TSC synchronization [CPU#%d -> CPU#%d]:\n",
+ smp_processor_id(), cpu);
  pr_warning("Measured %Ld cycles TSC warp between CPUs, "
    "turning off TSC clock.\n", max_warp);
  mark_tsc_unstable("check_tsc_sync_source failed");
  } else {
- printk(" passed.\n");
+ pr_debug("TSC synchronization [CPU#%d -> CPU#%d]: passed\n");
  }
 
  /*

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

[Ingo Molnar]

* Mike Travis <travis@...> wrote:

> --- linux.orig/arch/x86/kernel/smpboot.c
> +++ linux/arch/x86/kernel/smpboot.c
> @@ -442,6 +442,84 @@
>   return c->llc_shared_map;
>  }
>  
> +/* Summarize Processor Information */
> +static void __init summarize_cpu_info(void)
> +{
> + cpumask_var_t cpulist, cpusdone;
> + int cpu;
> + int err = 0;
> +
> + if (!alloc_cpumask_var(&cpulist, GFP_KERNEL))
> + err = 1;
> + else if (!alloc_cpumask_var(&cpusdone, GFP_KERNEL)) {
> + free_cpumask_var(cpulist);
> + err = 1;
> + }
> + if (err) {
> + printk(KERN_INFO "Can't print processor summaries\n");
> + return;
> + }
> +
> + cpumask_clear(cpusdone);
> + for (cpu = 0; cpu < nr_cpu_ids; cpu++) {
> + struct cpuinfo_x86 *c;
> + char buf[128];
> + int ncpu, len;
> + unsigned long minlpj, maxlpj, avglpj = 0;
> +
> + /* skip if cpu has already been displayed */
> + if (cpumask_test_cpu(cpu, cpusdone))
> + continue;
> +
> + c = &cpu_data(cpu);
> + minlpj = ULONG_MAX;
> + maxlpj = 0;
> +
> + cpumask_clear(cpulist);
> +
> + /* collate all cpus with same specifics */
> + for (ncpu = cpu; ncpu < nr_cpu_ids; ncpu++) {
> + struct cpuinfo_x86 *n = &cpu_data(ncpu);
> +
> + if (c->x86 != n->x86 ||
> +    c->x86_vendor != n->x86_vendor ||
> +    c->x86_model  != n->x86_model  ||
> +    c->x86_mask   != n->x86_mask   ||
> +    strcmp(c->x86_model_id, n->x86_model_id))
> + continue;
> +
> + cpumask_set_cpu(ncpu, cpulist);
> + cpumask_set_cpu(ncpu, cpusdone);
> +
> + if (cpu_data(ncpu).loops_per_jiffy < minlpj)
> + minlpj = cpu_data(ncpu).loops_per_jiffy;
> +
> + if (cpu_data(ncpu).loops_per_jiffy > maxlpj)
> + maxlpj = cpu_data(ncpu).loops_per_jiffy;
> +
> + avglpj += cpu_data(ncpu).loops_per_jiffy;
> + }
> +
> + len = cpulist_scnprintf(buf, sizeof(buf), cpulist);
> + printk(KERN_INFO
> + "Processor Information for CPUS: %s%s\n",
> + buf, (len == sizeof(buf)-1) ? "..." : "");
> +
> + printk(KERN_INFO);
> + print_cpu_info(c);
> +
> + avglpj /= cpumask_weight(cpulist);
> + printk(KERN_INFO "BogoMIPS: MIN %lu.%02lu (%lu) "
> + "AVG %lu.%02lu (%lu) MAX %lu.%02lu (%lu)\n",
> + minlpj/(500000/HZ), (minlpj/(5000/HZ)) % 100, minlpj,
> + avglpj/(500000/HZ), (avglpj/(5000/HZ)) % 100, avglpj,
> + maxlpj/(500000/HZ), (maxlpj/(5000/HZ)) % 100, maxlpj);
> + }
> +
> + free_cpumask_var(cpusdone);
> + free_cpumask_var(cpulist);
> +}
> +

Sigh, that's _way_ too complex.

If you cannot print it in a summarized way without carrying over stupid
state like bitmaps then please do the simple and obvious, and print:

booting CPUs: #0 #1 #2 #3 #4 #5 #6 ...

It's a really long line with 4096 CPUs but that's not a big problem - on
most systems it will look sane.

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

[Mike Travis]

Ingo Molnar wrote:

> * Mike Travis <travis@...> wrote:
>
>> --- linux.orig/arch/x86/kernel/smpboot.c
>> +++ linux/arch/x86/kernel/smpboot.c
>> @@ -442,6 +442,84 @@
>>   return c->llc_shared_map;
>>  }
>>  
>> +/* Summarize Processor Information */
>> +static void __init summarize_cpu_info(void)
>> +{
>> + cpumask_var_t cpulist, cpusdone;
>> + int cpu;
>> + int err = 0;
>> +
>> + if (!alloc_cpumask_var(&cpulist, GFP_KERNEL))
>> + err = 1;
>> + else if (!alloc_cpumask_var(&cpusdone, GFP_KERNEL)) {
>> + free_cpumask_var(cpulist);
>> + err = 1;
>> + }
>> + if (err) {
>> + printk(KERN_INFO "Can't print processor summaries\n");
>> + return;
>> + }
>> +
>> + cpumask_clear(cpusdone);
>> + for (cpu = 0; cpu < nr_cpu_ids; cpu++) {
>> + struct cpuinfo_x86 *c;
>> + char buf[128];
>> + int ncpu, len;
>> + unsigned long minlpj, maxlpj, avglpj = 0;
>> +
>> + /* skip if cpu has already been displayed */
>> + if (cpumask_test_cpu(cpu, cpusdone))
>> + continue;
>> +
>> + c = &cpu_data(cpu);
>> + minlpj = ULONG_MAX;
>> + maxlpj = 0;
>> +
>> + cpumask_clear(cpulist);
>> +
>> + /* collate all cpus with same specifics */
>> + for (ncpu = cpu; ncpu < nr_cpu_ids; ncpu++) {
>> + struct cpuinfo_x86 *n = &cpu_data(ncpu);
>> +
>> + if (c->x86 != n->x86 ||
>> +    c->x86_vendor != n->x86_vendor ||
>> +    c->x86_model  != n->x86_model  ||
>> +    c->x86_mask   != n->x86_mask   ||
>> +    strcmp(c->x86_model_id, n->x86_model_id))
>> + continue;
>> +
>> + cpumask_set_cpu(ncpu, cpulist);
>> + cpumask_set_cpu(ncpu, cpusdone);
>> +
>> + if (cpu_data(ncpu).loops_per_jiffy < minlpj)
>> + minlpj = cpu_data(ncpu).loops_per_jiffy;
>> +
>> + if (cpu_data(ncpu).loops_per_jiffy > maxlpj)
>> + maxlpj = cpu_data(ncpu).loops_per_jiffy;
>> +
>> + avglpj += cpu_data(ncpu).loops_per_jiffy;
>> + }
>> +
>> + len = cpulist_scnprintf(buf, sizeof(buf), cpulist);
>> + printk(KERN_INFO
>> + "Processor Information for CPUS: %s%s\n",
>> + buf, (len == sizeof(buf)-1) ? "..." : "");
>> +
>> + printk(KERN_INFO);
>> + print_cpu_info(c);
>> +
>> + avglpj /= cpumask_weight(cpulist);
>> + printk(KERN_INFO "BogoMIPS: MIN %lu.%02lu (%lu) "
>> + "AVG %lu.%02lu (%lu) MAX %lu.%02lu (%lu)\n",
>> + minlpj/(500000/HZ), (minlpj/(5000/HZ)) % 100, minlpj,
>> + avglpj/(500000/HZ), (avglpj/(5000/HZ)) % 100, avglpj,
>> + maxlpj/(500000/HZ), (maxlpj/(5000/HZ)) % 100, maxlpj);
>> + }
>> +
>> + free_cpumask_var(cpusdone);
>> + free_cpumask_var(cpulist);
>> +}
>> +
>
> Sigh, that's _way_ too complex.
>
> If you cannot print it in a summarized way without carrying over stupid
> state like bitmaps then please do the simple and obvious, and print:
>
> booting CPUs: #0 #1 #2 #3 #4 #5 #6 ...

That is almost exactly what it does.  The following function prints
each cpu # as they are being booted, so you see a progressive listing.

Booting Node   0, Processors  1 2 3 4 5 6 7 Ok.
Booting Node   1, Processors  8 9 10 11 12 13 14 15 Ok.
Booting Node   2, Processors  16 17 18 19 20 21 22 23 Ok.

+#ifdef CONFIG_NUMA
+ if (system_state == SYSTEM_BOOTING) {
+ static int current_node = -1;
+ int node = cpu_to_node(cpu);
+
+ if (node != current_node) {
+ if (current_node > (-1))
+ pr_cont(" Ok.\n");
+ current_node = node;
+ pr_info("Booting Node %3d, Processors ", node);
+ }
+ pr_cont(" %d%s", cpu, cpu == (nr_cpu_ids - 1) ? " Ok.\n" : "");
+ } else
+#endif
+ pr_info("Booting Processor %d APIC 0x%x\n", cpu, apicid);

The part you highlight above is to print the summary shown below of the cpus
in the system after they have been booted, and since it's an init function,
it will be removed.

Processor Information for CPUS: 0-191,208-223,256-271,...
Genuine Intel(R) CPU             0000 @ 2.13GHz stepping 04
BogoMIPS: MIN 3989.01 (7978031) AVG 4266.62 (8533249) MAX 4537.51 (9075028)
Processor Information for CPUS: 192-207,240-255,272-287,...
Genuine Intel(R) CPU             0000 @ 2.13GHz stepping 03
BogoMIPS: MIN 4021.49 (8042995) AVG 4265.91 (8531833) MAX 4479.79 (8959584)

> It's a really long line with 4096 CPUs but that's not a big problem - on
> most systems it will look sane.
>
> Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[David Rientjes]

It's possible to reduce the number of SRAT messages emitted to the kernel
log by printing each valid pxm once and then creating bitmaps to represent
the apic ids that map to the same node.

This reduces lines such as

        SRAT: PXM 0 -> APIC 0 -> Node 0
        SRAT: PXM 0 -> APIC 1 -> Node 0
        SRAT: PXM 1 -> APIC 2 -> Node 1
        SRAT: PXM 1 -> APIC 3 -> Node 1

to

        SRAT: PXM 0 -> APIC {0-1} -> Node 0
        SRAT: PXM 1 -> APIC {2-3} -> Node 1

The buffer used to store the apic id list is 128 characters in length.
If that is too small to represent all the apic id ranges that are bound
to a single pxm, a trailing "..." is added.  APICID_LIST_LEN should be
manually increased for such configurations.

Acked-by: Mike Travis <travis@...>
Signed-off-by: David Rientjes <rientjes@...>
---
 arch/x86/mm/srat_64.c |   41 +++++++++++++++++++++++++++++++++++++----
 drivers/acpi/numa.c   |    5 +++++
 include/linux/acpi.h  |    3 ++-
 3 files changed, 44 insertions(+), 5 deletions(-)

diff --git a/arch/x86/mm/srat_64.c b/arch/x86/mm/srat_64.c
--- a/arch/x86/mm/srat_64.c
+++ b/arch/x86/mm/srat_64.c
@@ -36,6 +36,9 @@ static int num_node_memblks __initdata;
 static struct bootnode node_memblk_range[NR_NODE_MEMBLKS] __initdata;
 static int memblk_nodeid[NR_NODE_MEMBLKS] __initdata;
 
+static DECLARE_BITMAP(apicid_map, MAX_LOCAL_APIC) __initdata;
+#define APICID_LIST_LEN (128)
+
 static __init int setup_node(int pxm)
 {
  return acpi_map_pxm_to_node(pxm);
@@ -136,8 +139,6 @@ acpi_numa_x2apic_affinity_init(struct acpi_srat_x2apic_cpu_affinity *pa)
  apicid_to_node[apic_id] = node;
  node_set(node, cpu_nodes_parsed);
  acpi_numa = 1;
- printk(KERN_INFO "SRAT: PXM %u -> APIC %u -> Node %u\n",
-       pxm, apic_id, node);
 }
 
 /* Callback for Proximity Domain -> LAPIC mapping */
@@ -170,8 +171,40 @@ acpi_numa_processor_affinity_init(struct acpi_srat_cpu_affinity *pa)
  apicid_to_node[apic_id] = node;
  node_set(node, cpu_nodes_parsed);
  acpi_numa = 1;
- printk(KERN_INFO "SRAT: PXM %u -> APIC %u -> Node %u\n",
-       pxm, apic_id, node);
+}
+
+void __init acpi_numa_print_srat_mapping(void)
+{
+ char apicid_list[APICID_LIST_LEN];
+ int i, j;
+
+ for (i = 0; i < MAX_PXM_DOMAINS; i++) {
+ int len;
+ int nid;
+
+ nid = pxm_to_node(i);
+ if (nid == NUMA_NO_NODE)
+ continue;
+
+ bitmap_zero(apicid_map, MAX_LOCAL_APIC);
+ for (j = 0; j < MAX_LOCAL_APIC; j++)
+ if (apicid_to_node[j] == nid)
+ set_bit(j, apicid_map);
+
+ if (bitmap_empty(apicid_map, MAX_LOCAL_APIC))
+ continue;
+
+ /*
+ * If the bitmap cannot be listed in a buffer of length
+ * APICID_LIST_LEN, then it is suffixed with "...".
+ */
+ len = bitmap_scnlistprintf(apicid_list, APICID_LIST_LEN,
+   apicid_map, MAX_LOCAL_APIC);
+ pr_info("SRAT: PXM %u -> APIC {%s%s} -> Node %u\n",
+ i, apicid_list,
+ (len == APICID_LIST_LEN - 1) ? "..." : "",
+ nid);
+ }
 }
 
 #ifdef CONFIG_MEMORY_HOTPLUG_SPARSE
diff --git a/drivers/acpi/numa.c b/drivers/acpi/numa.c
--- a/drivers/acpi/numa.c
+++ b/drivers/acpi/numa.c
@@ -281,6 +281,10 @@ acpi_table_parse_srat(enum acpi_srat_type id,
     handler, max_entries);
 }
 
+void __init __attribute__((weak)) acpi_numa_print_srat_mapping(void)
+{
+}
+
 int __init acpi_numa_init(void)
 {
  /* SRAT: Static Resource Affinity Table */
@@ -292,6 +296,7 @@ int __init acpi_numa_init(void)
  acpi_table_parse_srat(ACPI_SRAT_TYPE_MEMORY_AFFINITY,
       acpi_parse_memory_affinity,
       NR_NODE_MEMBLKS);
+ acpi_numa_print_srat_mapping();
  }
 
  /* SLIT: System Locality Information Table */
diff --git a/include/linux/acpi.h b/include/linux/acpi.h
--- a/include/linux/acpi.h
+++ b/include/linux/acpi.h
@@ -92,12 +92,13 @@ int acpi_table_parse_madt (enum acpi_madt_type id, acpi_table_entry_handler hand
 int acpi_parse_mcfg (struct acpi_table_header *header);
 void acpi_table_print_madt_entry (struct acpi_subtable_header *madt);
 
-/* the following four functions are architecture-dependent */
+/* the following six functions are architecture-dependent */
 void acpi_numa_slit_init (struct acpi_table_slit *slit);
 void acpi_numa_processor_affinity_init (struct acpi_srat_cpu_affinity *pa);
 void acpi_numa_x2apic_affinity_init(struct acpi_srat_x2apic_cpu_affinity *pa);
 void acpi_numa_memory_affinity_init (struct acpi_srat_mem_affinity *ma);
 void acpi_numa_arch_fixup(void);
+void acpi_numa_print_srat_mapping(void);
 
 #ifdef CONFIG_ACPI_HOTPLUG_CPU
 /* Arch dependent functions for cpu hotplug support */
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[David Rientjes]

On Thu, 12 Nov 2009, Mike Travis wrote:

> Limit the number of per cpu ACPI messages when system is booting to
> prevent clogging up the console output with repetitious messages.
>

... "by changing the log level from KERN_INFO to KERN_DEBUG."

> Signed-off-by: Mike Travis <travis@...>
> ---
>  drivers/acpi/fan.c            |    2 +-
>  drivers/acpi/processor_core.c |    2 +-
>  drivers/acpi/tables.c         |   28 +++++++++++++++++++---------
>  3 files changed, 21 insertions(+), 11 deletions(-)
>
> --- linux.orig/drivers/acpi/fan.c
> +++ linux/drivers/acpi/fan.c
> @@ -267,7 +267,7 @@
>   goto end;
>   }
>  
> - dev_info(&device->dev, "registered as cooling_device%d\n", cdev->id);
> + dev_dbg(&device->dev, "registered as cooling_device%d\n", cdev->id);
>  
>   device->driver_data = cdev;
>   result = sysfs_create_link(&device->dev.kobj,
> --- linux.orig/drivers/acpi/processor_core.c
> +++ linux/drivers/acpi/processor_core.c
> @@ -845,7 +845,7 @@
>   goto err_power_exit;
>   }
>  
> - dev_info(&device->dev, "registered as cooling_device%d\n",
> + dev_dbg(&device->dev, "registered as cooling_device%d\n",
>   pr->cdev->id);
>  
>   result = sysfs_create_link(&device->dev.kobj,
> --- linux.orig/drivers/acpi/tables.c
> +++ linux/drivers/acpi/tables.c
> @@ -66,11 +66,15 @@
>   {
>   struct acpi_madt_local_x2apic *p =
>      (struct acpi_madt_local_x2apic *)header;
> - printk(KERN_INFO PREFIX
> -       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
> -       p->local_apic_id, p->uid,
> -       (p->lapic_flags & ACPI_MADT_ENABLED) ?
> -       "enabled" : "disabled");
> + /*
> + * Per cpu tracing clogs console output when NR_CPUS
> + * is large.  Send only to kernel log buffer.
> + */
> + printk(KERN_DEBUG PREFIX
> + "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
> + p->local_apic_id, p->uid,
> + (p->lapic_flags & ACPI_MADT_ENABLED) ?
> + "enabled" : "disabled");
>   }
>   break;
>  

You can still use dev_dbg(PREFIX "...") here.

> @@ -171,10 +175,16 @@
>   {
>   struct acpi_madt_local_sapic *p =
>      (struct acpi_madt_local_sapic *)header;
> - printk(KERN_INFO PREFIX
> -       "LSAPIC (acpi_id[0x%02x] lsapic_id[0x%02x] lsapic_eid[0x%02x] %s)\n",
> -       p->processor_id, p->id, p->eid,
> -       (p->lapic_flags & ACPI_MADT_ENABLED) ? "enabled" : "disabled");
> + /*
> + * Per cpu tracing clogs console output when NR_CPUS
> + * is large.  Send only to kernel log buffer.
> + */
> + printk(KERN_DEBUG PREFIX
> + "LSAPIC (acpi_id[0x%02x] lsapic_id[0x%02x] "
> + "lsapic_eid[0x%02x] %s)\n",
> + p->processor_id, p->id, p->eid,
> + (p->lapic_flags & ACPI_MADT_ENABLED) ?
> + "enabled" : "disabled");
>   }
>   break;
>  

Likewise, but recent emails from Linus indicate that we don't want to
break printk strings into multiple lines even if it goes over 80
characters unless broken at '\n'.  Users who grep for
"lsapic_id.*lsapic_eid" with this patch wouldn't find the string.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[David Rientjes]

On Thu, 12 Nov 2009, Mike Travis wrote:

> Limit the number of per cpu INIT messages when system is booting to
> prevent clogging up the console output with repetitious messages.
>

Needs a better changelog.  What did you do to effect that change?  It
looks like you're only emitting certain messages from the boot cpu.

> Signed-off-by: Mike Travis <travis@...>
> ---
>  init/calibrate.c |   22 +++++++++++++---------
>  kernel/cpu.c     |    5 ++---
>  2 files changed, 15 insertions(+), 12 deletions(-)
>
> --- linux.orig/init/calibrate.c
> +++ linux/init/calibrate.c
> @@ -123,23 +123,26 @@
>  {
>   unsigned long ticks, loopbit;
>   int lps_precision = LPS_PREC;
> + bool boot_cpu = (smp_processor_id() == 0);
>  
>   if (preset_lpj) {
>   loops_per_jiffy = preset_lpj;
> - printk(KERN_INFO
> - "Calibrating delay loop (skipped) preset value.. ");
> - } else if ((smp_processor_id() == 0) && lpj_fine) {
> + if (boot_cpu)
> + pr_info("Calibrating delay loop (skipped) "
> + "preset value.. ");

Same comment as before about breaking printk strings into multiple lines
when not broken at '\n'.  All the other patches your series look good
after this, however.

> + } else if ((boot_cpu) && lpj_fine) {

Parentheses around boot_cpu?

>   loops_per_jiffy = lpj_fine;
> - printk(KERN_INFO
> - "Calibrating delay loop (skipped), "
> + pr_info("Calibrating delay loop (skipped), "
>   "value calculated using timer frequency.. ");
>   } else if ((loops_per_jiffy = calibrate_delay_direct()) != 0) {
> - printk(KERN_INFO
> - "Calibrating delay using timer specific routine.. ");
> + if (boot_cpu)
> + pr_info("Calibrating delay using timer "
> + "specific routine.. ");
>   } else {
>   loops_per_jiffy = (1<<12);
>  
> - printk(KERN_INFO "Calibrating delay loop... ");
> + if (boot_cpu)
> + pr_info("Calibrating delay loop... ");
>   while ((loops_per_jiffy <<= 1) != 0) {
>   /* wait for "start of" clock tick */
>   ticks = jiffies;
> @@ -170,7 +173,8 @@
>   loops_per_jiffy &= ~loopbit;
>   }
>   }
> - printk(KERN_CONT "%lu.%02lu BogoMIPS (lpj=%lu)\n",
> + if (boot_cpu)
> + pr_cont("%lu.%02lu BogoMIPS (lpj=%lu)\n",
>   loops_per_jiffy/(500000/HZ),
>   (loops_per_jiffy/(5000/HZ)) % 100, loops_per_jiffy);
>  }
> --- linux.orig/kernel/cpu.c
> +++ linux/kernel/cpu.c
> @@ -392,10 +392,9 @@
>   if (cpu == first_cpu)
>   continue;
>   error = _cpu_down(cpu, 1);
> - if (!error) {
> + if (!error)
>   cpumask_set_cpu(cpu, frozen_cpus);
> - printk("CPU%d is down\n", cpu);
> - } else {
> + else {
>   printk(KERN_ERR "Error taking CPU%d down: %d\n",
>   cpu, error);
>   break;

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

[Mike Travis]

David Rientjes wrote:

> On Thu, 12 Nov 2009, Mike Travis wrote:
>
>> Limit the number of per cpu ACPI messages when system is booting to
>> prevent clogging up the console output with repetitious messages.
>>
>
> ... "by changing the log level from KERN_INFO to KERN_DEBUG."
>
>> Signed-off-by: Mike Travis <travis@...>
>> ---
>>  drivers/acpi/fan.c            |    2 +-
>>  drivers/acpi/processor_core.c |    2 +-
>>  drivers/acpi/tables.c         |   28 +++++++++++++++++++---------
>>  3 files changed, 21 insertions(+), 11 deletions(-)
>>
>> --- linux.orig/drivers/acpi/fan.c
>> +++ linux/drivers/acpi/fan.c
>> @@ -267,7 +267,7 @@
>>   goto end;
>>   }
>>  
>> - dev_info(&device->dev, "registered as cooling_device%d\n", cdev->id);
>> + dev_dbg(&device->dev, "registered as cooling_device%d\n", cdev->id);
>>  
>>   device->driver_data = cdev;
>>   result = sysfs_create_link(&device->dev.kobj,
>> --- linux.orig/drivers/acpi/processor_core.c
>> +++ linux/drivers/acpi/processor_core.c
>> @@ -845,7 +845,7 @@
>>   goto err_power_exit;
>>   }
>>  
>> - dev_info(&device->dev, "registered as cooling_device%d\n",
>> + dev_dbg(&device->dev, "registered as cooling_device%d\n",
>>   pr->cdev->id);
>>  
>>   result = sysfs_create_link(&device->dev.kobj,
>> --- linux.orig/drivers/acpi/tables.c
>> +++ linux/drivers/acpi/tables.c
>> @@ -66,11 +66,15 @@
>>   {
>>   struct acpi_madt_local_x2apic *p =
>>      (struct acpi_madt_local_x2apic *)header;
>> - printk(KERN_INFO PREFIX
>> -       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
>> -       p->local_apic_id, p->uid,
>> -       (p->lapic_flags & ACPI_MADT_ENABLED) ?
>> -       "enabled" : "disabled");
>> + /*
>> + * Per cpu tracing clogs console output when NR_CPUS
>> + * is large.  Send only to kernel log buffer.
>> + */
>> + printk(KERN_DEBUG PREFIX
>> + "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
>> + p->local_apic_id, p->uid,
>> + (p->lapic_flags & ACPI_MADT_ENABLED) ?
>> + "enabled" : "disabled");
>>   }
>>   break;
>>  
>
> You can still use dev_dbg(PREFIX "...") here.

I thought dev_dbg needed the 'dev' structure and I wasn't sure how to get that...?

>
>> @@ -171,10 +175,16 @@
>>   {
>>   struct acpi_madt_local_sapic *p =
>>      (struct acpi_madt_local_sapic *)header;
>> - printk(KERN_INFO PREFIX
>> -       "LSAPIC (acpi_id[0x%02x] lsapic_id[0x%02x] lsapic_eid[0x%02x] %s)\n",
>> -       p->processor_id, p->id, p->eid,
>> -       (p->lapic_flags & ACPI_MADT_ENABLED) ? "enabled" : "disabled");
>> + /*
>> + * Per cpu tracing clogs console output when NR_CPUS
>> + * is large.  Send only to kernel log buffer.
>> + */
>> + printk(KERN_DEBUG PREFIX
>> + "LSAPIC (acpi_id[0x%02x] lsapic_id[0x%02x] "
>> + "lsapic_eid[0x%02x] %s)\n",
>> + p->processor_id, p->id, p->eid,
>> + (p->lapic_flags & ACPI_MADT_ENABLED) ?
>> + "enabled" : "disabled");
>>   }
>>   break;
>>  
>
> Likewise, but recent emails from Linus indicate that we don't want to
> break printk strings into multiple lines even if it goes over 80
> characters unless broken at '\n'.  Users who grep for
> "lsapic_id.*lsapic_eid" with this patch wouldn't find the string.

Ahh, ok, I hadn't heard that yet.  (Grep just needs to be made smarter... ;-)

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

[Mike Travis]

Hmm, yes I agree, too much cut and paste.  Will update. -thanks!

David Rientjes wrote:

> On Thu, 12 Nov 2009, Mike Travis wrote:
>
>> Limit the number of per cpu INIT messages when system is booting to
>> prevent clogging up the console output with repetitious messages.
>>
>
> Needs a better changelog.  What did you do to effect that change?  It
> looks like you're only emitting certain messages from the boot cpu.
>
>> Signed-off-by: Mike Travis <travis@...>
>> ---
>>  init/calibrate.c |   22 +++++++++++++---------
>>  kernel/cpu.c     |    5 ++---
>>  2 files changed, 15 insertions(+), 12 deletions(-)
>>
>> --- linux.orig/init/calibrate.c
>> +++ linux/init/calibrate.c
>> @@ -123,23 +123,26 @@
>>  {
>>   unsigned long ticks, loopbit;
>>   int lps_precision = LPS_PREC;
>> + bool boot_cpu = (smp_processor_id() == 0);
>>  
>>   if (preset_lpj) {
>>   loops_per_jiffy = preset_lpj;
>> - printk(KERN_INFO
>> - "Calibrating delay loop (skipped) preset value.. ");
>> - } else if ((smp_processor_id() == 0) && lpj_fine) {
>> + if (boot_cpu)
>> + pr_info("Calibrating delay loop (skipped) "
>> + "preset value.. ");
>
> Same comment as before about breaking printk strings into multiple lines
> when not broken at '\n'.  All the other patches your series look good
> after this, however.
>
>> + } else if ((boot_cpu) && lpj_fine) {
>
> Parentheses around boot_cpu?
>
>>   loops_per_jiffy = lpj_fine;
>> - printk(KERN_INFO
>> - "Calibrating delay loop (skipped), "
>> + pr_info("Calibrating delay loop (skipped), "
>>   "value calculated using timer frequency.. ");
>>   } else if ((loops_per_jiffy = calibrate_delay_direct()) != 0) {
>> - printk(KERN_INFO
>> - "Calibrating delay using timer specific routine.. ");
>> + if (boot_cpu)
>> + pr_info("Calibrating delay using timer "
>> + "specific routine.. ");
>>   } else {
>>   loops_per_jiffy = (1<<12);
>>  
>> - printk(KERN_INFO "Calibrating delay loop... ");
>> + if (boot_cpu)
>> + pr_info("Calibrating delay loop... ");
>>   while ((loops_per_jiffy <<= 1) != 0) {
>>   /* wait for "start of" clock tick */
>>   ticks = jiffies;
>> @@ -170,7 +173,8 @@
>>   loops_per_jiffy &= ~loopbit;
>>   }
>>   }
>> - printk(KERN_CONT "%lu.%02lu BogoMIPS (lpj=%lu)\n",
>> + if (boot_cpu)
>> + pr_cont("%lu.%02lu BogoMIPS (lpj=%lu)\n",
>>   loops_per_jiffy/(500000/HZ),
>>   (loops_per_jiffy/(5000/HZ)) % 100, loops_per_jiffy);
>>  }
>> --- linux.orig/kernel/cpu.c
>> +++ linux/kernel/cpu.c
>> @@ -392,10 +392,9 @@
>>   if (cpu == first_cpu)
>>   continue;
>>   error = _cpu_down(cpu, 1);
>> - if (!error) {
>> + if (!error)
>>   cpumask_set_cpu(cpu, frozen_cpus);
>> - printk("CPU%d is down\n", cpu);
>> - } else {
>> + else {
>>   printk(KERN_ERR "Error taking CPU%d down: %d\n",
>>   cpu, error);
>>   break;

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

[David Rientjes]

On Thu, 12 Nov 2009, Mike Travis wrote:

> > > --- linux.orig/drivers/acpi/tables.c
> > > +++ linux/drivers/acpi/tables.c
> > > @@ -66,11 +66,15 @@
> > >   {
> > >   struct acpi_madt_local_x2apic *p =
> > >      (struct acpi_madt_local_x2apic *)header;
> > > - printk(KERN_INFO PREFIX
> > > -       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
> > > -       p->local_apic_id, p->uid,
> > > -       (p->lapic_flags & ACPI_MADT_ENABLED) ?
> > > -       "enabled" : "disabled");
> > > + /*
> > > + * Per cpu tracing clogs console output when NR_CPUS
> > > + * is large.  Send only to kernel log buffer.
> > > + */
> > > + printk(KERN_DEBUG PREFIX
> > > + "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
> > > + p->local_apic_id, p->uid,
> > > + (p->lapic_flags & ACPI_MADT_ENABLED) ?
> > > + "enabled" : "disabled");
> > >   }
> > >   break;
> > >  
> >
> > You can still use dev_dbg(PREFIX "...") here.
>
> I thought dev_dbg needed the 'dev' structure and I wasn't sure how to get
> that...?
>

Ah, ok, it needs to be pr_debug(PREFIX "...") then.

Any reason why the other printk's in acpi_table_print_madt_entry() weren't
converted to use KERN_DEBUG?  It might make more sense to convert all
those to use a new acpi=verbose flag.

I'm not sure if Ingo is the right person to go through for acpi patches, I
think this should probably be submitted to Len Brown <lenb@...> and
linux-acpi@... instead.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[Yinghai Lu-3]

On Thu, Nov 12, 2009 at 9:19 AM, Mike Travis <travis@...> wrote:

> With a large number of processors in a system there is an excessive amount
> of messages sent to the system console.  It's estimated that with 4096
> processors in a system, and the console baudrate set to 56K, the startup
> messages will take about 84 minutes to clear the serial port.
>
> This set of patches limits the number of repetitious messages which contain
> no additional information.  Much of this information is obtainable from the
> /proc and /sysfs.   Most of the messages are also sent to the kernel log
> buffer as KERN_DEBUG messages so it can be used to examine more closely any
> details specific to a processor.
>
> The list of message transformations....
>
> For system_state == SYSTEM_BOOTING:
>
> [   18.669304] Booting Node   0, Processors  1 2 3 4 5 6 7 Ok.
> [   19.321065] Booting Node   1, Processors  8 9 10 11 12 13 14 15 Ok.
> [   20.065325] Booting Node   2, Processors  16 17 18 19 20 21 22 23 Ok.
> ..
> [  117.153053] Booting Node  63, Processors  1016 1017 1018 1019 1020 1021 1022 1023 Ok.
> [  117.952235] Brought up 1024 CPUs
>
> Timing shows that with NO bootup messages, it takes only slightly less time
> so printing adds very little overhead:
>
> [   18.670219] Booting all processors
> [  117.180248] Brought up 1024 CPUs
>
> For Processor Information printout, the specifics of CPU0 are printed and
> then at the end of the bootup sequence, a summary is printed:
>
> [  117.957682] Processor Information for CPUS: 0-191,208-223,256-271,...
> [  117.968034] Genuine Intel(R) CPU             0000 @ 2.13GHz stepping 04
> [  117.977406] BogoMIPS: MIN 3989.01 (7978031) AVG 4266.62 (8533249) MAX 4537.51 (9075028)
> [  117.984496] Processor Information for CPUS: 192-207,240-255,272-287,...
> [  117.996032] Genuine Intel(R) CPU             0000 @ 2.13GHz stepping 03
> [  118.001404] BogoMIPS: MIN 4021.49 (8042995) AVG 4265.91 (8531833) MAX 4479.79 (8959584)
> [  118.012373] Processor Information for CPUS: 224-239,736-751
> [  118.020032] Genuine Intel(R) CPU             0000 @ 1.87GHz stepping 03
> [  118.028033] BogoMIPS: MIN 3733.92 (7467855) AVG 3746.96 (7493933) MAX 3939.52 (7879056)
> [  118.036360] Processor Information for CPUS: 320-335,384-415,432-447,...
> [  118.044032] Intel(R) Xeon(R) CPU           X7560  @ 2.27GHz stepping 05
> [  118.053404] BogoMIPS: MIN 4244.65 (8489318) AVG 4532.45 (9064917) MAX 4666.80 (9333604)
> [  118.060644] Total of 1024 processors activated (4386353.46 BogoMIPS).
>
>
> The following lines have been removed:
>
>        CPU: Physical Processor ID:
>        CPU: Processor Core ID:
>        CPU %d/0x%x -> Node %d

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

[Yinghai Lu-3]

On Thu, Nov 12, 2009 at 9:19 AM, Mike Travis <travis@...> wrote:
>
> Second version...

what is the boot time that you can spare your this patchset?

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

[Ingo Molnar]

* Mike Travis <travis@...> wrote:

>
>
> Ingo Molnar wrote:
> >* Mike Travis <travis@...> wrote:
> >
> >>--- linux.orig/arch/x86/kernel/smpboot.c
> >>+++ linux/arch/x86/kernel/smpboot.c
> >>@@ -442,6 +442,84 @@
> >> return c->llc_shared_map;
> >> }
> >>+/* Summarize Processor Information */
> >>+static void __init summarize_cpu_info(void)
> >>+{
> >>+ cpumask_var_t cpulist, cpusdone;
> >>+ int cpu;
> >>+ int err = 0;
> >>+
> >>+ if (!alloc_cpumask_var(&cpulist, GFP_KERNEL))
> >>+ err = 1;
> >>+ else if (!alloc_cpumask_var(&cpusdone, GFP_KERNEL)) {
> >>+ free_cpumask_var(cpulist);
> >>+ err = 1;
> >>+ }
> >>+ if (err) {
> >>+ printk(KERN_INFO "Can't print processor summaries\n");
> >>+ return;
> >>+ }
> >>+
> >>+ cpumask_clear(cpusdone);
> >>+ for (cpu = 0; cpu < nr_cpu_ids; cpu++) {
> >>+ struct cpuinfo_x86 *c;
> >>+ char buf[128];
> >>+ int ncpu, len;
> >>+ unsigned long minlpj, maxlpj, avglpj = 0;
> >>+
> >>+ /* skip if cpu has already been displayed */
> >>+ if (cpumask_test_cpu(cpu, cpusdone))
> >>+ continue;
> >>+
> >>+ c = &cpu_data(cpu);
> >>+ minlpj = ULONG_MAX;
> >>+ maxlpj = 0;
> >>+
> >>+ cpumask_clear(cpulist);
> >>+
> >>+ /* collate all cpus with same specifics */
> >>+ for (ncpu = cpu; ncpu < nr_cpu_ids; ncpu++) {
> >>+ struct cpuinfo_x86 *n = &cpu_data(ncpu);
> >>+
> >>+ if (c->x86 != n->x86 ||
> >>+    c->x86_vendor != n->x86_vendor ||
> >>+    c->x86_model  != n->x86_model  ||
> >>+    c->x86_mask   != n->x86_mask   ||
> >>+    strcmp(c->x86_model_id, n->x86_model_id))
> >>+ continue;
> >>+
> >>+ cpumask_set_cpu(ncpu, cpulist);
> >>+ cpumask_set_cpu(ncpu, cpusdone);
> >>+
> >>+ if (cpu_data(ncpu).loops_per_jiffy < minlpj)
> >>+ minlpj = cpu_data(ncpu).loops_per_jiffy;
> >>+
> >>+ if (cpu_data(ncpu).loops_per_jiffy > maxlpj)
> >>+ maxlpj = cpu_data(ncpu).loops_per_jiffy;
> >>+
> >>+ avglpj += cpu_data(ncpu).loops_per_jiffy;
> >>+ }
> >>+
> >>+ len = cpulist_scnprintf(buf, sizeof(buf), cpulist);
> >>+ printk(KERN_INFO
> >>+ "Processor Information for CPUS: %s%s\n",
> >>+ buf, (len == sizeof(buf)-1) ? "..." : "");
> >>+
> >>+ printk(KERN_INFO);
> >>+ print_cpu_info(c);
> >>+
> >>+ avglpj /= cpumask_weight(cpulist);
> >>+ printk(KERN_INFO "BogoMIPS: MIN %lu.%02lu (%lu) "
> >>+ "AVG %lu.%02lu (%lu) MAX %lu.%02lu (%lu)\n",
> >>+ minlpj/(500000/HZ), (minlpj/(5000/HZ)) % 100, minlpj,
> >>+ avglpj/(500000/HZ), (avglpj/(5000/HZ)) % 100, avglpj,
> >>+ maxlpj/(500000/HZ), (maxlpj/(5000/HZ)) % 100, maxlpj);
> >>+ }
> >>+
> >>+ free_cpumask_var(cpusdone);
> >>+ free_cpumask_var(cpulist);
> >>+}
> >>+
> >
> >Sigh, that's _way_ too complex.
> >
> >If you cannot print it in a summarized way without carrying over
> >stupid state like bitmaps then please do the simple and obvious,
> >and print:
> >
> >booting CPUs: #0 #1 #2 #3 #4 #5 #6 ...
>
> That is almost exactly what it does. [...]

You are missing my point i think, which is that we dont want the 76
lines long summarize_cpu_info() complexity during bootup. Lets keep it
_very_ simple and zap excessive messages - like DaveJ's patch did.

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

[Ingo Molnar]

* David Rientjes <rientjes@...> wrote:

> It's possible to reduce the number of SRAT messages emitted to the kernel
> log by printing each valid pxm once and then creating bitmaps to represent
> the apic ids that map to the same node.
>
> This reduces lines such as
>
> SRAT: PXM 0 -> APIC 0 -> Node 0
> SRAT: PXM 0 -> APIC 1 -> Node 0
> SRAT: PXM 1 -> APIC 2 -> Node 1
> SRAT: PXM 1 -> APIC 3 -> Node 1
>
> to
>
> SRAT: PXM 0 -> APIC {0-1} -> Node 0
> SRAT: PXM 1 -> APIC {2-3} -> Node 1
>
> The buffer used to store the apic id list is 128 characters in length.
> If that is too small to represent all the apic id ranges that are bound
> to a single pxm, a trailing "..." is added.  APICID_LIST_LEN should be
> manually increased for such configurations.
>
> Acked-by: Mike Travis <travis@...>
> Signed-off-by: David Rientjes <rientjes@...>
> ---
>  arch/x86/mm/srat_64.c |   41 +++++++++++++++++++++++++++++++++++++----
>  drivers/acpi/numa.c   |    5 +++++
>  include/linux/acpi.h  |    3 ++-
>  3 files changed, 44 insertions(+), 5 deletions(-)
>
> diff --git a/arch/x86/mm/srat_64.c b/arch/x86/mm/srat_64.c
> --- a/arch/x86/mm/srat_64.c
> +++ b/arch/x86/mm/srat_64.c
> @@ -36,6 +36,9 @@ static int num_node_memblks __initdata;
>  static struct bootnode node_memblk_range[NR_NODE_MEMBLKS] __initdata;
>  static int memblk_nodeid[NR_NODE_MEMBLKS] __initdata;
>  
> +static DECLARE_BITMAP(apicid_map, MAX_LOCAL_APIC) __initdata;
> +#define APICID_LIST_LEN (128)
> +
>  static __init int setup_node(int pxm)
>  {
>   return acpi_map_pxm_to_node(pxm);
> @@ -136,8 +139,6 @@ acpi_numa_x2apic_affinity_init(struct acpi_srat_x2apic_cpu_affinity *pa)
>   apicid_to_node[apic_id] = node;
>   node_set(node, cpu_nodes_parsed);
>   acpi_numa = 1;
> - printk(KERN_INFO "SRAT: PXM %u -> APIC %u -> Node %u\n",
> -       pxm, apic_id, node);
>  }
>  
>  /* Callback for Proximity Domain -> LAPIC mapping */
> @@ -170,8 +171,40 @@ acpi_numa_processor_affinity_init(struct acpi_srat_cpu_affinity *pa)
>   apicid_to_node[apic_id] = node;
>   node_set(node, cpu_nodes_parsed);
>   acpi_numa = 1;
> - printk(KERN_INFO "SRAT: PXM %u -> APIC %u -> Node %u\n",
> -       pxm, apic_id, node);
> +}
> +
> +void __init acpi_numa_print_srat_mapping(void)
> +{
> + char apicid_list[APICID_LIST_LEN];
> + int i, j;
> +
> + for (i = 0; i < MAX_PXM_DOMAINS; i++) {
> + int len;
> + int nid;
> +
> + nid = pxm_to_node(i);
> + if (nid == NUMA_NO_NODE)
> + continue;
> +
> + bitmap_zero(apicid_map, MAX_LOCAL_APIC);
> + for (j = 0; j < MAX_LOCAL_APIC; j++)
> + if (apicid_to_node[j] == nid)
> + set_bit(j, apicid_map);
> +
> + if (bitmap_empty(apicid_map, MAX_LOCAL_APIC))
> + continue;
> +
> + /*
> + * If the bitmap cannot be listed in a buffer of length
> + * APICID_LIST_LEN, then it is suffixed with "...".
> + */
> + len = bitmap_scnlistprintf(apicid_list, APICID_LIST_LEN,
> +   apicid_map, MAX_LOCAL_APIC);
> + pr_info("SRAT: PXM %u -> APIC {%s%s} -> Node %u\n",
> + i, apicid_list,
> + (len == APICID_LIST_LEN - 1) ? "..." : "",
> + nid);
> + }
>  }

No. As i suggested many times before, just get rid of the printouts or
make them boot-debug-flag dependent.

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