printk: convert byte-buffer to variable-length record buffer

From: Kay Sievers <[email protected]>
Subject: printk: convert byte-buffer to variable-length record buffer

- Record-based stream instead of the traditional byte stream buffer. All records carry a 64 bit timestamp, the syslog facility and priority in the record header.

- Records consume almost the same amount, sometimes less memory than the traditional byte stream buffer (if printk_time is enabled). The record header is 16 bytes long, plus some padding bytes at the end if needed. The byte-stream buffer needed 3 chars for the syslog prefix, 15 char for the timestamp and a newline.

- Buffer management is based on message sequence numbers. When records need to be discarded, the reading heads move on to the next full record. Unlike the byte-stream buffer, no old logged lines get truncated or partly overwritten by new ones. Sequence numbers also allow consumers of the log stream to get notified if any message in the stream they are about to read gets discarded during the time of reading.

- Better buffered IO support for KERN_CONT continuation lines, when printk() is called multiple times for a single line. The use of KERN_CONT is now mandatory to use continuation; a few places in the kernel need trivial fixes here. The buffering could possibly be extended to per-cpu variables to allow better thread-safety for multiple printk() invocations for a single line.

- Full-featured syslog facility value support. Different facilities can tag their messages. All userspace-injected messages enforce a facility value > 0 now, to be able to reliably distinguish them from the kernel-generated messages. Independent subsystems like a baseband processor running its own firmware, or a kernel-related userspace process can use their own unique facility values. Multiple independent log streams can co-exist that way in the same buffer. All share the same global sequence number counter to ensure proper ordering (and interleaving) and to allow the consumers of the log to reliably correlate the events from different facilities.

---
 drivers/char/mem.c     |   55 +-
 include/linux/printk.h |   11 
 kernel/printk.c        | 1020 ++++++++++++++++++++++++++++---------------------
 3 files changed, 642 insertions(+), 444 deletions(-)

@@ -810,33 +810,54 @@ static const struct file_operations oldm
 static ssize_t kmsg_writev(struct kiocb *iocb, const struct iovec *iv,
 			   unsigned long count, loff_t pos)
 {
-	char *line, *p;
+	char *buf, *line;
 	int i;
-	ssize_t ret = -EFAULT;
+	int level = default_message_loglevel;
+	int facility = 1;	/* LOG_USER */
 	size_t len = iov_length(iv, count);
+	ssize_t ret = len;
 
-	line = kmalloc(len + 1, GFP_KERNEL);
-	if (line == NULL)
+	if (len > 1024)
+		return -EINVAL;
+	buf = kmalloc(len+1, GFP_KERNEL);
+	if (buf == NULL)
 		return -ENOMEM;
 
-	/*
-	 * copy all vectors into a single string, to ensure we do
-	 * not interleave our log line with other printk calls
-	 */
-	p = line;
+	line = buf;
 	for (i = 0; i < count; i++) {
-		if (copy_from_user(p, iv[i].iov_base, iv[i].iov_len))
+		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len))
 			goto out;
-		p += iv[i].iov_len;
+		line += iv[i].iov_len;
+	}
+
+	/*
+	 * Extract and skip the syslog prefix <[0-9]*>. Coming from userspace
+	 * the decimal value represents 32bit, the lower 3 bit are the log
+	 * level, the rest are the log facility.
+	 *
+	 * If no prefix or no userspace facility is specified, we
+	 * enforce LOG_USER, to be able to reliably distinguish
+	 * kernel-generated messages from userspace-injected ones.
+	 */
+	line = buf;
+	if (line[0] == '<') {
+		char *endp = NULL;
+
+		i = simple_strtoul(line+1, &endp, 10);
+		if (endp && endp[0] == '>') {
+			level = i & 7;
+			if (i >> 3)
+				facility = i >> 3;
+			endp++;
+			len -= endp - line;
+			line = endp;
+		}
 	}
-	p[0] = '\0';
+	line[len] = '\0';
 
-	ret = printk("%s", line);
-	/* printk can add a prefix */
-	if (ret > len)
-		ret = len;
+	printk_emit(facility, level, NULL, 0, "%s", line);
 out:
-	kfree(line);
+	kfree(buf);
 	return ret;
 }
 

@@ -95,8 +95,19 @@ extern int printk_needs_cpu(int cpu);
 extern void printk_tick(void);
 
 #ifdef CONFIG_PRINTK
+asmlinkage __printf(5, 0)
+int vprintk_emit(int facility, int level,
+		 const char *dict, size_t dictlen,
+		 const char *fmt, va_list args);
+
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
+
+asmlinkage __printf(5, 6) __cold
+asmlinkage int printk_emit(int facility, int level,
+			   const char *dict, size_t dictlen,
+			   const char *fmt, ...);
+
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 

This is not true..

I did not add that, it's just 'diff' that moves this hunk while adding stuff before it. It's the same text as in the current code:

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=blob;f=kernel/printk.c;h=b663c2c95d3922e4c080e8974c09c6ce99b4355f;hb=HEAD#l729

Kay

Sure, but its still not true.

Well, it is very very nearly true, and people should basically expect it to be.

There are exceptions, but they are ridiculously specific
- no NMI context
- we've had trouble with the percpu runqueue lock (due to the stupid wakeup)
- for similar reasons, we've had trouble with printk called from
within some terminal locks.

But basically, it damn well should be considered a hard rule that you can printk from pretty much anything. The few cases where that is not true are big problems, and should be considered to be real problems, not "oh, you can't printk from here".

Linus

With the new record design you could actually make the thing lockless and allow writing to it from NMI context. IIRC vsnprintf() doesn't do any allocations/locks.

Yep :-(

Thing is, with bonkers stuff like usb-console and kms/drm that's a _lot_ of code running under the logbuf/console locks.

The top-level console lock shouldn't be a problem - we use trylock and delay if it is held.

It's the lower-level driver-specific locks that screw us up. And quite frankly, I am *not* willing to say that that is a printk() problem. That is purely a "USB serial console is damn well broken" issue, and should not be considered a limitation of printk.

Linus

I'm happy to call all that broken ;-)

USB serial console was a drunken bet gone wrong. I'm amazed that it even works at times, and it should never be considered critical enough to affect any core kernel code.

greg k-h

Hi Kay,

This patch was included in today's linux-next, and it looks like it broke printk on my configuration.

It's a bit hard to describe exactly what's wrong, but here are the main points:

1. PRINTK_TIME timing information is gone.
2. Newline issues. It appears to be adding newlines where it shouldn't. For example:

Before:

[   10.110626] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]

After:
parport0: PC-style at 0x378
, irq 7
[
PCSPP
,TRISTATE
]

3. Things are not properly aligned, such as stack traces.

It's always unconditionally recorded now. It looks fine in 'dmesg' output, right?

Yeah, we need to make sure, we never merge the (always racy) continuation printk() users with (non-racy) non-continuation users. Therefore KERN_CONT is required to suppress the newline and to merge the content with the earlier non-newline-terminated printk() line.

I 'm sure, I have signed up for the job to fix what's needed here. :)

Patch for parport is below.

Mind sending the entire output of your 'dmesg', which shows it?

We recently just needed to fix the "<%u>" in the dump, which got recognized as syslog prority prefixes. There might be a few more KERN_CONT missing ...

Thanks,
Kay

From: Kay Sievers <[email protected]>
Subject: parport: use KERN_CONT in printk() continuation lines

---
 drivers/parport/parport_pc.c |   16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

@@ -2351,7 +2351,7 @@ struct parport *parport_pc_probe_port(un
 
 	printk(KERN_INFO "%s: PC-style at 0x%lx", p->name, p->base);
 	if (p->base_hi && priv->ecr)
-		printk(" (0x%lx)", p->base_hi);
+		printk(KERN_CONT " (0x%lx)", p->base_hi);
 	if (p->irq == PARPORT_IRQ_AUTO) {
 		p->irq = PARPORT_IRQ_NONE;
 		parport_irq_probe(p);

@@ -2362,7 +2362,7 @@ struct parport *parport_pc_probe_port(un
 		p->irq = PARPORT_IRQ_NONE;
 	}
 	if (p->irq != PARPORT_IRQ_NONE) {
-		printk(", irq %d", p->irq);
+		printk(KERN_CONT ", irq %d", p->irq);
 		priv->ctr_writable |= 0x10;
 
 		if (p->dma == PARPORT_DMA_AUTO) {

@@ -2386,21 +2386,21 @@ struct parport *parport_pc_probe_port(un
 		/* p->ops->ecp_read_data = parport_pc_ecp_read_block_pio; */
 #endif /* IEEE 1284 support */
 		if (p->dma != PARPORT_DMA_NONE) {
-			printk(", dma %d", p->dma);
+			printk(KERN_CONT ", dma %d", p->dma);
 			p->modes |= PARPORT_MODE_DMA;
 		} else
-			printk(", using FIFO");
+			printk(KERN_CONT ", using FIFO");
 	} else
 		/* We can't use the DMA channel after all. */
 		p->dma = PARPORT_DMA_NONE;
 #endif /* Allowed to use FIFO/DMA */
 
-	printk(" [");
+	printk(KERN_CONT " [");
 
 #define printmode(x) \
 	{\
 		if (p->modes & PARPORT_MODE_##x) {\
-			printk("%s%s", f ? "," : "", #x);\
+			printk(KERN_CONT "%s%s", f ? "," : "", #x);\
 			f++;\
 		} \
 	}

@@ -2416,9 +2416,9 @@ struct parport *parport_pc_probe_port(un
 	}
 #undef printmode
 #ifndef CONFIG_PARPORT_1284
-	printk("(,...)");
+	printk(KERN_CONT "(,...)");
 #endif /* CONFIG_PARPORT_1284 */
-	printk("]\n");
+	printk(KERN_CONT "]\n");
 	if (probedirq != PARPORT_IRQ_NONE)
 		printk(KERN_INFO "%s: irq %d detected\n", p->name, probedirq);
 

Yup. Is there no intention to show it in the console output though? it was quite handy there.

The 3rd one actually looks like the KERN_CONT problem now that you've explained it. You can see it in the 'saved trace' test in the boot log.

I've attached the boot log which shows several other places with this issue, if you're ok with it I can try patching those myself.

Initializing cgroup subsys cpuset
Initializing cgroup subsys cpu
Linux version 3.4.0-rc6-next-20120508-sasha-00001-g8de7752-dirty (sasha@ksplice-shell2) (gcc version 4.4.5 (Debian 4.4.5-8) ) #178 SMP PREEMPT Tue May 8 04:27:40 EDT 2012 Command line: init=virt/init console=ttyS0 sched_debug slub_debug=FZPU rw numa=fake=10 root=/dev/vda
KERNEL supported cpus:
Intel GenuineIntel
AMD AuthenticAMD
Centaur CentaurHauls
e820: BIOS-provided physical RAM map:
BIOS-e820: [mem 0x0000000000000000-0x000000000009dbff] usable
BIOS-e820: [mem 0x000000000009dc00-0x000000000009ffff] reserved
BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
BIOS-e820: [mem 0x0000000000100000-0x000000007fffcfff] usable
BIOS-e820: [mem 0x000000007fffd000-0x000000007fffffff] reserved
BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
NX (Execute Disable) protection: active
DMI 2.4 present.
No AGP bridge found
e820: last_pfn = 0x7fffd max_arch_pfn = 0x400000000
x86 PAT enabled: cpu 0, old 0x70406, new 0x7010600070106
found SMP MP-table at [mem 0x000fd5d0-0x000fd5df] mapped at [ffff8800000fd5d0]
init_memory_mapping: [mem 0x00000000-0x7fffcfff]
ACPI: RSDP 00000000000fd3f0 00014 (v00 BOCHS )
ACPI: RSDT 000000007fffd660 00034 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
ACPI: FACP 000000007fffff80 00074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
ACPI: DSDT 000000007fffd9b0 02589 (v01 BXPC BXDSDT 00000001 INTL 20100528)
ACPI: FACS 000000007fffff40 00040
ACPI: SSDT 000000007fffd7e0 001C1 (v01 BOCHS BXPCSSDT 00000001 BXPC 00000001)
ACPI: APIC 000000007fffd6e0 0008A (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001)
ACPI: HPET 000000007fffd6a0 00038 (v01 BOCHS BXPCHPET 00000001 BXPC 00000001)
No NUMA configuration found
Faking a node at [mem 0x0000000000000000-0x000000007fffcfff]
Faking node 0 at [mem 0x0000000000000000-0x000000000dffffff] (224MB)
Faking node 1 at [mem 0x000000000e000000-0x000000001bffffff] (224MB)
Faking node 2 at [mem 0x000000001c000000-0x0000000029ffffff] (224MB)
Faking node 3 at [mem 0x000000002a000000-0x0000000035ffffff] (192MB)
Faking node 4 at [mem 0x0000000036000000-0x0000000041ffffff] (192MB)
Faking node 5 at [mem 0x0000000042000000-0x000000004dffffff] (192MB)
Faking node 6 at [mem 0x000000004e000000-0x0000000059ffffff] (192MB)
Faking node 7 at [mem 0x000000005a000000-0x0000000065ffffff] (192MB)
Faking node 8 at [mem 0x0000000066000000-0x0000000071ffffff] (192MB)
Faking node 9 at [mem 0x0000000072000000-0x000000007fffcfff] (223MB)
Initmem setup node 0 [mem 0x00000000-0x0dffffff]
NODE_DATA [mem 0x0dfcf000-0x0dffffff]
Initmem setup node 1 [mem 0x0e000000-0x1bffffff]
NODE_DATA [mem 0x1bfcf000-0x1bffffff]
Initmem setup node 2 [mem 0x1c000000-0x29ffffff]
NODE_DATA [mem 0x29fcf000-0x29ffffff]
Initmem setup node 3 [mem 0x2a000000-0x35ffffff]
NODE_DATA [mem 0x35fcf000-0x35ffffff]
Initmem setup node 4 [mem 0x36000000-0x41ffffff]
NODE_DATA [mem 0x41fcf000-0x41ffffff]
Initmem setup node 5 [mem 0x42000000-0x4dffffff]
NODE_DATA [mem 0x4dfcf000-0x4dffffff]
Initmem setup node 6 [mem 0x4e000000-0x59ffffff]
NODE_DATA [mem 0x59fcf000-0x59ffffff]
Initmem setup node 7 [mem 0x5a000000-0x65ffffff]
NODE_DATA [mem 0x65fcf000-0x65ffffff]
Initmem setup node 8 [mem 0x66000000-0x71ffffff]
NODE_DATA [mem 0x71fcf000-0x71ffffff]
Initmem setup node 9 [mem 0x72000000-0x7fffcfff]
NODE_DATA [mem 0x7ffcb000-0x7fffbfff]
kvm-clock: Using msrs 4b564d01 and 4b564d00
kvm-clock: cpu 0, msr 0:41d7841, boot clock
Zone ranges:
DMA
[mem 0x00010000-0x00ffffff]
DMA32
[mem 0x01000000-0xffffffff]
Normal
empty
Movable zone start for each node
Early memory node ranges

  node   0: [mem 0x00010000-0x0009cfff]
  node   0: [mem 0x00100000-0x0dffffff]
  node   1: [mem 0x0e000000-0x1bffffff]
  node   2: [mem 0x1c000000-0x29ffffff]
  node   3: [mem 0x2a000000-0x35ffffff]
  node   4: [mem 0x36000000-0x41ffffff]
  node   5: [mem 0x42000000-0x4dffffff]
  node   6: [mem 0x4e000000-0x59ffffff]
  node   7: [mem 0x5a000000-0x65ffffff]
  node   8: [mem 0x66000000-0x71ffffff]
  node   9: [mem 0x72000000-0x7fffcfff]

ACPI: PM-Timer IO Port: 0xb008
ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
ACPI: LAPIC (acpi_id[0x02] lapic_id[0x02] enabled)
ACPI: LAPIC (acpi_id[0x03] lapic_id[0x03] enabled)
ACPI: IOAPIC (id[0x04] address[0xfec00000] gsi_base[0]) IOAPIC[0]: apic_id 4, version 17, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) Using ACPI (MADT) for SMP configuration information
ACPI: HPET id: 0x8086a201 base: 0xfed00000
SMP: Allowing 4 CPUs, 0 hotplug CPUs
PM: Registered nosave memory: 000000000009d000 - 000000000009e000
PM: Registered nosave memory: 000000000009e000 - 00000000000a0000
PM: Registered nosave memory: 00000000000a0000 - 00000000000f0000
PM: Registered nosave memory: 00000000000f0000 - 0000000000100000
e820: [mem 0x80000000-0xfeffbfff] available for PCI devices Booting paravirtualized kernel on KVM
setup_percpu: NR_CPUS:4096 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:10
PERCPU: Embedded 475 pages/cpu @ffff88000d800000 s1923672 r0 d21928 u2097152

[0]
0
[1]
1
[2]
2
[3]
3

kvm-clock: cpu 0, msr 0:d9d4841, primary cpu clock
KVM setup async PF for cpu 0
kvm-stealtime: cpu 0, msr d80f0c0
Built 10 zonelists in Node order, mobility grouping on. Total pages: 515973
Policy zone: DMA32
Kernel command line: init=virt/init console=ttyS0 sched_debug slub_debug=FZPU rw numa=fake=10 root=/dev/vda PID hash table entries: 4096 (order: 3, 32768 bytes)
__ex_table already sorted, skipping sort
xsave/xrstor: enabled xstate_bv 0x7, cntxt size 0x340
Checking aperture...
No AGP bridge found
Memory: 1978372k/2097140k available (30279k kernel code, 460k absent, 118308k reserved, 18880k data, 3380k init)
kmemleak: Kernel memory leak detector disabled
SLUB: Genslabs=15, HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=10
Preemptible hierarchical RCU implementation.
RCU debugfs-based tracing is enabled.
RCU dyntick-idle grace-period acceleration is enabled.
RCU lockdep checking is enabled.
RCU torture testing starts during boot.
Additional per-CPU info printed with stalls.
NR_IRQS:262400 nr_irqs:712 16
Console: colour VGA+ 80x25
console [ttyS0] enabled
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar

... MAX_LOCKDEP_SUBCLASSES:  8
... MAX_LOCK_DEPTH:          48
... MAX_LOCKDEP_KEYS:        8191
... CLASSHASH_SIZE:          4096
... MAX_LOCKDEP_ENTRIES:     16384
... MAX_LOCKDEP_CHAINS:      32768
... CHAINHASH_SIZE:          16384

memory used by lock dependency info: 6367 kB
per task-struct memory footprint: 2688 bytes
------------------------
| Locking API testsuite:
----------------------------------------------------------------------------
| spin |wlock |rlock |mutex | wsem | rsem |
--------------------------------------------------------------------------
A-A deadlock:

  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

A-B-B-A deadlock:

  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

             A-B-B-C-C-A deadlock:
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

             A-B-C-A-B-C deadlock:
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

         A-B-B-C-C-D-D-A deadlock:
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

         A-B-C-D-B-D-D-A deadlock:
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

         A-B-C-D-B-C-D-A deadlock:
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

double unlock:

  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

initialize held:

  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

bad unlock order:

  ok  |
  ok  |
  ok  |
  ok  |
  ok  |
  ok  |

--------------------------------------------------------------------------

              recursive read-lock:
             |
  ok  |
             |

ok |

recursive read-lock #2:
|
ok |

             |

ok |

            mixed read-write-lock:
             |
  ok  |
             |

ok |

            mixed write-read-lock:
             |
  ok  |
             |

ok |

--------------------------------------------------------------------------

     hard-irqs-on + irq-safe-A/12:
  ok  |
  ok  |
  ok  |

     soft-irqs-on + irq-safe-A/12:
  ok  |
  ok  |
  ok  |

     hard-irqs-on + irq-safe-A/21:
  ok  |
  ok  |
  ok  |

     soft-irqs-on + irq-safe-A/21:
  ok  |
  ok  |
  ok  |

       sirq-safe-A => hirqs-on/12:
  ok  |
  ok  |
  ok  |

       sirq-safe-A => hirqs-on/21:
  ok  |
  ok  |
  ok  |

         hard-safe-A + irqs-on/12:
  ok  |
  ok  |
  ok  |

         soft-safe-A + irqs-on/12:
  ok  |
  ok  |
  ok  |

         hard-safe-A + irqs-on/21:
  ok  |
  ok  |
  ok  |

         soft-safe-A + irqs-on/21:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #1/123:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #1/123:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #1/132:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #1/132:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #1/213:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #1/213:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #1/231:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #1/231:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #1/312:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #1/312:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #1/321:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #1/321:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #2/123:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #2/123:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #2/132:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #2/132:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #2/213:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #2/213:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #2/231:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #2/231:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #2/312:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #2/312:
  ok  |
  ok  |
  ok  |

    hard-safe-A + unsafe-B #2/321:
  ok  |
  ok  |
  ok  |

    soft-safe-A + unsafe-B #2/321:
  ok  |
  ok  |
  ok  |

hard-irq lock-inversion/123:

  ok  |
  ok  |
  ok  |

soft-irq lock-inversion/123:

  ok  |
  ok  |
  ok  |

hard-irq lock-inversion/132:

  ok  |
  ok  |
  ok  |

soft-irq lock-inversion/132:

  ok  |
  ok  |
  ok  |

hard-irq lock-inversion/213:

  ok  |
  ok  |
  ok  |

soft-irq lock-inversion/213:

  ok  |
  ok  |
  ok  |

hard-irq lock-inversion/231:

  ok  |
  ok  |
  ok  |

soft-irq lock-inversion/231:

  ok  |
  ok  |
  ok  |

hard-irq lock-inversion/312:

  ok  |
  ok  |
  ok  |

soft-irq lock-inversion/312:

  ok  |
  ok  |
  ok  |

hard-irq lock-inversion/321:

  ok  |
  ok  |
  ok  |

soft-irq lock-inversion/321:

  ok  |
  ok  |
  ok  |

hard-irq read-recursion/123:
ok |

soft-irq read-recursion/123:
ok |

hard-irq read-recursion/132:
ok |

soft-irq read-recursion/132:
ok |

hard-irq read-recursion/213:
ok |

soft-irq read-recursion/213:
ok |

hard-irq read-recursion/231:
ok |

soft-irq read-recursion/231:
ok |

hard-irq read-recursion/312:
ok |

soft-irq read-recursion/312:
ok |

hard-irq read-recursion/321:
ok |

soft-irq read-recursion/321:
ok |

-------------------------------------------------------
Good, all 218 testcases passed! |
---------------------------------
kmemleak: Early log buffer exceeded (1254), please increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE Detected 2491.820 MHz processor.
Calibrating delay loop (skipped) preset value.. 4983.64 BogoMIPS (lpj=2491820)
pid_max: default: 32768 minimum: 301
Security Framework initialized
AppArmor: AppArmor disabled by boot time parameter
Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes) Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes) Mount-cache hash table entries: 256
Initializing cgroup subsys debug
Initializing cgroup subsys cpuacct
Initializing cgroup subsys devices
Initializing cgroup subsys freezer
Initializing cgroup subsys net_cls
Initializing cgroup subsys blkio
Initializing cgroup subsys perf_event
Initializing cgroup subsys net_prio
mce: CPU supports 10 MCE banks
ACPI: Core revision 20120320
..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
CPU0: Intel(R) Core(TM) i5-2520M CPU @ 2.50GHz stepping 07
Performance Events: 16-deep LBR, SandyBridge events, Intel PMU driver.
PEBS disabled due to CPU errata.

... version:                2
... bit width:              48
... generic registers:      4
... value mask:             0000ffffffffffff
... max period:             000000007fffffff
... fixed-purpose events:   3
... event mask:             000000070000000f

NMI watchdog: enabled, takes one hw-pmu counter.
lockdep: fixing up alternatives.
Booting Node 1, Processors #1
kvm-clock: cpu 1, msr 0:1b9d4841, secondary cpu clock KVM setup async PF for cpu 1
kvm-stealtime: cpu 1, msr 1b80f0c0
NMI watchdog: enabled, takes one hw-pmu counter.
lockdep: fixing up alternatives.
Ok.
Booting Node 2, Processors #2
kvm-clock: cpu 2, msr 0:299d4841, secondary cpu clock KVM setup async PF for cpu 2
kvm-stealtime: cpu 2, msr 2980f0c0
NMI watchdog: enabled, takes one hw-pmu counter.
lockdep: fixing up alternatives.
Ok.
Booting Node 3, Processors #3 Ok.
kvm-clock: cpu 3, msr 0:35bd4841, secondary cpu clock KVM setup async PF for cpu 3
kvm-stealtime: cpu 3, msr 35a0f0c0
NMI watchdog: enabled, takes one hw-pmu counter. Brought up 4 CPUs
----------------
| NMI testsuite:
--------------------
remote IPI:
ok |

local IPI:
ok |

--------------------
Good, all 2 testcases passed! |
---------------------------------
Total of 4 processors activated (19934.56 BogoMIPS).
devtmpfs: initialized
initlevel:0=early, 5 registered initcalls
EVM: security.selinux
EVM: security.SMACK64
EVM: security.capability
initlevel:1=core, 36 registered initcalls
xor: automatically using best checksumming function:
avx : 15648.000 MB/sec
atomic64 test passed for x86-64 platform with CX8 and with SSE
kworker/u:0 (34) used greatest stack depth: 4952 bytes left
kworker/u:0 (36) used greatest stack depth: 4488 bytes left
dummy:
RTC time: 13:27:18, date: 05/08/12
NET: Registered protocol family 16
initlevel:2=postcore, 20 registered initcalls
initlevel:3=arch, 12 registered initcalls
ACPI: bus type pci registered
PCI: Using configuration type 1 for base access
initlevel:4=subsys, 96 registered initcalls
bio: create slab <bio-0> at 0
raid6: sse2x1 6890 MB/s
raid6: sse2x2 9812 MB/s
raid6: sse2x4 11179 MB/s
raid6: using algorithm sse2x4 (11179 MB/s)
raid6: using ssse3x2 recovery algorithm
ACPI: Added _OSI(Module Device)
ACPI: Added _OSI(Processor Device)
ACPI: Added _OSI(3.0 _SCP Extensions)
ACPI: Added _OSI(Processor Aggregator Device)
ACPI: Interpreter enabled
ACPI: (supports S0
S3
S4
S5
)
ACPI: Using IOAPIC for interrupt routing
ACPI: No dock devices found.
PCI: Ignoring host bridge windows from ACPI; if necessary, use "pci=use_crs" and report a bug
ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
PCI host bridge to bus 0000:00
pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffff]
pci 0000:00:01.3: quirk: [io 0xb000-0xb03f] claimed by PIIX4 ACPI
pci 0000:00:01.3: quirk: [io 0xb100-0xb10f] claimed by PIIX4 SMB
pci0000:00: Unable to request _OSC control (_OSC support mask: 0x1e)
ACPI: PCI Interrupt Link [LNKA] (IRQs
5
*10
11
)

ACPI: PCI Interrupt Link [LNKB] (IRQs
5
*10
11
)

ACPI: PCI Interrupt Link [LNKC] (IRQs
5
10
*11
)

ACPI: PCI Interrupt Link [LNKD] (IRQs
5
10
*11
)

ACPI: PCI Interrupt Link [LNKS] (IRQs
9
)
*0

vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
vgaarb: loaded
vgaarb: bridge control possible 0000:00:02.0
SCSI subsystem initialized
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
Linux media interface: v0.10
Linux video capture interface: v2.00
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]> PTP clock support registered
wmi: Mapper loaded
Advanced Linux Sound Architecture Driver Version 1.0.25.
PCI: Using ACPI for IRQ routing
Sangoma WANPIPE Router v1.1 (c) 1995-2000 Sangoma Technologies Inc.
NET: Registered protocol family 23
Bluetooth: Core ver 2.16
NET: Registered protocol family 31
Bluetooth: HCI device and connection manager initialized
Bluetooth: HCI socket layer initialized
Bluetooth: L2CAP socket layer initialized
Bluetooth: SCO socket layer initialized
NET: Registered protocol family 8
NET: Registered protocol family 20

------------[ cut here ]------------
WARNING: at net/wireless/reg.c:396 regulatory_init+0xce/0x144()
Hardware name: Bochs
db.txt is empty, you should update it...
Pid: 1, comm: swapper/0 Not tainted 3.4.0-rc6-next-20120508-sasha-00001-g8de7752-dirty #178
Call Trace:
 [<ffffffff810b6ca7>] warn_slowpath_common+0x87/0xb0
 [<ffffffff8425fb55>] ? sctp_snmp_proc_init+0x31/0x31
 [<ffffffff810b6d71>] warn_slowpath_fmt+0x41/0x50
 [<ffffffff8189c208>] ? __raw_spin_lock_init+0x38/0x70
 [<ffffffff8425fcf0>] regulatory_init+0xce/0x144
 [<ffffffff8425fbba>] cfg80211_init+0x65/0xcd
 [<ffffffff841d9639>] do_one_initcall+0x7a/0x155
 [<ffffffff841d9807>] do_basic_setup+0xc8/0xed
 [<ffffffff841d982c>] ? do_basic_setup+0xed/0xed
 [<ffffffff841f7ff7>] ? smp_init+0x85/0x8d
 [<ffffffff841d9a85>] kernel_init+0x1fe/0x280
 [<ffffffff810e7f0e>] ? sub_preempt_count+0xae/0xf0
 [<ffffffff82d8ca74>] kernel_thread_helper+0x4/0x10
 [<ffffffff810e884d>] ? finish_task_switch+0x8d/0x110
 [<ffffffff82d8ad74>] ? retint_restore_args+0x13/0x13
 [<ffffffff841d9887>] ? repair_env_string+0x5b/0x5b
 [<ffffffff82d8ca70>] ? gs_change+0x13/0x13
---[ end trace 44593438a59a9533 ]---
NetLabel: Initializing
NetLabel:  domain hash size = 128
NetLabel:  protocols = UNLABELED CIPSOv4
NetLabel:  unlabeled traffic allowed by default
cfg80211: Calling CRDA to update world regulatory domain
nfc: nfc_init: NFC Core ver 0.1
NET: Registered protocol family 39

initlevel:5=fs, 35 registered initcalls
HPET: 3 timers in total, 0 timers will be used for per-cpu timer
hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
hpet0: 3 comparators, 64-bit 100.000000 MHz counter
Switching to clocksource kvm-clock
FS-Cache: Loaded
CacheFiles: Loaded
pnp: PnP ACPI init
ACPI: bus type pnp registered
pnp: PnP ACPI: found 8 devices
ACPI: ACPI bus type pnp unregistered
NET: Registered protocol family 2
IP route cache hash table entries: 65536 (order: 7, 524288 bytes)
TCP established hash table entries: 262144 (order: 10, 4194304 bytes) TCP bind hash table entries: 65536 (order: 10, 5242880 bytes)
TCP: Hash tables configured (established 262144 bind 65536)
TCP: reno registered
UDP hash table entries: 1024 (order: 5, 196608 bytes)
UDP-Lite hash table entries: 1024 (order: 5, 196608 bytes)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
pci 0000:00:00.0: Limiting direct PCI/PCI transfers
pci 0000:00:01.0: PIIX3: Enabling Passive Release
pci 0000:00:01.0: Activating ISA DMA hang workarounds
DMA-API: preallocated 32768 debug entries
DMA-API: debugging enabled by kernel config
initlevel:6=device, 1764 registered initcalls
kvm: no hardware support
has_svm: not amd
kvm: no hardware support
Machine check injector initialized
microcode: CPU0 sig=0x206a7, pf=0x1, revision=0x1
microcode: CPU1 sig=0x206a7, pf=0x1, revision=0x1
microcode: CPU2 sig=0x206a7, pf=0x1, revision=0x1
microcode: CPU3 sig=0x206a7, pf=0x1, revision=0x1
microcode: Microcode Update Driver: v2.00 <[email protected]>, Peter Oruba
sha1_ssse3: Using AVX optimized SHA-1 implementation
Initializing RT-Tester: OK
====[ backtrace testing ]===========
Testing a backtrace from process context.
The following trace is a kernel self test and not a bug!
Pid: 1, comm: swapper/0 Tainted: G W 3.4.0-rc6-next-20120508-sasha-00001-g8de7752-dirty #178

Call Trace:
 [<ffffffff8112a850>] ? backtrace_test_irq_callback+0x20/0x20
 [<ffffffff8112a888>] backtrace_regression_test+0x38/0x110
 [<ffffffff841f80bf>] ? kallsyms_init+0x25/0x25
 [<ffffffff8119c5db>] ? __alloc_percpu+0xb/0x10
 [<ffffffff841d9639>] do_one_initcall+0x7a/0x155
 [<ffffffff841d9807>] do_basic_setup+0xc8/0xed
 [<ffffffff841d982c>] ? do_basic_setup+0xed/0xed
 [<ffffffff841f7ff7>] ? smp_init+0x85/0x8d
 [<ffffffff841d9a85>] kernel_init+0x1fe/0x280
 [<ffffffff810e7f0e>] ? sub_preempt_count+0xae/0xf0
 [<ffffffff82d8ca74>] kernel_thread_helper+0x4/0x10
 [<ffffffff810e884d>] ? finish_task_switch+0x8d/0x110
 [<ffffffff82d8ad74>] ? retint_restore_args+0x13/0x13
 [<ffffffff841d9887>] ? repair_env_string+0x5b/0x5b
 [<ffffffff82d8ca70>] ? gs_change+0x13/0x13
Testing a backtrace from irq context.
The following trace is a kernel self test and not a bug!
Pid: 16, comm: ksoftirqd/1 Tainted: G        W    3.4.0-rc6-next-20120508-sasha-00001-g8de7752-dirty #178
Call Trace:
 [<ffffffff8112a839>] backtrace_test_irq_callback+0x9/0x20
 [<ffffffff810be141>] tasklet_action+0xb1/0x130
 [<ffffffff810be8e8>] __do_softirq+0xc8/0x1c0
 [<ffffffff810beadd>] run_ksoftirqd+0xfd/0x230
 [<ffffffff810be9e0>] ? __do_softirq+0x1c0/0x1c0
 [<ffffffff810dad02>] kthread+0xb2/0xc0
 [<ffffffff82d8ca74>] kernel_thread_helper+0x4/0x10
 [<ffffffff810e884d>] ? finish_task_switch+0x8d/0x110
 [<ffffffff82d8ad74>] ? retint_restore_args+0x13/0x13
 [<ffffffff810dac50>] ? __init_kthread_worker+0x70/0x70
 [<ffffffff82d8ca70>] ? gs_change+0x13/0x13

Testing a saved backtrace.
The following trace is a kernel self test and not a bug!

[<ffffffff8105d1fa>] save_stack_trace+0x2a/0x50
 
[<ffffffff8112a934>] backtrace_regression_test+0xe4/0x110
 
[<ffffffff841d9639>] do_one_initcall+0x7a/0x155
 
[<ffffffff841d9807>] do_basic_setup+0xc8/0xed
 
[<ffffffff841d9a85>] kernel_init+0x1fe/0x280
 
[<ffffffff82d8ca74>] kernel_thread_helper+0x4/0x10

[<ffffffffffffffff>] 0xffffffffffffffff
====[ end of backtrace testing ]====
audit: initializing netlink socket (disabled)
type=2000 audit(1336483646.153:1): initialized
rcu-torture:--- Start of test: nreaders=8 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0 HugeTLB registered 2 MB page size, pre-allocated 0 pages
VFS: Disk quotas dquot_6.5.2
Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
DLM installed
squashfs: version 4.0 (2009/01/31) Phillip Lougher
NFS: Registering the id_resolver key type
FS-Cache: Netfs 'nfs' registered for caching
nfs4filelayout_init: NFSv4 File Layout Driver Registering...
NFS: objlayout_init: Registered OSD pNFS Layout Driver
Installing knfsd (copyright (C) 1996 [email protected]).
FS-Cache: Netfs 'cifs' registered for caching
NTFS driver 2.1.30 [Flags: R/W DEBUG].
EFS: 1.0a - http://aeschi.ch.eu.org/efs/
jffs2: version 2.2. (NAND) (SUMMARY) © 2001-2006 Red Hat, Inc.
ROMFS MTD (C) 2007 Red Hat, Inc.
QNX4 filesystem 0.2.3 registered.
QNX6 filesystem 1.0.0 registered.
fuse init (API version 7.19)
JFS: nTxBlock = 8192, nTxLock = 65536
SGI XFS with ACLs, security attributes, realtime, large block/inode numbers, debug enabled
9p: Installing v9fs 9p2000 file system support
FS-Cache: Netfs '9p' registered for caching
NILFS version 2 loaded
BeFS version: 0.9.3
OCFS2 1.5.0
ocfs2: Registered cluster interface o2cb
ocfs2: Registered cluster interface user
OCFS2 DLMFS 1.5.0
OCFS2 User DLM kernel interface loaded
OCFS2 Node Manager 1.5.0
OCFS2 DLM 1.5.0
Btrfs loaded
GFS2 installed
ceph: loaded (mds proto 32)
msgmni has been set to 3864
NET: Registered protocol family 38
async_tx: api initialized (async)
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
start plist test
end plist test
crc32: CRC_LE_BITS = 64, CRC_BE BITS = 64
crc32: self tests passed, processed 225944 bytes in 171576 nsec
crc32c: CRC_LE_BITS = 64
crc32c: self tests passed, processed 225944 bytes in 87453 nsec
xz_dec_test: module loaded
xz_dec_test: Create a device node with 'mknod xz_dec_test c 248 0' and write .xz files to it.
pci_hotplug: PCI Hot Plug PCI Core version: 0.5
pciehp: PCI Express Hot Plug Controller Driver version: 0.4
cpcihp_zt5550: ZT5550 CompactPCI Hot Plug Driver version: 0.2
cpcihp_generic: Generic port I/O CompactPCI Hot Plug Driver version: 0.1
cpcihp_generic: not configured, disabling.
shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
acpiphp: Slot [1] registered
acpiphp: Slot [2] registered
acpiphp: Slot [3] registered
acpiphp: Slot [4] registered
acpiphp: Slot [5] registered
acpiphp: Slot [6] registered
acpiphp: Slot [7] registered
acpiphp: Slot [8] registered
acpiphp: Slot [9] registered
acpiphp: Slot [10] registered
acpiphp: Slot [11] registered
acpiphp: Slot [12] registered
acpiphp: Slot [13] registered
acpiphp: Slot [14] registered
acpiphp: Slot [15] registered
acpiphp: Slot [16] registered
acpiphp: Slot [17] registered
acpiphp: Slot [18] registered
acpiphp: Slot [19] registered
acpiphp: Slot [20] registered
acpiphp: Slot [21] registered
acpiphp: Slot [22] registered
acpiphp: Slot [23] registered
acpiphp: Slot [24] registered
acpiphp: Slot [25] registered
acpiphp: Slot [26] registered
acpiphp: Slot [27] registered
acpiphp: Slot [28] registered
acpiphp: Slot [29] registered
acpiphp: Slot [30] registered
Refined TSC clocksource calibration: 2491.904 MHz.
acpiphp: Slot [31] registered
acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
ALI M7101 PMU not found.
INTEL CARILLO RANCH LPC not found.
Carillo Ranch Backlight Driver Initialized.
i2c-core: driver [adp8860_bl] using legacy suspend method
i2c-core: driver [adp8860_bl] using legacy resume method
i2c-core: driver [adp8870_bl] using legacy suspend method
i2c-core: driver [adp8870_bl] using legacy resume method
rivafb_setup START
nvidiafb_setup START
VIA Graphics Integration Chipset framebuffer 2.4 initializing
Could not find Carillo Ranch MCH device.
no IO addresses supplied
hgafb: HGA card not detected.
hgafb: probe of hgafb.0 failed with error -22
cirrusfb 0000:00:02.0: Cirrus Logic chipset on PCI bus, RAM (4096 kB) at 0xfc000000
fbcon: CL Picasso4 (fb0) is primary device
Console: switching
to colour frame buffer device 80x30
usbcore: registered new interface driver udlfb
usbcore: registered new interface driver smscufx
uvesafb: failed to execute /sbin/v86d
uvesafb: make sure that the v86d helper is installed and executable
uvesafb: Getting VBE info block failed (eax=0x4f00, err=-2)
uvesafb: vbe_init() failed with -22
uvesafb: probe of uvesafb.0 failed with error -22
vga16fb: mapped to 0xffff8800000a0000
fb1: VGA16 VGA frame buffer device
input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
ACPI: Power Button [PWRF]
GHES: HEST is not enabled!
ERST DBG: ERST support is disabled.
ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
XENFS: not registering filesystem on non-xen platform
Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
�serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
00:06: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
Initializing Nozomi driver 2.1d
lp: driver loaded but no devices found
Non-volatile memory driver v1.3
ppdev: user-space parallel port driver
Linux agpgart interface v0.103
ipmi message handler version 39.2
ipmi device interface
IPMI System Interface driver.
ipmi_si: Adding default-specified kcs state machine
ipmi_si: Trying default-specified kcs state machine at i/o address 0xca2, slave address 0x0, irq 0
ipmi_si: Interface detection failed
ipmi_si: Adding default-specified smic state machine
ipmi_si: Trying default-specified smic state machine at i/o address 0xca9, slave address 0x0, irq 0
ipmi_si: Interface detection failed
ipmi_si: Adding default-specified bt state machine
ipmi_si: Trying default-specified bt state machine at i/o address 0xe4, slave address 0x0, irq 0
ipmi_si: Interface detection failed
ipmi_si: Unable to find any System Interface(s)
IPMI Watchdog: driver initialized
Copyright (C) 2004 MontaVista Software - IPMI Powerdown via sys_reboot.
Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
Hangcheck: Using getrawmonotonic().
ramoops: platform device not found, using module parameters
ramoops: The memory size and the record size must be non-zero
ramoops: probe of ramoops failed with error -22
[drm] Initialized drm 1.1.0 20060810
[drm] radeon defaulting to kernel modesetting.
[drm] radeon kernel modesetting enabled.
[drm:i915_init] *ERROR* drm/i915 can't work without intel_agp module!
usbcore: registered new interface driver udl
i2c-core: driver [ch7006] using legacy suspend method
i2c-core: driver [ch7006] using legacy resume method
parport_pc 00:05: reported by Plug and Play ACPI
parport0: PC-style at 0x378
, irq 7
[
PCSPP
,TRISTATE
]
lp0: using parport0 (interrupt-driven).
lp0: console ready
FDC 0 is a S82078B
brd: module loaded
loop: module loaded
Compaq SMART2 Driver (v 2.6.0)
HP CISS Driver (v 3.6.26)
MM: desc_per_page = 128
nbd: registered device at major 43
vda: unknown partition table
'Low Performance USB Block' driver is deprecated. Please switch to usb-storage
usbcore: registered new interface driver ub
drbd: initialized. Version: 8.3.11 (api:88/proto:86-96)
drbd: built-in
drbd: registered as block device major 147
drbd: minor_table @ 0xffff880070805da8
rbd: loaded rbd (rados block device)
mtip32xx Version 1.2.6os3
ibmasm: IBM ASM Service Processor Driver version 1.0 loaded
lkdtm: No crash points registered, enable through debugfs
Phantom Linux Driver, version n0.9.8, init OK
i2c-core: driver [apds9802als] using legacy suspend method
i2c-core: driver [apds9802als] using legacy resume method
i2c-core: driver [isl29003] using legacy suspend method
i2c-core: driver [isl29003] using legacy resume method
i2c-core: driver [tsl2550] using legacy suspend method
i2c-core: driver [tsl2550] using legacy resume method
Silicon Labs C2 port support v. 0.51.0 - (C) 2007 Rodolfo Giometti
c2port c2port0: C2 port uc added
c2port c2port0: uc flash has 30 blocks x 512 bytes (15360 bytes total)
i2c-core: driver [fsa9480] using legacy suspend method
i2c-core: driver [fsa9480] using legacy resume method
usbcore: registered new interface driver pn533
Uniform Multi-Platform E-IDE driver
piix 0000:00:01.1: IDE controller (0x8086:0x7010 rev 0x00)
piix 0000:00:01.1: not 100% native mode: will probe irqs later

    ide0: BM-DMA at 0xc180-0xc187
    ide1: BM-DMA at 0xc188-0xc18f

hdc: QEMU DVD-ROM, ATAPI CD/DVD-ROM drive
hdc: MWDMA2 mode selected
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
ide1 at 0x170-0x177,0x376 on irq 15
ide_generic: please use "probe_mask=0x3f" module parameter for probing all legacy ISA IDE ports ide-gd driver 1.18
ide-cd driver 5.00
ide-cd: hdc: ATAPI 4X DVD-ROM drive, 512kB Cache
cdrom: Uniform CD-ROM driver Revision: 3.20
Loading iSCSI transport class v2.0-870.
fnic: Cisco FCoE HBA Driver, ver 1.5.0.2
bnx2fc: Broadcom NetXtreme II FCoE Driver bnx2fc v1.0.10 (Jan 22, 2011)
iscsi: registered transport (tcp)
Loading Adaptec I2O RAID: Version 2.4 Build 5go
Detecting Adaptec I2O RAID controllers...
Adaptec aacraid driver 1.2-0[28900]-ms
aic94xx: Adaptec aic94xx SAS/SATA driver version 1.0.3 loaded
isci: Intel(R) C600 SAS Controller Driver - version 1.1.0
scsi: <fdomain> Detection failed (no card)
qla2xxx [0000:00:00.0]-0005: : QLogic Fibre Channel HBA Driver: 8.03.07.13-k.
iscsi: registered transport (qla4xxx)
QLogic iSCSI HBA Driver
Emulex LightPulse Fibre Channel SCSI driver 8.3.30
Copyright(c) 2004-2009 Emulex. All rights reserved.
Brocade BFA FC/FCOE SCSI driver - version: 3.0.23.0
DC390: clustering now enabled by default. If you get problems load
with "disable_clustering=1" and report to maintainers
megaraid cmm: 2.20.2.7 (Release Date: Sun Jul 16 00:01:03 EST 2006)
megaraid: 2.20.5.1 (Release Date: Thu Nov 16 15:32:35 EST 2006)
megasas: 00.00.06.15-rc1 Mon. Mar. 19 17:00:00 PDT 2012
mpt2sas version 13.100.00.00 loaded
GDT-HA: Storage RAID Controller Driver. Version: 3.05
3ware Storage Controller device driver for Linux v1.26.02.003.
3ware 9000 Storage Controller device driver for Linux v2.26.02.014.
LSI 3ware SAS/SATA-RAID Controller device driver for Linux v3.26.02.000.
ppa: Version 2.07 (for Linux 2.4.x)
imm: Version 2.05 (for Linux 2.4.0)
ipr: IBM Power RAID SCSI Device Driver version: 2.5.3 (March 10, 2012) RocketRAID 3xxx/4xxx Controller driver v1.6 (090910)
stex: Promise SuperTrak EX Driver version: 4.6.0000.4 libcxgbi:libcxgbi_init_module: tag itt 0x1fff, 13 bits, age 0xf, 4 bits. libcxgbi:ddp_setup_host_page_size: system PAGE 4096, ddp idx 0.
Chelsio T3 iSCSI Driver cxgb3i v2.0.0 (Jun. 2010)
iscsi: registered transport (cxgb3i)
Chelsio T4 iSCSI Driver cxgb4i v0.9.1 (Aug. 2010)
iscsi: registered transport (cxgb4i)
Broadcom NetXtreme II iSCSI Driver bnx2i v2.7.0.3 (Jun 15, 2011)
iscsi: registered transport (bnx2i)
iscsi: registered transport (be2iscsi)
VMware PVSCSI driver - version 1.0.2.0-k
hv_vmbus: registering driver hv_storvsc
st: Version 20101219, fixed bufsize 32768, s/g segs 256
osst :I: Tape driver with OnStream support version 0.99.4
osst :I: $Id: osst.c,v 1.73 2005/01/01 21:13:34 wriede Exp $
SCSI Media Changer driver v0.25
osd: LOADED open-osd 0.2.1
scsi_debug: host protection
scsi0 : scsi_debug, version 1.82 [20100324], dev_size_mb=8, opts=0x0
scsi 0:0:0:0: Direct-Access Linux scsi_debug 0004 PQ: 0 ANSI: 5
sd 0:0:0:0: [sda] 16384 512-byte logical blocks: (8.38 MB/8.00 MiB)
sd 0:0:0:0: Attached scsi generic sg0 type 0
scsi_scan_0 (3479) used greatest stack depth: 3768 bytes left
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
sda: unknown partition table
sd 0:0:0:0: [sda] Attached SCSI disk
Error: Driver 'pata_platform' is already registered, aborting...
Rounding down aligned max_sectors from 4294967295 to 8388600
SSFDC read-only Flash Translation layer
mtdoops: mtd device (mtddev=name/number) must be supplied
physmap-flash.0: failed to claim resource 0
Generic platform RAM MTD, (c) 2004 Simtec Electronics
slram: not enough parameters.
ftl_cs: FTL header not found.
onenand_wait: timeout! ctrl=0x0000 intr=0x0000
OneNAND 16MB 1.8V 16-bit (0x04)
OneNAND version = 0x001e
Scanning device for bad blocks
Creating 1 MTD partitions on "OneNAND simulator":
0x000000000000-0x000001000000 : "OneNAND simulator partition"
ftl_cs: FTL header not found.
HSI/SSI char device loaded
bonding: Ethernet Channel Bonding Driver: v3.7.1 (April 27, 2011)
eql: Equalizer2002: Simon Janes ([email protected]) and David S. Miller ([email protected]) Micrel KS8995 Ethernet switch SPI driver version 0.1.1
tun: Universal TUN/TAP device driver, 1.6
tun: (C) 1999-2004 Max Krasnyansky <[email protected]>
arcnet loaded.
arcnet: RFC1201 "standard" (`a') encapsulation support loaded.
arcnet: RFC1051 "simple standard" (`s') encapsulation support loaded.
arcnet: raw mode (`r') encapsulation support loaded.
arcnet: cap mode (`c') encapsulation support loaded.
arcnet: COM90xx chipset support
S1: No ARCnet cards found.
arcnet: COM90xx IO-mapped mode support (by David Woodhouse et el.)
E-mail me if you actually test this driver, please!
arc%d: No autoprobe for IO mapped cards; you must specify the base address!
arcnet: RIM I (entirely mem-mapped) support
E-mail me if you actually test the RIM I driver, please!
Given: node 00h, shmem 0h, irq 0
No autoprobe for RIM I; you must specify the shmem and irq!
arcnet: COM20020 PCI support
ipddp.c:v0.01 8/28/97 Bradford W. Johnson <[email protected]>
ipddp0: Appletalk-IP Encap. mode by Bradford W. Johnson <[email protected]>
vcan: Virtual CAN interface driver
slcan: serial line CAN interface driver
slcan: 10 dynamic interface channels.
CAN device driver interface
usbcore: registered new interface driver peak_usb
cnic: Broadcom NetXtreme II CNIC Driver cnic v2.5.10 (March 21, 2012)
e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
e1000: Copyright (c) 1999-2006 Intel Corporation.
e1000e: Intel(R) PRO/1000 Network Driver - 2.0.0-k
e1000e: Copyright(c) 1999 - 2012 Intel Corporation.
igb: Intel(R) Gigabit Ethernet Network Driver - version 3.4.7-k
igb: Copyright (c) 2007-2012 Intel Corporation.
igbvf: Intel(R) Gigabit Virtual Function Network Driver - version 2.0.1-k
igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
mkiss: AX.25 Multikiss, Hans Albas PE1AYX
AX.25: 6pack driver, Revision: 0.3.0
YAM driver version 0.8 by F1OAT/F6FBB
AX.25: bpqether driver version 004
baycom_ser_fdx: (C) 1996-2000 Thomas Sailer, HB9JNX/AE4WA
baycom_ser_fdx: version 0.10
hdlcdrv: (C) 1996-2000 Thomas Sailer HB9JNX/AE4WA
hdlcdrv: version 0.8
baycom_ser_hdx: (C) 1996-2000 Thomas Sailer, HB9JNX/AE4WA
baycom_ser_hdx: version 0.10
baycom_par: (C) 1996-2000 Thomas Sailer, HB9JNX/AE4WA
baycom_par: version 0.9
NET3 PLIP version 2.4-parport [email protected]
plip0: Parallel port at 0x378, using IRQ 7.
PPP generic driver version 2.4.2
PPP BSD Compression module registered
PPP Deflate Compression module registered
PPP MPPE Compression module registered
NET: Registered protocol family 24
PPTP driver version 0.8.5
SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256) (6 bit encapsulation enabled).
CSLIP: code copyright 1989 Regents of the University of California.
SLIP linefill/keepalive option.
iwlwifi: Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
iwlwifi: Copyright(c) 2003-2012 Intel Corporation
iwl4965: Intel(R) Wireless WiFi 4965 driver for Linux, in-tree:
iwl4965: Copyright(c) 2003-2011 Intel Corporation
iwl3945: Intel(R) PRO/Wireless 3945ABG/BG Network Connection driver for Linux, in-tree:s
iwl3945: Copyright(c) 2003-2011 Intel Corporation
VMware vmxnet3 virtual NIC driver - version 1.1.29.0-k-NAPI
usbcore: registered new interface driver asix
usbcore: registered new interface driver cdc_ether
usbcore: registered new interface driver cdc_eem
usbcore: registered new interface driver net1080
usbcore: registered new interface driver cdc_subset
usbcore: registered new interface driver zaurus
usbcore: registered new interface driver sierra_net
usbcore: registered new interface driver cdc_ncm
usbcore: registered new interface driver qmi_wwan
adummy: version 1.0
I2O subsystem v1.325
i2o: max drivers = 8
I2O Configuration OSM v1.323
I2O Bus Adapter OSM v1.317
I2O Block Device OSM v1.325
I2O SCSI Peripheral OSM v1.316
I2O ProcFS OSM v1.316
Fusion MPT base driver 3.04.20
Copyright (c) 1999-2008 LSI Corporation
Fusion MPT SPI Host driver 3.04.20
Fusion MPT FC Host driver 3.04.20
Fusion MPT SAS Host driver 3.04.20
Fusion MPT misc device (ioctl) driver 3.04.20
mptctl: Registered with Fusion MPT base driver
mptctl: /dev/mptctl @ (major,minor=10,220)
Fusion MPT LAN driver 3.04.20
Generic UIO driver for PCI 2.3 devices version: 0.01.0
ks0108: ERROR: parport didn't register new device
cfag12864b: ERROR: ks0108 is not initialized
cfag12864bfb: ERROR: cfag12864b is not initialized
aoe: AoE v47 initialised.
paride: aten registered as protocol 0
paride: bpck registered as protocol 1
paride: comm registered as protocol 2
paride: dstr registered as protocol 3
paride: k951 registered as protocol 4
paride: k971 registered as protocol 5
paride: epat registered as protocol 6
paride: epia registered as protocol 7
paride: frpw registered as protocol 8
paride: friq registered as protocol 9
paride: fit2 registered as protocol 10
paride: fit3 registered as protocol 11
paride: on20 registered as protocol 12
paride: on26 registered as protocol 13
paride: ktti registered as protocol 14
pd: pd version 1.05, major 45, cluster 64, nice 0
pda: Autoprobe failed
pd: no valid drive found
pcd: pcd version 1.07, major 46, nice 0
pcd0: Autoprobe failed
pcd: No CD-ROM drive found
pf: pf version 1.04, major 47, cluster 64, nice 0
pf: No ATAPI disk detected
pt: pt version 1.04, major 96
pt0: Autoprobe failed
pt: No ATAPI tape drive detected
pg: pg version 1.02, major 97
pga: Autoprobe failed
pg: No ATAPI device detected
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
uhci_hcd: USB Universal Host Controller Interface driver
usbcore: registered new interface driver cdc_wdm
Initializing USB Mass Storage driver...
usbcore: registered new interface driver usb-storage
USB Mass Storage support registered.
usbcore: registered new interface driver libusual
i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
serio: i8042 KBD port at 0x60,0x64 irq 1
serio: i8042 AUX port at 0x60,0x64 irq 12
mousedev: PS/2 mouse device common for all mice
input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
usbcore: registered new interface driver synaptics_usb
rtc_cmos 00:01: RTC can wake from S4
rtc_cmos 00:01: rtc core: registered rtc_cmos as rtc0
rtc0: alarms up to one day, 114 bytes nvram, hpet irqs
rtc-test rtc-test.0: rtc core: registered test as rtc1
rtc-test rtc-test.1: rtc core: registered test as rtc2
i2c /dev entries driver
lirc_dev: IR Remote Control driver registered, major 232
IR NEC protocol handler initialized
IR RC5(x) protocol handler initialized
IR RC6 protocol handler initialized
IR JVC protocol handler initialized
IR Sony protocol handler initialized
IR RC5 (streamzap) protocol handler initialized
IR SANYO protocol handler initialized
IR MCE Keyboard/mouse protocol handler initialized
IR LIRC bridge handler initialized
gspca_main: v2.14.0 registered
usbcore: registered new interface driver jl2005bcd
vivi-000: V4L2 device registered as video0
Video Technology Magazine Virtual Video Capture Board ver 0.8.1 successfully loaded. pps pps0: new PPS source ktimer
pps pps0: ktimer PPS source registered
pps_ldisc: PPS line discipline registered
pps_parport: parallel port PPS client
pps_parport: couldn't register with parport0
Driver for 1-wire Dallas network protocol.
usbcore: registered new interface driver DS9490R
DS1WM w1 busmaster driver - (c) 2004 Szabolcs Gyurko
1-Wire driver for the DS2760 battery monitor chip - (c) 2004-2005, Szabolcs Gyurko
i2c-core: driver [sbs-battery] using legacy suspend method
md: linear personality registered for level -1
md: raid0 personality registered for level 0
md: raid1 personality registered for level 1
md: raid10 personality registered for level 10
md: raid6 personality registered for level 6
md: raid5 personality registered for level 5
md: raid4 personality registered for level 4
md: multipath personality registered for level -4
md: faulty personality registered for level -5
device-mapper: uevent: version 1.0.3
device-mapper: ioctl: 4.22.0-ioctl (2011-10-19) initialised: [email protected]
device-mapper: multipath: version 1.3.0 loaded
device-mapper: multipath round-robin: version 1.0.0 loaded
device-mapper: multipath queue-length: version 0.1.0 loaded
device-mapper: multipath service-time: version 0.2.0 loaded
device-mapper: dm-log-userspace: version 1.1.0 loaded
Bluetooth: Virtual HCI driver ver 1.3
Bluetooth: HCI UART driver ver 2.2
Bluetooth: HCI H4 protocol initialized
Bluetooth: HCI BCSP protocol initialized
Bluetooth: HCILL protocol initialized
Bluetooth: HCIATH3K protocol initialized
usbcore: registered new interface driver btusb
Bluetooth: Generic Bluetooth SDIO driver ver 0.1
usbcore: registered new interface driver ath3k
ISDN subsystem Rev: 1.1.2.3/
1.1.2.2/
1.1.2.3/
1.1.2.2/
1.1.2.2

PPP BSD Compression module registered
CAPI 2.0 started up with major 68 (middleware)
Modular ISDN core version 1.1.28
NET: Registered protocol family 34
DSP module 2.0
mISDN_dsp: DSP clocks every 64 samples. This equals 8 jiffies.
mISDN: Layer-1-over-IP driver Rev. 2.00
0 virtual devices registered
dss1_divert module successfully installed
gigaset: Driver for Gigaset 307x (debug build)
gigaset: Kernel CAPI interface
usbcore: registered new interface driver usb_gigaset
usb_gigaset: USB Driver for Gigaset 307x using M105
usbcore: registered new interface driver bas_gigaset
bas_gigaset: USB Driver for Gigaset 307x
EDAC MC: Ver: 2.1.0
AMD64 EDAC driver v3.4.0
cpuidle: using governor ladder
cpuidle: using governor menu
sdhci: Secure Digital Host Controller Interface driver
sdhci: Copyright(c) Pierre Ossman
usbcore: registered new interface driver ushc
sdhci-pltfm: SDHCI platform and OF driver helper
user_mad: couldn't register device number
iscsi: registered transport (iser)
EFI Variables Facility v0.08 2004-May-17
dcdbas dcdbas: Dell Systems Management Base Driver (version 5.6.0-3.2)
No iBFT detected.
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
usbcore: registered new interface driver Abilis Systems as10x usb driver
usbip_core: usbip_core_init:814: USB/IP Core v1.0.0
usbcore: registered new interface driver usbip-host
usbip_host: usbip_host_init:270: USB/IP Host Driver v1.0.0
usbcore: registered new interface driver w35und
usbcore: registered new interface driver prism2_usb
usbcore: registered new interface driver asus-oled
input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2 Panel driver version 0.9.5 registered on parport0 (io=0x378).
usbcore: registered new interface driver r8712u
usbcore: registered new interface driver tranzport
usbcore: registered new interface driver alphatrack
VME User Space Access Driver
vme_user: No cards, skipping registration
zram: num_devices not specified. Using default: 1
zram: Creating 1 devices ...
Loading crystalhd 0.9.27
beceem: Beceem Communications Inc. WiMAX driver, 5.2.45
Copyright 2010. Beceem Communications Inc
usbcore: registered new interface driver usbbcm
usbcore: registered new interface driver ft1000usb
input: Speakup as /devices/virtual/input/input3
initialized device: /dev/synth, node (MAJOR 10, MINOR 25)
speakup 3.1.6: initialized
synth name on entry is: (null)
i2c-core: driver [cptm1217] using legacy suspend method
i2c-core: driver [cptm1217] using legacy resume method
Linux telephony interface: v1.00
ixj driver initialized.
ozwpan ozwpan: Ozmo Devices WPAN
ozwpan ozwpan: new USB bus registered, assigned bus number 1
usb usb1: New USB device found, idVendor=1d6b, idProduct=0001
usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb1: Product: Ozmo Devices WPAN
usb usb1: Manufacturer: Linux 3.4.0-rc6-next-20120508-sasha-00001-g8de7752-dirty Ozmo WPAN usb usb1: SerialNumber: ozwpan
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 8 ports detected
asus_wmi: Asus Management GUID not found
asus_wmi: Management GUID not found
asus_wmi: Management GUID not found
msi_laptop: driver 0.5 successfully loaded
compal_laptop: Motherboard not recognized (You could try the module's force-parameter)
acerhdf: Acer Aspire One Fan driver, v.0.5.26
acerhdf: unknown (unsupported) BIOS version Bochs/Bochs/Bochs, please report, aborting!
hp_accel: driver loaded
hdaps: supported laptop not found!
hdaps: driver init failed (ret=-19)!
fujitsu_laptop: driver 0.6.0 successfully loaded
fujitsu_tablet: Unknown (using defaults)
msi_wmi: This machine doesn't have MSI-hotkeys through WMI
topstar_laptop: ACPI extras driver loaded
intel_oaktrail: Platform not recognized (You could try the module's force-parameter)
hv_utils: Registering HyperV Utility Driver
hv_vmbus: registering driver hv_util
Audio Excel DSP 16 init driver Copyright (C) Riccardo Facchetti 1995-98
aedsp16: I/O, IRQ and DMA are mandatory
pss: mss_io, mss_dma, mss_irq and pss_io must be set.
ad1848/cs4248 codec driver Copyright (C) by Hannu Savolainen 1993-1996
ad1848: No ISAPnP cards found, trying standard ones...
MediaTrix audio driver Copyright (C) by Hannu Savolainen 1993-1996
I/O, IRQ, DMA and type are mandatory
Pro Audio Spectrum driver Copyright (C) by Hannu Savolainen 1993-1996
I/O, IRQ, DMA and type are mandatory
sb: Init: Starting Probe...
sb: Init: Done
Cyrix Kahlua VSA1 XpressAudio support (c) Copyright 2003 Red Hat Inc
uart6850: irq and io must be set.
YM3812 and OPL-3 driver Copyright (C) by Hannu Savolainen, Rob Hooft 1993-1996 MIDI Loopback device driver

ALSA sound/core/seq/oss/seq_oss.c:236 can't register device seq
ALSA sound/core/oss/pcm_oss.c:3009 unable to register OSS PCM device 0:0

no UART detected at 0x1
ALSA sound/drivers/mtpav.c:589 MTVAP port 0x378 is busy
snd_mtpav: probe of snd_mtpav failed with error -16
snd_mts64: probe of snd_mts64.0 failed with error -5
snd_portman2x4: probe of snd_portman2x4.0 failed with error -5
input: PC Speaker as /devices/platform/pcspkr/input/input4
PCSP: CONFIG_DEBUG_PAGEALLOC is enabled, which may make the sound noisy.
usbcore: registered new interface driver snd-usb-audio
usbcore: registered new interface driver snd-ua101
usbcore: registered new interface driver snd-usb-usx2y
usbcore: registered new interface driver snd-usb-us122l
usbcore: registered new interface driver snd-usb-caiaq
usbcore: registered new interface driver snd-usb-6fire
oprofile: using NMI interrupt.
pktgen: Packet Generator for packet performance testing. Version: 2.74 GACT probability on
Mirror/redirect action on
Simple TC action Loaded
netem: version 1.3
u32 classifier
Performance counters on
input device check on
Actions configured
Netfilter messages via NETLINK v0.30.
nfnl_acct: registering with nfnetlink.
nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
ctnetlink v0.93: registering with nfnetlink.
NF_TPROXY: Transparent proxy support initialized, version 4.1.0
NF_TPROXY: Copyright (c) 2006-2007 BalaBit IT Ltd.
xt_time: kernel timezone is -0000
ip_set: protocol 6
IPVS: Registered protocols (TCP, UDP, SCTP, AH, ESP)
IPVS: Connection hash table configured (size=4096, memory=64Kbytes)
IPVS: Creating netns size=3104 id=0
IPVS: ipvs loaded.
IPVS: [rr] scheduler registered.
IPVS: [wrr] scheduler registered.
IPVS: [lc] scheduler registered.
IPVS: [wlc] scheduler registered.
IPVS: [lblc] scheduler registered.
IPVS: [lblcr] scheduler registered.
IPVS: [dh] scheduler registered.
IPVS: [sh] scheduler registered.
IPVS: [sed] scheduler registered.
IPVS: [nq] scheduler registered.
IPVS: ftp: loaded support on port[0] = 21
IPVS: [sip] pe registered.
IPv4 over IPv4 tunneling driver
gre: GRE over IPv4 demultiplexor driver
ip_gre: GRE over IPv4 tunneling driver
ip_tables: (C) 2000-2006 Netfilter Core Team
ipt_CLUSTERIP: ClusterIP Version 0.8 loaded successfully
arp_tables: (C) 2002 David S. Miller
TCP: cubic registered
Initializing XFRM netlink socket
NET: Registered protocol family 10
Mobile IPv6
ip6_tables: (C) 2000-2006 Netfilter Core Team
IPv6 over IPv4 tunneling driver
NET: Registered protocol family 17
NET: Registered protocol family 15
Bridge firewalling registered
Ebtables v2.0 registered
NET: Registered protocol family 4
NET: Registered protocol family 5
NET: Registered protocol family 9
X.25 for Linux Version 0.2
NET: Registered protocol family 6
NET: Registered protocol family 11
NET: Registered protocol family 3
can: controller area network core (rev 20090105 abi 8)
NET: Registered protocol family 29
can: raw protocol (rev 20090105)
can: broadcast manager protocol (rev 20090105 t)
can: netlink gateway (rev 20101209)
IrCOMM protocol (Dag Brattli)
Bluetooth: RFCOMM TTY layer initialized
Bluetooth: RFCOMM socket layer initialized
Bluetooth: RFCOMM ver 1.11
Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Bluetooth: BNEP filters: protocol multicast
Bluetooth: CMTP (CAPI Emulation) ver 1.0
Bluetooth: HIDP (Human Interface Emulation) ver 1.2
RPC: Registered rdma transport module.
NET: Registered protocol family 33
RxRPC: Registered security type 2 'rxkad'
lec:lane_module_init: lec.c: initialized
mpoa:atm_mpoa_init: mpc.c: initialized
L2TP core driver, V2.0
PPPoL2TP kernel driver, V2.0
L2TP IP encapsulation support (L2TPv3)
L2TP netlink interface
L2TP ethernet pseudowire support (L2TPv3)
L2TP debugfs support
L2TP IP encapsulation support for IPv6 (L2TPv3)
NET4: DECnet for Linux: V.2.5.68s (C) 1995-2003 Linux DECnet Project Team
DECnet: Routing cache hash table of 1024 buckets, 80Kbytes
NET: Registered protocol family 12
NET: Registered protocol family 19
NET: Registered protocol family 35
8021q: 802.1Q VLAN Support v1.8
DCCP: Activated CCID 2 (TCP-like)
DCCP: Activated CCID 3 (TCP-Friendly Rate Control)
sctp: Hash tables configured (established 26214 bind 26214)
NET: Registered protocol family 21
Registered RDS/iwarp transport
Registered RDS/infiniband transport
Registered RDS/tcp transport
lib80211: common routines for IEEE802.11 drivers
TIPC: Activated (version 2.0.0)
NET: Registered protocol family 30
TIPC: Started in single node mode
9pnet: Installing 9P2000 support
NET: Registered protocol family 37
NET: Registered protocol family 36
Registering the dns_resolver key type
libceph: loaded (mon/osd proto 15/24, osdmap 5/6 5/6)
batman_adv: B.A.T.M.A.N. advanced 2012.1.0 (compatibility version 14) loaded
openvswitch: Open vSwitch switching datapath
initlevel:7=late, 60 registered initcalls
registered taskstats version 1
kAFS: Red Hat AFS client v0.1 registering.
FS-Cache: Netfs 'afs' registered for caching
IMA: No TPM chip found, activating TPM-bypass!
raid6test: testing the 4-disk case...
raid6test: test_disks(0, 1): faila= 0(D) failb= 1(D) OK
CPA self-test:
raid6test: test_disks(0, 2): faila= 0(D) failb= 2(P) OK
raid6test: test_disks(0, 3): faila= 0(D) failb= 3(Q) OK
raid6test: test_disks(1, 2): faila= 1(D) failb= 2(P) OK
raid6test: test_disks(1, 3): faila= 1(D) failb= 3(Q) OK
4k 524285 large 0 gb 0 x 262144[ffff880000000000-ffff88003ffff000] miss 0
raid6test: test_disks(2, 3): faila= 2(P) failb= 3(Q) OK
raid6test: testing the 5-disk case...
raid6test: test_disks(0, 1): faila= 0(D) failb= 1(D) OK
raid6test: test_disks(0, 2): faila= 0(D) failb= 2(D) OK
raid6test: test_disks(0, 3): faila= 0(D) failb= 3(P) OK
raid6test: test_disks(0, 4): faila= 0(D) failb= 4(Q) OK
raid6test: test_disks(1, 2): faila= 1(D) failb= 2(D) OK
raid6test: test_disks(1, 3): faila= 1(D) failb= 3(P) OK
raid6test: test_disks(1, 4): faila= 1(D) failb= 4(Q) OK
raid6test: test_disks(2, 3): faila= 2(D) failb= 3(P) OK
raid6test: test_disks(2, 4): faila= 2(D) failb= 4(Q) OK
raid6test: test_disks(3, 4): faila= 3(P) failb= 4(Q) OK
raid6test: testing the 11-disk case...
raid6test: test_disks(0, 1): faila= 0(D) failb= 1(D) OK
raid6test: test_disks(0, 2): faila= 0(D) failb= 2(D) OK
raid6test: test_disks(0, 3): faila= 0(D) failb= 3(D) OK
raid6test: test_disks(0, 4): faila= 0(D) failb= 4(D) OK
raid6test: test_disks(0, 5): faila= 0(D) failb= 5(D) OK
raid6test: test_disks(0, 6): faila= 0(D) failb= 6(D) OK
raid6test: test_disks(0, 7): faila= 0(D) failb= 7(D) OK
raid6test: test_disks(0, 8): faila= 0(D) failb= 8(D) OK
raid6test: test_disks(0, 9): faila= 0(D) failb= 9(P) OK
raid6test: test_disks(0, 10): faila= 0(D) failb= 10(Q) OK
raid6test: test_disks(1, 2): faila= 1(D) failb= 2(D) OK
raid6test: test_disks(1, 3): faila= 1(D) failb= 3(D) OK
raid6test: test_disks(1, 4): faila= 1(D) failb= 4(D) OK
raid6test: test_disks(1, 5): faila= 1(D) failb= 5(D) OK
raid6test: test_disks(1, 6): faila= 1(D) failb= 6(D) OK
raid6test: test_disks(1, 7): faila= 1(D) failb= 7(D) OK
raid6test: test_disks(1, 8): faila= 1(D) failb= 8(D) OK
raid6test: test_disks(1, 9): faila= 1(D) failb= 9(P) OK
raid6test: test_disks(1, 10): faila= 1(D) failb= 10(Q) OK
raid6test: test_disks(2, 3): faila= 2(D) failb= 3(D) OK
raid6test: test_disks(2, 4): faila= 2(D) failb= 4(D) OK
raid6test: test_disks(2, 5): faila= 2(D) failb= 5(D) OK
raid6test: test_disks(2, 6): faila= 2(D) failb= 6(D) OK
raid6test: test_disks(2, 7): faila= 2(D) failb= 7(D) OK
raid6test: test_disks(2, 8): faila= 2(D) failb= 8(D) OK
raid6test: test_disks(2, 9): faila= 2(D) failb= 9(P) OK
raid6test: test_disks(2, 10): faila= 2(D) failb= 10(Q) OK
raid6test: test_disks(3, 4): faila= 3(D) failb= 4(D) OK
raid6test: test_disks(3, 5): faila= 3(D) failb= 5(D) OK
raid6test: test_disks(3, 6): faila= 3(D) failb= 6(D) OK
raid6test: test_disks(3, 7): faila= 3(D) failb= 7(D) OK
raid6test: test_disks(3, 8): faila= 3(D) failb= 8(D) OK
raid6test: test_disks(3, 9): faila= 3(D) failb= 9(P) OK
raid6test: test_disks(3, 10): faila= 3(D) failb= 10(Q) OK
raid6test: test_disks(4, 5): faila= 4(D) failb= 5(D) OK
raid6test: test_disks(4, 6): faila= 4(D) failb= 6(D) OK
raid6test: test_disks(4, 7): faila= 4(D) failb= 7(D) OK
raid6test: test_disks(4, 8): faila= 4(D) failb= 8(D) OK
raid6test: test_disks(4, 9): faila= 4(D) failb= 9(P) OK
raid6test: test_disks(4, 10): faila= 4(D) failb= 10(Q) OK
raid6test: test_disks(5, 6): faila= 5(D) failb= 6(D) OK
raid6test: test_disks(5, 7): faila= 5(D) failb= 7(D) OK
raid6test: test_disks(5, 8): faila= 5(D) failb= 8(D) OK
raid6test: test_disks(5, 9): faila= 5(D) failb= 9(P) OK
raid6test: test_disks(5, 10): faila= 5(D) failb= 10(Q) OK
raid6test: test_disks(6, 7): faila= 6(D) failb= 7(D) OK
raid6test: test_disks(6, 8): faila= 6(D) failb= 8(D) OK
raid6test: test_disks(6, 9): faila= 6(D) failb= 9(P) OK
raid6test: test_disks(6, 10): faila= 6(D) failb= 10(Q) OK
raid6test: test_disks(7, 8): faila= 7(D) failb= 8(D) OK
raid6test: test_disks(7, 9): faila= 7(D) failb= 9(P) OK
raid6test: test_disks(7, 10): faila= 7(D) failb= 10(Q) OK
raid6test: test_disks(8, 9): faila= 8(D) failb= 9(P) OK
raid6test: test_disks(8, 10): faila= 8(D) failb= 10(Q) OK
raid6test: test_disks(9, 10): faila= 9(P) failb= 10(Q) OK
raid6test: testing the 12-disk case...
raid6test: test_disks(0, 1): faila= 0(D) failb= 1(D) OK
raid6test: test_disks(0, 2): faila= 0(D) failb= 2(D) OK
raid6test: test_disks(0, 3): faila= 0(D) failb= 3(D) OK
raid6test: test_disks(0, 4): faila= 0(D) failb= 4(D) OK
raid6test: test_disks(0, 5): faila= 0(D) failb= 5(D) OK
raid6test: test_disks(0, 6): faila= 0(D) failb= 6(D) OK
raid6test: test_disks(0, 7): faila= 0(D) failb= 7(D) OK
raid6test: test_disks(0, 8): faila= 0(D) failb= 8(D) OK
raid6test: test_disks(0, 9): faila= 0(D) failb= 9(D) OK
raid6test: test_disks(0, 10): faila= 0(D) failb= 10(P) OK
raid6test: test_disks(0, 11): faila= 0(D) failb= 11(Q) OK
raid6test: test_disks(1, 2): faila= 1(D) failb= 2(D) OK
raid6test: test_disks(1, 3): faila= 1(D) failb= 3(D) OK
raid6test: test_disks(1, 4): faila= 1(D) failb= 4(D) OK
raid6test: test_disks(1, 5): faila= 1(D) failb= 5(D) OK
raid6test: test_disks(1, 6): faila= 1(D) failb= 6(D) OK
raid6test: test_disks(1, 7): faila= 1(D) failb= 7(D) OK
raid6test: test_disks(1, 8): faila= 1(D) failb= 8(D) OK
raid6test: test_disks(1, 9): faila= 1(D) failb= 9(D) OK
raid6test: test_disks(1, 10): faila= 1(D) failb= 10(P) OK
raid6test: test_disks(1, 11): faila= 1(D) failb= 11(Q) OK
raid6test: test_disks(2, 3): faila= 2(D) failb= 3(D) OK
raid6test: test_disks(2, 4): faila= 2(D) failb= 4(D) OK
raid6test: test_disks(2, 5): faila= 2(D) failb= 5(D) OK
raid6test: test_disks(2, 6): faila= 2(D) failb= 6(D) OK
raid6test: test_disks(2, 7): faila= 2(D) failb= 7(D) OK
raid6test: test_disks(2, 8): faila= 2(D) failb= 8(D) OK
raid6test: test_disks(2, 9): faila= 2(D) failb= 9(D) OK
raid6test: test_disks(2, 10): faila= 2(D) failb= 10(P) OK
raid6test: test_disks(2, 11): faila= 2(D) failb= 11(Q) OK
raid6test: test_disks(3, 4): faila= 3(D) failb= 4(D) OK
raid6test: test_disks(3, 5): faila= 3(D) failb= 5(D) OK
raid6test: test_disks(3, 6): faila= 3(D) failb= 6(D) OK
raid6test: test_disks(3, 7): faila= 3(D) failb= 7(D) OK
raid6test: test_disks(3, 8): faila= 3(D) failb= 8(D) OK
raid6test: test_disks(3, 9): faila= 3(D) failb= 9(D) OK
raid6test: test_disks(3, 10): faila= 3(D) failb= 10(P) OK
raid6test: test_disks(3, 11): faila= 3(D) failb= 11(Q) OK
raid6test: test_disks(4, 5): faila= 4(D) failb= 5(D) OK
raid6test: test_disks(4, 6): faila= 4(D) failb= 6(D) OK
raid6test: test_disks(4, 7): faila= 4(D) failb= 7(D) OK
raid6test: test_disks(4, 8): faila= 4(D) failb= 8(D) OK
raid6test: test_disks(4, 9): faila= 4(D) failb= 9(D) OK
raid6test: test_disks(4, 10): faila= 4(D) failb= 10(P) OK
raid6test: test_disks(4, 11): faila= 4(D) failb= 11(Q) OK
raid6test: test_disks(5, 6): faila= 5(D) failb= 6(D) OK
raid6test: test_disks(5, 7): faila= 5(D) failb= 7(D) OK
raid6test: test_disks(5, 8): faila= 5(D) failb= 8(D) OK
raid6test: test_disks(5, 9): faila= 5(D) failb= 9(D) OK
raid6test: test_disks(5, 10): faila= 5(D) failb= 10(P) OK
raid6test: test_disks(5, 11): faila= 5(D) failb= 11(Q) OK
raid6test: test_disks(6, 7): faila= 6(D) failb= 7(D) OK
raid6test: test_disks(6, 8): faila= 6(D) failb= 8(D) OK
raid6test: test_disks(6, 9): faila= 6(D) failb= 9(D) OK
raid6test: test_disks(6, 10): faila= 6(D) failb= 10(P) OK
raid6test: test_disks(6, 11): faila= 6(D) failb= 11(Q) OK
raid6test: test_disks(7, 8): faila= 7(D) failb= 8(D) OK
raid6test: test_disks(7, 9): faila= 7(D) failb= 9(D) OK
raid6test: test_disks(7, 10): faila= 7(D) failb= 10(P) OK
raid6test: test_disks(7, 11): faila= 7(D) failb= 11(Q) OK
raid6test: test_disks(8, 9): faila= 8(D) failb= 9(D) OK
raid6test: test_disks(8, 10): faila= 8(D) failb= 10(P) OK
raid6test: test_disks(8, 11): faila= 8(D) failb= 11(Q) OK
raid6test: test_disks(9, 10): faila= 9(D) failb= 10(P) OK
raid6test: test_disks(9, 11): faila= 9(D) failb= 11(Q) OK
raid6test: test_disks(10, 11): faila= 10(P) failb= 11(Q) OK
raid6test: testing the 16-disk case...
raid6test: test_disks(0, 1): faila= 0(D) failb= 1(D) OK
raid6test: test_disks(0, 2): faila= 0(D) failb= 2(D) OK
raid6test: test_disks(0, 3): faila= 0(D) failb= 3(D) OK
raid6test: test_disks(0, 4): faila= 0(D) failb= 4(D) OK
raid6test: test_disks(0, 5): faila= 0(D) failb= 5(D) OK
raid6test: test_disks(0, 6): faila= 0(D) failb= 6(D) OK
raid6test: test_disks(0, 7): faila= 0(D) failb= 7(D) OK
raid6test: test_disks(0, 8): faila= 0(D) failb= 8(D) OK
raid6test: test_disks(0, 9): faila= 0(D) failb= 9(D) OK
raid6test: test_disks(0, 10): faila= 0(D) failb= 10(D) OK
raid6test: test_disks(0, 11): faila= 0(D) failb= 11(D) OK
raid6test: test_disks(0, 12): faila= 0(D) failb= 12(D) OK
raid6test: test_disks(0, 13): faila= 0(D) failb= 13(D) OK
raid6test: test_disks(0, 14): faila= 0(D) failb= 14(P) OK
raid6test: test_disks(0, 15): faila= 0(D) failb= 15(Q) OK
raid6test: test_disks(1, 2): faila= 1(D) failb= 2(D) OK
raid6test: test_disks(1, 3): faila= 1(D) failb= 3(D) OK
raid6test: test_disks(1, 4): faila= 1(D) failb= 4(D) OK
raid6test: test_disks(1, 5): faila= 1(D) failb= 5(D) OK
raid6test: test_disks(1, 6): faila= 1(D) failb= 6(D) OK
raid6test: test_disks(1, 7): faila= 1(D) failb= 7(D) OK
raid6test: test_disks(1, 8): faila= 1(D) failb= 8(D) OK
raid6test: test_disks(1, 9): faila= 1(D) failb= 9(D) OK
raid6test: test_disks(1, 10): faila= 1(D) failb= 10(D) OK
raid6test: test_disks(1, 11): faila= 1(D) failb= 11(D) OK
raid6test: test_disks(1, 12): faila= 1(D) failb= 12(D) OK
raid6test: test_disks(1, 13): faila= 1(D) failb= 13(D) OK
raid6test: test_disks(1, 14): faila= 1(D) failb= 14(P) OK
raid6test: test_disks(1, 15): faila= 1(D) failb= 15(Q) OK
raid6test: test_disks(2, 3): faila= 2(D) failb= 3(D) OK
raid6test: test_disks(2, 4): faila= 2(D) failb= 4(D) OK
raid6test: test_disks(2, 5): faila= 2(D) failb= 5(D) OK
raid6test: test_disks(2, 6): faila= 2(D) failb= 6(D) OK
raid6test: test_disks(2, 7): faila= 2(D) failb= 7(D) OK
raid6test: test_disks(2, 8): faila= 2(D) failb= 8(D) OK
raid6test: test_disks(2, 9): faila= 2(D) failb= 9(D) OK
raid6test: test_disks(2, 10): faila= 2(D) failb= 10(D) OK
raid6test: test_disks(2, 11): faila= 2(D) failb= 11(D) OK
raid6test: test_disks(2, 12): faila= 2(D) failb= 12(D) OK
raid6test: test_disks(2, 13): faila= 2(D) failb= 13(D) OK
raid6test: test_disks(2, 14): faila= 2(D) failb= 14(P) OK
raid6test: test_disks(2, 15): faila= 2(D) failb= 15(Q) OK
raid6test: test_disks(3, 4): faila= 3(D) failb= 4(D) OK
raid6test: test_disks(3, 5): faila= 3(D) failb= 5(D) OK
raid6test: test_disks(3, 6): faila= 3(D) failb= 6(D) OK
raid6test: test_disks(3, 7): faila= 3(D) failb= 7(D) OK
raid6test: test_disks(3, 8): faila= 3(D) failb= 8(D) OK
raid6test: test_disks(3, 9): faila= 3(D) failb= 9(D) OK
raid6test: test_disks(3, 10): faila= 3(D) failb= 10(D) OK
raid6test: test_disks(3, 11): faila= 3(D) failb= 11(D) OK
raid6test: test_disks(3, 12): faila= 3(D) failb= 12(D) OK
raid6test: test_disks(3, 13): faila= 3(D) failb= 13(D) OK
raid6test: test_disks(3, 14): faila= 3(D) failb= 14(P) OK
raid6test: test_disks(3, 15): faila= 3(D) failb= 15(Q) OK
raid6test: test_disks(4, 5): faila= 4(D) failb= 5(D) OK
raid6test: test_disks(4, 6): faila= 4(D) failb= 6(D) OK
raid6test: test_disks(4, 7): faila= 4(D) failb= 7(D) OK
raid6test: test_disks(4, 8): faila= 4(D) failb= 8(D) OK
raid6test: test_disks(4, 9): faila= 4(D) failb= 9(D) OK
raid6test: test_disks(4, 10): faila= 4(D) failb= 10(D) OK
raid6test: test_disks(4, 11): faila= 4(D) failb= 11(D) OK
raid6test: test_disks(4, 12): faila= 4(D) failb= 12(D) OK
raid6test: test_disks(4, 13): faila= 4(D) failb= 13(D) OK
raid6test: test_disks(4, 14): faila= 4(D) failb= 14(P) OK
raid6test: test_disks(4, 15): faila= 4(D) failb= 15(Q) OK
raid6test: test_disks(5, 6): faila= 5(D) failb= 6(D) OK
raid6test: test_disks(5, 7): faila= 5(D) failb= 7(D) OK
raid6test: test_disks(5, 8): faila= 5(D) failb= 8(D) OK
raid6test: test_disks(5, 9): faila= 5(D) failb= 9(D) OK
raid6test: test_disks(5, 10): faila= 5(D) failb= 10(D) OK
raid6test: test_disks(5, 11): faila= 5(D) failb= 11(D) OK
raid6test: test_disks(5, 12): faila= 5(D) failb= 12(D) OK
raid6test: test_disks(5, 13): faila= 5(D) failb= 13(D) OK
raid6test: test_disks(5, 14): faila= 5(D) failb= 14(P) OK
raid6test: test_disks(5, 15): faila= 5(D) failb= 15(Q) OK
raid6test: test_disks(6, 7): faila= 6(D) failb= 7(D) OK
raid6test: test_disks(6, 8): faila= 6(D) failb= 8(D) OK
raid6test: test_disks(6, 9): faila= 6(D) failb= 9(D) OK
raid6test: test_disks(6, 10): faila= 6(D) failb= 10(D) OK
raid6test: test_disks(6, 11): faila= 6(D) failb= 11(D) OK
raid6test: test_disks(6, 12): faila= 6(D) failb= 12(D) OK
raid6test: test_disks(6, 13): faila= 6(D) failb= 13(D) OK
raid6test: test_disks(6, 14): faila= 6(D) failb= 14(P) OK
raid6test: test_disks(6, 15): faila= 6(D) failb= 15(Q) OK
raid6test: test_disks(7, 8): faila= 7(D) failb= 8(D) OK
raid6test: test_disks(7, 9): faila= 7(D) failb= 9(D) OK
raid6test: test_disks(7, 10): faila= 7(D) failb= 10(D) OK
raid6test: test_disks(7, 11): faila= 7(D) failb= 11(D) OK
raid6test: test_disks(7, 12): faila= 7(D) failb= 12(D) OK
raid6test: test_disks(7, 13): faila= 7(D) failb= 13(D) OK
raid6test: test_disks(7, 14): faila= 7(D) failb= 14(P) OK
raid6test: test_disks(7, 15): faila= 7(D) failb= 15(Q) OK
raid6test: test_disks(8, 9): faila= 8(D) failb= 9(D) OK
raid6test: test_disks(8, 10): faila= 8(D) failb= 10(D) OK
raid6test: test_disks(8, 11): faila= 8(D) failb= 11(D) OK
raid6test: test_disks(8, 12): faila= 8(D) failb= 12(D) OK
raid6test: test_disks(8, 13): faila= 8(D) failb= 13(D) OK
raid6test: test_disks(8, 14): faila= 8(D) failb= 14(P) OK
raid6test: test_disks(8, 15): faila= 8(D) failb= 15(Q) OK
raid6test: test_disks(9, 10): faila= 9(D) failb= 10(D) OK
raid6test: test_disks(9, 11): faila= 9(D) failb= 11(D) OK
raid6test: test_disks(9, 12): faila= 9(D) failb= 12(D) OK
raid6test: test_disks(9, 13): faila= 9(D) failb= 13(D) OK
raid6test: test_disks(9, 14): faila= 9(D) failb= 14(P) OK
raid6test: test_disks(9, 15): faila= 9(D) failb= 15(Q) OK
raid6test: test_disks(10, 11): faila= 10(D) failb= 11(D) OK
raid6test: test_disks(10, 12): faila= 10(D) failb= 12(D) OK
raid6test: test_disks(10, 13): faila= 10(D) failb= 13(D) OK
raid6test: test_disks(10, 14): faila= 10(D) failb= 14(P) OK
raid6test: test_disks(10, 15): faila= 10(D) failb= 15(Q) OK
raid6test: test_disks(11, 12): faila= 11(D) failb= 12(D) OK
raid6test: test_disks(11, 13): faila= 11(D) failb= 13(D) OK
raid6test: test_disks(11, 14): faila= 11(D) failb= 14(P) OK
raid6test: test_disks(11, 15): faila= 11(D) failb= 15(Q) OK
raid6test: test_disks(12, 13): faila= 12(D) failb= 13(D) OK
raid6test: test_disks(12, 14): faila= 12(D) failb= 14(P) OK
raid6test: test_disks(12, 15): faila= 12(D) failb= 15(Q) OK
raid6test: test_disks(13, 14): faila= 13(D) failb= 14(P) OK
raid6test: test_disks(13, 15): faila= 13(D) failb= 15(Q) OK
raid6test: test_disks(14, 15): faila= 14(P) failb= 15(Q) OK raid6test:
raid6test: complete (257 tests, 0 failures)
Magic number: 12:896:482
sound pcmC0D0c: hash matches
register_blkdev: cannot get major 3 for hd
4k 524285 large 0 gb 0 x 262144[ffff880000000000-ffff88003ffff000] miss 0 4k 524285 large 0 gb 0 x 262144[ffff880000000000-ffff88003ffff000] miss 0
ok.
console [netcon0] enabled
netconsole: network logging started
rtc_cmos 00:01: setting system clock to 2012-05-08 13:27:56 UTC (1336483676) BIOS EDD facility v0.16 2004-Jun-25, 1 devices found
ALSA device list:
#0: Dummy 1
#1: Loopback 1
#2: Virtual MIDI Card 1
#3: Internal PC-Speaker at port 0x61
md: Waiting for all devices to be available before autodetect
md: If you don't use raid, use raid=noautodetect
md: Autodetecting RAID arrays.
md: Scanned 0 and added 0 devices.
md: autorun ...
md: ... autorun DONE.
kjournald starting. Commit interval 5 seconds
EXT3-fs (vda): using internal journal
EXT3-fs (vda): recovery complete
EXT3-fs (vda): mounted filesystem with ordered data mode
VFS: Mounted root (ext3 filesystem) on device 250:0.
devtmpfs: mounted
debug: unmapping init [mem 0xffffffff84003000-0xffffffff8434ffff] Write protecting the kernel read-only data: 43008k
Testing CPA: undo ffffffff81000000-ffffffff83a00000
Testing CPA: again
debug: unmapping init [mem 0xffff880002d96000-0xffff880002dfffff]
debug: unmapping init [mem 0xffff8800039e5000-0xffff8800039fffff] Mounting...
sh-4.2# hrtimer: interrupt took 4472708 ns
xQEMU: Terminated

The percpu stuff should be pending (thought it was in -next already):
https://lkml.org/lkml/2012/3/29/317

The ACPI stuff was fixed here:
https://lkml.org/lkml/2012/4/2/532

But only the vt and hpet things got merged so far:
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=5da527aafed2834852fc4fe21daeaeadf7c61af3

I'll respin the ACPI parts now.

That would be awesome. If you decide otherwise, please let me know, and I'll take care of them.

Even if we decide to relax the current strict behaviour later, we should fix all stuff we run into. Userspace really relies on proper messages, and not partial or mixed up things to guess what they mean.

The nice thing with the currently strict logic is that only two instances of KERN_CONT running at the same time can race against each other and mix their own messages. Unlike the old kmsg behaviour, users which log a single proper terminated line, will never get interleaved with the KERN_CONT users. This reduces the "risk" of garbled messages to the users which actually decided to take this "risk".

Thanks,
Kay

Sent the rest out, which got lost a while ago. Here's the already fixed and pending stuff, so you can check what's not covered and still missing on your box.

percpu:
http://thread.gmane.org/gmane.linux.kernel/1274450

mm:
http://thread.gmane.org/gmane.linux.kernel/1293437

acpi:
http://thread.gmane.org/gmane.linux.kernel/1293438

Thanks,
Kay

Woops, look like I've did this one all over.

What about PRINTK_TIME? Are there plans to enable it on console output?

Yeah, we should restore the old behaviour. The timestamp is always stored internally, regardless of the CONFIG_PRINTK_TIME or tunable setting. At the moment, seems they are only (conditionally) added to the syslog() output and (unconditionally) to the /dev/kmsg export.

I guess we just re-define CONFIG_PRINTK_TIME and the tunable as: "show time in syslog() and on the console output".

Karel will likely extend dmesg(1) to use /dev/kmsg instead of syslog() when it's readable and dmesg(1) can still show the time stamps read from /dev/kmsg, even when CONFIG_PRINTK_TIME is not set, so the old tunable basically becomes a "show timestamps on the console" flag. :)

Kay

That would be good to put back, can you do that?

thanks,

greg k-h

Why?

I really think this is just a bug in the new code.

KERN_CONT should not be needed if the previous printk didn't have a final "\n".

We made it easier to use printk for a reason a few months ago. The new rules are:

- If you have a KERN_<loglevel>, it *always* starts a new line, the
obvious exception being KERN_CONT

- the loglevels *only* matter at the start of the printk - so if you
have '\n' embedded in a single printk, that changes nothing what-so-ever. It's not line-based.

- if you didn't have a '\n', and don't have a loglevel, KERN_CONT is implied.

Quite frankly, those three rules (a) make sense and (b) make things easy.

Breaking them now is a bug. Please don't go adding ugly KERN_CONT when there really isn't any reason for it. Just fix the printk code you broke.

Linus

Thanks for making that clear.

Is there a reason to keep KERN_CONT under this set of rules at all?

I'm guessing that there are very few places that have a final '\n' but still want to use KERN_CONT, and even in that case it should be trivially easy to fix them up.

Besides that, from what I understand, KERN_CONT isn't really needed.

Yes, a very subtle and rare one.

If you want to print out a string that starts with "<%d>", you *have* to use a prefix, in order to not make printk think that the "<*>" is the prefix itself.

And if you don't want to start a new line, you need to use KERN_CONT.

So there is *one* case, and one case only, where KERN_CONT is useful, and it's when the string you are printing out could otherwise be mistaken for a prefix itself (the "<%d>" thing isn't the only such string, of course - it could be a "%s" where the string has those characters in it.

So think of KERN_CONT as a "quoting safety" thing. And in 99% of all cases it is obviously not actually needed. So in general, KERN_CONT is useless and should not be used, but that doesn't mean that it can be removed as a _concept_.

Linus

Btw, KERN_DEFAULT is the exact same thing for the "I start a new line, but I don't really have a special priority level".

And it's *way* overused. At one point we used to have the policy that all new printk()'s should have a priority level, presumably so that we at some point could have just made it a real argument instead (ie 'printk(prio, "fmt", arg)').

However, that turned out to be just stupid (the same way encouraging people to always use KERN_CONT was/is stupid). It turns out that a lot of printk's really don't have a good priority level, there's no reason to force them to use KERN_DEFAULT, and it doesn't actually add *any* value what-so-ever.

But again, it can be useful for the special case where you start a new printk() with a string that could be mistaken for the priority marker. So exactly like KERN_CONT, KERN_DEFAULT can be used for "quoting" purposes.

Of course, if you print out random strings with odd random crap in the first few characters, you're probably doing something really really wrong. So 99% of the time, you should never need KERN_DEFAULT or KERN_CONT. They exist for the rare exceptional case, and they do *need* to exist, but they should not generally need to be *used*.

So it's like a defibrillator: it is good to *have* one, but it's really bad to have to *use* one.

Linus

/me nominates this for LWN quote of the week!

Thanks for bringing sanity into printk,

Ingo

I rather teach the people with known heart problems to only slap their shocks at people who wear a sign that they are prepared to get treated, instead of just letting them "help" the healthy random next guy. :)

Sounds like the view of sanity of the guys with heart problems, not so much of the healthy guys. :)

In other words:
Isolation of risk-takers from non-risk-takers is usually a good thing.

Explicit annotation of exceptions almost every time beats expressions which need heuristics to construct the context.

We use typed pointer instead of void too, even when we don't need it most of the time. :)

Kay

Just to check all the options we have, and I have no good idea how they would work out. It's just an idea, without giving much thought about possible side effects:

Can we somehow store the PID of the printk() thread that has left the un-terminated line behind in the buffer, and flush it out when the next printk() is from a differnt PID? That could prevent the mangling of "atomic" printk()s by continuation users, and merging unrelated continuation users together.

Would it make sense to make the printk line buffer per CPU, so they are not shared between threads, and continuation could work more reliable?

Kay

How about this? It relaxes the need for KERN_CONT, but it limits continuation lines to repeated calls of the same thread.

If things race against each other, the lines are separated and not wrongly mixed with the data from other users.

I would be happy with that, as it protects the "atomic" users of printk() from getting mixed up with continuation users.

Thanks,
Kay

From: Kay Sievers <[email protected]>
Subject: printk() - do not merge continuation lines of different threads

---

 kernel/printk.c |   18 ++++++++++--------
 1 file changed, 10 insertions(+), 8 deletions(-)

@@ -1230,12 +1230,13 @@ asmlinkage int vprintk_emit(int facility
 	static size_t buflen;
 	static int buflevel;
 	static char textbuf[LOG_LINE_MAX];
+	static struct task_struct *cont;
 	char *text = textbuf;
 	size_t textlen;
 	unsigned long flags;
 	int this_cpu;
 	bool newline = false;
-	bool cont = false;
+	bool prefix = false;
 	int printed_len = 0;
 
 	boot_delay_msec();

@@ -1295,20 +1296,17 @@ asmlinkage int vprintk_emit(int facility
 		case '0' ... '7':
 			if (level == -1)
 				level = text[1] - '0';
-			text += 3;
-			textlen -= 3;
-			break;
 		case 'c':	/* KERN_CONT */
-			cont = true;
 		case 'd':	/* KERN_DEFAULT */
+			if (text[1] != 'c')
+				prefix = true;
 			text += 3;
 			textlen -= 3;
-			break;
 		}
 	}
 
-	if (buflen && (!cont || dict)) {
-		/* no continuation; flush existing buffer */
+	if (buflen && (prefix || dict || cont != current)) {
+		/* flush existing buffer */
 		log_store(facility, buflevel, NULL, 0, buf, buflen);
 		printed_len += buflen;
 		buflen = 0;

@@ -1342,6 +1340,10 @@ asmlinkage int vprintk_emit(int facility
 				  dict, dictlen, text, textlen);
 			printed_len += textlen;
 		}
+		cont = NULL;
+	} else {
+		/* remember thread which filled the buffer */
+		cont = current;
 	}
 
 	/*

Fair enough, looks reasonable.

Except your case-statement sucks. Having a "case 'c':" that basically then immediately has an "if (it was not 'c')" is just disturbing. Just move the code that is common to all the cases outside the case statement entirely, and make the 'c' case not do anything at all, and remove that crazy extraneous if-statement.

Linus

From: Kay Sievers <[email protected]>
Subject: printk() - do not merge continuation lines of different threads

This prevents the merging of printk() continuation lines of different threads, in the case they race against each other.

It should properly isolate "atomic" single-line printk() users from continuation users, to make sure the single-line users will never be merged with the racy continuation ones.

---

 kernel/printk.c |   19 ++++++++++---------
 1 file changed, 10 insertions(+), 9 deletions(-)

@@ -1230,12 +1230,13 @@ asmlinkage int vprintk_emit(int facility
 	static size_t buflen;
 	static int buflevel;
 	static char textbuf[LOG_LINE_MAX];
+	static struct task_struct *cont;
 	char *text = textbuf;
 	size_t textlen;
 	unsigned long flags;
 	int this_cpu;
 	bool newline = false;
-	bool cont = false;
+	bool prefix = false;
 	int printed_len = 0;
 
 	boot_delay_msec();

@@ -1295,20 +1296,16 @@ asmlinkage int vprintk_emit(int facility
 		case '0' ... '7':
 			if (level == -1)
 				level = text[1] - '0';
-			text += 3;
-			textlen -= 3;
-			break;
-		case 'c':	/* KERN_CONT */
-			cont = true;
 		case 'd':	/* KERN_DEFAULT */
+			prefix = true;
+		case 'c':	/* KERN_CONT */
 			text += 3;
 			textlen -= 3;
-			break;
 		}
 	}
 
-	if (buflen && (!cont || dict)) {
-		/* no continuation; flush existing buffer */
+	if (buflen && (prefix || dict || cont != current)) {
+		/* flush existing buffer */
 		log_store(facility, buflevel, NULL, 0, buf, buflen);
 		printed_len += buflen;
 		buflen = 0;

@@ -1342,6 +1339,10 @@ asmlinkage int vprintk_emit(int facility
 				  dict, dictlen, text, textlen);
 			printed_len += textlen;
 		}
+		cont = NULL;
+	} else {
+		/* remember thread which filled the buffer */
+		cont = current;
 	}
 
 	/*

[]

Here is something which might make sense, and could become be the most reliable and fail-tolerant version so far. It is also the least restrictive one regarding the input format, and takes the same amount of resources as the current implementation.

We fully isolate continuation users from non-continuation users. If a continuation user gets interrupted by a an ordinary non-continuation user, we will no longer touch the buffer of the continuation user, we just emit the ordinary message.

When the same thread comes back and continues printing, we still append to the earlier buffer we stored.

The only case where printk() still gets messed up now, is when multiple threads use continuation at the same time, which is way less likely than mixing with ordinary users.

We will also never merge two racing continuation users into one line; the worst thing that can happen now, is that they end split up into more than the intended single line.

Note: In this version, the KERN_* prefixes have all no further meaning anymore, besides that they carry the priority, or prevent they the content of the line to be parsed for a priority.

All the special rules are gone. KERN_CONT is the same as KERN_DEFAULT now.

Even continuation users could use prefixes now, if they wanted to. We should be context-aware enough now, with remembering the owner (task) of the buffered data, that we might be able to relax all the special rules regarding the prefixes.

Any ideas about that?

Thanks,
Kay

From: Kay Sievers <[email protected]>
Subject: printk() - fully separate continuation line users from ordinary ones
---

 printk.c |   86 ++++++++++++++++++++++++++++++---------------------------------
 1 file changed, 41 insertions(+), 45 deletions(-)

@@ -1232,17 +1232,16 @@ asmlinkage int vprintk_emit(int facility, int level,
 			    const char *fmt, va_list args)
 {
 	static int recursion_bug;
-	static char buf[LOG_LINE_MAX];
-	static size_t buflen;
-	static int buflevel;
+	static char cont_buf[LOG_LINE_MAX];
+	static size_t cont_len;
+	static int cont_level;
+	static struct task_struct *cont_task;
 	static char textbuf[LOG_LINE_MAX];
-	static struct task_struct *cont;
 	char *text = textbuf;
-	size_t textlen;
+	size_t text_len;
 	unsigned long flags;
 	int this_cpu;
 	bool newline = false;
-	bool prefix = false;
 	int printed_len = 0;
 
 	boot_delay_msec();

@@ -1288,11 +1287,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
 	 */
-	textlen = vscnprintf(text, sizeof(textbuf), fmt, args);
+	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
-	if (textlen && text[textlen-1] == '\n') {
-		textlen--;
+	if (text_len && text[text_len-1] == '\n') {
+		text_len--;
 		newline = true;
 	}
 

@@ -1303,52 +1302,49 @@ asmlinkage int vprintk_emit(int facility, int level,
 			if (level == -1)
 				level = text[1] - '0';
 		case 'd':	/* KERN_DEFAULT */
-			prefix = true;
 		case 'c':	/* KERN_CONT */
 			text += 3;
-			textlen -= 3;
+			text_len -= 3;
 		}
 	}
 
-	if (buflen && (prefix || dict || cont != current)) {
-		/* flush existing buffer */
-		log_store(facility, buflevel, NULL, 0, buf, buflen);
-		printed_len += buflen;
-		buflen = 0;
-	}
+	if (level == -1)
+		level = default_message_loglevel;
 
-	if (buflen == 0) {
-		/* remember level for first message in the buffer */
-		if (level == -1)
-			buflevel = default_message_loglevel;
-		else
-			buflevel = level;
-	}
+	if (!newline) {
+		if (cont_len && cont_task != current) {
+			/* flush earlier buffer from different thread */
+			log_store(facility, cont_level, NULL, 0, cont_buf, cont_len);
+			cont_len = 0;
+		}
 
-	if (buflen || !newline) {
-		/* append to existing buffer, or buffer until next message */
-		if (buflen + textlen > sizeof(buf))
-			textlen = sizeof(buf) - buflen;
-		memcpy(buf + buflen, text, textlen);
-		buflen += textlen;
-	}
+		if (!cont_len) {
+			cont_level = level;
+			cont_task = current;
+		}
 
-	if (newline) {
-		/* end of line; flush buffer */
-		if (buflen) {
-			log_store(facility, buflevel,
-				  dict, dictlen, buf, buflen);
-			printed_len += buflen;
-			buflen = 0;
+		/* buffer, or append to earlier buffer from same thread */
+		if (cont_len + text_len > sizeof(cont_buf))
+			text_len = sizeof(cont_buf) - cont_len;
+		memcpy(cont_buf + cont_len, text, text_len);
+		cont_len += text_len;
+	} else {
+		if (cont_len && cont_task == current) {
+			/* append to earlier buffer and flush */
+			if (cont_len + text_len > sizeof(cont_buf))
+				text_len = sizeof(cont_buf) - cont_len;
+			memcpy(cont_buf + cont_len, text, text_len);
+			cont_len += text_len;
+			log_store(facility, cont_level,
+				  NULL, 0, cont_buf, cont_len);
+			cont_len = 0;
+			cont_task = NULL;
+			printed_len = cont_len;
 		} else {
-			log_store(facility, buflevel,
-				  dict, dictlen, text, textlen);
-			printed_len += textlen;
+			log_store(facility, level,
+				  dict, dictlen, text, text_len);
+			printed_len = text_len;
 		}
-		cont = NULL;
-	} else {
-		/* remember thread which filled the buffer */
-		cont = current;
 	}
 
 	/*

That's wrong.

Key, KERN_CONT and KERN_DEFAULT really are different and have fundamentally different semantics. The fact that you think they aren't shows that you don't understand it.

Your "current" check doesn't change anything.

There are two main and important differences:

- people can avoid using '\n' if they know the next printk will have
a KERN_xxx marker (xxx != CONT).

This is often useful for having loops that print out individual
entries all on the same line - print all of them without the '\n'.

The printk afterwards will automatically start a new line if it has
KERN_DEFAULT.

If you make KERN_CONT and KERN_DEFAULT the same, it is a BUG. Don't do it.

- You don't seem to realize that interrupts are threaded events too,
but they will happen with the same task-struct.

An interrupt that prints out with KERN_DEFAULT had better not act
the same way as KERN_CONT.

So dammit, just stop trying to get rid of KERN_CONT or KERN_DEFAULT. They are both real, and they are both *different*. If you think they are the same, you are WRONG.

Don't try to change the rules because you think you are "clever". You're only making things worse.

Linus

Though it is a pain when people do this and the output from each iteration of the loop gets interleaved with other printk() output. Perhaps it is OK to do multiple printk() calls in initialization code where it kernel is mostly single
threaded. But it should be avoided in "oh dear, something bad happened" bits of code (in case the badness isn't localized and all the other cpus are spitting out partial messages too).

-Tony

Good point, understood, and adapted to the new logic.

Here is a new RFC version. I think it's slightly better than the currently implemented logic in Greg's tree:

We fully isolate continuation users from non-continuation users. If a continuation user gets interrupted by an ordinary non-continuation user, we will not touch the continuation buffer, we just emit the ordinary message. When the same thread comes back and continues its printing, we still append to the earlier buffer we stored.

The only case where printk() still gets messed up now, is when multiple threads (or interrupts) race against each other.

We will also never wrongly merge two racing continuation users into one line.

Current intended behavior, and general rules:
printk() starting with KERN_* (not KERN_CONT) and ending with '\n' will *always* logged as single line, *never* be merged with anything else.

printk() not starting with any KERN_* might get merged with an earlier line buffered by the *same* thread.

printk() not ending with '\n' will be buffered.

Buffered lines will be flushed when a different thread emits a printk() that needs to be buffered --> race.

Buffered line will be flushed, when the same thread emits a printk() with a KERN_* (not KERN_CONT) --> newline missing.

Buffered line will be joined, when the same thread emits a printk() without any KERN_* or with KERN_CONT.

Does that sounds correct? Anything to add or adjust?

Thanks,
Kay

---

  printk.c |   97 +++++++++++++++++++++++++++++++++++----------------------------
  1 file changed, 54 insertions(+), 43 deletions(-)

@@ -1232,13 +1232,13 @@ asmlinkage int vprintk_emit(int facility, int level,
 			    const char *fmt, va_list args)
 {
 	static int recursion_bug;
-	static char buf[LOG_LINE_MAX];
-	static size_t buflen;
-	static int buflevel;
+	static char cont_buf[LOG_LINE_MAX];
+	static size_t cont_len;
+	static int cont_level;
+	static struct task_struct *cont_task;
 	static char textbuf[LOG_LINE_MAX];
-	static struct task_struct *cont;
 	char *text = textbuf;
-	size_t textlen;
+	size_t text_len;
 	unsigned long flags;
 	int this_cpu;
 	bool newline = false;

@@ -1288,11 +1288,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
 	 */
-	textlen = vscnprintf(text, sizeof(textbuf), fmt, args);
+	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
-	if (textlen && text[textlen-1] == '\n') {
-		textlen--;
+	if (text_len && text[text_len-1] == '\n') {
+		text_len--;
 		newline = true;
 	}
 

@@ -1306,49 +1306,60 @@ asmlinkage int vprintk_emit(int facility, int level,
 			prefix = true;
 		case 'c':	/* KERN_CONT */
 			text += 3;
-			textlen -= 3;
+			text_len -= 3;
 		}
 	}
 
-	if (buflen && (prefix || dict || cont != current)) {
-		/* flush existing buffer */
-		log_store(facility, buflevel, NULL, 0, buf, buflen);
-		printed_len += buflen;
-		buflen = 0;
-	}
+	if (level == -1)
+		level = default_message_loglevel;
 
-	if (buflen == 0) {
-		/* remember level for first message in the buffer */
-		if (level == -1)
-			buflevel = default_message_loglevel;
-		else
-			buflevel = level;
-	}
+	if (!newline) {
+		if (cont_len && (prefix || cont_task != current)) {
+			/*
+			 * Flush earlier buffer, either from a different
+			 * thread, or when we've seen a new prefix.
+			 */
+			log_store(facility, cont_level, NULL, 0, cont_buf, cont_len);
+			cont_len = 0;
+		}
 
-	if (buflen || !newline) {
-		/* append to existing buffer, or buffer until next message */
-		if (buflen + textlen > sizeof(buf))
-			textlen = sizeof(buf) - buflen;
-		memcpy(buf + buflen, text, textlen);
-		buflen += textlen;
-	}
+		if (!cont_len) {
+			cont_level = level;
+			cont_task = current;
+		}
+
+		/* buffer/append to earlier buffer from same thread */
+		if (cont_len + text_len > sizeof(cont_buf))
+			text_len = sizeof(cont_buf) - cont_len;
+		memcpy(cont_buf + cont_len, text, text_len);
+		cont_len += text_len;
+	} else {
+		if (cont_len && cont_task == current) {
+			if (prefix) {
+				/*
+				 * New prefix in same thread; flush. Either
+				 * no earlier newline, or in an interrupt.
+				 */
+				log_store(facility, cont_level,
+					  NULL, 0, cont_buf, cont_len);
+				cont_len = 0;
+			}
 
-	if (newline) {
-		/* end of line; flush buffer */
-		if (buflen) {
-			log_store(facility, buflevel,
-				  dict, dictlen, buf, buflen);
-			printed_len += buflen;
-			buflen = 0;
+			/* append to earlier buffer and flush */
+			if (cont_len + text_len > sizeof(cont_buf))
+				text_len = sizeof(cont_buf) - cont_len;
+			memcpy(cont_buf + cont_len, text, text_len);
+			cont_len += text_len;
+			log_store(facility, cont_level,
+				  NULL, 0, cont_buf, cont_len);
+			cont_len = 0;
+			cont_task = NULL;
+			printed_len = cont_len;
 		} else {
-			log_store(facility, buflevel,
-				  dict, dictlen, text, textlen);
-			printed_len += textlen;
+			log_store(facility, level,
+				  dict, dictlen, text, text_len);
+			printed_len = text_len;
 		}
-		cont = NULL;
-	} else {
-		/* remember thread which filled the buffer */
-		cont = current;
 	}
 
 	/*

It's not necessarily a matter of "thread comes back", although that situation can happen too. You can get this situation quite simply if you have two processes in foreground kernel mode on two different CPU's sending continuation printk's at the same time.

I'm not sure how you guarantee this? The only way you *could* guarantee this is if you used a continuation buffer in the task_struct for foreground kernel code, and a per-CPU continuation buffer for interrupt code.

Is there any difference in any of the cases in terms of how printk's that are prefixed with KERN_CONT versus a printk that does not have any KERN_* prefix? If so, is there value in keeping KERN_CONT?

- Ted

As far as I know, no.

It is a useful marker to show where prints
are actually continued.

#define KERN_CONT ""

would save a small amount of text.

Nah, we can't do that. We need it to tell "here is your non-prefix to parse, leave the data behind alone".

Kay

That's where I think you're still a bit uncertain how the _current_ printk system works. Your _new_ printk system should have identical behavior. Though if you manage to use the call tree and current to coalesce complete messages more correctly, that'd be great.

No, you are. Read my answer from two days ago in this thread.

KERN_CONT is *not* the same as "". Not now, not ever. If you make it the same, you're broken.

The reason is simple: KERN_CONT "<3>" should print out the string "<3>". If you make KERN_CONT be "", it will do the wrong thing, and think that the <3> is a priority marker.

Please people, this is subtle, and current code does things RIGHT. Any code that changes it to do something else is almost certainly buggy. The new semantics had better be the same as the old one.

The change to verify that 'current' matches the previous printout is so far the *only* sane semantic change I've seen in this thread. Everything else has been pure garbage.

Linus

I think it's a distinction without a difference for, as fas as I know, that's a case that doesn't exist in the current kernel.

$ grep -rP --include=*.[ch] "\bpr_cont\s*\(\s*\"<" *
$ grep -rP --include=*.[ch] "\bprintk\s*\(\s*KERN_CONT\s*\"<" *
arch/x86/kernel/dumpstack_32.c:				printk(KERN_CONT "<%02x> ", c);
arch/x86/kernel/dumpstack_64.c:				printk(KERN_CONT "<%02x> ", c);
arch/powerpc/kernel/process.c:				printk(KERN_CONT "<%08x> ", instr);
drivers/media/video/tm6000/tm6000-core.c:			printk(KERN_CONT "<<< ");
drivers/media/video/cx231xx/cx231xx-core.c:			printk(KERN_CONT "<<<");

It surely does, and we needed to add KERN_CONT in the past because stuff got eaten by the prefix parser.
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commit;h=40c8cefaaf12734327db7199a56e60058d98e7b6
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commit;h=13f541c10b30fc6529200d7f9a0073217709622f

Kay

So? Even if we hadn't had this bug before (we have), your argument is utter crap. Even if we weren't to have that patter right *now*, that doesn't mean that it cannot happen.

Your grep is also not at all exhaustive. What if somebody does

printk("%s.."

how are you going to prove that '%s' doesn't contain a level marker thing? It's much easier to just say "use a KERN_CONT" (or more commonly KERN_DEFAULT) to avoid the problem.

We do need an escape model. The current KERN_CONT does that. Stop arguing for crap.

Linus

True. I've fixed the ones you've introduced when you changed printk semantics in the past.

What happened to the pragmatic Linus Torvalds? Did the dogmatic one replace him again temporarily?

Not what I said.

I believe I know the printk subsystem and its uses as well as anyone. I don't think there is a case today.

Or an agreement to not to emit "<[0-7cd]>"
as the first 3 bytes after a newline or as the start of a new printk. It could just
as easily be an escape is a required leading non "<" character.

I think that's not onerous.

Correctness in all cases can be a good thing. Simplicity may be better because complexity is reduced.

cheers, Joe

Ok, let's continue with sane things then. :)

Here is a stupid kernel module which creates 3 racy printk() loops, 2 of them do continuation, one does an atomic print. The continuation one prints one char per printk.
http://people.freedesktop.org/~kay/printk-race/printk-race.c

The lines all try to look like:
(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA) (CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC) (XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX)

Every loop has it's own uppercase character. The line enclosed in '()'. 'A' is the atomic one, the cont ones are 'C' and 'X'.

Our current kernel look like:

[   99.056806] XC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   99.059772] XC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   99.062168] XCCX(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   99.066479] CXXC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   99.070063] XC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   99.073081] XCCXCXCXCXCXCXCXCXCXCXCXCXCXCXCCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXC)
[   99.148325] (CCXCXCX)
[   99.155468] (XXCXCXCXCCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXCXXCXCXCXCXCXCXCXCXC)
[   99.277357] (CCXCXCXCX)
  http://people.freedesktop.org/~kay/printk-race/printk-out-before.txt

The kernel with the record buffer, and the 'current' who owns the cont buffer looks like:

[   78.080866] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   78.082790] (CC
[   78.084152] (XX
[   78.084497] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   78.085494] C
[   78.086125] X
[   78.087188] C
[   78.088669] X
[   78.089803] C
[   78.091510] X
[   78.091924] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   78.094112] CC
[   78.096171] X
  http://people.freedesktop.org/~kay/printk-race/printk-out-after.txt

Thanks,
Kay

Having only one continuation user racing against an atomic printk user looks like this:

Current kernel:

[   54.062900] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.068200] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.071698] (CC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.074103] C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.076052] C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.078116] C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.080096] C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.082060] CC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   54.086121] C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  http://people.freedesktop.org/~kay/printk-race/printk-out-before-2.txt

Record buffer, with cont buffer owner:

[   33.431129] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.435112] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.439131] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.441820] (CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC)
[   33.445292] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.450131] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.453127] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.456084] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.459143] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.462161] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   33.465165] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  http://people.freedesktop.org/~kay/printk-race/printk-out-after-2.txt

Kay

This seems to work significantly better for me than all earlier versions. The single line users like dev_printk() should be reliable now.

Thanks,
Kay

From: Kay Sievers <[email protected]>
Subject: printk() - isolate KERN_CONT users from ordinary complete lines

Arrange the continuation printk() buffering to be fully separated from the ordinary full line users.

Limit the exposure to races and wrong printk() line merges to users of continuation only. Ordinary full line users racing against continuation users will no longer affect each other.

Multiple continuation users from different threads, racing against each other will not wrongly be merged into a single line, but printed as separate lines.

Test output of a kernel module which starts two separate threads which race against each other, one of them printing a single full terminated line:
printk("(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)\n");

The other one printing the line, every character separate in a continuation loop:
printk("(C");
for (i = 0; i < 58; i++)

          printk(KERN_CONT "C");

printk(KERN_CONT "C)\n");

Behavior of single and non-thread-aware printk() buffer:

  # modprobe printk-race
  printk test init
  (CC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  CC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  CC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  CC(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  C(AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC)
  (CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC)

New behavior with separate and thread-aware continuation buffer:

  # modprobe printk-race
  printk test init
  (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  (CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC)
  (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
  (CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC)
  (CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC)

---

 kernel/printk.c |  113 ++++++++++++++++++++++++++++++++------------------------
 1 file changed, 65 insertions(+), 48 deletions(-)

@@ -1264,13 +1264,13 @@ asmlinkage int vprintk_emit(int facility
 			    const char *fmt, va_list args)
 {
 	static int recursion_bug;
-	static char buf[LOG_LINE_MAX];
-	static size_t buflen;
-	static int buflevel;
+	static char cont_buf[LOG_LINE_MAX];
+	static size_t cont_len;
+	static int cont_level;
+	static struct task_struct *cont_task;
 	static char textbuf[LOG_LINE_MAX];
-	static struct task_struct *cont;
 	char *text = textbuf;
-	size_t textlen;
+	size_t text_len;
 	unsigned long flags;
 	int this_cpu;
 	bool newline = false;

@@ -1320,15 +1320,15 @@ asmlinkage int vprintk_emit(int facility
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
 	 */
-	textlen = vscnprintf(text, sizeof(textbuf), fmt, args);
+	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
-	if (textlen && text[textlen-1] == '\n') {
-		textlen--;
+	if (text_len && text[text_len-1] == '\n') {
+		text_len--;
 		newline = true;
 	}
 
-	/* strip syslog prefix and extract log level or flags */
+	/* strip syslog prefix and extract log level or control flags */
 	if (text[0] == '<' && text[1] && text[2] == '>') {
 		switch (text[1]) {
 		case '0' ... '7':

@@ -1338,49 +1338,67 @@ asmlinkage int vprintk_emit(int facility
 			prefix = true;
 		case 'c':	/* KERN_CONT */
 			text += 3;
-			textlen -= 3;
+			text_len -= 3;
 		}
 	}
 
-	if (buflen && (prefix || dict || cont != current)) {
-		/* flush existing buffer */
-		log_store(facility, buflevel, NULL, 0, buf, buflen);
-		printed_len += buflen;
-		buflen = 0;
-	}
-
-	if (buflen == 0) {
-		/* remember level for first message in the buffer */
-		if (level == -1)
-			buflevel = default_message_loglevel;
-		else
-			buflevel = level;
-	}
-
-	if (buflen || !newline) {
-		/* append to existing buffer, or buffer until next message */
-		if (buflen + textlen > sizeof(buf))
-			textlen = sizeof(buf) - buflen;
-		memcpy(buf + buflen, text, textlen);
-		buflen += textlen;
-	}
-
-	if (newline) {
-		/* end of line; flush buffer */
-		if (buflen) {
-			log_store(facility, buflevel,
-				  dict, dictlen, buf, buflen);
-			printed_len += buflen;
-			buflen = 0;
-		} else {
-			log_store(facility, buflevel,
-				  dict, dictlen, text, textlen);
-			printed_len += textlen;
+	if (level == -1)
+		level = default_message_loglevel;
+
+	if (dict) {
+		prefix = true;
+		newline = true;
+	}
+
+	if (!newline) {
+		if (cont_len && (prefix || cont_task != current)) {
+			/*
+			 * Flush earlier buffer, which is either from a
+			 * different thread, or when we got a new prefix.
+			 */
+			log_store(facility, cont_level, NULL, 0, cont_buf, cont_len);
+			cont_len = 0;
 		}
-		cont = NULL;
+
+		if (!cont_len) {
+			cont_level = level;
+			cont_task = current;
+		}
+
+		/* buffer or append to earlier buffer from the same thread */
+		if (cont_len + text_len > sizeof(cont_buf))
+			text_len = sizeof(cont_buf) - cont_len;
+		memcpy(cont_buf + cont_len, text, text_len);
+		cont_len += text_len;
 	} else {
-		/* remember thread which filled the buffer */
-		cont = current;
+		if (cont_len && cont_task == current) {
+			if (prefix) {
+				/*
+				 * New prefix from the same thread; flush. We
+				 * either got no earlier newline, or we race
+				 * with an interrupt.
+				 */
+				log_store(facility, cont_level,
+					  NULL, 0, cont_buf, cont_len);
+				cont_len = 0;
+			}
+
+			/* append to the earlier buffer and flush */
+			if (cont_len + text_len > sizeof(cont_buf))
+				text_len = sizeof(cont_buf) - cont_len;
+			memcpy(cont_buf + cont_len, text, text_len);
+			cont_len += text_len;
+			log_store(facility, cont_level,
+				  NULL, 0, cont_buf, cont_len);
+			cont_len = 0;
+			cont_task = NULL;
+			printed_len = cont_len;
+		} else {
+			/* ordinary single and terminated line */
+			log_store(facility, level,
+				  dict, dictlen, text, text_len);
+			printed_len = text_len;
+		}
 	}
 
 	/*

@@ -1470,7 +1488,6 @@ EXPORT_SYMBOL(printk);
 #define LOG_LINE_MAX 0
 static struct log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
-static char *log_text(const struct log *msg) { return NULL; }
 static void call_console_drivers(int level, const char *text, size_t len) {}
 static size_t msg_print_text(const struct log *msg, bool syslog,
 			     char *buf, size_t size) { return 0; }

We must be at least as good as we are, sure.

But the aim is to be *better* not to be *identical*, especially when things go wrong, and they do go wrong far too often in the current code. What we have today is really not good enough. We have a lot of context during logging (like the thread), and we should use it to make the best out of it _before_ we log the stuff away.

That's what we try. We just need to get all the details out of the peoples heads, which are nowhere written down, to make it happen. It's a bit of a painful process sometimes. :)

The conversion from the "put all bytes in a bag and let's find out later what happened"-buffer to a real separated record buffer imposed some changes to the logic, and we need to restore/adapt some useful rules now, which could't be preserved 1:1. But I'm confident that we manage to get a better overall picture in the end.

Kay

The access to printk is fully serialized. If only one thread does continuation (needs buffering), it will still own the continuation buffer. We record the "owner" (pointer to the task) of the data.

Yeah adding it to struct task would reliably work. :) But as we record the "owner" of the continuation buffer, we should be able to flush the content of the earlier buffer, instead of wrongly merging it. The same struct task and interrupts could go wrong, that's true.

Yeah, it is. It will instruct to merge with the buffer, but also tell not the parse the prefix, in case you want to log stuff like "<7>" as real data and not as a prefix.

Kay

The idea was: Prefixes are not used that often, but not using a prefix should not expose the user to wrongly get appended to an earlier non-terminated line of another thread.

The point was to limit the "risk" of wrong merges to users of continuation, and not to users which send ordinary "atomic" lines.

It significantly limits wrong merges, especially for users which can rightfully expect not to get a wrong merge.

It is a different behaviour. "Innocent" users are not exposed to "risky" users.

But a lot of stuff which does not look for continuation, has no prefix, hasn't it? I rather make the "I want to be appended" explicit, instead giving the "I don't care about the log level" any meaning.

I think continuation is special, and ideally should not be much used. We should not "optimize" for it, and not accept breakage introduced to ordinary users that way.

It's true, it's much easier, but it's also much less reliable.

I can do this, I just don't think it's the right thing to do.

I surely would prefer reliability over rather weird heuristics for special cases. Today, we should be able to trust at least non-continuation printk users, which we can't, if we do expose them to the very real problems of continuation.

Still not convinced? :)

Kay

I think your premise is wrong for a couple of reasons.

1: printk content is not guaranteed to be stable.

printk content should not be guaranteed to be stable. It'd make it difficult to simply add a new message or extend or correct an existing one.

2: There are _thousands_ of printks without prefix levels.

KERN_CONT was always kind of a half-stupid idea. It's only real purpose is to designate message continuations but it never gave enough information to correctly coalesce the messages.

I think you need to give up on the idea that printk output can be made to be machine readable.

If you really want to have users get complete and not-interleaved messages you need to buffer partial messages, Whether or not printk message coalescing needs to have a cookie or can be done well enough by using call tree information as suggested by Andrew Morton is tbd.

Changing printk semantics and trying to stabilize printk message content are bad ideas though.

I think printk_emit is an OK idea. Having a per-subsystem notification mechanism, something like an expanded ethtool is certainly useful.

Making the new additional content of printk_emit discoverable would be useful.

Converting log_buf from circular to record oriented and adding another binary header/descriptor to it is a good idea too.

cheers, Joe

Nobody talks about the content of the strings.

Again, that's only what you make out of it.

My point is reliable log _storage_ and with that properly working, the output _format_ gets as _reliable_ as possible. Continuation printk() today is entirely unreliable, not only for the continuation users, also for everybody else, because we merge randomly with atomic printk() users.

We have (stupid ) scripts that diff dmesg after supposed-to-be-harmless kernel changes to automatically spot problems. You can see all the broken merges of continuation lines, and they also affect lines which do simple and proper atomic printk()s. This is not useful, and again it's the broken _logic_ of storage not the _content_ of the message.

Right, and nobody is crazy enough to think we want to touch them all.

Right, it's the annotation of an exception; not nice, but pretty well-defined, and can be isolated from the non-exception by software instead of a human.

Nobody talks about that in this very context. It is all about better _reliability_ of the facility not about _content_.

The structured data, possibly attached to the log message, which uniquely identifies the kernel device, is surely meant to be machine readable, and no, I'm absolutely not giving up on that approach.

I'm convinced, that we need something simpler than a new cookie logic. It can work sure, but I doubt we really wants to change the code flow of all the stuff.

Again, nobody talks about content of here.

But reliable context-aware facilities are almost never a bad idea. We can certainly make printk() better without changing the whole source tree.

You might not oppose to the heuristics and the "throw it all in a bag an let's find out later" strategy, I certainly don't like it and think it's very broken.

It is all available through /dev/kmsg,

Kay

printk_time=1 does not work anymore with this patch on serial console.

but dmesg still have that time printout.

Yinghai

Known issue, I think Kay is working on the solution for this right now...

greg k-h

Sure, and this seems to work for me.

Thanks,
Kay

From: Kay Sievers <[email protected]>
Subject: printk() - restore timestamp printing at console output

The output of the timestamps got lost with the conversion of the kmsg buffer to records; restore the old behavior.

Document, that CONFIG_PRINTK_TIME now only controls the output of the timestamps in the syslog() system call and on the console, and not the recording of the timestamps.

---

 kernel/printk.c   |   43 ++++++++++++++++++++++++++-----------------
 lib/Kconfig.debug |   16 ++++++++++------
 2 files changed, 36 insertions(+), 23 deletions(-)

@@ -786,6 +786,22 @@ static bool printk_time;
 #endif
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
+static size_t prepend_timestamp(unsigned long long t, char *buf)
+{
+	unsigned long rem_ns;
+
+	if (!printk_time)
+		return 0;
+
+	if (!buf)
+		return 15;
+
+	rem_ns = do_div(t, 1000000000);
+
+	return sprintf(buf, "[%5lu.%06lu] ",
+		       (unsigned long) t, rem_ns / 1000);
+}
+
 static int syslog_print_line(u32 idx, char *text, size_t size)
 {
 	struct log *msg;

@@ -800,9 +816,7 @@ static int syslog_print_line(u32 idx, ch
 			len++;
 		if (msg->level > 99)
 			len++;
-
-		if (printk_time)
-			len += 15;
+		len += prepend_timestamp(0, NULL);
 
 		len += msg->text_len;
 		len++;

@@ -810,15 +824,7 @@ static int syslog_print_line(u32 idx, ch
 	}
 
 	len = sprintf(text, "<%u>", msg->level);
-
-	if (printk_time) {
-		unsigned long long t = msg->ts_nsec;
-		unsigned long rem_ns = do_div(t, 1000000000);
-
-		len += sprintf(text + len, "[%5lu.%06lu] ",
-				   (unsigned long) t, rem_ns / 1000);
-	}
-
+	len += prepend_timestamp(msg->ts_nsec, text + len);
 	if (len + msg->text_len > size)
 		return -EINVAL;
 	memcpy(text + len, log_text(msg), msg->text_len);

@@ -1741,7 +1747,7 @@ again:
 	for (;;) {
 		struct log *msg;
 		static char text[LOG_LINE_MAX];
-		size_t len;
+		size_t len, l;
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);

@@ -1761,10 +1767,13 @@ again:
 
 		msg = log_from_idx(console_idx);
 		level = msg->level & 7;
-		len = msg->text_len;
-		if (len+1 >= sizeof(text))
-			len = sizeof(text)-1;
-		memcpy(text, log_text(msg), len);
+
+		len = prepend_timestamp(msg->ts_nsec, text);
+		l = msg->text_len;
+		if (len + l + 1 >= sizeof(text))
+			l = sizeof(text) - len - 1;
+		memcpy(text + len, log_text(msg), l);
+		len += l;
 		text[len++] = '\n';
 
 		console_idx = log_next(console_idx);

@@ -3,12 +3,16 @@ config PRINTK_TIME
 	bool "Show timing information on printks"
 	depends on PRINTK
 	help
-	  Selecting this option causes timing information to be
-	  included in printk output.  This allows you to measure
-	  the interval between kernel operations, including bootup
-	  operations.  This is useful for identifying long delays
-	  in kernel startup.  Or add printk.time=1 at boot-time.
-	  See Documentation/kernel-parameters.txt
+	  Selecting this option causes time stamps of the printk()
+	  messages to be added to the output of the syslog() system
+	  call and at the console.
+
+	  The timestamp is always recorded internally, and exported
+	  to /dev/kmsg. This flag just specifies if the timestamp should
+	  be included, not that the timestamp is recorded.
+
+	  The behavior is also controlled by the kernel command line
+	  parameter printk.time=1. See Documentation/kernel-parameters.txt
 
 config DEFAULT_MESSAGE_LOGLEVEL
 	int "Default message log level (1-7)"

This has a small issue with the way timing is printed compared to how it worked previously.

Consider the following case:

printk("\n foo \n bar \n zoot")

Previously, you would see timing on each line of the print, but now you see it only on the first.

What code does this? Shouldn't those be individual printk lines? I didn't think that type of line would ever work properly in the past.

thanks,

greg k-h

At least the lockdep code, in several places:

        __print_lock_name(safe_class);
        printk(");\n");
        printk("\n *** DEADLOCK ***\n\n");

Which has looked fine before.

We've *always* supported multiple lines, Greg. And it has always worked. It's very inconvenient to have to use multiple printk's when one would do.

That said, I think it would be interesting if the timing values were just not printed at all when they match the last one, which would happen with this kind of setup (and also happens if your time source sucks).

You'd still want the lines to line up, though.

Linus

Should we just pad the multi-newline-in-one-record output with 15 spaces when printk_time is on?

Kay

Yeah, I think that would be the nicest thing.

Btw, I'd also *love* to see some model (eventually - not necessarily now) where we could have the option of the time printouts being a bit different (rather than just on/off). It would be very nice if we had "relative" time printouts for events close together, so the rule could be something like:

- if time is same as last line, pad with empty

- if time is more than a minute from last one, show an absolute value
of dd hh:mm:ss

- otherwise, show a relative value of +ss.mmmmmm

So the on/off choice could be on/off/relative.

Hmm?

Linus

Breaks the "grep for specific messages" case.

Why?

Sure, if you grep for times, you'd not want to enable the relative time. But why would you grep for a time anyway? Regardless, it would be your choice.

Generally, relative times are much more useful - the absolute time seldom is.

Linus

I'd be grepping for specific message content, not times. But I'd want to see the times for the messages, to know if they're related events or not.

Relative times are great, no problem there.
But relative to what? The previous message?

That's no good unless viewing all messages,
rather than a grep'd subset.

But with a choice, we do get the best of both, so no problemo.

Cheers

So I got something like this:

# sleep 61 ; echo foo > /dev/kmsg ; sleep 61 ; echo bar > /dev/kmsg ;
sleep 5 ; echo zoot > /dev/kmsg ; sleep 10 ; echo foo > /dev/kmsg ;
echo bar > /dev/kmsg ; sleep 61 ; echo zoot > /dev/kmsg ; echo foo >
/dev/kmsg

[  673.222632] foo
[  734.315249] bar
[   +5.077527] zoot
[  +10.235225] foo
[   +0.002971] bar
[  810.883085] zoot

[ +0.003081] foo

If that looks right, I can send a patch once this printf overhaul is stable, unless Kay already plans on doing it as part of his work.

So judging by my own use, I really think that

(a) the microseconds are *totally* useless for the absolute time. In
fact, they are worse than useless: they take up space and are actively distracting.

If the last message was over a minute ago, *nobody* cares about
the microsecond. The microseconds are useful when there are multiple messages and you see that "oh, those events happened within a couple of ms of each other", but for the absolute time they are just bad.

Even the *seconds* are probably not that interesting.

(b) The one thing I have often wanted is not "after how many seconds
of boot", but "when". So it would actually be nice if the absolute time was converted into local time. The kernel can actually do that, so I suspect that the best format for the relative timestamps would really be something like

because that would be really useful sometimes.

(And no, never mind the year. If you log those things long-term, the year will be in the full log, so logging the year in the dmesg is just pointless.)

I dunno. The above is what I would have liked to see quite often. I look at dmesg, and notice that I had an WARN_ON_ONCE in it, and I have no idea when it happened, because the "seconds since boot" is totally useless information for me, as I'm too lazy to try to use /proc/uptime to calculate what it is.

Linus

Yeah, that looks generally more useful.

"dmesg -T" tries to translate that to wall clock time too. At the moment, it can't really do that reliable at the point of reading the timestamps though, because the monotonic time used does not include the time spent in suspend.

One other problem with the current logic is that the timestamp we get at the moment is not guaranteed to monotonic, log lines from different CPUs at the same time can jump forth and back, so the relative-time calculation could, with the current code, show negative values.

Not sure what options we have to use a more better clock source, if things are expected to work in NMIs and IRQs.

Kay

Look in syslog ?

That usually requires root permission, so it's an extra (annoying) step. It also gives all kinds or other mostly irrelevant information for a kernel person.

Besides, according to the same argument, dmesg shouldn't have times *at*all*. So the "look in your syslog" is pointless for discussing the dmesg timestamp.

Linus

It's good for dates. Not as good for times.
I figure anyone trying to diagnose a kernel issue
already has access to /var/log/ as well. :)

But it's good as you propose with an option.

Cheers

Oddly enough, just yesterday I was looking in dmesg on one of my servers, trying to find a hint of why syslog and a number of other things had failed to start at boot...

I would like to give a +1 on absolute time, and -1 on local timezone and a -$LARGE_NUMBER on low resolution.

Why? Getting events accurately timed across multiple hosts can be really useful when trying to reconstruct, ahem, "network events".

Getting UTC time at some fairly high resolution is useful for that. I would say the useful resolution is probably milliseconds.

-hpa

I just sent out the fix to restore the original multi-line behaviour, I have nothing else queued in that area at the moment.

I'm busy making the prink() output look the same as it was before but without the wrong continuation merges. New features need to wait a little bit, so go ahead. :)

But I want to express, that I'm very interested in finding out if we could switch to a 'better' clock source as we have today, which can safely be translated to wall clock time not leaving the suspend time out, and not jumping forth and back in time between logs from different CPUs. I think that would be very useful for your patch too.

Kay

Does this fix it for you? It should fully restore the current behavior for multi-line printing.

Thanks,
Kay

From: Kay Sievers <[email protected]>
Subject: printk() - restore prefix/timestamp printing for multi-newline strings

Calls like:
printk("\n *** DEADLOCK ***\n\n");
will print 3 properly indented, separated, syslog + timestamp prefixed lines in the log output.

---

 printk.c |  127 +++++++++++++++++++++++++++++++++++++--------------------------
 1 file changed, 76 insertions(+), 51 deletions(-)

index c42faf9..ee312c7 100644
@@ -448,7 +448,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 
 	/* escape non-printable characters */
 	for (i = 0; i < msg->text_len; i++) {
-		char c = log_text(msg)[i];
+		unsigned char c = log_text(msg)[i];
 
 		if (c < ' ' || c >= 128)
 			len += sprintf(user->buf + len, "\\x%02x", c);

@@ -461,7 +461,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 		bool line = true;
 
 		for (i = 0; i < msg->dict_len; i++) {
-			char c = log_dict(msg)[i];
+			unsigned char c = log_dict(msg)[i];
 
 			if (line) {
 				user->buf[len++] = ' ';

@@ -785,56 +791,81 @@ static bool printk_time;
 #endif
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t prepend_timestamp(unsigned long long t, char *buf)
+static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
 {
-	unsigned long rem_ns;
+	size_t len = 0;
 
-	if (!printk_time)
-		return 0;
+	if (syslog) {
+		if (buf) {
+			len += sprintf(buf, "<%u>", msg->level);
+		} else {
+			len += 3;
+			if (msg->level > 9)
+				len++;
+			if (msg->level > 99)
+				len++;
+		}
+	}
 
-	if (!buf)
-		return 15;
+	if (printk_time) {
+		if (buf) {
+			unsigned long long ts = msg->ts_nsec;
+			unsigned long rem_nsec = do_div(ts, 1000000000);
 
-	rem_ns = do_div(t, 1000000000);
+			len += sprintf(buf + len, "[%5lu.%06lu] ",
+					 (unsigned long) ts, rem_nsec / 1000);
+		} else {
+			len += 15;
+		}
+	}
 
-	return sprintf(buf, "[%5lu.%06lu] ",
-		       (unsigned long) t, rem_ns / 1000);
+	return len;
 }
 
-static int syslog_print_line(u32 idx, char *text, size_t size)
+static size_t msg_print_text(const struct log *msg, bool syslog,
+			     char *buf, size_t size)
 {
-	struct log *msg;
-	size_t len;
+	const char *text = log_text(msg);
+	size_t text_size = msg->text_len;
+	size_t len = 0;
 
-	msg = log_from_idx(idx);
-	if (!text) {
-		/* calculate length only */
-		len = 3;
+	do {
+		const char *next = memchr(text, '\n', text_size);
+		size_t text_len;
 
-		if (msg->level > 9)
-			len++;
-		if (msg->level > 99)
-			len++;
-		len += prepend_timestamp(0, NULL);
+		if (next) {
+			text_len = next - text;
+			next++;
+			text_size -= next - text;
+		} else {
+			text_len = text_size;
+		}
 
-		len += msg->text_len;
-		len++;
-		return len;
-	}
+		if (buf) {
+			if (print_prefix(msg, syslog, NULL) +
+			    text_len + 1>= size - len)
+				break;
+
+			len += print_prefix(msg, syslog, buf + len);
+			memcpy(buf + len, text, text_len);
+			len += text_len;
+			buf[len++] = '\n';
+		} else {
+			/* SYSLOG_ACTION_* buffer size only calculation */
+			len += print_prefix(msg, syslog, NULL);
+			len += text_len + 1;
+		}
+
+		text = next;
+	} while (text);
 
-	len = sprintf(text, "<%u>", msg->level);
-	len += prepend_timestamp(msg->ts_nsec, text + len);
-	if (len + msg->text_len > size)
-		return -EINVAL;
-	memcpy(text + len, log_text(msg), msg->text_len);
-	len += msg->text_len;
-	text[len++] = '\n';
 	return len;
 }
 
 static int syslog_print(char __user *buf, int size)
 {
 	char *text;
+	struct log *msg;
 	int len;
 
 	text = kmalloc(LOG_LINE_MAX, GFP_KERNEL);

@@ -847,7 +878,8 @@ static int syslog_print(char __user *buf, int size)
 		syslog_seq = log_first_seq;
 		syslog_idx = log_first_idx;
 	}
-	len = syslog_print_line(syslog_idx, text, LOG_LINE_MAX);
+	msg = log_from_idx(syslog_idx);
+	len = msg_print_text(msg, true, text, LOG_LINE_MAX);
 	syslog_idx = log_next(syslog_idx);
 	syslog_seq++;
 	raw_spin_unlock_irq(&logbuf_lock);

@@ -887,14 +919,18 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		seq = clear_seq;
 		idx = clear_idx;
 		while (seq < log_next_seq) {
-			len += syslog_print_line(idx, NULL, 0);
+			struct log *msg = log_from_idx(idx);
+
+			len += msg_print_text(msg, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}
 		seq = clear_seq;
 		idx = clear_idx;
 		while (len > size && seq < log_next_seq) {
-			len -= syslog_print_line(idx, NULL, 0);
+			struct log *msg = log_from_idx(idx);
+
+			len -= msg_print_text(msg, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}

@@ -904,9 +940,10 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 
 		len = 0;
 		while (len >= 0 && seq < next_seq) {
+			struct log *msg = log_from_idx(idx);
 			int textlen;
 
-			textlen = syslog_print_line(idx, text, LOG_LINE_MAX);
+			textlen = msg_print_text(msg, true, text, LOG_LINE_MAX);
 			if (textlen < 0) {
 				len = textlen;
 				break;

@@ -1044,7 +1081,9 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 			seq = syslog_seq;
 			idx = syslog_idx;
 			while (seq < log_next_seq) {
-				error += syslog_print_line(idx, NULL, 0);
+				struct log *msg = log_from_idx(idx);
+
+				error += msg_print_text(msg, true, NULL, 0);
 				idx = log_next(idx);
 				seq++;
 			}

@@ -1439,10 +1478,8 @@ static struct log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
 static char *log_text(const struct log *msg) { return NULL; }
 static void call_console_drivers(int level, const char *text, size_t len) {}
-static size_t prepend_timestamp(unsigned long long t, char *buf)
-{
-	return 0;
-}
+static size_t msg_print_text(const struct log *msg, bool syslog,
+			     char *buf, size_t size) { return 0; }
 
 #endif /* CONFIG_PRINTK */
 

@@ -1750,7 +1787,7 @@ again:
 	for (;;) {
 		struct log *msg;
 		static char text[LOG_LINE_MAX];
-		size_t len, l;
+		size_t len;
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);

@@ -1771,13 +1808,7 @@ again:
 		msg = log_from_idx(console_idx);
 		level = msg->level & 7;
 
-		len = prepend_timestamp(msg->ts_nsec, text);
-		l = msg->text_len;
-		if (len + l + 1 >= sizeof(text))
-			l = sizeof(text) - len - 1;
-		memcpy(text + len, log_text(msg), l);
-		len += l;
-		text[len++] = '\n';
+		len = msg_print_text(msg, false, text, sizeof(text));
 
 		console_idx = log_next(console_idx);
 		console_seq++;

Hello Kay,

Bad news, this patch breaks all kmsg_dump users.

Per current printk.c:

* The 'struct log' buffer header must never be directly exported to
* userspace, it is a kernel-private implementation detail that might
* need to be changed in the future, when the requirements change.

But kmsg_dump users get the raw log, not text. Some users may even use strlen() on the buffers, e.g. ramoops module was using it just recently, before persistent_ram rework.

So, starting from this patch every kmsg_dump user is getting the binary stuff, which is barely usable, and breaks a longstanding user-visible ABIs (e.g. mtdoops, oops dumping into nvram on PowerPC, and ramoops of course).

I'm not sure how we can fix this without allocating a huge buffer (and thus wasting memory), or reworking the whole kmsg_dump concept and its users.

Ideas?

p.s. And, btw, during HW bring-up, when there's even no serial console usable, I somewhat liked to directly print log_buf memory from a JTAG debugger, and thus see the kernel logs. Now that'll look ugly. Heh. :-)

Anton Vorontsov
Email: [email protected]

These cases export their own format, it's just that the dump routines could copy the buffer in only two steps (beginning and end of the ring buffer), while in the future their code would need an update to copy it record for record now. The exported format in the dump does not necessarily need to change.

It should be possible to convert them pretty easily to do that, they operate on their own allocated buffers already. Some of them seem to mangle the line-buffer already, so they should be able to copy record-by-record either.

I think an iterator in the dumper code is nicer and simpler. It will even provide structured data to the dumper, if the dumper wants to make use of it in the future. The prefix mangling of the text in the nvram dumper could surely benefit from that.

The iterator would basically work similar to the printing of the whole buffer at a newly registered boot console, which was doing a similar logic as the dumper does.

Yeah, that probably does not look pretty anymore, but it still all works, right? Doesn't have he debugger a strings(1)-like output to print of a memory area?

Kay

Here is an untested patch, which should restore the old plain text export format of the kmsg buffer. I adds an iterator to the dumper routine, which can be used by the dumper to properly copy the data out of the kmsg record buffer. All current users are converted in the same patch.

Any feedback/help in testing/updating and getting this thing into a mergeable state would be greatly appreciated.

There are two versions of the iterator:
kmsg_dump_get_line() starts with the oldest records. With the next call, the iterator retrieves one line after the other. Useful for cases like printing to a console or any other stream device.

kmsg_dump_get_buffer() fills a buffer with as many of the youngest records as fit into it. With the next call, the iterator retrieves the next block of older messages. Useful to dump the entire buffer with one shot, or chunk the data into blocks and store them, with the youngest messages being the most important, retrieved first.

Unlike the old logic, there are no stale pointers handed out to the dumper, if case things get overwritten while a dump is in progress, lines are not truncated or overwritten.

Thanks,
Kay

---
 arch/powerpc/platforms/pseries/nvram.c     |   60 +---------
 arch/x86/platform/mrst/early_printk_mrst.c |   13 --
 drivers/mtd/mtdoops.c                      |   22 ---
 fs/pstore/platform.c                       |   34 ++---
 include/linux/kmsg_dump.h                  |   39 +++++-
 kernel/printk.c                            |  173 ++++++++++++++++++++++++-----
 6 files changed, 204 insertions(+), 137 deletions(-)

@@ -68,9 +68,7 @@ static const char *pseries_nvram_os_part
 };
 
 static void oops_to_nvram(struct kmsg_dumper *dumper,
-		enum kmsg_dump_reason reason,
-		const char *old_msgs, unsigned long old_len,
-		const char *new_msgs, unsigned long new_len);
+			  enum kmsg_dump_reason reason);
 
 static struct kmsg_dumper nvram_kmsg_dumper = {
 	.dump = oops_to_nvram

@@ -504,28 +502,6 @@ int __init pSeries_nvram_init(void)
 }
 
 /*
- * Try to capture the last capture_len bytes of the printk buffer.  Return
- * the amount actually captured.
- */
-static size_t capture_last_msgs(const char *old_msgs, size_t old_len,
-				const char *new_msgs, size_t new_len,
-				char *captured, size_t capture_len)
-{
-	if (new_len >= capture_len) {
-		memcpy(captured, new_msgs + (new_len - capture_len),
-								capture_len);
-		return capture_len;
-	} else {
-		/* Grab the end of old_msgs. */
-		size_t old_tail_len = min(old_len, capture_len - new_len);
-		memcpy(captured, old_msgs + (old_len - old_tail_len),
-								old_tail_len);
-		memcpy(captured + old_tail_len, new_msgs, new_len);
-		return old_tail_len + new_len;
-	}
-}
-
-/*
  * Are we using the ibm,rtas-log for oops/panic reports?  And if so,
  * would logging this oops/panic overwrite an RTAS event that rtas_errd
  * hasn't had a chance to read and process?  Return 1 if so, else 0.

@@ -541,27 +517,6 @@ static int clobbering_unread_rtas_event(
 						NVRAM_RTAS_READ_TIMEOUT);
 }
 
-/* Squeeze out each line's <n> severity prefix. */
-static size_t elide_severities(char *buf, size_t len)
-{
-	char *in, *out, *buf_end = buf + len;
-	/* Assume a <n> at the very beginning marks the start of a line. */
-	int newline = 1;
-
-	in = out = buf;
-	while (in < buf_end) {
-		if (newline && in+3 <= buf_end &&
-				*in == '<' && isdigit(in[1]) && in[2] == '>') {
-			in += 3;
-			newline = 0;
-		} else {
-			newline = (*in == '\n');
-			*out++ = *in++;
-		}
-	}
-	return out - buf;
-}
-
 /* Derived from logfs_compress() */
 static int nvram_compress(const void *in, void *out, size_t inlen,
 							size_t outlen)

@@ -619,9 +574,7 @@ static int zip_oops(size_t text_len)
  * partition.  If that's too much, go back and capture uncompressed text.
  */
 static void oops_to_nvram(struct kmsg_dumper *dumper,
-		enum kmsg_dump_reason reason,
-		const char *old_msgs, unsigned long old_len,
-		const char *new_msgs, unsigned long new_len)
+			  enum kmsg_dump_reason reason)
 {
 	static unsigned int oops_count = 0;
 	static bool panicking = false;

@@ -660,14 +613,13 @@ static void oops_to_nvram(struct kmsg_du
 		return;
 
 	if (big_oops_buf) {
-		text_len = capture_last_msgs(old_msgs, old_len,
-			new_msgs, new_len, big_oops_buf, big_oops_buf_sz);
-		text_len = elide_severities(big_oops_buf, text_len);
+		kmsg_dump_get_buffer(dumper, false,
+				     big_oops_buf, big_oops_buf_sz, &text_len);
 		rc = zip_oops(text_len);
 	}
 	if (rc != 0) {
-		text_len = capture_last_msgs(old_msgs, old_len,
-				new_msgs, new_len, oops_data, oops_data_sz);
+		kmsg_dump_get_buffer(dumper, true,
+				     oops_data, oops_data_sz, &text_len);
 		err_type = ERR_TYPE_KERNEL_PANIC;
 		*oops_len = (u16) text_len;
 	}

@@ -110,19 +110,16 @@ static struct kmsg_dumper dw_dumper;
 static int dumper_registered;
 
 static void dw_kmsg_dump(struct kmsg_dumper *dumper,
-			enum kmsg_dump_reason reason,
-			const char *s1, unsigned long l1,
-			const char *s2, unsigned long l2)
+			 enum kmsg_dump_reason reason)
 {
-	int i;
+	static char line[1024];
+	size_t len;
 
 	/* When run to this, we'd better re-init the HW */
 	mrst_early_console_init();
 
-	for (i = 0; i < l1; i++)
-		early_mrst_console.write(&early_mrst_console, s1 + i, 1);
-	for (i = 0; i < l2; i++)
-		early_mrst_console.write(&early_mrst_console, s2 + i, 1);
+	while (kmsg_dump_get_line(dumper, true, line, sizeof(line), &len))
+		early_mrst_console.write(&early_mrst_console, line, len);
 }
 
 /* Set the ratio rate to 115200, 8n1, IRQ disabled */

@@ -304,32 +304,17 @@ static void find_next_position(struct mt
 }
 
 static void mtdoops_do_dump(struct kmsg_dumper *dumper,
-		enum kmsg_dump_reason reason, const char *s1, unsigned long l1,
-		const char *s2, unsigned long l2)
+			    enum kmsg_dump_reason reason)
 {
 	struct mtdoops_context *cxt = container_of(dumper,
 			struct mtdoops_context, dump);
-	unsigned long s1_start, s2_start;
-	unsigned long l1_cpy, l2_cpy;
-	char *dst;
-
-	if (reason != KMSG_DUMP_OOPS &&
-	    reason != KMSG_DUMP_PANIC)
-		return;
 
 	/* Only dump oopses if dump_oops is set */
 	if (reason == KMSG_DUMP_OOPS && !dump_oops)
 		return;
 
-	dst = cxt->oops_buf + MTDOOPS_HEADER_SIZE; /* Skip the header */
-	l2_cpy = min(l2, record_size - MTDOOPS_HEADER_SIZE);
-	l1_cpy = min(l1, record_size - MTDOOPS_HEADER_SIZE - l2_cpy);
-
-	s2_start = l2 - l2_cpy;
-	s1_start = l1 - l1_cpy;
-
-	memcpy(dst, s1 + s1_start, l1_cpy);
-	memcpy(dst + l1_cpy, s2 + s2_start, l2_cpy);
+	kmsg_dump_get_buffer(dumper, true, cxt->oops_buf + MTDOOPS_HEADER_SIZE,
+			     record_size - MTDOOPS_HEADER_SIZE, NULL);
 
 	/* Panics must be written immediately */
 	if (reason != KMSG_DUMP_OOPS)

@@ -375,6 +360,7 @@ static void mtdoops_notify_add(struct mt
 		return;
 	}
 
+	cxt->dump.max_reason = KMSG_DUMP_OOPS;
 	cxt->dump.dump = mtdoops_do_dump;
 	err = kmsg_dump_register(&cxt->dump);
 	if (err) {

@@ -94,20 +94,15 @@ static const char *get_reason_str(enum k
  * as we can from the end of the buffer.
  */
 static void pstore_dump(struct kmsg_dumper *dumper,
-	    enum kmsg_dump_reason reason,
-	    const char *s1, unsigned long l1,
-	    const char *s2, unsigned long l2)
+			enum kmsg_dump_reason reason)
 {
-	unsigned long	s1_start, s2_start;
-	unsigned long	l1_cpy, l2_cpy;
-	unsigned long	size, total = 0;
-	char		*dst;
+	unsigned long	total = 0;
 	const char	*why;
 	u64		id;
-	int		hsize, ret;
 	unsigned int	part = 1;
 	unsigned long	flags = 0;
 	int		is_locked = 0;
+	int		ret;
 
 	why = get_reason_str(reason);
 

@@ -119,30 +114,25 @@ static void pstore_dump(struct kmsg_dump
 		spin_lock_irqsave(&psinfo->buf_lock, flags);
 	oopscount++;
 	while (total < kmsg_bytes) {
+		char *dst;
+		unsigned long size;
+		int hsize;
+		size_t len;
+
 		dst = psinfo->buf;
 		hsize = sprintf(dst, "%s#%d Part%d\n", why, oopscount, part);
 		size = psinfo->bufsize - hsize;
 		dst += hsize;
 
-		l2_cpy = min(l2, size);
-		l1_cpy = min(l1, size - l2_cpy);
-
-		if (l1_cpy + l2_cpy == 0)
+		if (!kmsg_dump_get_buffer(dumper, true, dst, size, &len))
 			break;
 
-		s2_start = l2 - l2_cpy;
-		s1_start = l1 - l1_cpy;
-
-		memcpy(dst, s1 + s1_start, l1_cpy);
-		memcpy(dst + l1_cpy, s2 + s2_start, l2_cpy);
-
 		ret = psinfo->write(PSTORE_TYPE_DMESG, reason, &id, part,
-				   hsize + l1_cpy + l2_cpy, psinfo);
+				    hsize + len, psinfo);
 		if (ret == 0 && reason == KMSG_DUMP_OOPS && pstore_is_mounted())
 			pstore_new_entry = 1;
-		l1 -= l1_cpy;
-		l2 -= l2_cpy;
-		total += l1_cpy + l2_cpy;
+
+		total += hsize + len;
 		part++;
 	}
 	if (in_nmi()) {

@@ -21,6 +21,7 @@
  * is passed to the kernel.
  */
 enum kmsg_dump_reason {
+	KMSG_DUMP_UNDEF,
 	KMSG_DUMP_PANIC,
 	KMSG_DUMP_OOPS,
 	KMSG_DUMP_EMERG,

@@ -31,23 +32,35 @@ enum kmsg_dump_reason {
 
 /**
  * struct kmsg_dumper - kernel crash message dumper structure
- * @dump:	The callback which gets called on crashes. The buffer is passed
- * 		as two sections, where s1 (length l1) contains the older
- * 		messages and s2 (length l2) contains the newer.
  * @list:	Entry in the dumper list (private)
+ * @dump:	Call into dumping code which will retrieve the data with
+ * 		through the record iterator
+ * @max_reason:	filter for highest reason number that should be dumped
  * @registered:	Flag that specifies if this is already registered
  */
 struct kmsg_dumper {
-	void (*dump)(struct kmsg_dumper *dumper, enum kmsg_dump_reason reason,
-			const char *s1, unsigned long l1,
-			const char *s2, unsigned long l2);
 	struct list_head list;
-	int registered;
+	void (*dump)(struct kmsg_dumper *dumper, enum kmsg_dump_reason reason);
+	enum kmsg_dump_reason max_reason;
+	bool active;
+	bool registered;
+
+	/* private state of the kmsg iterator */
+	u32 cur_idx;
+	u32 next_idx;
+	u64 cur_seq;
+	u64 next_seq;
 };
 
 #ifdef CONFIG_PRINTK
 void kmsg_dump(enum kmsg_dump_reason reason);
 
+bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
+			  char *line, size_t size, size_t *len);
+
+bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
+			  char *buf, size_t size, size_t *len);
+
 int kmsg_dump_register(struct kmsg_dumper *dumper);
 
 int kmsg_dump_unregister(struct kmsg_dumper *dumper);

@@ -56,6 +69,18 @@ static inline void kmsg_dump(enum kmsg_d
 {
 }
 
+bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
+			  const char *line, size_t size, size_t *len)
+{
+	return false
+}
+
+bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
+			    char *buf, size_t size, size_t *len)
+{
+	return false;
+}
+
 static inline int kmsg_dump_register(struct kmsg_dumper *dumper)
 {
 	return -EINVAL;

On Tue, 2012-05-29 at 18:07 +0200, Kay Sievers wrote:
[]