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 <[email protected]>
Cc: Paul Menzel <[email protected]>
Cc: Joerg Roedel <[email protected]>
Cc: Suravee Suthikulpanit <[email protected]>
Cc: [email protected]
---
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
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 <[email protected]>
> Cc: Paul Menzel <[email protected]>
> Cc: Joerg Roedel <[email protected]>
> Cc: Suravee Suthikulpanit <[email protected]>
> Cc: [email protected]
> ---
> 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
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
(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 <[email protected]>
> Cc: Paul Menzel <[email protected]>
> Cc: Joerg Roedel <[email protected]>
> Cc: Suravee Suthikulpanit <[email protected]>
> Cc: [email protected]
> ---
> ?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.
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/[email protected]/
Alexander
On 2021-04-11, Alexander Monakov <[email protected]> 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
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
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.
On Sun 2021-04-11 21:52:59, John Ogness wrote:
> On 2021-04-11, Alexander Monakov <[email protected]> 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
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