Big log level reduction...

90% of what we print isn't useful to a normal user. This
dramatically reduces the amount of messages printed by
OPAL in normal circumstances.

We still need to add a way to bump the log level at boot
based on a BMC scratch register or some HDAT property.

Signed-off-by: Benjamin Herrenschmidt <benh@kernel.crashing.org>
Signed-off-by: Michael Neuling <mikey@neuling.org>
Signed-off-by: Stewart Smith <stewart@linux.vnet.ibm.com>

15 files changed, 46 insertions, 51 deletions

diff --git a/core/device.c b/core/device.c
index f3ee63f..42c47d1 100644
--- a/core/device.c
+++ b/core/device.c
@@ -893,7 +893,7 @@ int dt_expand_node(struct dt_node *node, const void *fdt, int fdt_node)
 
 void dt_expand(const void *fdt)
 {
-	printf("FDT: Parsing fdt @%p\n", fdt);
+	prlog(PR_DEBUG, "FDT: Parsing fdt @%p\n", fdt);
 
 	if (dt_expand_node(dt_root, fdt, 0) < 0)
 		abort();
diff --git a/core/init.c b/core/init.c
index 228186a..206b1ab 100644
--- a/core/init.c
+++ b/core/init.c
@@ -119,8 +119,8 @@ static bool try_load_elf64_le(struct elf_hdr *header)
 	kernel_size = le64_to_cpu(kh->e_shoff) +
 		(le16_to_cpu(kh->e_shentsize) * le16_to_cpu(kh->e_shnum));
 
-	printf("INIT: 64-bit kernel entry at 0x%llx, size 0x%lx\n",
-	       kernel_entry, kernel_size);
+	prlog(PR_DEBUG, "INIT: 64-bit kernel entry at 0x%llx, size 0x%lx\n",
+	      kernel_entry, kernel_size);
 
 	return true;
 }
@@ -371,7 +371,7 @@ static bool load_kernel(void)
 	if (dt_has_node_property(dt_chosen, "kernel-base-address", NULL)) {
 		kernel_entry = dt_prop_get_u64(dt_chosen,
 					       "kernel-base-address");
-		printf("INIT: Kernel image at 0x%llx\n",kernel_entry);
+		prlog(PR_DEBUG, "INIT: Kernel image at 0x%llx\n", kernel_entry);
 		kh = (struct elf_hdr *)kernel_entry;
 		/*
 		 * If the kernel is at 0, restore it as it was overwritten
@@ -398,11 +398,12 @@ static bool load_kernel(void)
 		}
 	}
 
-	printf("INIT: Kernel loaded, size: %zu bytes (0 = unknown preload)\n",
-	       kernel_size);
+	prlog(PR_DEBUG,
+	      "INIT: Kernel loaded, size: %zu bytes (0 = unknown preload)\n",
+	      kernel_size);
 
 	if (kh->ei_ident != ELF_IDENT) {
-		printf("INIT: ELF header not found. Assuming raw binary.\n");
+		prerror("INIT: ELF header not found. Assuming raw binary.\n");
 		return true;
 	}
 
@@ -413,7 +414,7 @@ static bool load_kernel(void)
 		if (!try_load_elf32(kh))
 			return false;
 	} else {
-		printf("INIT: Neither ELF32 not ELF64 ?\n");
+		prerror("INIT: Neither ELF32 not ELF64 ?\n");
 		return false;
 	}
 
@@ -542,7 +543,7 @@ void __noreturn load_and_boot_kernel(bool is_reboot)
 
 	/* Dump the selected console */
 	stdoutp = dt_prop_get_def(dt_chosen, "linux,stdout-path", NULL);
-	printf("INIT: stdout-path: %s\n", stdoutp ? stdoutp : "");
+	prlog(PR_DEBUG, "INIT: stdout-path: %s\n", stdoutp ? stdoutp : "");
 
 
 	printf("INIT: Starting kernel at 0x%llx, fdt at %p %u bytes)\n",
diff --git a/core/interrupts.c b/core/interrupts.c
index b9f4d14..9161960 100644
--- a/core/interrupts.c
+++ b/core/interrupts.c
@@ -230,8 +230,8 @@ void add_opal_interrupts(void)
 				continue;
 			name = is->ops->name ? is->ops->name(is, isn) : NULL;
 			ns = name ? strlen(name) : 0;
-			printf("irq %x name: %s (%d/%d)\n",
-			       isn, name ? name : "<null>", ns, tns);
+			prlog(PR_DEBUG, "irq %x name: %s (%d/%d)\n",
+			      isn, name ? name : "<null>", ns, tns);
 			names = realloc(names, tns + ns + 1);
 			if (name) {
 				strcpy(names + tns, name);
diff --git a/core/mem_region.c b/core/mem_region.c
index ec38b24..8d1363f 100644
--- a/core/mem_region.c
+++ b/core/mem_region.c
@@ -926,7 +926,7 @@ static void mem_region_parse_reserved_properties(void)
 	const struct dt_property *names, *ranges;
 	struct mem_region *region;
 
-	prlog(PR_INFO, "MEM: parsing reserved memory from "
+	prlog(PR_DEBUG, "MEM: parsing reserved memory from "
 			"reserved-names/-ranges properties\n");
 
 	names = dt_find_property(dt_root, "reserved-names");
diff --git a/core/nvram-format.c b/core/nvram-format.c
index 84407fc..923098a 100644
--- a/core/nvram-format.c
+++ b/core/nvram-format.c
@@ -156,12 +156,12 @@ int nvram_check(void *nvram_image, const uint32_t nvram_size)
 		}
 	}
 	if (!found_common) {
-		prerror("NVRAM: Common partition not found !\n");
+		prlog_once(PR_ERR, "NVRAM: Common partition not found !\n");
 		goto failed;
 	}
 
 	if (!skiboot_part_hdr) {
-		prerror("NVRAM: Skiboot private partition not found !\n");
+		prlog_once(PR_ERR, "NVRAM: Skiboot private partition not found !\n");
 		goto failed;
 	} else {
 		/*
@@ -222,11 +222,8 @@ const char *nvram_query(const char *key)
 	 *
 	 * NB: nvram_validate() can update skiboot_part_hdr
 	 */
-	if (!nvram_validate()) {
-		prerror("NVRAM: Look up for '%s' failed due to bad format!\n",
-			key);
+	if (!nvram_validate())
 		return NULL;
-	}
 
 	part_end = (const char *) skiboot_part_hdr
 		+ be16_to_cpu(skiboot_part_hdr->len) * 16 - 1;
diff --git a/core/opal.c b/core/opal.c
index 14357cc..8095f73 100644
--- a/core/opal.c
+++ b/core/opal.c
@@ -64,8 +64,8 @@ void opal_table_init(void)
 	struct opal_table_entry *s = __opal_table_start;
 	struct opal_table_entry *e = __opal_table_end;
 
-	printf("OPAL table: %p .. %p, branch table: %p\n",
-	       s, e, opal_branch_table);
+	prlog(PR_DEBUG, "OPAL table: %p .. %p, branch table: %p\n",
+	      s, e, opal_branch_table);
 	while(s < e) {
 		opal_branch_table[s->token] = function_entry_address(s->func);
 		opal_num_args[s->token] = s->nargs;
diff --git a/core/pci.c b/core/pci.c
index 63d9d24..cc18db1 100644
--- a/core/pci.c
+++ b/core/pci.c
@@ -1737,7 +1737,7 @@ void pci_init_slots(void)
 	if (platform.pre_pci_fixup)
 		platform.pre_pci_fixup();
 
-	prlog(PR_NOTICE, "PCI: Resetting PHBs...\n");
+	prlog(PR_INFO, "PCI: Resetting PHBs...\n");
 	pci_do_jobs(pci_reset_phb);
 
 	prlog(PR_NOTICE, "PCI: Probing slots...\n");
diff --git a/hdata/spira.c b/hdata/spira.c
index fd7f351..16ec46a 100644
--- a/hdata/spira.c
+++ b/hdata/spira.c
@@ -1301,7 +1301,7 @@ int parse_hdat(bool is_opal)
 
 	add_stop_levels();
 
-	prlog(PR_INFO, "Parsing HDAT...done\n");
+	prlog(PR_DEBUG, "Parsing HDAT...done\n");
 
 	return 0;
 }
diff --git a/hw/lpc.c b/hw/lpc.c
index b5fbc6c..6fdd1f0 100644
--- a/hw/lpc.c
+++ b/hw/lpc.c
@@ -1186,8 +1186,8 @@ static void lpc_init_chip_p9(struct dt_node *opb_node)
 	val &= 0xf0000000;
 	opb_write(lpc, opb_master_reg_base + 0xc, val, 4);
 
-	printf("LPC[%03x]: Initialized, access via MMIO @%p\n",
-	       gcid, lpc->mbase);
+	prlog(PR_INFO, "LPC[%03x]: Initialized\n", gcid);
+	prlog(PR_DEBUG,"access via MMIO @%p\n", lpc->mbase);
 
 	chip->lpc = lpc;
 }
@@ -1210,7 +1210,8 @@ void lpc_init(void)
 		}
 	}
 	if (lpc_default_chip_id >= 0)
-		printf("LPC: Default bus on chip 0x%x\n", lpc_default_chip_id);
+		prlog(PR_DEBUG, "Default bus on chip 0x%x\n",
+		      lpc_default_chip_id);
 
 	if (has_lpc) {
 		opal_register(OPAL_LPC_WRITE, opal_lpc_write, 5);
diff --git a/hw/phb4.c b/hw/phb4.c
index 7e8ba3b..4d93b81 100644
--- a/hw/phb4.c
+++ b/hw/phb4.c
@@ -308,9 +308,10 @@ static int64_t phb4_rc_write(struct phb4 *p, uint32_t offset, uint8_t sz,
 			break;
 		}
 
-		if (old != oldold)
-			PHBDBG(p, "Rewrote %x to %x for reg %x for W1C\n",
-			       oldold, old, reg);
+		if (old != oldold) {
+			PHBLOGCFG(p, "Rewrote %x to %x for reg %x for W1C\n",
+				  oldold, old, reg);
+		}
 
 		if (sz == 1) {
 			shift = (offset & 3) << 3;
@@ -4259,7 +4260,7 @@ static void phb4_probe_stack(struct dt_node *stk_node, uint32_t pec_index,
 	stk_index = dt_prop_get_u32(stk_node, "reg");
 	phb_num = dt_prop_get_u32(stk_node, "ibm,phb-index");
 	path = dt_get_path(stk_node);
-	prlog(PR_NOTICE, "PHB: Chip %d Found PHB4 PBCQ%d Stack %d at %s\n",
+	prlog(PR_INFO, "PHB: Chip %d Found PHB4 PBCQ%d Stack %d at %s\n",
 	      gcid, pec_index, stk_index, path);
 	free(path);
 
@@ -4297,11 +4298,6 @@ static void phb4_probe_stack(struct dt_node *stk_node, uint32_t pec_index,
 	xscom_write(gcid, nest_stack + XPEC_NEST_STK_MMIO_BAR1_MASK, mmio1_bmask << 8);
 	bar_en |= XPEC_NEST_STK_BAR_EN_MMIO0 | XPEC_NEST_STK_BAR_EN_MMIO1;
 
-	prlog(PR_ERR, "PHB[%d:%d]   PHB@0x%016llx   IRQ@0x%016llx\n",
-	      gcid, phb_num, phb_bar, irq_bar);
-	prlog(PR_ERR, "PHB[%d:%d] MMIO0@0x%016llx MMIO1@0x%016llx \n",
-	      gcid, phb_num, mmio0_bar, mmio1_bar);
-
 	/* Build MMIO windows list */
 	mmio_win_sz = 0;
 	if (mmio0_bar) {
@@ -4328,13 +4324,13 @@ static void phb4_probe_stack(struct dt_node *stk_node, uint32_t pec_index,
 
 	/* Check ETU reset */
 	xscom_read(gcid, pci_stack + XPEC_PCI_STK_ETU_RESET, &val);
-	prlog_once(PR_ERR, "ETU reset: %llx\n", val);
+	prlog_once(PR_DEBUG, "ETU reset: %llx\n", val);
 	xscom_write(gcid, pci_stack + XPEC_PCI_STK_ETU_RESET, 0);
 	time_wait_ms(1);
 
 	// show we can read phb mmio space
 	foo = (void *)(phb_bar + 0x800); // phb version register
-	prlog_once(PR_ERR, "Version reg: 0x%016llx\n", in_be64(foo));
+	prlog_once(PR_DEBUG, "Version reg: 0x%016llx\n", in_be64(foo));
 
 	/* Create PHB node */
 	reg[0] = phb_bar;
diff --git a/hw/phys-map.c b/hw/phys-map.c
index 0fbd60d..8cccbf0 100644
--- a/hw/phys-map.c
+++ b/hw/phys-map.c
@@ -195,7 +195,7 @@ void phys_map_init(void)
 		phys_map = &phys_map_nimbus;
 	}
 
-	prlog(PR_NOTICE, "Assigning physical memory map table for %s\n", name);
+	prlog(PR_DEBUG, "Assigning physical memory map table for %s\n", name);
 
 }
 
diff --git a/hw/psi.c b/hw/psi.c
index 9da0257..69e03e5 100644
--- a/hw/psi.c
+++ b/hw/psi.c
@@ -1108,8 +1108,8 @@ static bool psi_init_psihb(struct dt_node *psihb)
 	psi_init_interrupts(psi);
 	psi_create_mm_dtnode(psi);
 
-	printf("PSI[0x%03x]: Found PSI bridge [active=%d]\n",
-			psi->chip_id, psi->active);
+	prlog(PR_INFO, "PSI[0x%03x]: Found PSI bridge [active=%d]\n",
+	      psi->chip_id, psi->active);
 	return true;
 }
 
diff --git a/hw/slw.c b/hw/slw.c
index ce409f9..c0ab9de 100644
--- a/hw/slw.c
+++ b/hw/slw.c
@@ -307,7 +307,7 @@ static bool slw_set_overrides_p9(struct proc_chip *chip, struct cpu_thread *c)
 	rc = xscom_read(chip->id,
 			XSCOM_ADDR_P9_EC_SLAVE(core, EC_PPM_SPECIAL_WKUP_HYP),
 			&tmp);
-	prlog(PR_NOTICE, "SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x%016llx\n", tmp);
+	prlog(PR_DEBUG, "SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x%016llx\n", tmp);
 	rc = xscom_read(chip->id,
 			XSCOM_ADDR_P9_EC_SLAVE(core, EC_PPM_SPECIAL_WKUP_OTR),
 			&tmp);
@@ -1145,7 +1145,7 @@ static void slw_init_chip_p9(struct proc_chip *chip)
 {
 	struct cpu_thread *c;
 
-	prlog(PR_NOTICE, "SLW: Init chip 0x%x\n", chip->id);
+	prlog(PR_DEBUG, "SLW: Init chip 0x%x\n", chip->id);
 
 	/* At power ON setup inits for power-mgt */
 	for_each_available_core_in_chip(c, chip->id)
diff --git a/hw/xscom.c b/hw/xscom.c
index 63813f1..a739b3c 100644
--- a/hw/xscom.c
+++ b/hw/xscom.c
@@ -740,11 +740,11 @@ void xscom_init(void)
 		else
 			chip_name = chip_names[chip->type];
 
-		printf("XSCOM: chip 0x%x at 0x%llx [%s DD%x.%x]\n",
-		       gcid, chip->xscom_base,
-		       chip_name,
-		       chip->ec_level >> 4,
-		       chip->ec_level & 0xf);
+		/* We keep a "CHIP" prefix to make the log more user-friendly */
+		prlog(PR_NOTICE, "CHIP: Chip ID %04x type: %s DD%x.%x\n",
+		      gcid, chip_name, chip->ec_level >> 4,
+		      chip->ec_level & 0xf);
+		prlog(PR_DEBUG, "XSCOM: Base address: 0x%llx\n", chip->xscom_base);
 	}
 
 	/* Collect details to trigger xstop via XSCOM write */
@@ -752,10 +752,10 @@ void xscom_init(void)
 	if (p) {
 		xstop_xscom.addr = dt_property_get_cell(p, 0);
 		xstop_xscom.fir_bit = dt_property_get_cell(p, 1);
-		prlog(PR_INFO, "XSTOP: XSCOM addr = 0x%llx, FIR bit = %lld\n",
-					xstop_xscom.addr, xstop_xscom.fir_bit);
+		prlog(PR_DEBUG, "XSTOP: XSCOM addr = 0x%llx, FIR bit = %lld\n",
+		      xstop_xscom.addr, xstop_xscom.fir_bit);
 	} else
-		prlog(PR_INFO, "XSTOP: ibm,sw-checkstop-fir prop not found\n");
+		prlog(PR_DEBUG, "XSTOP: ibm,sw-checkstop-fir prop not found\n");
 }
 
 void xscom_used_by_console(void)
diff --git a/libstb/stb.c b/libstb/stb.c
index 28d004d..f798bcb 100644
--- a/libstb/stb.c
+++ b/libstb/stb.c
@@ -206,7 +206,7 @@ int tb_measure(enum resource_id id, void *buf, size_t len)
 
 	digestp = NULL;
 	if (!trusted_mode) {
-		prlog(PR_NOTICE, "STB: %s skipped resource %d, "
+		prlog(PR_INFO, "STB: %s skipped resource %d, "
 		      "trusted_mode=0\n", __func__, id);
 		return STB_TRUSTED_MODE_DISABLED;
 	}
@@ -291,7 +291,7 @@ int sb_verify(enum resource_id id, void *buf, size_t len)
 	const char *name = NULL;
 
 	if (!secure_mode) {
-		prlog(PR_NOTICE, "STB: %s skipped resource %d, "
+		prlog(PR_INFO, "STB: %s skipped resource %d, "
 		      "secure_mode=0\n", __func__, id);
 		return STB_SECURE_MODE_DISABLED;
 	}