Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Jesper Juhl]

I get this in dmesg with 2.6.18-git6 :
      a3:<6>Time: acpi_pm clocksource has been installed.

Looks like some printk() somewhere is not adding \n correctly after
outputting a message priority or a message priority too much is
used... I've not investigated where this happens, but just wanted to
report it.

-- 
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Randy Dunlap]

On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:

> I get this in dmesg with 2.6.18-git6 :
>       a3:<6>Time: acpi_pm clocksource has been installed.
> 
> Looks like some printk() somewhere is not adding \n correctly after
> outputting a message priority or a message priority too much is
> used... I've not investigated where this happens, but just wanted to
> report it.

Hi,
How about posting (pasting) some of the message log before that?

---
~Randy

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Jesper Juhl]

On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> 
> > I get this in dmesg with 2.6.18-git6 :
> >       a3:<6>Time: acpi_pm clocksource has been installed.
> > 
> > Looks like some printk() somewhere is not adding \n correctly after
> > outputting a message priority or a message priority too much is
> > used... I've not investigated where this happens, but just wanted to
> > report it.
> 
> Hi,
> How about posting (pasting) some of the message log before that?
> 
Sure, below is the entire dmesg output from this boot of the box 
(including the line above) :


Linux version 2.6.18-git6 (juhl@dragon) (gcc version 3.4.6) #1 SMP PREEMPT Wed Sep 27 01:52:25 CEST 2006
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
 BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000e8000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 000000007ffb0000 (usable)
 BIOS-e820: 000000007ffb0000 - 000000007ffc0000 (ACPI data)
 BIOS-e820: 000000007ffc0000 - 000000007fff0000 (ACPI NVS)
 BIOS-e820: 000000007fff0000 - 0000000080000000 (reserved)
 BIOS-e820: 00000000ff7c0000 - 0000000100000000 (reserved)
1151MB HIGHMEM available.
896MB LOWMEM available.
found SMP MP-table at 000ff780
On node 0 totalpages: 524208
  DMA zone: 4096 pages, LIFO batch:0
  Normal zone: 225280 pages, LIFO batch:31
  HighMem zone: 294832 pages, LIFO batch:31
DMI 2.3 present.
ACPI: RSDP (v000 ACPIAM                                ) @ 0x000f9bb0
ACPI: RSDT (v001 A M I  OEMRSDT  0x12000506 MSFT 0x00000097) @ 0x7ffb0000
ACPI: FADT (v002 A M I  OEMFACP  0x12000506 MSFT 0x00000097) @ 0x7ffb0200
ACPI: MADT (v001 A M I  OEMAPIC  0x12000506 MSFT 0x00000097) @ 0x7ffb0390
ACPI: OEMB (v001 A M I  AMI_OEM  0x12000506 MSFT 0x00000097) @ 0x7ffc0040
ACPI: DSDT (v001  939M2 939M2150 0x00000150 INTL 0x02002026) @ 0x00000000
ACPI: PM-Timer IO Port: 0x808
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
Processor #0 15:3 APIC version 16
ACPI: LAPIC (acpi_id[0x02] lapic_id[0x01] enabled)
Processor #1 15:3 APIC version 16
ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
IOAPIC[0]: apic_id 2, version 17, address 0xfec00000, GSI 0-23
ACPI: IOAPIC (id[0x03] address[0xfec10000] gsi_base[24])
IOAPIC[1]: apic_id 3, version 17, address 0xfec10000, GSI 24-39
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
ACPI: IRQ0 used by override.
ACPI: IRQ2 used by override.
ACPI: IRQ9 used by override.
Enabling APIC mode:  Flat.  Using 2 I/O APICs
Using ACPI (MADT) for SMP configuration information
Allocating PCI resources starting at 88000000 (gap: 80000000:7f7c0000)
Detected 2200.221 MHz processor.
Built 1 zonelists.  Total pages: 524208
Kernel command line: BOOT_IMAGE=2.6.18git6 ro root=801
mapped APIC to ffffd000 (fee00000)
mapped IOAPIC to ffffc000 (fec00000)
mapped IOAPIC to ffffb000 (fec10000)
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Initializing CPU#0
CPU 0 irqstacks, hard=c04b4000 soft=c04b2000
PID hash table entries: 4096 (order: 12, 16384 bytes)
Console: colour dummy device 80x25
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES:    8
... MAX_LOCK_DEPTH:          30
... MAX_LOCKDEP_KEYS:        2048
... CLASSHASH_SIZE:           1024
... MAX_LOCKDEP_ENTRIES:     8192
... MAX_LOCKDEP_CHAINS:      8192
... CHAINHASH_SIZE:          4096
 memory used by lock dependency info: 696 kB
 per task-struct memory footprint: 1200 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! |
---------------------------------
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 2071596k/2096832k available (2245k kernel code, 24100k reserved, 927k data, 212k init, 1179328k highmem)
virtual kernel memory layout:
    fixmap  : 0xfff81000 - 0xfffff000   ( 504 kB)
    pkmap   : 0xff800000 - 0xffc00000   (4096 kB)
    vmalloc : 0xf8800000 - 0xff7fe000   ( 111 MB)
    lowmem  : 0xc0000000 - 0xf8000000   ( 896 MB)
      .init : 0xc0478000 - 0xc04ad000   ( 212 kB)
      .data : 0xc03315f9 - 0xc041930c   ( 927 kB)
      .text : 0xc0100000 - 0xc03315f9   (2245 kB)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay using timer specific routine.. 4402.74 BogoMIPS (lpj=2201372)
Mount-cache hash table entries: 512
CPU: After generic identify, caps: 178bfbff e3d3fbff 00000000 00000000 00000001 00000000 00000003
CPU: After vendor identify, caps: 178bfbff e3d3fbff 00000000 00000000 00000001 00000000 00000003
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 1024K (64 bytes/line)
CPU 0(2) -> Core 0
CPU: After all inits, caps: 178bfbff e3d3fbff 00000000 00000410 00000001 00000000 00000003
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
Checking 'hlt' instruction... OK.
Freeing SMP alternatives: 12k freed
ACPI: Core revision 20060707
CPU0: AMD Athlon(tm) 64 X2 Dual Core Processor 4400+ stepping 02
lockdep: not fixing up alternatives.
Booting processor 1/1 eip 2000
CPU 1 irqstacks, hard=c04b5000 soft=c04b3000
Initializing CPU#1
Calibrating delay using timer specific routine.. 4399.53 BogoMIPS (lpj=2199768)
CPU: After generic identify, caps: 178bfbff e3d3fbff 00000000 00000000 00000001 00000000 00000003
CPU: After vendor identify, caps: 178bfbff e3d3fbff 00000000 00000000 00000001 00000000 00000003
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 1024K (64 bytes/line)
CPU 1(2) -> Core 1
CPU: After all inits, caps: 178bfbff e3d3fbff 00000000 00000410 00000001 00000000 00000003
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#1.
CPU1: AMD Athlon(tm) 64 X2 Dual Core Processor 4400+ stepping 02
Total of 2 processors activated (8802.28 BogoMIPS).
ENABLING IO-APIC IRQs
..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
checking TSC synchronization across 2 CPUs: 
CPU#0 had -30 usecs TSC skew, fixed it up.
CPU#1 had 30 usecs TSC skew, fixed it up.
Brought up 2 CPUs
migration_cost=393
NET: Registered protocol family 16
ACPI: bus type pci registered
PCI: PCI BIOS revision 3.00 entry at 0xf0031, last bus=4
PCI: Using configuration type 1
Setting up standard PCI resources
ACPI: Interpreter enabled
ACPI: Using IOAPIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (0000:00)
PCI: Probing PCI hardware (bus 00)
PCI quirk: region 0800-083f claimed by ali7101 ACPI
Boot video device is 0000:03:00.0
PCI: Transparent bridge - 0000:00:06.0
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.P0P4._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.HTT_._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEB1._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEB2._PRT]
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 *5 6 7 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 *10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 *10 11 12 14 15), disabled.
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 *10 11 12 14 15), disabled.
ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKF] (IRQs *3 4 5 6 7 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 7 10 11 12 14 15) *9
ACPI: PCI Interrupt Link [LNKP] (IRQs 3 4 *5 6 7 10 11 12 14 15)
SCSI subsystem initialized
PCI: Using ACPI for IRQ routing
PCI: If a device doesn't work, try "pci=routeirq".  If it helps, post a report
PCI: Bridge: 0000:00:01.0
  IO window: disabled.
  MEM window: ff200000-ff2fffff
  PREFETCH window: disabled.
PCI: Bridge: 0000:00:02.0
  IO window: disabled.
  MEM window: ff300000-ff3fffff
  PREFETCH window: disabled.
PCI: Bridge: 0000:00:05.0
  IO window: disabled.
  MEM window: ff400000-ff4fffff
  PREFETCH window: c7f00000-d7efffff
PCI: Bridge: 0000:00:06.0
  IO window: d000-dfff
  MEM window: ff500000-ff5fffff
  PREFETCH window: 88000000-880fffff
ACPI: PCI Interrupt 0000:00:01.0[A] -> GSI 29 (level, low) -> IRQ 16
PCI: Setting latency timer of device 0000:00:01.0 to 64
ACPI: PCI Interrupt 0000:00:02.0[A] -> GSI 34 (level, low) -> IRQ 17
PCI: Setting latency timer of device 0000:00:02.0 to 64
PCI: Setting latency timer of device 0000:00:05.0 to 64
PCI: Setting latency timer of device 0000:00:06.0 to 64
NET: Registered protocol family 2
IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
TCP established hash table entries: 65536 (order: 9, 2359296 bytes)
TCP bind hash table entries: 32768 (order: 8, 1179648 bytes)
TCP: Hash tables configured (established 65536 bind 32768)
TCP reno registered
Machine check exception polling timer started.
Initializing RT-Tester: OK
highmem bounce pool size: 64 pages
io scheduler noop registered
io scheduler cfq registered (default)
vesafb: framebuffer at 0xc8000000, mapped to 0xf8880000, using 3072k, total 16384k
vesafb: mode is 1024x768x16, linelength=2048, pages=9
vesafb: protected mode interface info at c000:7880
vesafb: pmi: set display start = c00c79d3, set palette = c00c7ab3
vesafb: pmi: ports = 
vesafb: scrolling: redraw
vesafb: Truecolor: size=0:5:6:5, shift=0:11:5:0
Console: switching to colour frame buffer device 128x48
fb0: VESA VGA frame buffer device
Real Time Clock Driver v1.12ac
Serial: 8250/16550 driver $Revision: 1.90 $ 2 ports, IRQ sharing disabled
serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
via-rhine.c:v1.10-LK1.4.2 Sept-11-2006 Written by Donald Becker
ACPI: PCI Interrupt 0000:04:07.0[A] -> GSI 22 (level, low) -> IRQ 18
ACPI: PCI Interrupt 0000:04:06.0[A] -> GSI 21 (level, low) -> IRQ 19
eth0: VIA Rhine II at 0xff5fec00, 00:50:ba:f2:<6>serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
mice: PS/2 mouse device common for all mice
EDAC MC: Ver: 2.0.1 Sep 27 2006
TCP cubic registered
NET: Registered protocol family 1
NET: Registered protocol family 17
Starting balanced_irq
Using IPI Shortcut mode
a3:<6>Time: acpi_pm clocksource has been installed.
1d, IRQ 18.
eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.
input: AT Translated Set 2 keyboard as /class/input/input0
input: ImExPS/2 Generic Explorer Mouse as /class/input/input1
scsi0 : Adaptec AIC7XXX EISA/VLB/PCI SCSI HBA DRIVER, Rev 7.0
        <Adaptec 29160N Ultra160 SCSI adapter>
        aic7892: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs

scsi 0:0:4:0: CD-ROM            PIONEER  DVD-ROM DVD-305  1.03 PQ: 0 ANSI: 2
 target0:0:4: Beginning Domain Validation
 target0:0:4: FAST-20 SCSI 20.0 MB/s ST (50 ns, offset 16)
 target0:0:4: Domain Validation skipping write tests
 target0:0:4: Ending Domain Validation
sr0: scsi3-mmc drive: 16x/40x cd/rw xa/form2 cdda tray
Uniform CD-ROM driver Revision: 3.20
sr 0:0:4:0: Attached scsi CD-ROM sr0
sr 0:0:4:0: Attached scsi generic sg0 type 5
scsi 0:0:5:0: CD-ROM            PLEXTOR  CD-R   PX-W1210S 1.01 PQ: 0 ANSI: 2
 target0:0:5: Beginning Domain Validation
 target0:0:5: FAST-20 SCSI 20.0 MB/s ST (50 ns, offset 16)
 target0:0:5: Domain Validation skipping write tests
 target0:0:5: Ending Domain Validation
sr1: scsi3-mmc drive: 32x/32x writer cd/rw xa/form2 cdda tray
sr 0:0:5:0: Attached scsi CD-ROM sr1
sr 0:0:5:0: Attached scsi generic sg1 type 5
scsi 0:0:6:0: Direct-Access     IBM      DDYS-T36950N     S96H PQ: 0 ANSI: 3
scsi0:A:6:0: Tagged Queuing enabled.  Depth 200
 target0:0:6: Beginning Domain Validation
 target0:0:6: wide asynchronous
 target0:0:6: FAST-80 WIDE SCSI 160.0 MB/s DT (12.5 ns, offset 63)
 target0:0:6: Ending Domain Validation
SCSI device sda: 71687340 512-byte hdwr sectors (36704 MB)
sda: Write Protect is off
sda: Mode Sense: cb 00 00 08
SCSI device sda: drive cache: write back
SCSI device sda: 71687340 512-byte hdwr sectors (36704 MB)
sda: Write Protect is off
sda: Mode Sense: cb 00 00 08
SCSI device sda: drive cache: write back
 sda: sda1 sda2 sda3 sda4
sd 0:0:6:0: Attached scsi disk sda
sd 0:0:6:0: Attached scsi generic sg2 type 0
kjournald starting.  Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 212k freed
Write protecting the kernel read-only data: 371k
Adding 763076k swap on /dev/sda3.  Priority:-1 extents:1 across:763076k
EXT3 FS on sda1, internal journal
ACPI: PCI Interrupt 0000:04:05.0[A] -> GSI 20 (level, low) -> IRQ 20
Linux agpgart interface v0.101 (c) Dave Jones
ReiserFS: sda2: found reiserfs format "3.6" with standard journal
ReiserFS: sda2: using ordered data mode
ReiserFS: sda2: journal params: device sda2, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: sda2: checking transaction log (sda2)
ReiserFS: sda2: Using r5 hash to sort names
ReiserFS: sda4: found reiserfs format "3.6" with standard journal
ReiserFS: sda4: using ordered data mode
ReiserFS: sda4: journal params: device sda4, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: sda4: checking transaction log (sda4)
ReiserFS: sda4: Using r5 hash to sort names
eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Randy Dunlap]

On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:

> On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > 
> > > I get this in dmesg with 2.6.18-git6 :
> > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > 
> > > Looks like some printk() somewhere is not adding \n correctly after
> > > outputting a message priority or a message priority too much is
> > > used... I've not investigated where this happens, but just wanted to
> > > report it.
> > 
> > Hi,
> > How about posting (pasting) some of the message log before that?
> > 
> Sure, below is the entire dmesg output from this boot of the box 
> (including the line above) :

OK, would you boot with "initcall_debug" on the kernel command
line and post the relevant output again, please?

> serio: i8042 KBD port at 0x60,0x64 irq 1
> mice: PS/2 mouse device common for all mice
> EDAC MC: Ver: 2.0.1 Sep 27 2006
> TCP cubic registered
> NET: Registered protocol family 1
> NET: Registered protocol family 17
> Starting balanced_irq
> Using IPI Shortcut mode
> a3:<6>Time: acpi_pm clocksource has been installed.
> 1d, IRQ 18.

---
~Randy

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Jesper Juhl]

On Wednesday 27 September 2006 02:54, Randy Dunlap wrote:
> On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:
> 
> > On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > > 
> > > > I get this in dmesg with 2.6.18-git6 :
> > > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > > 
> > > > Looks like some printk() somewhere is not adding \n correctly after
> > > > outputting a message priority or a message priority too much is
> > > > used... I've not investigated where this happens, but just wanted to
> > > > report it.
> > > 
> > > Hi,
> > > How about posting (pasting) some of the message log before that?
> > > 
> > Sure, below is the entire dmesg output from this boot of the box 
> > (including the line above) :
> 
> OK, would you boot with "initcall_debug" on the kernel command
> line and post the relevant output again, please?

Sure thing :

Real Time Clock Driver v1.12ac
Calling initcall 0xc0491cc0: serial8250_init+0x0/0xf0()
Serial: 8250/16550 driver $Revision: 1.90 $ 2 ports, IRQ sharing disabled
serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
Calling initcall 0xc0491db0: serial8250_pci_init+0x0/0x20()
Calling initcall 0xc0491f10: firmware_class_init+0x0/0x70()
Calling initcall 0xc0492000: topology_sysfs_init+0x0/0x70()
Calling initcall 0xc04928a0: floppy_init+0x0/0x620()
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
Calling initcall 0xc0492ec0: rhine_init+0x0/0x20()
via-rhine.c:v1.10-LK1.4.2 Sept-11-2006 Written by Donald Becker
Calling initcall 0xc0492fd0: net_olddevs_init+0x0/0x40()
ACPI: PCI Interrupt 0000:04:07.0[A] -> Calling initcall 0xc0493380: spi_transport_init+0x0/0x30()
Calling initcall 0xc04933b0: fc_transport_init+0x0/0x40()
Calling initcall 0xc04933f0: ahc_linux_init+0x0/0xa0()
Calling initcall 0xc0493490: init_sd+0x0/0x70()
Calling initcall 0xc0493500: init_sr+0x0/0x30()
Calling initcall 0xc0493530: init_sg+0x0/0x90()
Calling initcall 0xc04935c0: cdrom_init+0x0/0x10()
Calling initcall 0xc0493710: i8042_init+0x0/0x90()
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
Calling initcall 0xc04938c0: mousedev_init+0x0/0xe0()
ACPI: PCI Interrupt 0000:04:06.0[A] -> GSI 21 (level, low) -> IRQ 19
mice: PS/2 mouse device common for all mice
GSI 22 (level, low) -> IRQ 18
Calling initcall 0xc04939a0: atkbd_init+0x0/0x20()
Calling initcall 0xc04939c0: psmouse_init+0x0/0x50()
Calling initcall 0xc0493a10: edac_mc_init+0x0/0xe0()
EDAC MC: Ver: 2.0.1 Sep 27 2006
Calling initcall 0xc0494010: init_acpi_pm_clocksource+0x0/0x110()
Calling initcall 0xc0494150: init_soundcore+0x0/0x60()
Calling initcall 0xc0496cf0: init_syncookies+0x0/0x20()
Calling initcall 0xc0496d10: inet_diag_init+0x0/0x60()
Calling initcall 0xc0496d70: tcp_diag_init+0x0/0x10()
Calling initcall 0xc0496d80: cubictcp_register+0x0/0xc0()
TCP cubic registered
eth0: VIA Rhine II at 0xff5fec00, 00:50:ba:f2:a3:1d, IRQ 18.
eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.
Calling initcall 0xc0496e40: af_unix_init+0x0/0x70()
input: AT Translated Set 2 keyboard as /class/input/input0
NET: Registered protocol family 1
Calling initcall 0xc0496eb0: packet_init+0x0/0x4c()
NET: Registered protocol family 17
Calling initcall 0xc047f2e0: amd_exit_cpu+0x0/0x20()
Calling initcall 0xc047f9b0: cyrix_exit_cpu+0x0/0x20()
Calling initcall 0xc047f9f0: nsc_exit_cpu+0x0/0x20()
Calling initcall 0xc047fcb0: centaur_exit_cpu+0x0/0x20()
Calling initcall 0xc047ff60: transmeta_exit_cpu+0x0/0x20()
Calling initcall 0xc0480f90: rise_exit_cpu+0x0/0x20()
Calling initcall 0xc0481040: nexgen_exit_cpu+0x0/0x20()
Calling initcall 0xc0481090: umc_exit_cpu+0x0/0x20()
Calling initcall 0xc0484900: check_nmi_watchdog+0x0/0x1b0()
Calling initcall 0xc0484b70: init_lapic_nmi_sysfs+0x0/0x40()
Calling initcall 0xc0484bf0: balanced_irq_init+0x0/0x1c0()
Starting balanced_irq
Calling initcall 0xc0486790: io_apic_bug_finalize+0x0/0x20()
Calling initcall 0xc0487f30: print_ipi_mode+0x0/0x30()
Using IPI Shortcut mode
Calling initcall 0xc0489750: clocksource_done_booting+0x0/0x20()
Calling initcall 0xc02449a0: acpi_poweroff_init+0x0/0x58()<6>Time: acpi_pm clocksource has been installed.

Calling initcall 0xc0490cd0: seqgen_init+0x0/0x10()
Calling initcall 0xc02eab10: net_random_reseed+0x0/0x70()
Calling initcall 0xc0496a70: tcp_congestion_default+0x0/0x10()
input: ImExPS/2 Generic Explorer Mouse as /class/input/input1


-- 
Jesper Juhl <jesper.juhl@gmail.com>

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Randy Dunlap]

On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:

> On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > 
> > > I get this in dmesg with 2.6.18-git6 :
> > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > 
> > > Looks like some printk() somewhere is not adding \n correctly after
> > > outputting a message priority or a message priority too much is
> > > used... I've not investigated where this happens, but just wanted to
> > > report it.
> > 
> > Hi,
> > How about posting (pasting) some of the message log before that?
> > 
> Sure, below is the entire dmesg output from this boot of the box 
> (including the line above) :

I suppose that you have CONFIG_PCI_MULTITHREAD_PROBE=y ?
What happens if you change to to =n ?

> eth0: VIA Rhine II at 0xff5fec00, 00:50:ba:f2:<6>serio: i8042 AUX port at 0x60,0x64 irq 12
> serio: i8042 KBD port at 0x60,0x64 irq 1
> mice: PS/2 mouse device common for all mice
> EDAC MC: Ver: 2.0.1 Sep 27 2006
> TCP cubic registered
> NET: Registered protocol family 1
> NET: Registered protocol family 17
> Starting balanced_irq
> Using IPI Shortcut mode
> a3:<6>Time: acpi_pm clocksource has been installed.
> 1d, IRQ 18.
> eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.

I'm pretty sure that this is caused by parallel device probing.
The serio and clocksource messages are interspersed with the
eth0 (via rhine) info.  Garbled.

Greg, is this expected?

---
~Randy

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Greg KH]

On Tue, Sep 26, 2006 at 08:54:15PM -0700, Randy Dunlap wrote:
> On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:
> 
> > On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > > 
> > > > I get this in dmesg with 2.6.18-git6 :
> > > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > > 
> > > > Looks like some printk() somewhere is not adding \n correctly after
> > > > outputting a message priority or a message priority too much is
> > > > used... I've not investigated where this happens, but just wanted to
> > > > report it.
> > > 
> > > Hi,
> > > How about posting (pasting) some of the message log before that?
> > > 
> > Sure, below is the entire dmesg output from this boot of the box 
> > (including the line above) :
> 
> I suppose that you have CONFIG_PCI_MULTITHREAD_PROBE=y ?
> What happens if you change to to =n ?
> 
> > eth0: VIA Rhine II at 0xff5fec00, 00:50:ba:f2:<6>serio: i8042 AUX port at 0x60,0x64 irq 12
> > serio: i8042 KBD port at 0x60,0x64 irq 1
> > mice: PS/2 mouse device common for all mice
> > EDAC MC: Ver: 2.0.1 Sep 27 2006
> > TCP cubic registered
> > NET: Registered protocol family 1
> > NET: Registered protocol family 17
> > Starting balanced_irq
> > Using IPI Shortcut mode
> > a3:<6>Time: acpi_pm clocksource has been installed.
> > 1d, IRQ 18.
> > eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.
> 
> I'm pretty sure that this is caused by parallel device probing.
> The serio and clocksource messages are interspersed with the
> eth0 (via rhine) info.  Garbled.
> 
> Greg, is this expected?

Only if one bit of code doesn't write a full line to the printk()
buffer, yes that could happen.

What driver writes "a3:"?  I couldn't find it anywhere in Linus's
current tree.

thanks,

greg k-h

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Randy Dunlap]

On Tue, 26 Sep 2006 21:32:39 -0700 Greg KH wrote:

> On Tue, Sep 26, 2006 at 08:54:15PM -0700, Randy Dunlap wrote:
> > On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:
> > 
> > > On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > > > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > > > 
> > > > > I get this in dmesg with 2.6.18-git6 :
> > > > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > > > 
> > > > > Looks like some printk() somewhere is not adding \n correctly after
> > > > > outputting a message priority or a message priority too much is
> > > > > used... I've not investigated where this happens, but just wanted to
> > > > > report it.
> > > > 
> > > > Hi,
> > > > How about posting (pasting) some of the message log before that?
> > > > 
> > > Sure, below is the entire dmesg output from this boot of the box 
> > > (including the line above) :
> > 
> > I suppose that you have CONFIG_PCI_MULTITHREAD_PROBE=y ?
> > What happens if you change to to =n ?
> > 
> > > eth0: VIA Rhine II at 0xff5fec00, 00:50:ba:f2:<6>serio: i8042 AUX port at 0x60,0x64 irq 12
> > > serio: i8042 KBD port at 0x60,0x64 irq 1
> > > mice: PS/2 mouse device common for all mice
> > > EDAC MC: Ver: 2.0.1 Sep 27 2006
> > > TCP cubic registered
> > > NET: Registered protocol family 1
> > > NET: Registered protocol family 17
> > > Starting balanced_irq
> > > Using IPI Shortcut mode
> > > a3:<6>Time: acpi_pm clocksource has been installed.
> > > 1d, IRQ 18.
> > > eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.
> > 
> > I'm pretty sure that this is caused by parallel device probing.
> > The serio and clocksource messages are interspersed with the
> > eth0 (via rhine) info.  Garbled.
> > 
> > Greg, is this expected?
> 
> Only if one bit of code doesn't write a full line to the printk()
> buffer, yes that could happen.
> 
> What driver writes "a3:"?  I couldn't find it anywhere in Linus's
> current tree.

Nope, that's part of the NIC's MAC address.  It was split up.

---
~Randy

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Randy Dunlap]

On Tue, 26 Sep 2006 21:52:35 -0700 Randy Dunlap wrote:

> On Tue, 26 Sep 2006 21:32:39 -0700 Greg KH wrote:
> 
> > On Tue, Sep 26, 2006 at 08:54:15PM -0700, Randy Dunlap wrote:
> > > On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:
> > > 
> > > > On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > > > > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > > > > 
> > > > > > I get this in dmesg with 2.6.18-git6 :
> > > > > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > > > > 
> > > > > > Looks like some printk() somewhere is not adding \n correctly after
> > > > > > outputting a message priority or a message priority too much is
> > > > > > used... I've not investigated where this happens, but just wanted to
> > > > > > report it.
> > > > > 
> > > > > Hi,
> > > > > How about posting (pasting) some of the message log before that?
> > > > > 
> > > > Sure, below is the entire dmesg output from this boot of the box 
> > > > (including the line above) :
> > > 
> > > I suppose that you have CONFIG_PCI_MULTITHREAD_PROBE=y ?
> > > What happens if you change to to =n ?
> > > 
> > > > eth0: VIA Rhine II at 0xff5fec00, 00:50:ba:f2:<6>serio: i8042 AUX port at 0x60,0x64 irq 12
> > > > serio: i8042 KBD port at 0x60,0x64 irq 1
> > > > mice: PS/2 mouse device common for all mice
> > > > EDAC MC: Ver: 2.0.1 Sep 27 2006
> > > > TCP cubic registered
> > > > NET: Registered protocol family 1
> > > > NET: Registered protocol family 17
> > > > Starting balanced_irq
> > > > Using IPI Shortcut mode
> > > > a3:<6>Time: acpi_pm clocksource has been installed.
> > > > 1d, IRQ 18.
> > > > eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.
> > > 
> > > I'm pretty sure that this is caused by parallel device probing.
> > > The serio and clocksource messages are interspersed with the
> > > eth0 (via rhine) info.  Garbled.
> > > 
> > > Greg, is this expected?
> > 
> > Only if one bit of code doesn't write a full line to the printk()
> > buffer, yes that could happen.
> > 
> > What driver writes "a3:"?  I couldn't find it anywhere in Linus's
> > current tree.
> 
> Nope, that's part of the NIC's MAC address.  It was split up.

Sorry.  In this case, it was via-rhine.c:

	for (i = 0; i < 5; i++)
		printk("%2.2x:", dev->dev_addr[i]);
	printk("%2.2x, IRQ %d.\n", dev->dev_addr[i], pdev->irq);

so it does break the printk()s up itself.

---
~Randy

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Greg KH]

On Tue, Sep 26, 2006 at 09:56:22PM -0700, Randy Dunlap wrote:
> On Tue, 26 Sep 2006 21:52:35 -0700 Randy Dunlap wrote:
> 
> > On Tue, 26 Sep 2006 21:32:39 -0700 Greg KH wrote:
> > 
> > > On Tue, Sep 26, 2006 at 08:54:15PM -0700, Randy Dunlap wrote:
> > > > On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:
> > > > 
> > > > > On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > > > > > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > > > > > 
> > > > > > > I get this in dmesg with 2.6.18-git6 :
> > > > > > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > > > > > 
> > > > > > > Looks like some printk() somewhere is not adding \n correctly after
> > > > > > > outputting a message priority or a message priority too much is
> > > > > > > used... I've not investigated where this happens, but just wanted to
> > > > > > > report it.
> > > > > > 
> > > > > > Hi,
> > > > > > How about posting (pasting) some of the message log before that?
> > > > > > 
> > > > > Sure, below is the entire dmesg output from this boot of the box 
> > > > > (including the line above) :
> > > > 
> > > > I suppose that you have CONFIG_PCI_MULTITHREAD_PROBE=y ?
> > > > What happens if you change to to =n ?
> > > > 
> > > > > eth0: VIA Rhine II at 0xff5fec00, 00:50:ba:f2:<6>serio: i8042 AUX port at 0x60,0x64 irq 12
> > > > > serio: i8042 KBD port at 0x60,0x64 irq 1
> > > > > mice: PS/2 mouse device common for all mice
> > > > > EDAC MC: Ver: 2.0.1 Sep 27 2006
> > > > > TCP cubic registered
> > > > > NET: Registered protocol family 1
> > > > > NET: Registered protocol family 17
> > > > > Starting balanced_irq
> > > > > Using IPI Shortcut mode
> > > > > a3:<6>Time: acpi_pm clocksource has been installed.
> > > > > 1d, IRQ 18.
> > > > > eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.
> > > > 
> > > > I'm pretty sure that this is caused by parallel device probing.
> > > > The serio and clocksource messages are interspersed with the
> > > > eth0 (via rhine) info.  Garbled.
> > > > 
> > > > Greg, is this expected?
> > > 
> > > Only if one bit of code doesn't write a full line to the printk()
> > > buffer, yes that could happen.
> > > 
> > > What driver writes "a3:"?  I couldn't find it anywhere in Linus's
> > > current tree.
> > 
> > Nope, that's part of the NIC's MAC address.  It was split up.
> 
> Sorry.  In this case, it was via-rhine.c:
> 
> 	for (i = 0; i < 5; i++)
> 		printk("%2.2x:", dev->dev_addr[i]);
> 	printk("%2.2x, IRQ %d.\n", dev->dev_addr[i], pdev->irq);
> 
> so it does break the printk()s up itself.

Ok, yes, so messed up log messages will happen with the multi-threaded
boot stuff.

sorry,

greg k-h

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Joe Perches]

On Tue, 2006-09-26 at 21:56 -0700, Randy Dunlap wrote:
> > Nope, that's part of the NIC's MAC address.  It was split up.
> 
> Sorry.  In this case, it was via-rhine.c:
> 
> 	for (i = 0; i < 5; i++)
> 		printk("%2.2x:", dev->dev_addr[i]);
> 	printk("%2.2x, IRQ %d.\n", dev->dev_addr[i], pdev->irq);
> 
> so it does break the printk()s up itself.

Changing all of those MAC address printks to a single function
could prevent this.

http://www.uwsg.iu.edu/hypermail/linux/net/0602.1/0002.html

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Randy Dunlap]

On Tue, 26 Sep 2006 22:10:43 -0700 Joe Perches wrote:

> On Tue, 2006-09-26 at 21:56 -0700, Randy Dunlap wrote:
> > > Nope, that's part of the NIC's MAC address.  It was split up.
> > 
> > Sorry.  In this case, it was via-rhine.c:
> > 
> > 	for (i = 0; i < 5; i++)
> > 		printk("%2.2x:", dev->dev_addr[i]);
> > 	printk("%2.2x, IRQ %d.\n", dev->dev_addr[i], pdev->irq);
> > 
> > so it does break the printk()s up itself.
> 
> Changing all of those MAC address printks to a single function
> could prevent this.
> 
> http://www.uwsg.iu.edu/hypermail/linux/net/0602.1/0002.html

True enough.  Thanks for the patch.
However, in this case, the single-printed MAC address still needs
a \n, with the IRQ on a separate line (wasting vertical screen space),
or it needs a custom printk() that is all done at one time.
Probably the latter IMO.  Oh, it looks like your patch
has a way to handle that too.  Good.
What happened to your patch?

---
~Randy

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Joe Perches]

On Tue, 2006-09-26 at 22:17 -0700, Randy Dunlap wrote:
> > > so it does break the printk()s up itself.
> > Changing all of those MAC address printks to a single function
> > could prevent this.
> > http://www.uwsg.iu.edu/hypermail/linux/net/0602.1/0002.html
> True enough.  Thanks for the patch.
> However, in this case, the single-printed MAC address still needs
> a \n, with the IRQ on a separate line (wasting vertical screen space),
> or it needs a custom printk() that is all done at one time.
> Probably the latter IMO.  Oh, it looks like your patch
> has a way to handle that too.  Good.
> What happened to your patch?

I sent it as an RFC with samples and such.
It's out of date and it went comment free.
I could bring it forward if anyone wants it.

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Randy Dunlap]

On Tue, 26 Sep 2006 22:19:53 -0700 Joe Perches wrote:

> On Tue, 2006-09-26 at 22:17 -0700, Randy Dunlap wrote:
> > > > so it does break the printk()s up itself.
> > > Changing all of those MAC address printks to a single function
> > > could prevent this.
> > > http://www.uwsg.iu.edu/hypermail/linux/net/0602.1/0002.html
> > True enough.  Thanks for the patch.
> > However, in this case, the single-printed MAC address still needs
> > a \n, with the IRQ on a separate line (wasting vertical screen space),
> > or it needs a custom printk() that is all done at one time.
> > Probably the latter IMO.  Oh, it looks like your patch
> > has a way to handle that too.  Good.
> > What happened to your patch?
> 
> I sent it as an RFC with samples and such.
> It's out of date and it went comment free.
> I could bring it forward if anyone wants it.

I think that it's needed, but it's really up to the netdev
people.  If you do resend it, please note this problem
(that Jesper posted) as well.

Thanks,
---
~Randy

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Jesper Juhl]

On 27/09/06, Randy Dunlap <rdunlap@xenotime.net> wrote:
> On Wed, 27 Sep 2006 02:36:58 +0200 Jesper Juhl wrote:
>
> > On Wednesday 27 September 2006 02:33, Randy Dunlap wrote:
> > > On Wed, 27 Sep 2006 02:22:18 +0200 Jesper Juhl wrote:
> > >
> > > > I get this in dmesg with 2.6.18-git6 :
> > > >       a3:<6>Time: acpi_pm clocksource has been installed.
> > > >
> > > > Looks like some printk() somewhere is not adding \n correctly after
> > > > outputting a message priority or a message priority too much is
> > > > used... I've not investigated where this happens, but just wanted to
> > > > report it.
> > >
> > > Hi,
> > > How about posting (pasting) some of the message log before that?
> > >
> > Sure, below is the entire dmesg output from this boot of the box
> > (including the line above) :
>
> I suppose that you have CONFIG_PCI_MULTITHREAD_PROBE=y ?

Correct.

> What happens if you change to to =n ?
>
Doing that resolves the issue.

So yes, you are correct in your other posts in this thread that the
problem is caused by multiple printk()'s from different locations
being mixed up.

-- 
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Denis Vlasenko]

On Wednesday 27 September 2006 07:17, Randy Dunlap wrote:
> On Tue, 26 Sep 2006 22:10:43 -0700 Joe Perches wrote:
> 
> > On Tue, 2006-09-26 at 21:56 -0700, Randy Dunlap wrote:
> > > > Nope, that's part of the NIC's MAC address.  It was split up.
> > > 
> > > Sorry.  In this case, it was via-rhine.c:
> > > 
> > > 	for (i = 0; i < 5; i++)
> > > 		printk("%2.2x:", dev->dev_addr[i]);
> > > 	printk("%2.2x, IRQ %d.\n", dev->dev_addr[i], pdev->irq);
> > > 
> > > so it does break the printk()s up itself.
> > 
> > Changing all of those MAC address printks to a single function
> > could prevent this.
> > 
> > http://www.uwsg.iu.edu/hypermail/linux/net/0602.1/0002.html
> 
> True enough.  Thanks for the patch.
> However, in this case, the single-printed MAC address still needs
> a \n, with the IRQ on a separate line (wasting vertical screen space),
> or it needs a custom printk() that is all done at one time.

Custom print_mac worked very nice for me in acx driver.
In order to accomodate arbitrary text before/after mac addres,
I did it this way:

#define MACSTR "%02X:%02X:%02X:%02X:%02X:%02X"
#define MAC(bytevector) \
        ((unsigned char *)bytevector)[0], \
        ((unsigned char *)bytevector)[1], \
        ((unsigned char *)bytevector)[2], \
        ((unsigned char *)bytevector)[3], \
        ((unsigned char *)bytevector)[4], \
        ((unsigned char *)bytevector)[5]

void print_mac(const char *head, const unsigned char *mac, const char *tail)
{
        printk("%s"MACSTR"%s", head, MAC(mac), tail);
}


Usage: print_mac("adev->bssid: ", adev->bssid, "\n");
--
vda

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Joe Perches]

On Thu, 2006-09-28 at 12:56 +0200, Denis Vlasenko wrote:
> \#define MACSTR "%02X:%02X:%02X:%02X:%02X:%02X"
> #define MAC(bytevector) \
>         ((unsigned char *)bytevector)[0], \
>         ((unsigned char *)bytevector)[1], \
>         ((unsigned char *)bytevector)[2], \
>         ((unsigned char *)bytevector)[3], \
>         ((unsigned char *)bytevector)[4], \
>         ((unsigned char *)bytevector)[5]

This is similar to the 802.11 way.
802.11 uses MAC_FMT and MAC_ARG.
I think a common style is preferable.

It's fine, but it increases the size of kernel image
by up to ~100K.  Using a common function, a stack
automatic and "%s" in the printk decreases the size
of the kernel. 

Strictly, not all MAC addresses are 6 byte.

Maybe all the Ethernet/TR addresses should use the
IEEE EUI48 designation?  That feels a bit like the
KiB/KB distinction, but it is technically correct.

Would a patch with an DEV6_ADDR->EUI48 substitution
be acceptable?

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Denis Vlasenko]

On Thursday 28 September 2006 18:08, Joe Perches wrote:
> On Thu, 2006-09-28 at 12:56 +0200, Denis Vlasenko wrote:
> > \#define MACSTR "%02X:%02X:%02X:%02X:%02X:%02X"
> > #define MAC(bytevector) \
> >         ((unsigned char *)bytevector)[0], \
> >         ((unsigned char *)bytevector)[1], \
> >         ((unsigned char *)bytevector)[2], \
> >         ((unsigned char *)bytevector)[3], \
> >         ((unsigned char *)bytevector)[4], \
> >         ((unsigned char *)bytevector)[5]
> 
> This is similar to the 802.11 way.
> 802.11 uses MAC_FMT and MAC_ARG.
> I think a common style is preferable.
> 
> It's fine, but it increases the size of kernel image
> by up to ~100K.  Using a common function, a stack
> automatic and "%s" in the printk decreases the size
> of the kernel. 

You deleted part of my message where I show exactly that:
a common function, which handles 80% of usage cases.

You are trying to cover all possible cases with this monstrosity:

extern char *__dev_addr6_fmt(char* buf, const unsigned char *addr);
#define DEV_ADDR6_FMT "%s" /* expands to: "FF:FF:FF:FF:FF:FF" */
#define DEV_ADDR6_BUF char __dev_addr6_buf[sizeof("FF:FF:FF:FF:FF:FF")]
#define DEV_ADDR6(addr) __dev_addr6_fmt(__dev_addr6_buf,(const unsigned char*)addr)
#define DEV_ADDR6_BUF_2 char __dev_addr6_buf_2[sizeof("FF:FF:FF:FF:FF:FF")]
#define DEV_ADDR6_2(addr) __dev_addr6_fmt(__dev_addr6_buf_2,(const unsigned char*)addr)
#define DEV_ADDR6_BUF_3 char __dev_addr6_buf_3[sizeof("FF:FF:FF:FF:FF:FF")]
#define DEV_ADDR6_3(addr) __dev_addr6_fmt(__dev_addr6_buf_3,(const unsigned char*)addr)
#define DEV_ADDR6_BUF_4 char __dev_addr6_buf_4[sizeof("FF:FF:FF:FF:FF:FF")]
#define DEV_ADDR6_4(addr) __dev_addr6_fmt(__dev_addr6_buf_4,(const unsigned char*)addr)

Usage:

DEV_ADDR6_BUF;
...
printk(", h/w address " DEV_ADDR6_FMT "\n", DEV_ADDR6(dev->dev_addr));

Why don't you use a parameter for DEV_ADDR6{_BUF}? DEV_ADDR6_BUF(var_name).
DEV_ADDR6(var_name, addr). That would be less cryptic.

In my case, it's just

print_mac(", h/w address ", dev->dev_addr, "\n");

Actually, I think it makes sense to have both: yours for complicated
cases (printk with lots of other %something) and mine for simple ones
(no local variable, smaller code).

> Strictly, not all MAC addresses are 6 byte.
> 
> Maybe all the Ethernet/TR addresses should use the
> IEEE EUI48 designation?  That feels a bit like the
> KiB/KB distinction, but it is technically correct.
> 
> Would a patch with an DEV6_ADDR->EUI48 substitution
> be acceptable?

Maybe. Doesn't look obvious, but if it is in standards...
--
vda

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Joe Perches]

On Thu, 2006-09-28 at 18:19 +0200, Denis Vlasenko wrote:
> You are trying to cover all possible cases with this monstrosity:
> extern char *__dev_addr6_fmt(char* buf, const unsigned char *addr);
> #define DEV_ADDR6_FMT "%s" /* expands to: "FF:FF:FF:FF:FF:FF" */
> #define DEV_ADDR6_BUF char __dev_addr6_buf[sizeof("FF:FF:FF:FF:FF:FF")]
> DEV_ADDR6_BUF;
> ...
> printk(", h/w address " DEV_ADDR6_FMT "\n", DEV_ADDR6(dev->dev_addr));

Yup, it's not pretty.

> Why don't you use a parameter for DEV_ADDR6{_BUF}? DEV_ADDR6_BUF(var_name).
> DEV_ADDR6(var_name, addr). That would be less cryptic.

Your idea makes code a bit visually longer, but I've no real objection.

> print_mac(", h/w address ", dev->dev_addr, "\n");

> > Would a patch with a DEV6_ADDR->EUI48 substitution
> > be acceptable?
> 
> Maybe. Doesn't look obvious, but if it is in standards...

Perhaps:

extern char *__EUI48_fmt(char *buf, const unsigned char *addr);
#define EUI48_FMT "%s" /* expands to: "FF:FF:FF:FF:FF:FF" */
#define DECLARE_EUI48(name) char name[sizeof("FF:FF:FF:FF:FF:FF")]
#define EUI48(name, addr) __EUI48_fmt(name, (const unsigned char *)addr)

use case:

{
	DECLARE_EUI48(eui48);
	printk("mac: " EUI48_FMT, EUI48(eui48, dev->dev_addr));
}

Here's one with an assumption of an eui48 buffer name.

extern char *__EUI48_fmt(char *buf, const unsigned char *addr);
#define EUI48_FMT "%s" /* expands to: "FF:FF:FF:FF:FF:FF" */
#define DECLARE_EUI48 char __eui48_buf[sizeof("FF:FF:FF:FF:FF:FF")]
#define EUI48(addr) __EUI48_fmt(__eui48_buf, (const unsigned char *)addr)

use case:

{
	DECLARE_EUI48;
	printk("mac: " EUI48_FMT, EUI48(dev->dev_addr));
}

Which one do you like more?

Re: Tiny error in printk output for clocksource : a3:<6>Time: acpi_pm clocksource has been installed.

[Joe Perches]

On Thu, 2006-09-28 at 18:19 +0200, Denis Vlasenko wrote:
> Actually, I think it makes sense to have both: yours for complicated
> cases (printk with lots of other %something) and mine for simple ones
> (no local variable, smaller code).
> > Strictly, not all MAC addresses are 6 byte.
> > Maybe all the Ethernet/TR addresses should use the
> > IEEE EUI48 designation?  That feels a bit like the
> > KiB/KB distinction, but it is technically correct.
> > Would a patch with an DEV6_ADDR->EUI48 substitution
> > be acceptable?
> Maybe. Doesn't look obvious, but if it is in standards...

I brought the RFC patch from several months ago forward
using the implicit stack var in DECLARE_EUI48.

It's quite large, > 300k.

The patches also use single printks for more messages so
that when CONFIG_PCI_MULTITHREAD_PROBE is set, message
lines won't be split.

I separated the patches into groups where the output is:
1-identical, 2-changed but likely harmless, and 3-other.

In some cases, mac addresses are formatted for use in
/proc and seq_printf either in lower case or with just
a "%x" instead of "%02X", or not colon separated.
It's not good to change those formats.

I'd like to agree on the form before posting.

implicit DECLARE_EUI48; and EUI48(address)
or
explicit DECLARE_EUI48(name) and EUI48(name, address)

Warts:

There are some new non-debug warnings that are generated
when using the stack automatic because some of the debug
printks don't get compiled and you get "unused variable"
warnings.

It's possible to remove the DECLARE_EUI48 completely
by not indirecting the formatting string
"%02X:%02X:%02X:%02X:%02X:%02X" to "%s" and a function,
but it increases the kernel or module size.