On Tue, 2012-07-10 at 00:40 +0200, Kay Sievers wrote: > On Tue, Jul 10, 2012 at 12:29 AM, Joe Perches <j...@perches.com> wrote: > > On Tue, 2012-07-10 at 00:10 +0200, Kay Sievers wrote: > >> On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches <j...@perches.com> wrote: > >> > On Sun, 2012-07-08 at 19:55 +0200, Kay Sievers wrote: > >> > > >> >> At the same time the CPU#2 prints the same warning with a continuation > >> >> line, but the buffer from CPU#1 can not be flushed to the console, nor > >> >> can the continuation line printk()s from CPU#2 be merged at this point. > >> >> The consoles are still locked and busy with replaying the old log > >> >> messages, so the new continuation data is just stored away in the record > >> >> buffer as it is coming in. > >> >> If the console would be registered a bit earlier, or the warning would > >> >> happen a bit later, we would probably not see any of this. > >> >> > >> >> I can fake something like this just by holding the console semaphore > >> >> over a longer time and printing continuation lines with different CPUs > >> >> in a row. > >> >> > >> >> The patch below seems to work for me. It is also here: > >> >> > >> >> http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD > >> >> > >> >> It only applies cleanly on top of this patch: > >> >> > >> >> http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD > >> >> > >> > > >> > Hi Kay. > >> > > >> > I just ran a test with what's in Greg's driver-core -for-linus branch. > >> > > >> > One of the differences in dmesg is timestamping of consecutive > >> > pr_<level>("foo...) > >> > followed directly by > >> > pr_cont("bar...") > >> > > >> > For instance: (dmesg is 3.4, dmesg.0 is 3.5-rc6+) > >> > > >> > # grep MAP /var/log/dm* -A1 > >> > dmesg:[ 0.781687] ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ] > >> > dmesg-[ 0.781707] ata2: port disabled--ignoring > >> > -- > >> > dmesg.0:[ 0.948881] ata_piix 0000:00:1f.2: MAP [ > >> > dmesg.0-[ 0.948883] P0 P2 P1 P3 ] > >> > > >> > These messages originate starting at > >> > drivers/ata/ata_piix.c:1354 > >> > > >> > All the continuations are emitted with pr_cont. > >> > > >> > I think this output should still be coalesced without > >> > timestamp deltas. Perhaps the timestamping code can > >> > still be reworked to avoid too small a delta producing > >> > a new timestamp and another dmesg line. > >> > >> Hmm, I don't see that. > >> > >> If I do: > >> pr_info("["); > >> for (i = 0; i < 4; i++) > >> pr_cont("%i ", i); > >> pr_cont("]\n"); > >> > >> I get: > >> 6,173,0;[0 1 2 3 ] > >> > >> And if I fill the cont buffer and forcefully hold the console sem > >> during all that, and we can't merge anymore, I get: > >> 6,167,0;[ > >> 4,168,0;0 > >> 4,169,0;1 > >> 4,170,0;2 > >> 4,171,0;3 > >> 4,172,0;] > >> > >> But the output is still all fine for both lines: > >> [ 0.000000] [0 1 2 3 ] > >> [ 0.000000] [0 1 2 3 ] > >> > >> What do I miss? > > > > In this case the initial line is dev_info not pr_info > > so there are the additional dict descriptors output to > > /dev/kmsg as well. > > > > Maybe that interferes with continuations. Dunno. > > Yes, it does. Annotated records dev_printk() must be reliable in the > data storage and for the consumers. We can not expose them to the racy > continuation printk()s. We need to be able to trust the data they > print and not possibly merge unrelated things into it. > > If it's needed, we can try to set the flags accordingly, that they > *look* like a line in the classic byte-stream output, but the > interface in /dev/kmsg must not export them that way, because > continuation lines can never be trusted to be correct.
Then you've changed semantics and I think you need to fix it. A dev_<level> call is not guaranteed to be a complete message. There are dev_<level> and netdev_<level> calls followed by pr_cont. Maybe these could be fixed up and then they could be always integral. There don't look to be too many. This may be most (all?) of them: drivers/ata/ata_piix.c | 16 +++++++++----- drivers/media/rc/redrat3.c | 36 ++++++++++++++++----------------- drivers/net/ethernet/broadcom/bnx2.c | 26 ++++++++++++++---------- 3 files changed, 42 insertions(+), 36 deletions(-) diff --git a/drivers/ata/ata_piix.c b/drivers/ata/ata_piix.c index 3c809bf..f51962f 100644 --- a/drivers/ata/ata_piix.c +++ b/drivers/ata/ata_piix.c @@ -1346,38 +1346,42 @@ static const int *__devinit piix_init_sata_map(struct pci_dev *pdev, const int *map; int i, invalid_map = 0; u8 map_value; + char maps[50] = {0}; + int len = 0; pci_read_config_byte(pdev, ICH5_PMR, &map_value); map = map_db->map[map_value & map_db->mask]; - dev_info(&pdev->dev, "MAP ["); for (i = 0; i < 4; i++) { switch (map[i]) { case RV: invalid_map = 1; - pr_cont(" XX"); + len += snprintf(maps + len, sizeof(maps) - len, " XX"); break; case NA: - pr_cont(" --"); + len += snprintf(maps + len, sizeof(maps) - len, " --"); break; case IDE: WARN_ON((i & 1) || map[i + 1] != IDE); pinfo[i / 2] = piix_port_info[ich_pata_100]; i++; - pr_cont(" IDE IDE"); + len += snprintf(maps + len, sizeof(maps) - len, + " IDE IDE"); break; default: - pr_cont(" P%d", map[i]); + len += snprintf(maps + len, sizeof(maps) - len, + " P%d", map[i]); if (i & 1) pinfo[i / 2].flags |= ATA_FLAG_SLAVE_POSS; break; } } - pr_cont(" ]\n"); + + dev_info(&pdev->dev, "MAP [%s ]\n", maps); if (invalid_map) dev_err(&pdev->dev, "invalid MAP value %u\n", map_value); diff --git a/drivers/media/rc/redrat3.c b/drivers/media/rc/redrat3.c index 2878b0e..636a245 100644 --- a/drivers/media/rc/redrat3.c +++ b/drivers/media/rc/redrat3.c @@ -296,41 +296,36 @@ static void redrat3_issue_async(struct redrat3_dev *rr3) static void redrat3_dump_fw_error(struct redrat3_dev *rr3, int code) { - if (!rr3->transmitting && (code != 0x40)) - dev_info(rr3->dev, "fw error code 0x%02x: ", code); + const char *msg = ""; switch (code) { case 0x00: - pr_cont("No Error\n"); + msg = "No Error"; break; /* Codes 0x20 through 0x2f are IR Firmware Errors */ case 0x20: - pr_cont("Initial signal pulse not long enough " - "to measure carrier frequency\n"); + msg = "Initial signal pulse not long enough to measure carrier frequency"; break; case 0x21: - pr_cont("Not enough length values allocated for signal\n"); + msg = "Not enough length values allocated for signal"; break; case 0x22: - pr_cont("Not enough memory allocated for signal data\n"); + msg = "Not enough memory allocated for signal data"; break; case 0x23: - pr_cont("Too many signal repeats\n"); + msg = "Too many signal repeats"; break; case 0x28: - pr_cont("Insufficient memory available for IR signal " - "data memory allocation\n"); + msg = "Insufficient memory available for IR signal data memory allocation"; break; case 0x29: - pr_cont("Insufficient memory available " - "for IrDa signal data memory allocation\n"); + msg = "Insufficient memory available for IrDa signal data memory allocation"; break; /* Codes 0x30 through 0x3f are USB Firmware Errors */ case 0x30: - pr_cont("Insufficient memory available for bulk " - "transfer structure\n"); + msg = "Insufficient memory available for bulk transfer structure"; break; /* @@ -339,20 +334,23 @@ static void redrat3_dump_fw_error(struct redrat3_dev *rr3, int code) */ case 0x40: if (!rr3->transmitting) - pr_cont("Signal capture has been terminated\n"); + msg = "Signal capture has been terminated"; break; case 0x41: - pr_cont("Attempt to set/get and unknown signal I/O " - "algorithm parameter\n"); + msg = "Attempt to set/get and unknown signal I/O algorithm parameter"; break; case 0x42: - pr_cont("Signal capture already started\n"); + msg = "Signal capture already started"; break; default: - pr_cont("Unknown Error\n"); + msg = "Unknown Error"; break; } + + if (!rr3->transmitting && (code != 0x40)) + dev_info(rr3->dev, "fw error code 0x%02x: %s\n", code, msg); + } static u32 redrat3_val_to_mod_freq(struct redrat3_signal_header *ph) diff --git a/drivers/net/ethernet/broadcom/bnx2.c b/drivers/net/ethernet/broadcom/bnx2.c index 1901da1..f5dd19f 100644 --- a/drivers/net/ethernet/broadcom/bnx2.c +++ b/drivers/net/ethernet/broadcom/bnx2.c @@ -987,24 +987,28 @@ static void bnx2_report_link(struct bnx2 *bp) { if (bp->link_up) { + const char *fc_type = ""; + const char *fc_on = ""; netif_carrier_on(bp->dev); - netdev_info(bp->dev, "NIC %s Link is Up, %d Mbps %s duplex", - bnx2_xceiver_str(bp), - bp->line_speed, - bp->duplex == DUPLEX_FULL ? "full" : "half"); if (bp->flow_ctrl) { if (bp->flow_ctrl & FLOW_CTRL_RX) { - pr_cont(", receive "); if (bp->flow_ctrl & FLOW_CTRL_TX) - pr_cont("& transmit "); - } - else { - pr_cont(", transmit "); + fc_type = ", receive & transmit"; + else + fc_type = ", receive"; + + } else { + fc_type = ", transmit"; } - pr_cont("flow control ON"); + fc_on = " flow control ON"; } - pr_cont("\n"); + netdev_info(bp->dev, "NIC %s Link is Up, %d Mbps %s duplex%s%s\n", + bnx2_xceiver_str(bp), + bp->line_speed, + bp->duplex == DUPLEX_FULL ? "full" : "half", + fc_type, fc_on); + } else { netif_carrier_off(bp->dev); netdev_err(bp->dev, "NIC %s Link is Down\n", _______________________________________________ Linuxppc-dev mailing list Linuxppc-dev@lists.ozlabs.org https://lists.ozlabs.org/listinfo/linuxppc-dev