[PATCH] x86, cpu: trivial printk formatting fixes

[PATCH] x86, cpu: trivial printk formatting fixes

[Steven Honeyman]

A 2 line printk makes dmesg output messy, because the second line does not get a timestamp.
For example:

[    0.012863] CPU0: Thermal monitoring enabled (TM1)
[    0.012869] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
[    0.012958] Freeing SMP alternatives memory: 28K (ffffffff81d86000 - ffffffff81d8d000)
[    0.014961] dmar: Host address width 39

Signed-off-by: Steven Honeyman <stevenhoneyman@gmail.com>
---
 arch/x86/kernel/cpu/common.c | 11 ++++++-----
 arch/x86/kernel/cpu/intel.c  |  6 ++----
 2 files changed, 8 insertions(+), 9 deletions(-)

diff --git a/arch/x86/kernel/cpu/common.c b/arch/x86/kernel/cpu/common.c
index 4b4f78c..fbdd7bf 100644
--- a/arch/x86/kernel/cpu/common.c
+++ b/arch/x86/kernel/cpu/common.c
@@ -494,12 +494,13 @@ void cpu_detect_tlb(struct cpuinfo_x86 *c)
 	if (this_cpu->c_detect_tlb)
 		this_cpu->c_detect_tlb(c);
 
-	printk(KERN_INFO "Last level iTLB entries: 4KB %d, 2MB %d, 4MB %d\n"
-		"Last level dTLB entries: 4KB %d, 2MB %d, 4MB %d, 1GB %d\n",
+	pr_info("Last level iTLB entries: 4KB %d, 2MB %d, 4MB %d\n",
 		tlb_lli_4k[ENTRIES], tlb_lli_2m[ENTRIES],
-		tlb_lli_4m[ENTRIES], tlb_lld_4k[ENTRIES],
-		tlb_lld_2m[ENTRIES], tlb_lld_4m[ENTRIES],
-		tlb_lld_1g[ENTRIES]);
+		tlb_lli_4m[ENTRIES]);
+
+	pr_info("Last level dTLB entries: 4KB %d, 2MB %d, 4MB %d, 1GB %d\n",
+		tlb_lld_4k[ENTRIES], tlb_lld_2m[ENTRIES],
+		tlb_lld_4m[ENTRIES], tlb_lld_1g[ENTRIES]);
 }
 
 void detect_ht(struct cpuinfo_x86 *c)
diff --git a/arch/x86/kernel/cpu/intel.c b/arch/x86/kernel/cpu/intel.c
index 9cc6b6f..dcd08a3 100644
--- a/arch/x86/kernel/cpu/intel.c
+++ b/arch/x86/kernel/cpu/intel.c
@@ -487,10 +487,8 @@ static void init_intel(struct cpuinfo_x86 *c)
 
 		rdmsrl(MSR_IA32_ENERGY_PERF_BIAS, epb);
 		if ((epb & 0xF) == ENERGY_PERF_BIAS_PERFORMANCE) {
-			printk_once(KERN_WARNING "ENERGY_PERF_BIAS:"
-				" Set to 'normal', was 'performance'\n"
-				"ENERGY_PERF_BIAS: View and update with"
-				" x86_energy_perf_policy(8)\n");
+			pr_info_once("ENERGY_PERF_BIAS: Set to 'normal', was 'performance'\n");
+			pr_info_once("ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)\n");
 			epb = (epb & ~0xF) | ENERGY_PERF_BIAS_NORMAL;
 			wrmsrl(MSR_IA32_ENERGY_PERF_BIAS, epb);
 		}
-- 
2.1.3

Re: [PATCH] x86, cpu: trivial printk formatting fixes

[Joe Perches]

On Sat, 2014-11-01 at 15:44 +0000, Steven Honeyman wrote:
> A 2 line printk makes dmesg output messy, because the second line does not get a timestamp.
> For example:
[]
> diff --git a/arch/x86/kernel/cpu/intel.c b/arch/x86/kernel/cpu/intel.c
[]
> @@ -487,10 +487,8 @@ static void init_intel(struct cpuinfo_x86 *c)
>  
>  		rdmsrl(MSR_IA32_ENERGY_PERF_BIAS, epb);
>  		if ((epb & 0xF) == ENERGY_PERF_BIAS_PERFORMANCE) {
> -			printk_once(KERN_WARNING "ENERGY_PERF_BIAS:"
> -				" Set to 'normal', was 'performance'\n"
> -				"ENERGY_PERF_BIAS: View and update with"
> -				" x86_energy_perf_policy(8)\n");
> +			pr_info_once("ENERGY_PERF_BIAS: Set to 'normal', was 'performance'\n");
> +			pr_info_once("ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)\n");

This changes the logging level.

You should either mention why in the changelog
or use pr_warn_once

Re: [PATCH] x86, cpu: trivial printk formatting fixes

[Borislav Petkov]

On Sat, Nov 01, 2014 at 03:44:56PM +0000, Steven Honeyman wrote:
> A 2 line printk makes dmesg output messy, because the second line does not get a timestamp.
> For example:
> 
> [    0.012863] CPU0: Thermal monitoring enabled (TM1)
> [    0.012869] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
> Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
> [    0.012958] Freeing SMP alternatives memory: 28K (ffffffff81d86000 - ffffffff81d8d000)
> [    0.014961] dmar: Host address width 39

It looks just fine here, albeit with repeated timestamp:

$ dmesg | grep -E "[id]TLB"
[    0.269607] Last level iTLB entries: 4KB 512, 2MB 1024, 4MB 512
[    0.269607] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 512, 1GB 0

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: [PATCH] x86, cpu: trivial printk formatting fixes

[Steven Honeyman]

On 1 November 2014 17:19, Borislav Petkov <bp@alien8.de> wrote:
> On Sat, Nov 01, 2014 at 03:44:56PM +0000, Steven Honeyman wrote:
>> A 2 line printk makes dmesg output messy, because the second line does not get a timestamp.
>> For example:
>>
>> [    0.012863] CPU0: Thermal monitoring enabled (TM1)
>> [    0.012869] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
>> Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
>> [    0.012958] Freeing SMP alternatives memory: 28K (ffffffff81d86000 - ffffffff81d8d000)
>> [    0.014961] dmar: Host address width 39
>
> It looks just fine here, albeit with repeated timestamp:
>
> $ dmesg | grep -E "[id]TLB"
> [    0.269607] Last level iTLB entries: 4KB 512, 2MB 1024, 4MB 512
> [    0.269607] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 512, 1GB 0

That's strange! Is it the same for the other one? I just double
checked on the slight chance I had an alias causing problems etc, but
that wasn't the case:

$ 'dmesg'|'grep' ENERGY
[    0.010557] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
$ dmesg --version && grep --version
dmesg from util-linux 2.25.2
grep (GNU grep) 2.20


On 1 November 2014 17:17, Joe Perches <joe@perches.com> wrote:
> This changes the logging level.
>
> You should either mention why in the changelog
> or use pr_warn_once

OK, I will resubmit with a new description if needed.
Would you agree that info is a more suitable log level than warn for
this message? Even notice seemed too much, as it isn't a 'significant
condition'


Thanks,
Steven

Re: [PATCH] x86, cpu: trivial printk formatting fixes

[Borislav Petkov]

On Sat, Nov 01, 2014 at 05:38:18PM +0000, Steven Honeyman wrote:
> On 1 November 2014 17:19, Borislav Petkov <bp@alien8.de> wrote:
> > On Sat, Nov 01, 2014 at 03:44:56PM +0000, Steven Honeyman wrote:
> >> A 2 line printk makes dmesg output messy, because the second line does not get a timestamp.
> >> For example:
> >>
> >> [    0.012863] CPU0: Thermal monitoring enabled (TM1)
> >> [    0.012869] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
> >> Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
> >> [    0.012958] Freeing SMP alternatives memory: 28K (ffffffff81d86000 - ffffffff81d8d000)
> >> [    0.014961] dmar: Host address width 39
> >
> > It looks just fine here, albeit with repeated timestamp:
> >
> > $ dmesg | grep -E "[id]TLB"
> > [    0.269607] Last level iTLB entries: 4KB 512, 2MB 1024, 4MB 512
> > [    0.269607] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 512, 1GB 0
> 
> That's strange! Is it the same for the other one? I just double

dmesg | grep ENERGY
[    0.061976] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
[    0.061976] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)

> checked on the slight chance I had an alias causing problems etc, but
> that wasn't the case:
> 
> $ 'dmesg'|'grep' ENERGY
> [    0.010557] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
> ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
> $ dmesg --version && grep --version
> dmesg from util-linux 2.25.2
> grep (GNU grep) 2.20

$ dmesg --version && grep --version
dmesg from util-linux 2.20.1
grep (GNU grep) 2.20

I've upgraged util-linux (for dmesg) on the other box:

$ dmesg --version && grep --version
dmesg from util-linux 2.25.1
grep (GNU grep) 2.18

and now I get:

dmesg | grep -E "[id]TLB"
[    0.269607] Last level iTLB entries: 4KB 512, 2MB 1024, 4MB 512
Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 512, 1GB 0

So I'd say it looks like a regression in dmesg itself.

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: [PATCH] x86, cpu: trivial printk formatting fixes

[Steven Honeyman]

On 1 November 2014 17:51, Borislav Petkov <bp@alien8.de> wrote:
> On Sat, Nov 01, 2014 at 05:38:18PM +0000, Steven Honeyman wrote:
>> On 1 November 2014 17:19, Borislav Petkov <bp@alien8.de> wrote:
>> > On Sat, Nov 01, 2014 at 03:44:56PM +0000, Steven Honeyman wrote:
>> >> A 2 line printk makes dmesg output messy, because the second line does not get a timestamp.
>> >> For example:
>> >>
>> >> [    0.012863] CPU0: Thermal monitoring enabled (TM1)
>> >> [    0.012869] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
>> >> Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
>> >> [    0.012958] Freeing SMP alternatives memory: 28K (ffffffff81d86000 - ffffffff81d8d000)
>> >> [    0.014961] dmar: Host address width 39
>> >
>> > It looks just fine here, albeit with repeated timestamp:
>> >
>> > $ dmesg | grep -E "[id]TLB"
>> > [    0.269607] Last level iTLB entries: 4KB 512, 2MB 1024, 4MB 512
>> > [    0.269607] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 512, 1GB 0
>>
>> That's strange! Is it the same for the other one? I just double
>
> dmesg | grep ENERGY
> [    0.061976] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
> [    0.061976] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
>
>> checked on the slight chance I had an alias causing problems etc, but
>> that wasn't the case:
>>
>> $ 'dmesg'|'grep' ENERGY
>> [    0.010557] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
>> ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
>> $ dmesg --version && grep --version
>> dmesg from util-linux 2.25.2
>> grep (GNU grep) 2.20
>
> $ dmesg --version && grep --version
> dmesg from util-linux 2.20.1
> grep (GNU grep) 2.20
>
> I've upgraged util-linux (for dmesg) on the other box:
>
> $ dmesg --version && grep --version
> dmesg from util-linux 2.25.1
> grep (GNU grep) 2.18
>
> and now I get:
>
> dmesg | grep -E "[id]TLB"
> [    0.269607] Last level iTLB entries: 4KB 512, 2MB 1024, 4MB 512
> Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 512, 1GB 0
>
> So I'd say it looks like a regression in dmesg itself.

Hmm - the difference is to do with the source of the kernel ring
buffer. The old output format be obtained using the latest dmesg by
adding "-S", which uses syslog(2) rather than /dev/kmsg.
(added in commit 7af230601ab)

The klogctl version interprets the \n and adds the timestamp
afterwards, but /dev/kmsg changes the '\n' to "\x0a" resulting in:
4,355,10557,-;ENERGY_PERF_BIAS: Set to 'normal', was
'performance'\x0aENERGY_P...

It looks as though it's just a matter of opinion/preference whether
control characters are printed (rfc5424)

Re: [PATCH] x86, cpu: trivial printk formatting fixes

[Borislav Petkov]

On Sun, Nov 02, 2014 at 04:03:52AM +0000, Steven Honeyman wrote:
> Hmm - the difference is to do with the source of the kernel ring
> buffer. The old output format be obtained using the latest dmesg by
> adding "-S", which uses syslog(2) rather than /dev/kmsg.
> (added in commit 7af230601ab)
> 
> The klogctl version interprets the \n and adds the timestamp
> afterwards, but /dev/kmsg changes the '\n' to "\x0a" resulting in:
> 4,355,10557,-;ENERGY_PERF_BIAS: Set to 'normal', was
> 'performance'\x0aENERGY_P...
> 
> It looks as though it's just a matter of opinion/preference whether
> control characters are printed (rfc5424)

Right, I see what you mean. There's this in the /dev/kmsg code

---
 * /dev/kmsg exports the structured data in the following line format:
 *   "level,sequnum,timestamp;<message text>\n"
 *
 * The optional key/value pairs are attached as continuation lines starting
 * with a space character and terminated by a newline. All possible
 * non-prinatable characters are escaped in the "\xff" notation.
 *
 * Users of the export format should ignore possible additional values
 * separated by ',', and find the message after the ';' character.
 */
--

and also

---
        /* escape non-printable characters */
        for (i = 0; i < msg->text_len; i++) {
                unsigned char c = log_text(msg)[i];

                if (c < ' ' || c >= 127 || c == '\\')
                        len += sprintf(user->buf + len, "\\x%02x", c);
                else
                        user->buf[len++] = c;
        }
--

in devkmsg_read().

Hmm, so this all looks like an agreed upon thing or whatever. Oh, and
btw, if you don't enable printk timestamping, you won't see the issue.

I'd say the simplest solution - and this is only me and I like practical
- is to accept your patch after all and stop wasting time with this :-)

Only after you fix it, though, to *not* change log levels for the other
printk message. FWIW, your change even improves the readability a bit of
those printks.

Thanks.

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: [PATCH] x86, cpu: trivial printk formatting fixes

[Joe Perches]

(Adding Len Brown, original post: https://lkml.org/lkml/2014/11/1/67)

On Sat, 2014-11-01 at 17:38 +0000, Steven Honeyman wrote:
> On 1 November 2014 17:17, Joe Perches <joe@perches.com> wrote:
> > This changes the logging level.
> >
> > You should either mention why in the changelog
> > or use pr_warn_once
> 
> OK, I will resubmit with a new description if needed.
> Would you agree that info is a more suitable log level than warn for
> this message? Even notice seemed too much, as it isn't a 'significant
> 	condition'

This is only emitted when the bios didn't do the "right thing".
See commit abe48b108247e9b90

So it seems more like the origial message isn't descriptive
enough than KERN_WARN is not the correct level.