[PATCH] iommu/amd: Fix extended features logging

[PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

print_iommu_info prints the EFR register and then the decoded list of
features on a separate line:

pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
 PPR X2APIC NX GT IA GA PC GA_vAPIC

The second line is emitted via 'pr_cont', which causes it to have a
different ('warn') loglevel compared to the previous line ('info').

Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
from the pci_info format string, but this doesn't work, as pci_info
calls implicitly append a newline anyway.

Restore the newline, and call pr_info with empty format string to set
the loglevel for subsequent pr_cont calls. The same solution is used in
EFI and uvesafb drivers.

Fixes: 9a295ff0ffc9 ("iommu/amd: Print extended features in one line to fix divergent log levels")
Signed-off-by: Alexander Monakov <amonakov@ispras.ru>
Cc: Paul Menzel <pmenzel@molgen.mpg.de>
Cc: Joerg Roedel <jroedel@suse.de>
Cc: Suravee Suthikulpanit <suravee.suthikulpanit@amd.com>
Cc: iommu@lists.linux-foundation.org
---
 drivers/iommu/amd/init.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/drivers/iommu/amd/init.c b/drivers/iommu/amd/init.c
index 596d0c413473..a25e241eff1c 100644
--- a/drivers/iommu/amd/init.c
+++ b/drivers/iommu/amd/init.c
@@ -1929,8 +1929,11 @@ static void print_iommu_info(void)
 		pci_info(pdev, "Found IOMMU cap 0x%hx\n", iommu->cap_ptr);
 
 		if (iommu->cap & (1 << IOMMU_CAP_EFR)) {
-			pci_info(pdev, "Extended features (%#llx):",
+			pci_info(pdev, "Extended features (%#llx):\n",
 				 iommu->features);
+
+			pr_info("");
+
 			for (i = 0; i < ARRAY_SIZE(feat_str); ++i) {
 				if (iommu_feature(iommu, (1ULL << i)))
 					pr_cont(" %s", feat_str[i]);
-- 
2.30.0

[PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

print_iommu_info prints the EFR register and then the decoded list of
features on a separate line:

pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
 PPR X2APIC NX GT IA GA PC GA_vAPIC

The second line is emitted via 'pr_cont', which causes it to have a
different ('warn') loglevel compared to the previous line ('info').

Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
from the pci_info format string, but this doesn't work, as pci_info
calls implicitly append a newline anyway.

Restore the newline, and call pr_info with empty format string to set
the loglevel for subsequent pr_cont calls. The same solution is used in
EFI and uvesafb drivers.

Fixes: 9a295ff0ffc9 ("iommu/amd: Print extended features in one line to fix divergent log levels")
Signed-off-by: Alexander Monakov <amonakov@ispras.ru>
Cc: Paul Menzel <pmenzel@molgen.mpg.de>
Cc: Joerg Roedel <jroedel@suse.de>
Cc: Suravee Suthikulpanit <suravee.suthikulpanit@amd.com>
Cc: iommu@lists.linux-foundation.org
---
 drivers/iommu/amd/init.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/drivers/iommu/amd/init.c b/drivers/iommu/amd/init.c
index 596d0c413473..a25e241eff1c 100644
--- a/drivers/iommu/amd/init.c
+++ b/drivers/iommu/amd/init.c
@@ -1929,8 +1929,11 @@ static void print_iommu_info(void)
 		pci_info(pdev, "Found IOMMU cap 0x%hx\n", iommu->cap_ptr);
 
 		if (iommu->cap & (1 << IOMMU_CAP_EFR)) {
-			pci_info(pdev, "Extended features (%#llx):",
+			pci_info(pdev, "Extended features (%#llx):\n",
 				 iommu->features);
+
+			pr_info("");
+
 			for (i = 0; i < ARRAY_SIZE(feat_str); ++i) {
 				if (iommu_feature(iommu, (1ULL << i)))
 					pr_cont(" %s", feat_str[i]);
-- 
2.30.0

_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Paul Menzel]

Dear Alexander,


Am 10.04.21 um 23:11 schrieb Alexander Monakov:
> print_iommu_info prints the EFR register and then the decoded list of
> features on a separate line:
> 
> pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
>   PPR X2APIC NX GT IA GA PC GA_vAPIC
> 
> The second line is emitted via 'pr_cont', which causes it to have a
> different ('warn') loglevel compared to the previous line ('info').
> 
> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> from the pci_info format string, but this doesn't work, as pci_info
> calls implicitly append a newline anyway.

Hmm, did I really screw that up during my testing? I am sorry about that.

I tried to wrap my head around, where the newline is implicitly 
appended, and only found the definitions below.

     include/linux/pci.h:#define pci_info(pdev, fmt, arg...) 
dev_info(&(pdev)->dev, fmt, ##arg)

     include/linux/dev_printk.h:#define dev_info(dev, fmt, ...) 
                                      \
     include/linux/dev_printk.h:     _dev_info(dev, dev_fmt(fmt), 
##__VA_ARGS__)

     include/linux/dev_printk.h:__printf(2, 3) __cold
     include/linux/dev_printk.h:void _dev_info(const struct device *dev, 
const char *fmt, ...);

     include/linux/compiler_attributes.h:#define __printf(a, b) 
          __attribute__((__format__(printf, a, b)))


> Restore the newline, and call pr_info with empty format string to set
> the loglevel for subsequent pr_cont calls. The same solution is used in
> EFI and uvesafb drivers.

Thank you for fixing this.

> Fixes: 9a295ff0ffc9 ("iommu/amd: Print extended features in one line to fix divergent log levels")
> Signed-off-by: Alexander Monakov <amonakov@ispras.ru>
> Cc: Paul Menzel <pmenzel@molgen.mpg.de>
> Cc: Joerg Roedel <jroedel@suse.de>
> Cc: Suravee Suthikulpanit <suravee.suthikulpanit@amd.com>
> Cc: iommu@lists.linux-foundation.org
> ---
>   drivers/iommu/amd/init.c | 5 ++++-
>   1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/iommu/amd/init.c b/drivers/iommu/amd/init.c
> index 596d0c413473..a25e241eff1c 100644
> --- a/drivers/iommu/amd/init.c
> +++ b/drivers/iommu/amd/init.c
> @@ -1929,8 +1929,11 @@ static void print_iommu_info(void)
>   		pci_info(pdev, "Found IOMMU cap 0x%hx\n", iommu->cap_ptr);
>   
>   		if (iommu->cap & (1 << IOMMU_CAP_EFR)) {
> -			pci_info(pdev, "Extended features (%#llx):",
> +			pci_info(pdev, "Extended features (%#llx):\n",
>   				 iommu->features);
> +
> +			pr_info("");
> +
>   			for (i = 0; i < ARRAY_SIZE(feat_str); ++i) {
>   				if (iommu_feature(iommu, (1ULL << i)))
>   					pr_cont(" %s", feat_str[i]);
> 

In the discussion *smpboot: CPU numbers printed as warning* [1] John wrote:

> It is supported to provide loglevels for CONT messages. The loglevel is
> then only used if the append fails:
> 
>     pr_cont(KERN_INFO "message part");
> 
> I don't know if we want to go down that path. But it is supported.


Kind regards,

Paul


[1]: https://lkml.org/lkml/2021/2/16/191

Re: [PATCH] iommu/amd: Fix extended features logging

[Paul Menzel]

Dear Alexander,


Am 10.04.21 um 23:11 schrieb Alexander Monakov:
> print_iommu_info prints the EFR register and then the decoded list of
> features on a separate line:
> 
> pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
>   PPR X2APIC NX GT IA GA PC GA_vAPIC
> 
> The second line is emitted via 'pr_cont', which causes it to have a
> different ('warn') loglevel compared to the previous line ('info').
> 
> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> from the pci_info format string, but this doesn't work, as pci_info
> calls implicitly append a newline anyway.

Hmm, did I really screw that up during my testing? I am sorry about that.

I tried to wrap my head around, where the newline is implicitly 
appended, and only found the definitions below.

     include/linux/pci.h:#define pci_info(pdev, fmt, arg...) 
dev_info(&(pdev)->dev, fmt, ##arg)

     include/linux/dev_printk.h:#define dev_info(dev, fmt, ...) 
                                      \
     include/linux/dev_printk.h:     _dev_info(dev, dev_fmt(fmt), 
##__VA_ARGS__)

     include/linux/dev_printk.h:__printf(2, 3) __cold
     include/linux/dev_printk.h:void _dev_info(const struct device *dev, 
const char *fmt, ...);

     include/linux/compiler_attributes.h:#define __printf(a, b) 
          __attribute__((__format__(printf, a, b)))


> Restore the newline, and call pr_info with empty format string to set
> the loglevel for subsequent pr_cont calls. The same solution is used in
> EFI and uvesafb drivers.

Thank you for fixing this.

> Fixes: 9a295ff0ffc9 ("iommu/amd: Print extended features in one line to fix divergent log levels")
> Signed-off-by: Alexander Monakov <amonakov@ispras.ru>
> Cc: Paul Menzel <pmenzel@molgen.mpg.de>
> Cc: Joerg Roedel <jroedel@suse.de>
> Cc: Suravee Suthikulpanit <suravee.suthikulpanit@amd.com>
> Cc: iommu@lists.linux-foundation.org
> ---
>   drivers/iommu/amd/init.c | 5 ++++-
>   1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/iommu/amd/init.c b/drivers/iommu/amd/init.c
> index 596d0c413473..a25e241eff1c 100644
> --- a/drivers/iommu/amd/init.c
> +++ b/drivers/iommu/amd/init.c
> @@ -1929,8 +1929,11 @@ static void print_iommu_info(void)
>   		pci_info(pdev, "Found IOMMU cap 0x%hx\n", iommu->cap_ptr);
>   
>   		if (iommu->cap & (1 << IOMMU_CAP_EFR)) {
> -			pci_info(pdev, "Extended features (%#llx):",
> +			pci_info(pdev, "Extended features (%#llx):\n",
>   				 iommu->features);
> +
> +			pr_info("");
> +
>   			for (i = 0; i < ARRAY_SIZE(feat_str); ++i) {
>   				if (iommu_feature(iommu, (1ULL << i)))
>   					pr_cont(" %s", feat_str[i]);
> 

In the discussion *smpboot: CPU numbers printed as warning* [1] John wrote:

> It is supported to provide loglevels for CONT messages. The loglevel is
> then only used if the append fails:
> 
>     pr_cont(KERN_INFO "message part");
> 
> I don't know if we want to go down that path. But it is supported.


Kind regards,

Paul


[1]: https://lkml.org/lkml/2021/2/16/191
_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

On Sun, 11 Apr 2021, Paul Menzel wrote:

> > The second line is emitted via 'pr_cont', which causes it to have a
> > different ('warn') loglevel compared to the previous line ('info').
> > 
> > Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> > from the pci_info format string, but this doesn't work, as pci_info
> > calls implicitly append a newline anyway.
> 
> Hmm, did I really screw that up during my testing? I am sorry about that.
> 
> I tried to wrap my head around, where the newline is implicitly appended, and
> only found the definitions below.
> 
>     include/linux/pci.h:#define pci_info(pdev, fmt, arg...)
> dev_info(&(pdev)->dev, fmt, ##arg)
> 
>     include/linux/dev_printk.h:#define dev_info(dev, fmt, ...)
> \
>     include/linux/dev_printk.h:     _dev_info(dev, dev_fmt(fmt),
> ##__VA_ARGS__)
> 
>     include/linux/dev_printk.h:__printf(2, 3) __cold
>     include/linux/dev_printk.h:void _dev_info(const struct device *dev, const
> char *fmt, ...);
> 
>     include/linux/compiler_attributes.h:#define __printf(a, b)
> __attribute__((__format__(printf, a, b)))

Yeah, it's not obvious: it happens in kernel/printk/printk.c:vprintk_store
where it does

	if (dev_info)
		lflags |= LOG_NEWLINE;

It doesn't seem to be documented; I think it prevents using pr_cont with
"rich" printk facilities that go via _dev_info.

I suspect it quietly changed in commit c313af145b9bc ("printk() - isolate
KERN_CONT users from ordinary complete lines").

> In the discussion *smpboot: CPU numbers printed as warning* [1] John wrote:
> 
> > It is supported to provide loglevels for CONT messages. The loglevel is
> > then only used if the append fails:
> > 
> >     pr_cont(KERN_INFO "message part");
> > 
> > I don't know if we want to go down that path. But it is supported.

Yeah, I saw that, but decided to go with the 'pr_info("")' solution, because
it is less magic, and already used in two other drivers.

pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is nice.

Best regards,
Alexander

Re: [PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

On Sun, 11 Apr 2021, Paul Menzel wrote:

> > The second line is emitted via 'pr_cont', which causes it to have a
> > different ('warn') loglevel compared to the previous line ('info').
> > 
> > Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> > from the pci_info format string, but this doesn't work, as pci_info
> > calls implicitly append a newline anyway.
> 
> Hmm, did I really screw that up during my testing? I am sorry about that.
> 
> I tried to wrap my head around, where the newline is implicitly appended, and
> only found the definitions below.
> 
>     include/linux/pci.h:#define pci_info(pdev, fmt, arg...)
> dev_info(&(pdev)->dev, fmt, ##arg)
> 
>     include/linux/dev_printk.h:#define dev_info(dev, fmt, ...)
> \
>     include/linux/dev_printk.h:     _dev_info(dev, dev_fmt(fmt),
> ##__VA_ARGS__)
> 
>     include/linux/dev_printk.h:__printf(2, 3) __cold
>     include/linux/dev_printk.h:void _dev_info(const struct device *dev, const
> char *fmt, ...);
> 
>     include/linux/compiler_attributes.h:#define __printf(a, b)
> __attribute__((__format__(printf, a, b)))

Yeah, it's not obvious: it happens in kernel/printk/printk.c:vprintk_store
where it does

	if (dev_info)
		lflags |= LOG_NEWLINE;

It doesn't seem to be documented; I think it prevents using pr_cont with
"rich" printk facilities that go via _dev_info.

I suspect it quietly changed in commit c313af145b9bc ("printk() - isolate
KERN_CONT users from ordinary complete lines").

> In the discussion *smpboot: CPU numbers printed as warning* [1] John wrote:
> 
> > It is supported to provide loglevels for CONT messages. The loglevel is
> > then only used if the append fails:
> > 
> >     pr_cont(KERN_INFO "message part");
> > 
> > I don't know if we want to go down that path. But it is supported.

Yeah, I saw that, but decided to go with the 'pr_info("")' solution, because
it is less magic, and already used in two other drivers.

pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is nice.

Best regards,
Alexander
_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[John Ogness]

On 2021-04-11, Alexander Monakov <amonakov@ispras.ru> wrote:
>>> The second line is emitted via 'pr_cont', which causes it to have a
>>> different ('warn') loglevel compared to the previous line ('info').
>>> 
>>> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
>>> from the pci_info format string, but this doesn't work, as pci_info
>>> calls implicitly append a newline anyway.
>> 
>> Hmm, did I really screw that up during my testing? I am sorry about that.
>> 
>> I tried to wrap my head around, where the newline is implicitly appended, and
>> only found the definitions below.
>> 
>>     include/linux/pci.h:#define pci_info(pdev, fmt, arg...)
>> dev_info(&(pdev)->dev, fmt, ##arg)
>> 
>>     include/linux/dev_printk.h:#define dev_info(dev, fmt, ...)
>> \
>>     include/linux/dev_printk.h:     _dev_info(dev, dev_fmt(fmt),
>> ##__VA_ARGS__)
>> 
>>     include/linux/dev_printk.h:__printf(2, 3) __cold
>>     include/linux/dev_printk.h:void _dev_info(const struct device *dev, const
>> char *fmt, ...);
>> 
>>     include/linux/compiler_attributes.h:#define __printf(a, b)
>> __attribute__((__format__(printf, a, b)))
>
> Yeah, it's not obvious: it happens in kernel/printk/printk.c:vprintk_store
> where it does
>
> 	if (dev_info)
> 		lflags |= LOG_NEWLINE;
>
> It doesn't seem to be documented; I think it prevents using pr_cont with
> "rich" printk facilities that go via _dev_info.
>
> I suspect it quietly changed in commit c313af145b9bc ("printk() - isolate
> KERN_CONT users from ordinary complete lines").

Yes, this behavior has been around for a while. I see no reason why it
should be that way. These days printk does not care if there is dev_info
included or not.

>> In the discussion *smpboot: CPU numbers printed as warning* [1] John wrote:
>> 
>>> It is supported to provide loglevels for CONT messages. The loglevel is
>>> then only used if the append fails:
>>> 
>>>     pr_cont(KERN_INFO "message part");
>>> 
>>> I don't know if we want to go down that path. But it is supported.
>
> Yeah, I saw that, but decided to go with the 'pr_info("")' solution, because
> it is less magic, and already used in two other drivers.

Note that what I was suggesting was to fix a different issue: If the
pr_cont() caller is interrupted by another printk user, then the
following pr_cont() calls will use the default loglevel. By explicitly
specifying the loglevel in pr_cont(), you can be sure that those pieces
get the desired loglevel, even if those pieces get separated off because
of an interrupting printk user.

So even if we fix dev_info to allow pr_cont continuation, it still may
be desirable to specify the loglevel in the pr_cont pieces.

> pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is
> nice.

I'd rather fix dev_info callers to allow pr_cont and then fix any code
that is using this workaround.

And if the print maintainers agree it is OK to encourage
pr_cont(LOGLEVEL "...") usage, then people should really start using
that if the loglevel on those pieces is important.

John Ogness

Re: [PATCH] iommu/amd: Fix extended features logging

[John Ogness]

On 2021-04-11, Alexander Monakov <amonakov@ispras.ru> wrote:
>>> The second line is emitted via 'pr_cont', which causes it to have a
>>> different ('warn') loglevel compared to the previous line ('info').
>>> 
>>> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
>>> from the pci_info format string, but this doesn't work, as pci_info
>>> calls implicitly append a newline anyway.
>> 
>> Hmm, did I really screw that up during my testing? I am sorry about that.
>> 
>> I tried to wrap my head around, where the newline is implicitly appended, and
>> only found the definitions below.
>> 
>>     include/linux/pci.h:#define pci_info(pdev, fmt, arg...)
>> dev_info(&(pdev)->dev, fmt, ##arg)
>> 
>>     include/linux/dev_printk.h:#define dev_info(dev, fmt, ...)
>> \
>>     include/linux/dev_printk.h:     _dev_info(dev, dev_fmt(fmt),
>> ##__VA_ARGS__)
>> 
>>     include/linux/dev_printk.h:__printf(2, 3) __cold
>>     include/linux/dev_printk.h:void _dev_info(const struct device *dev, const
>> char *fmt, ...);
>> 
>>     include/linux/compiler_attributes.h:#define __printf(a, b)
>> __attribute__((__format__(printf, a, b)))
>
> Yeah, it's not obvious: it happens in kernel/printk/printk.c:vprintk_store
> where it does
>
> 	if (dev_info)
> 		lflags |= LOG_NEWLINE;
>
> It doesn't seem to be documented; I think it prevents using pr_cont with
> "rich" printk facilities that go via _dev_info.
>
> I suspect it quietly changed in commit c313af145b9bc ("printk() - isolate
> KERN_CONT users from ordinary complete lines").

Yes, this behavior has been around for a while. I see no reason why it
should be that way. These days printk does not care if there is dev_info
included or not.

>> In the discussion *smpboot: CPU numbers printed as warning* [1] John wrote:
>> 
>>> It is supported to provide loglevels for CONT messages. The loglevel is
>>> then only used if the append fails:
>>> 
>>>     pr_cont(KERN_INFO "message part");
>>> 
>>> I don't know if we want to go down that path. But it is supported.
>
> Yeah, I saw that, but decided to go with the 'pr_info("")' solution, because
> it is less magic, and already used in two other drivers.

Note that what I was suggesting was to fix a different issue: If the
pr_cont() caller is interrupted by another printk user, then the
following pr_cont() calls will use the default loglevel. By explicitly
specifying the loglevel in pr_cont(), you can be sure that those pieces
get the desired loglevel, even if those pieces get separated off because
of an interrupting printk user.

So even if we fix dev_info to allow pr_cont continuation, it still may
be desirable to specify the loglevel in the pr_cont pieces.

> pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is
> nice.

I'd rather fix dev_info callers to allow pr_cont and then fix any code
that is using this workaround.

And if the print maintainers agree it is OK to encourage
pr_cont(LOGLEVEL "...") usage, then people should really start using
that if the loglevel on those pieces is important.

John Ogness
_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

On Sun, 11 Apr 2021, John Ogness wrote:

> > pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is
> > nice.
> 
> I'd rather fix dev_info callers to allow pr_cont and then fix any code
> that is using this workaround.

Note that existing two users of pr_info("") that I found are not using that
as a workaround: efi.c is using that when it announced a list of EFI tables:

efi: ACPI=0xadffe000 ACPI 2.0=0xadffe014 TPMFinalLog=0xadf2d000 ESRT=0xab70d618 SMBIOS=0xab70b000 SMBIOS 3.0=0xab709000 RNG=0xab707b98 TPMEventLog=0x9602c018

and uvesafb.c similarly uses it to print a list of conditionally-present
strings. In both cases it is really a standalone message, not a continuation
for something previously printed.

In contrast, my patch deals with a continuation line. I wouldn't really like
the decoded feature list to appear on the same line as the previous message,
because it would end up quite long:

[    0.266332] pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
[    0.266334] AMD-Vi:  PPR X2APIC NX GT IA GA PC GA_vAPIC

I think a good compromise is to change the first line from pci_info to pr_info,
losing the pci bus address. I'll send a v2.

Alexander

Re: [PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

On Sun, 11 Apr 2021, John Ogness wrote:

> > pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is
> > nice.
> 
> I'd rather fix dev_info callers to allow pr_cont and then fix any code
> that is using this workaround.

Note that existing two users of pr_info("") that I found are not using that
as a workaround: efi.c is using that when it announced a list of EFI tables:

efi: ACPI=0xadffe000 ACPI 2.0=0xadffe014 TPMFinalLog=0xadf2d000 ESRT=0xab70d618 SMBIOS=0xab70b000 SMBIOS 3.0=0xab709000 RNG=0xab707b98 TPMEventLog=0x9602c018

and uvesafb.c similarly uses it to print a list of conditionally-present
strings. In both cases it is really a standalone message, not a continuation
for something previously printed.

In contrast, my patch deals with a continuation line. I wouldn't really like
the decoded feature list to appear on the same line as the previous message,
because it would end up quite long:

[    0.266332] pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
[    0.266334] AMD-Vi:  PPR X2APIC NX GT IA GA PC GA_vAPIC

I think a good compromise is to change the first line from pci_info to pr_info,
losing the pci bus address. I'll send a v2.

Alexander
_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Joe Perches]

On Sun, 2021-04-11 at 21:52 +0200, John Ogness wrote:
> I'd rather fix dev_info callers to allow pr_cont and then fix any code
> that is using this workaround.

Assuming you mean all dev_<level>() uses, me too.

> And if the print maintainers agree it is OK to encourage
> pr_cont(LOGLEVEL "...") usage, then people should really start using
> that if the loglevel on those pieces is important.

I have no stong feeling about the use of pr_cont(<KERN_LEVEL>
as valuable or not.  I think it's just a trivial bit that
could be somewhat useful when interleaving occurs.

A somewhat better mechanism would be to have an explicit
cookie use like:

	cookie = printk_multipart_init(KERN_LEVEL, fmt, ...);
	while (<condition>)
		printk_multipart_cont(cookie, fmt, ...);
	printk_multipark_end(cookie, fmt, ...);

And separately, there should be a pr_debug_cont or equivalent.

Re: [PATCH] iommu/amd: Fix extended features logging

[Joe Perches]

On Sun, 2021-04-11 at 21:52 +0200, John Ogness wrote:
> I'd rather fix dev_info callers to allow pr_cont and then fix any code
> that is using this workaround.

Assuming you mean all dev_<level>() uses, me too.

> And if the print maintainers agree it is OK to encourage
> pr_cont(LOGLEVEL "...") usage, then people should really start using
> that if the loglevel on those pieces is important.

I have no stong feeling about the use of pr_cont(<KERN_LEVEL>
as valuable or not.  I think it's just a trivial bit that
could be somewhat useful when interleaving occurs.

A somewhat better mechanism would be to have an explicit
cookie use like:

	cookie = printk_multipart_init(KERN_LEVEL, fmt, ...);
	while (<condition>)
		printk_multipart_cont(cookie, fmt, ...);
	printk_multipark_end(cookie, fmt, ...);

And separately, there should be a pr_debug_cont or equivalent.


_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Petr Mladek]

On Sun 2021-04-11 14:08:14, Joe Perches wrote:
> On Sun, 2021-04-11 at 21:52 +0200, John Ogness wrote:
> > I'd rather fix dev_info callers to allow pr_cont and then fix any code
> > that is using this workaround.
> 
> Assuming you mean all dev_<level>() uses, me too.
> 
> > And if the print maintainers agree it is OK to encourage
> > pr_cont(LOGLEVEL "...") usage, then people should really start using
> > that if the loglevel on those pieces is important.
> 
> I have no stong feeling about the use of pr_cont(<KERN_LEVEL>
> as valuable or not.  I think it's just a trivial bit that
> could be somewhat useful when interleaving occurs.
> 
> A somewhat better mechanism would be to have an explicit
> cookie use like:
> 
> 	cookie = printk_multipart_init(KERN_LEVEL, fmt, ...);
> 	while (<condition>)
> 		printk_multipart_cont(cookie, fmt, ...);
> 	printk_multipark_end(cookie, fmt, ...);
> 
> And separately, there should be a pr_debug_cont or equivalent.

We would need to implement this a lockless way. It is doable,
for example, using some per-CPU X per-context buffers. Which would
require to disable preemption in the section.

But I think that using dev_cont_info() would be easier after all.

That said, some printk_*_init()/end() API would be useful
for storing the pieces in a temporary buffer. It would allow
to store the entire lines without the risk of interleaving
with other messages.

Best Regards,
Petr

Re: [PATCH] iommu/amd: Fix extended features logging

[Petr Mladek via iommu]

On Sun 2021-04-11 14:08:14, Joe Perches wrote:
> On Sun, 2021-04-11 at 21:52 +0200, John Ogness wrote:
> > I'd rather fix dev_info callers to allow pr_cont and then fix any code
> > that is using this workaround.
> 
> Assuming you mean all dev_<level>() uses, me too.
> 
> > And if the print maintainers agree it is OK to encourage
> > pr_cont(LOGLEVEL "...") usage, then people should really start using
> > that if the loglevel on those pieces is important.
> 
> I have no stong feeling about the use of pr_cont(<KERN_LEVEL>
> as valuable or not.  I think it's just a trivial bit that
> could be somewhat useful when interleaving occurs.
> 
> A somewhat better mechanism would be to have an explicit
> cookie use like:
> 
> 	cookie = printk_multipart_init(KERN_LEVEL, fmt, ...);
> 	while (<condition>)
> 		printk_multipart_cont(cookie, fmt, ...);
> 	printk_multipark_end(cookie, fmt, ...);
> 
> And separately, there should be a pr_debug_cont or equivalent.

We would need to implement this a lockless way. It is doable,
for example, using some per-CPU X per-context buffers. Which would
require to disable preemption in the section.

But I think that using dev_cont_info() would be easier after all.

That said, some printk_*_init()/end() API would be useful
for storing the pieces in a temporary buffer. It would allow
to store the entire lines without the risk of interleaving
with other messages.

Best Regards,
Petr
_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Petr Mladek]

On Sun 2021-04-11 21:52:59, John Ogness wrote:
> On 2021-04-11, Alexander Monakov <amonakov@ispras.ru> wrote:
> >>> The second line is emitted via 'pr_cont', which causes it to have a
> >>> different ('warn') loglevel compared to the previous line ('info').
> >>> 
> >>> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> >>> from the pci_info format string, but this doesn't work, as pci_info
> >>> calls implicitly append a newline anyway.
> >> 
> >> Hmm, did I really screw that up during my testing? I am sorry about that.
> >> 
> >> I tried to wrap my head around, where the newline is implicitly appended, and
> >> only found the definitions below.
> >> 
> > Yeah, it's not obvious: it happens in kernel/printk/printk.c:vprintk_store
> > where it does
> >
> > 	if (dev_info)
> > 		lflags |= LOG_NEWLINE;
> >
> > It doesn't seem to be documented; I think it prevents using pr_cont with
> > "rich" printk facilities that go via _dev_info.
> >
> > I suspect it quietly changed in commit c313af145b9bc ("printk() - isolate
> > KERN_CONT users from ordinary complete lines").
> 
> Yes, this behavior has been around for a while. I see no reason why it
> should be that way. These days printk does not care if there is dev_info
> included or not.

It seems that it has been this way since the dev_info was
introduced. It was called "dict" at that time. See

	if (buflen && (!cont || dict)) {
		/* no continuation; flush existing buffer */
		log_store(facility, buflevel, NULL, 0, buf, buflen);

in the commit 7ff9554bb578ba02166071d2d ("printk: convert byte-buffer
to variable-length record buffer").

I am not sure why. Well, dev_printk() previously printed the extra
information for every piece. See, the commit c4e00daaa96d3a0786f
("driver-core: extend dev_printk() to pass structured data").


> > Yeah, I saw that, but decided to go with the 'pr_info("")' solution, because
> > it is less magic, and already used in two other drivers.
> 
> Note that what I was suggesting was to fix a different issue: If the
> pr_cont() caller is interrupted by another printk user, then the
> following pr_cont() calls will use the default loglevel. By explicitly
> specifying the loglevel in pr_cont(), you can be sure that those pieces
> get the desired loglevel, even if those pieces get separated off because
> of an interrupting printk user.
> 
> So even if we fix dev_info to allow pr_cont continuation, it still may
> be desirable to specify the loglevel in the pr_cont pieces.
> 
> > pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is
> > nice.
> 
> I'd rather fix dev_info callers to allow pr_cont and then fix any code
> that is using this workaround.
> 
> And if the print maintainers agree it is OK to encourage
> pr_cont(LOGLEVEL "...") usage, then people should really start using
> that if the loglevel on those pieces is important.

To be sure. We would need to repeat also the dev_info() information
in the continuous piece.

By other words. The clean solution would be:

   + remove the automatic newline in
     kernel/printk/printk.c:vprintk_store

   + create wrappers, for example, dev_cont_info()

Best Regards,
Petr

Re: [PATCH] iommu/amd: Fix extended features logging

[Petr Mladek via iommu]

On Sun 2021-04-11 21:52:59, John Ogness wrote:
> On 2021-04-11, Alexander Monakov <amonakov@ispras.ru> wrote:
> >>> The second line is emitted via 'pr_cont', which causes it to have a
> >>> different ('warn') loglevel compared to the previous line ('info').
> >>> 
> >>> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> >>> from the pci_info format string, but this doesn't work, as pci_info
> >>> calls implicitly append a newline anyway.
> >> 
> >> Hmm, did I really screw that up during my testing? I am sorry about that.
> >> 
> >> I tried to wrap my head around, where the newline is implicitly appended, and
> >> only found the definitions below.
> >> 
> > Yeah, it's not obvious: it happens in kernel/printk/printk.c:vprintk_store
> > where it does
> >
> > 	if (dev_info)
> > 		lflags |= LOG_NEWLINE;
> >
> > It doesn't seem to be documented; I think it prevents using pr_cont with
> > "rich" printk facilities that go via _dev_info.
> >
> > I suspect it quietly changed in commit c313af145b9bc ("printk() - isolate
> > KERN_CONT users from ordinary complete lines").
> 
> Yes, this behavior has been around for a while. I see no reason why it
> should be that way. These days printk does not care if there is dev_info
> included or not.

It seems that it has been this way since the dev_info was
introduced. It was called "dict" at that time. See

	if (buflen && (!cont || dict)) {
		/* no continuation; flush existing buffer */
		log_store(facility, buflevel, NULL, 0, buf, buflen);

in the commit 7ff9554bb578ba02166071d2d ("printk: convert byte-buffer
to variable-length record buffer").

I am not sure why. Well, dev_printk() previously printed the extra
information for every piece. See, the commit c4e00daaa96d3a0786f
("driver-core: extend dev_printk() to pass structured data").


> > Yeah, I saw that, but decided to go with the 'pr_info("")' solution, because
> > it is less magic, and already used in two other drivers.
> 
> Note that what I was suggesting was to fix a different issue: If the
> pr_cont() caller is interrupted by another printk user, then the
> following pr_cont() calls will use the default loglevel. By explicitly
> specifying the loglevel in pr_cont(), you can be sure that those pieces
> get the desired loglevel, even if those pieces get separated off because
> of an interrupting printk user.
> 
> So even if we fix dev_info to allow pr_cont continuation, it still may
> be desirable to specify the loglevel in the pr_cont pieces.
> 
> > pr_info("") will also prepend 'AMD-Vi:' to the feature list, which is
> > nice.
> 
> I'd rather fix dev_info callers to allow pr_cont and then fix any code
> that is using this workaround.
> 
> And if the print maintainers agree it is OK to encourage
> pr_cont(LOGLEVEL "...") usage, then people should really start using
> that if the loglevel on those pieces is important.

To be sure. We would need to repeat also the dev_info() information
in the continuous piece.

By other words. The clean solution would be:

   + remove the automatic newline in
     kernel/printk/printk.c:vprintk_store

   + create wrappers, for example, dev_cont_info()

Best Regards,
Petr
_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Joe Perches]

(cc'ing the printk maintainers)

On Sun, 2021-04-11 at 00:11 +0300, Alexander Monakov wrote:
> print_iommu_info prints the EFR register and then the decoded list of
> features on a separate line:
> 
> pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
>  PPR X2APIC NX GT IA GA PC GA_vAPIC
> 
> The second line is emitted via 'pr_cont', which causes it to have a
> different ('warn') loglevel compared to the previous line ('info').
> 
> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> from the pci_info format string, but this doesn't work, as pci_info
> calls implicitly append a newline anyway.
> 
> Restore the newline, and call pr_info with empty format string to set
> the loglevel for subsequent pr_cont calls. The same solution is used in
> EFI and uvesafb drivers.
> 
> Fixes: 9a295ff0ffc9 ("iommu/amd: Print extended features in one line to fix divergent log levels")
> Signed-off-by: Alexander Monakov <amonakov@ispras.ru>
> Cc: Paul Menzel <pmenzel@molgen.mpg.de>
> Cc: Joerg Roedel <jroedel@suse.de>
> Cc: Suravee Suthikulpanit <suravee.suthikulpanit@amd.com>
> Cc: iommu@lists.linux-foundation.org
> ---
>  drivers/iommu/amd/init.c | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/iommu/amd/init.c b/drivers/iommu/amd/init.c
> index 596d0c413473..a25e241eff1c 100644
> --- a/drivers/iommu/amd/init.c
> +++ b/drivers/iommu/amd/init.c
> @@ -1929,8 +1929,11 @@ static void print_iommu_info(void)
>  		pci_info(pdev, "Found IOMMU cap 0x%hx\n", iommu->cap_ptr);
>  
> 
>  		if (iommu->cap & (1 << IOMMU_CAP_EFR)) {
> -			pci_info(pdev, "Extended features (%#llx):",
> +			pci_info(pdev, "Extended features (%#llx):\n",
>  				 iommu->features);
> +
> +			pr_info("");
> +
>  			for (i = 0; i < ARRAY_SIZE(feat_str); ++i) {
>  				if (iommu_feature(iommu, (1ULL << i)))
>  					pr_cont(" %s", feat_str[i]);

This shouldn't be necessary.
If this is true then a lot of output logging code broke.

Re: [PATCH] iommu/amd: Fix extended features logging

[Joe Perches]

(cc'ing the printk maintainers)

On Sun, 2021-04-11 at 00:11 +0300, Alexander Monakov wrote:
> print_iommu_info prints the EFR register and then the decoded list of
> features on a separate line:
> 
> pci 0000:00:00.2: AMD-Vi: Extended features (0x206d73ef22254ade):
>  PPR X2APIC NX GT IA GA PC GA_vAPIC
> 
> The second line is emitted via 'pr_cont', which causes it to have a
> different ('warn') loglevel compared to the previous line ('info').
> 
> Commit 9a295ff0ffc9 attempted to rectify this by removing the newline
> from the pci_info format string, but this doesn't work, as pci_info
> calls implicitly append a newline anyway.
> 
> Restore the newline, and call pr_info with empty format string to set
> the loglevel for subsequent pr_cont calls. The same solution is used in
> EFI and uvesafb drivers.
> 
> Fixes: 9a295ff0ffc9 ("iommu/amd: Print extended features in one line to fix divergent log levels")
> Signed-off-by: Alexander Monakov <amonakov@ispras.ru>
> Cc: Paul Menzel <pmenzel@molgen.mpg.de>
> Cc: Joerg Roedel <jroedel@suse.de>
> Cc: Suravee Suthikulpanit <suravee.suthikulpanit@amd.com>
> Cc: iommu@lists.linux-foundation.org
> ---
>  drivers/iommu/amd/init.c | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/iommu/amd/init.c b/drivers/iommu/amd/init.c
> index 596d0c413473..a25e241eff1c 100644
> --- a/drivers/iommu/amd/init.c
> +++ b/drivers/iommu/amd/init.c
> @@ -1929,8 +1929,11 @@ static void print_iommu_info(void)
>  		pci_info(pdev, "Found IOMMU cap 0x%hx\n", iommu->cap_ptr);
>  
> 
>  		if (iommu->cap & (1 << IOMMU_CAP_EFR)) {
> -			pci_info(pdev, "Extended features (%#llx):",
> +			pci_info(pdev, "Extended features (%#llx):\n",
>  				 iommu->features);
> +
> +			pr_info("");
> +
>  			for (i = 0; i < ARRAY_SIZE(feat_str); ++i) {
>  				if (iommu_feature(iommu, (1ULL << i)))
>  					pr_cont(" %s", feat_str[i]);

This shouldn't be necessary.
If this is true then a lot of output logging code broke.



_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu

Re: [PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

On Sun, 11 Apr 2021, Joe Perches wrote:

> (cc'ing the printk maintainers)
> 
[snip]
> 
> This shouldn't be necessary.
> If this is true then a lot of output logging code broke.

See also my response to Paul at
https://lore.kernel.org/lkml/alpine.LNX.2.20.13.2104111410340.11104@monopod.intra.ispras.ru/

Alexander

Re: [PATCH] iommu/amd: Fix extended features logging

[Alexander Monakov]

On Sun, 11 Apr 2021, Joe Perches wrote:

> (cc'ing the printk maintainers)
> 
[snip]
> 
> This shouldn't be necessary.
> If this is true then a lot of output logging code broke.

See also my response to Paul at
https://lore.kernel.org/lkml/alpine.LNX.2.20.13.2104111410340.11104@monopod.intra.ispras.ru/

Alexander
_______________________________________________
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu