On 5/7/24 06:49, Niklas Cassel wrote: > Hello Krzysztof, > > On Sun, May 05, 2024 at 01:06:28PM -0700, Krzysztof Olędzki wrote: >> Hi, >> >> I noticed that since https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=742bef476ca5352b16063161fb73a56629a6d995 (which also got backported to -stable kernels) several of messages from dmesg regarding the ATA subsystem are no longer logged. >> >> For example, on my Dell PowerEdge 840 which has only one PATA port I used to get: >> >> scsi host1: ata_piix >> ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xfc00 irq 14 >> ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xfc08 irq 15 >> ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ] >> ata2: port disabled--ignoring >> ata1.01: NODEV after polling detection >> ata1.00: ATAPI: SAMSUNG CD-R/RW SW-248F, R602, max UDMA/33 >> >> After that commit, the following two log entries are missing: >> ata2: port disabled--ignoring >> ata1.01: NODEV after polling detection >> >> Note that these are just examples, there are many more messages impacted by that. >> >> Looking at the code, these messages are logged via ata_link_dbg / ata_dev_dbg: >> ata_link_dbg(link, "port disabled--ignoring\n"); [in drivers/ata/libata-eh.c] >> ata_dev_dbg(dev, "NODEV after polling detection\n"); [in drivers/ata/libata-core.c] >> >> The commit change how the logging is called - ata_dev_printk function which was calling printk() directly got replaced with the following macro: >> >> +#define ata_dev_printk(level, dev, fmt, ...) \ >> + pr_ ## level("ata%u.%02u: " fmt, \ >> + (dev)->link->ap->print_id, \ >> + (dev)->link->pmp + (dev)->devno, \ >> + ##__VA_ARGS__) >> (...) >> #define ata_link_dbg(link, fmt, ...) \ >> - ata_link_printk(link, KERN_DEBUG, fmt, ##__VA_ARGS__) >> + ata_link_printk(debug, link, fmt, ##__VA_ARGS__) >> (...) >> #define ata_dev_dbg(dev, fmt, ...) \ >> - ata_dev_printk(dev, KERN_DEBUG, fmt, ##__VA_ARGS__) >> + ata_dev_printk(debug, dev, fmt, ##__VA_ARGS__ >> >> So, instead of printk(..., level == KERN_DEBUG, ) we now call pr_debug(...). This is a problem as printk(msg, KERN_DEBUG) != pr_debug(msg). >> >> pr_debug is defined as: >> /* If you are writing a driver, please use dev_dbg instead */ >> #if defined(CONFIG_DYNAMIC_DEBUG) || \ >> (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE)) >> #include <linux/dynamic_debug.h> >> >> /** >> * pr_debug - Print a debug-level message conditionally >> * @fmt: format string >> * @...: arguments for the format string >> * >> * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is >> * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with >> * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing. >> * >> * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses >> * pr_fmt() internally). >> */ >> #define pr_debug(fmt, ...) \ >> dynamic_pr_debug(fmt, ##__VA_ARGS__) >> #elif defined(DEBUG) >> #define pr_debug(fmt, ...) \ >> printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__) >> #else >> #define pr_debug(fmt, ...) \ >> no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__) >> #endif >> >> Without CONFIG_DYNAMIC_DEBUG and if no CONFIG_DEBUG is enabled, the end result is calling no_printk which means nothing gets logged. >> >> Looking at the code, there are more impacted calls, like for example ata_dev_dbg(dev, "disabling queued TRIM support\n") for ATA_HORKAGE_NO_NCQ_TRIM, which also seems like an important information to log, and there are more. >> >> Was this change done intentionally? Note that most of the "debug" printks in libata code seem to be guarded by ata_msg_info / ata_msg_probe / ATA_DEBUG which was sufficient to prevent excess debug information logging. >> One of the cases like this was covered in the patch: >> -#ifdef ATA_DEBUG >> if (status != 0xff && (status & (ATA_BUSY | ATA_DRQ))) >> - ata_port_printk(ap, KERN_DEBUG, "abnormal Status 0x%X\n", >> - status); >> -#endif >> + ata_port_dbg(ap, "abnormal Status 0x%X\n", status); >> >> Assuming this is the intended direction, would it make sense for now to at promote "unconditionally" logged messages from ata_link_dbg/ata_dev_dbg to ata_link_info/ata_dev_info? >> >> Longer term, perhaps we want to revisit ata_msg_info/ata_msg_probe/ATA_DEBUG/ATA_VERBOSE_DEBUG vs ata_dev_printk/ata_link_printk/pr_debug (and maybe also pr_devel), especially that DYNAMIC_DEBUG is available these days... > > The change to the dynamic debug model was very much intentional. > > CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG (and ata_msg_info/ata_msg_probe) > was replaced with dynamic debug. > > So the reason why you saw the messages before was most likely because you > built your kernel with CONFIG_ATA_DEBUG / CONFIG_ATA_VERBOSE_DEBUG. > If you want to see the same error messages, you are now expected to use > dynamic debug for the file which you want debug messages enabled. > > > I do agree that the debug prints that were NOT guarded by CONFIG_ATA_DEBUG > do now work differently, as they are no longer printed to dmesg at all. > I'm not sure if this part was intentional. I'm guessing that it wasn't. > > Looking at these three prints specifically: > ata_link_dbg(link, "port disabled--ignoring\n"); Given the recent addition of the port map mask, we could restore this print as an info level. > ata_dev_dbg(dev, "NODEV after polling detection\n"); This one is weird. It should be an error print. > ata_dev_dbg(dev, "disabling queued TRIM support\n"); This is also OK to restore as an info print. But given that, there are a lot more horkage disabling features that we probably should print. > > None of them were protected with CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG > before the series converting to dynamic debug was merged. > > > The best way forward is probably to look at all debug prints before the > series converting to dynamic debug was merged, and see if any print NOT > guarded by CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG should be considered > to promoted to an info print instead. > (The prints that were guarded are not relevant, for those you really are > expected to need to use dynamic debug in order to actually get them > printed to dmesg.) > > > Kind regards, > Niklas > -- Damien Le Moal Western Digital Research
