LinuxQuestions.org

LinuxQuestions.org (/questions/)
-   Linux - Kernel (http://www.linuxquestions.org/questions/linux-kernel-70/)
-   -   Rapid clock drift on Linux SMP (http://www.linuxquestions.org/questions/linux-kernel-70/rapid-clock-drift-on-linux-smp-773304/)

pmil 12-03-2009 04:22 PM

Rapid clock drift on Linux SMP
 
Hi all,

I have build a kernel for a dual-core Intel Atom target with SMP support enabled based on 2.6.31.6 release .

I have defined HZ to 1000 and I have enabled APIC support. I've placed a printk which is called every 1000 calls inside the LAPIC timer's handler. Although I was expecting to have my printk appeared/called every 1 sec (because 1000 Hz --> 1 ms tick), it is called every 0.25 sec, so somehow it's being speed up. Does anyone has any idea why this happens?

I also have another query. I ran /proc/timer_list and saw that each processor has a lapic timer interrupt, the handler of which is the “hrtimer_interrupt” handler (hrtimer.c) . However, the "local_apic_timer_interrupt" handler is also called (apic.c) with the same rate which is HZ*4. Any ideas why?

Thanks a lot in advance.

rweaver 12-03-2009 05:15 PM

It's hard to say without knowing a lot about the system configuration and being able to adjust settings to view the effects.

Are you currently running ntpd?

pmil 12-04-2009 08:07 AM

Quote:

Originally Posted by rweaver (Post 3778933)
It's hard to say without knowing a lot about the system configuration and being able to adjust settings to view the effects.

Are you currently running ntpd?

Hi! No, I am not running ntpd. As for the kernel configuration I have enabled SMP, HPET, LOCAL APIC and IO APIC. Here are the kernel messages (NOTE: I've made bold the points that my printk appears):

Code:

...
[    0.000000] found SMP MP-table at [c00fe200] fe200
...
[    0.000000] Using APIC driver default
[    0.000000] ACPI: PM-Timer IO Port: 0x408
[    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x02] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x01] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x03] enabled)
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] dfl dfl lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x02] dfl dfl lint[0x1])
[    0.000000] ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
[    0.000000] IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] Enabling APIC mode:  Flat.  Using 1 I/O APICs
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.000000] SMP: Allowing 4 CPUs, 0 hotplug CPUs
...
[    0.000000] Kernel command line: console=tty0 console=ttyS0,115200n8 initrd=/boot/ramdisk.gz ramdisk_size=8192 root=/dev/ram0 rw autoexec=xconf BOOT_IMAGE=/boot/bzImage
[    0.000000] PID hash table entries: 2048 (order: 11, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Enabling fast FPU save and restore... done.
[    0.000000] Enabling unmasked SIMD FPU exception support... done.
[    0.000000] Initializing CPU#0
[    0.000000] Initializing HighMem for node 0 (00000000:00000000)
[    0.000000] Memory: 497544k/515072k available (4432k kernel code, 15728k reserved, 2626k data, 380k init, 0k highmem)
[    0.000000] virtual kernel memory layout:
[    0.000000]    fixmap  : 0xfff1f000 - 0xfffff000  ( 896 kB)
[    0.000000]    pkmap  : 0xff800000 - 0xffc00000  (4096 kB)
[    0.000000]    vmalloc : 0xdff00000 - 0xff7fe000  ( 504 MB)
[    0.000000]    lowmem  : 0xc0000000 - 0xdf700000  ( 503 MB)
[    0.000000]      .init : 0xc16e5000 - 0xc1744000  ( 380 kB)
[    0.000000]      .data : 0xc1454187 - 0xc16e4ba8  (2626 kB)
[    0.000000]      .text : 0xc1000000 - 0xc1454187  (4432 kB)
[    0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.000000] SLUB: Genslabs=13, HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] NR_IRQS:2304 nr_irqs:440
[    0.000000] Fast TSC calibration using PIT
[    0.000000] Detected 1596.398 MHz processor.
[    0.000999] Console: colour VGA+ 80x25
[    0.000999] console [tty0] enabled
[    0.000999] console [ttyS0] enabled
[    0.000999] HPET: 3 timers in total, 0 timers will be used for per-cpu timer
[    0.001011] Calibrating delay loop (skipped), value calculated using timer frequency.. 3192.79 BogoMIPS (lpj=1596398)
[    0.003026] Security Framework initialized
[    0.004007] SELinux:  Initializing.
[    0.005026] Mount-cache hash table entries: 512
[    0.006225] Initializing cgroup subsys ns
[    0.007009] Initializing cgroup subsys cpuacct
[    0.008009] Initializing cgroup subsys freezer
[    0.009029] CPU: L1 I cache: 32K, L1 D cache: 24K
[    0.011004] CPU: L2 cache: 512K
[    0.012004] CPU: Physical Processor ID: 0
[    0.013004] CPU: Processor Core ID: 0
[    0.014006] mce: CPU supports 5 MCE banks
[    0.015012] CPU0: Thermal monitoring enabled (TM1)
[    0.016006] using mwait in idle threads.
[    0.017010] Performance Counters: Atom events, Intel PMU driver.
[    0.020013] ... version:                3
[    0.021004] ... bit width:              40
[    0.022004] ... generic counters:        2
[    0.023004] ... value mask:              000000ffffffffff
[    0.024004] ... max period:              000000007fffffff
[    0.025004] ... fixed-purpose counters:  3
[    0.026004] ... counter mask:            0000000700000003
[    0.027007] Checking 'hlt' instruction... OK.
[    0.033078] ACPI: Core revision 20090521
[    0.043456] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.054947] CPU0: Intel(R) Atom(TM) CPU  330  @ 1.60GHz stepping 02
[    0.057999] Booting processor 1 APIC 0x2 ip 0x6000
[    0.000999] Initializing CPU#1
[    0.000999] Calibrating delay using timer specific routine.. 3191.87 BogoMIPS (lpj=1595936)
[    0.000999] CPU: L1 I cache: 32K, L1 D cache: 24K
[    0.000999] CPU: L2 cache: 512K
[    0.000999] CPU: Physical Processor ID: 0
[    0.000999] CPU: Processor Core ID: 1
[    0.000999] mce: CPU supports 5 MCE banks
[    0.000999] CPU1: Thermal monitoring enabled (TM1)
[    0.000999] x86 PAT enabled: cpu 1, old 0x7040600070406, new 0x7010600070106
[    0.130947] CPU1: Intel(R) Atom(TM) CPU  330  @ 1.60GHz stepping 02
[    0.133011] checking TSC synchronization [CPU#0 -> CPU#1]:
[    0.133999] Measured 48 cycles TSC warp between CPUs, turning off TSC clock.
[    0.133999] Marking TSC unstable due to check_tsc_sync_source failed
[    0.134155] Booting processor 2 APIC 0x1 ip 0x6000
[    0.000999] Initializing CPU#2
[    0.000999] Calibrating delay using timer specific routine.. 3191.86 BogoMIPS (lpj=1595930)
[    0.000999] CPU: L1 I cache: 32K, L1 D cache: 24K
[    0.000999] CPU: L2 cache: 512K
[    0.000999] CPU: Physical Processor ID: 0
[    0.000999] CPU: Processor Core ID: 0
[    0.000999] mce: CPU supports 5 MCE banks
[    0.000999] CPU2: Thermal monitoring enabled (TM1)
[    0.000999] x86 PAT enabled: cpu 2, old 0x7040600070406, new 0x7010600070106
[    0.208361] CPU2: Intel(R) Atom(TM) CPU  330  @ 1.60GHz stepping 02
[    0.211194] Booting processor 3 APIC 0x3 ip 0x6000
[    0.000999] Initializing CPU#3
[    0.000999] Calibrating delay using timer specific routine.. 3191.87 BogoMIPS (lpj=1595935)
[    0.000999] CPU: L1 I cache: 32K, L1 D cache: 24K
[    0.000999] CPU: L2 cache: 512K
[    0.000999] CPU: Physical Processor ID: 0
[    0.000999] CPU: Processor Core ID: 1
[    0.000999] mce: CPU supports 5 MCE banks
[    0.000999] CPU3: Thermal monitoring enabled (TM1)
[    0.000999] x86 PAT enabled: cpu 3, old 0x7040600070406, new 0x7010600070106
[    0.285430] CPU3: Intel(R) Atom(TM) CPU  330  @ 1.60GHz stepping 02
[    0.288039] Brought up 4 CPUs
[    0.289006] Total of 4 processors activated (12768.39 BogoMIPS).
[    0.290444] khelper used greatest stack depth: 7020 bytes left
[    0.297616] Time: 14:25:42  Date: 12/04/09
[    0.298108] NET: Registered protocol family 16
[    0.300390] ACPI: bus type pci registered
[    0.301266] PCI: MCFG configuration 0: base f0000000 segment 0 buses 0 - 127
[    0.302005] PCI: MCFG area at f0000000 reserved in E820
[    0.303003] PCI: Using MMCONFIG for extended config space
[    0.304003] PCI: Using configuration type 1 for base access
[    0.325277] bio: create slab <bio-0> at 0
[    0.332197] ACPI: Interpreter enabled
[    0.336008] ACPI: (supports S0 S1 S3 S4 S5)
[    0.340338] ACPI: Using IOAPIC for interrupt routing
[    0.356168] ACPI: No dock devices found.
[    0.362293] ACPI: PCI Root Bridge [PCI0] (0000:00)
[    0.367694] pci 0000:00:1b.0: PME# supported from D0 D3hot D3cold
[    0.374020] pci 0000:00:1b.0: PME# disabled
[    0.378054] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold
[    0.384006] pci 0000:00:1c.0: PME# disabled
[    0.389074] pci 0000:00:1c.2: PME# supported from D0 D3hot D3cold
[    0.395006] pci 0000:00:1c.2: PME# disabled
[    0.399074] pci 0000:00:1c.3: PME# supported from D0 D3hot D3cold
[    0.405006] pci 0000:00:1c.3: PME# disabled
[    0.410369] pci 0000:00:1d.7: PME# supported from D0 D3hot D3cold
[    0.416007] pci 0000:00:1d.7: PME# disabled
[    0.420141] pci 0000:00:1f.0: quirk: region 0400-047f claimed by ICH6 ACPI/GPIO/TCO
[    0.428007] pci 0000:00:1f.0: quirk: region 0500-053f claimed by ICH6 GPIO
[    0.435007] pci 0000:00:1f.0: ICH7 LPC Generic IO decode 1 PIO at 0680 (mask 007f)
[    0.443220] pci 0000:00:1f.2: PME# supported from D3hot
[    0.448006] pci 0000:00:1f.2: PME# disabled
[    0.453252] pci 0000:01:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.459010] pci 0000:01:00.0: PME# disabled
[    0.464239] pci 0000:00:1e.0: transparent bridge
[    0.479165] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 7 9 10 *11 12)
[    0.486100] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 7 9 10 11 12) *0, disabled.
[    0.494443] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 7 *9 10 11 12)
[    0.501554] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 7 9 10 *11 12)
[    0.508555] ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 7 9 10 11 12) *0, disabled.
[    0.517112] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 7 9 10 11 12) *0, disabled.
[    0.525439] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 7 *9 10 11 12)
[    0.532558] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 7 9 *10 11 12)
[    0.540747] SCSI subsystem initialized
[    0.545613] usbcore: registered new interface driver usbfs
[    0.551291] usbcore: registered new interface driver hub
[    0.556844] usbcore: registered new device driver usb
[    0.562667] PCI: Using ACPI for IRQ routing
[    0.583556] cfg80211: Using static regulatory domain info
[    0.589006] cfg80211: Regulatory domain: US
[    0.593003]        (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[    0.600005]        (2402000 KHz - 2472000 KHz @ 40000 KHz), (600 mBi, 2700 mBm)
[    0.607007]        (5170000 KHz - 5190000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
[    0.614005]        (5190000 KHz - 5210000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
[    0.621005]        (5210000 KHz - 5230000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
[    0.628005]        (5230000 KHz - 5330000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
[    0.635005]        (5735000 KHz - 5835000 KHz @ 40000 KHz), (600 mBi, 3000 mBm)
[    0.641013] cfg80211: Calling CRDA for country: US
[    0.646854] NetLabel: Initializing
[    0.647004] NetLabel:  domain hash size = 128
[    0.648002] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.649027] NetLabel:  unlabeled traffic allowed by default
[    0.650221] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.652541] hpet0: 3 comparators, 64-bit 14.318180 MHz counter
[    0.663038] pnp: PnP ACPI init
[    0.666202] ACPI: bus type pnp registered
[    0.676968] pnp: PnP ACPI: found 12 devices
[    0.681228] ACPI: ACPI bus type pnp unregistered
[    0.685937] system 00:01: iomem range 0xf0000000-0xf3ffffff has been reserved
[    0.693143] system 00:01: iomem range 0xfed13000-0xfed13fff has been reserved
[    0.700349] system 00:01: iomem range 0xfed14000-0xfed17fff has been reserved
[    0.707550] system 00:01: iomem range 0xfed18000-0xfed18fff has been reserved
[    0.714754] system 00:01: iomem range 0xfed19000-0xfed19fff has been reserved
[    0.721955] system 00:01: iomem range 0xfed1c000-0xfed1ffff has been reserved
[    0.729161] system 00:01: iomem range 0xfed20000-0xfed3ffff has been reserved
[    0.736362] system 00:01: iomem range 0xfed45000-0xfed99fff has been reserved
[    0.743568] system 00:01: iomem range 0xc0000-0xdffff could not be reserved
[    0.750596] system 00:01: iomem range 0xe0000-0xfffff could not be reserved
[    0.757637] system 00:06: ioport range 0x500-0x53f has been reserved
[    0.764059] system 00:06: ioport range 0x400-0x47f has been reserved
[    0.770480] system 00:06: ioport range 0x680-0x6ff has been reserved
[    0.813067] pci 0000:01:00.0: BAR 6: no parent found for of device [0xfffe0000-0xffffffff]
[    0.821480] pci 0000:00:1c.0: PCI bridge, secondary bus 0000:01
[    0.827468] pci 0000:00:1c.0:  IO window: 0x1000-0x1fff
[    0.832849] pci 0000:00:1c.0:  MEM window: 0x30100000-0x301fffff
[    0.839014] pci 0000:00:1c.0:  PREFETCH window: 0x00000030000000-0x000000300fffff
[    0.846688] pci 0000:00:1c.2: PCI bridge, secondary bus 0000:02
[    0.852672] pci 0000:00:1c.2:  IO window: disabled
[    0.857616] pci 0000:00:1c.2:  MEM window: disabled
[    0.862650] pci 0000:00:1c.2:  PREFETCH window: disabled
[    0.868117] pci 0000:00:1c.3: PCI bridge, secondary bus 0000:03
[    0.874100] pci 0000:00:1c.3:  IO window: disabled
[    0.879043] pci 0000:00:1c.3:  MEM window: disabled
[    0.884073] pci 0000:00:1c.3:  PREFETCH window: disabled
[    0.889540] pci 0000:00:1e.0: PCI bridge, secondary bus 0000:04
[    0.895523] pci 0000:00:1e.0:  IO window: disabled
[    0.900469] pci 0000:00:1e.0:  MEM window: disabled
[    0.905505] pci 0000:00:1e.0:  PREFETCH window: disabled
[    0.911015] pci 0000:00:1c.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[    0.917813] pci 0000:00:1c.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[    0.924609] pci 0000:00:1c.3: PCI INT D -> GSI 19 (level, low) -> IRQ 19
[    0.931517] NET: Registered protocol family 2
[    0.936131] IP route cache hash table entries: 4096 (order: 2, 16384 bytes)
[    0.943755] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[    0.951201] TCP bind hash table entries: 16384 (order: 5, 131072 bytes)
[    0.965351] TCP: Hash tables configured (established 16384 bind 16384)
[    0.967253] THIS IS MY PRINTK!! 1                
[    0.976784] TCP reno registered
[    0.980185] NET: Registered protocol family 1
[    0.984749] Trying to unpack rootfs image as initramfs...
[    0.990800] rootfs image is not initramfs (no cpio magic); looks like an initrd
[    1.004006] Freeing initrd memory: 2841k freed
[    1.016037] microcode: CPU0 sig=0x106c2, pf=0x8, revision=0x20d
[    1.022047] microcode: CPU1 sig=0x106c2, pf=0x8, revision=0x20d
[    1.028049] microcode: CPU2 sig=0x106c2, pf=0x8, revision=0x20d
[    1.034046] microcode: CPU3 sig=0x106c2, pf=0x8, revision=0x20d
[    1.040171] Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[    1.048105] Scanning for low memory corruption every 60 seconds
[    1.054927] audit: initializing netlink socket (disabled)
[    1.060427] type=2000 audit(1259936742.060:1): initialized
[    1.083704] HugeTLB registered 4 MB page size, pre-allocated 0 pages
[    1.097280] VFS: Disk quotas dquot_6.5.2
[    1.101492] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.110312] NTFS driver 2.1.29 [Flags: R/O].
[    1.115131] msgmni has been set to 978
[    1.120262] alg: No test for stdrng (krng)
[    1.124803] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    1.132315] io scheduler noop registered
[    1.136304] io scheduler anticipatory registered
[    1.140985] io scheduler deadline registered
[    1.145499] io scheduler cfq registered (default)
[    1.152361] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    1.158759] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    1.166267] ACPI: Power Button [PWRF]
[    1.170230] input: Sleep Button as /devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input1
[    1.178511] ACPI: Sleep Button [SLPB]
[    1.182777] processor LNXCPU:00: registered as cooling_device0
[    1.188846] processor LNXCPU:01: registered as cooling_device1
[    1.194897] processor LNXCPU:02: registered as cooling_device2
[    1.200963] processor LNXCPU:03: registered as cooling_device3
[    1.218937] Non-volatile memory driver v1.3
[    1.223289] intel_rng: Firmware space is locked read-only. If you can't or
[    1.223293] intel_rng: don't want to disable this in firmware setup, and if
[    1.223296] intel_rng: you are certain that your system has a functional
[    1.223299] intel_rng: RNG, try using the 'no_fwh_detect' option.
[    1.250928] Linux agpgart interface v0.103
[    1.255256] agpgart-intel 0000:00:00.0: Intel 945G Chipset
[    1.261119] agpgart-intel 0000:00:00.0: detected 7932K stolen memory
[    1.268002] THIS IS MY PRINTK!! 2               
[    1.275321] agpgart-intel 0000:00:00.0: AGP aperture is 256M @ 0x20000000
[    1.282463] [drm] Initialized drm 1.1.0 20060810
[    1.287204] pci 0000:00:02.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    1.297619] [drm] Initialized i915 1.6.0 20080730 for 0000:00:02.0 on minor 0
[    1.304891] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    1.529252] THIS IS MY PRINTK!! 3                
˙[    1.555108] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    1.562171] 00:09: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    1.568626] brd: module loaded
[    1.574233] loop: module loaded
[    1.577665] input: Macintosh mouse button emulation as /devices/virtual/input/input2
[    1.586285] ata_piix 0000:00:1f.1: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[    1.593690] scsi0 : ata_piix
[    1.596988] scsi1 : ata_piix
[    1.601111] ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0x20b0 irq 14
[    1.608147] ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x20b8 irq 15
[    1.615243] ata_piix 0000:00:1f.2: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[    1.622507] ata_piix 0000:00:1f.2: MAP [
[    1.626533]  P0 P2 P1 P3 ]
[    1.629638] scsi2 : ata_piix
[    1.632900] scsi3 : ata_piix
[    1.636254] ata3: SATA max UDMA/133 cmd 0x20c8 ctl 0x20ec bmdma 0x20a0 irq 19
[    1.643461] ata4: SATA max UDMA/133 cmd 0x20c0 ctl 0x20e8 bmdma 0x20a8 irq 19
[    1.651552] Intel(R) PRO/1000 Network Driver - version 7.3.21-k3-NAPI
[    1.658064] Copyright (c) 1999-2006 Intel Corporation.
[    1.663379] e1000e: Intel(R) PRO/1000 Network Driver - 1.0.2-k2
[    1.669364] e1000e: Copyright (c) 1999-2008 Intel Corporation.
[    1.675485] e100: Intel(R) PRO/100 Network Driver, 3.5.24-k2-NAPI
[    1.681645] e100: Copyright(c) 1999-2006 Intel Corporation
[    1.687526] sky2 driver version 1.23
[    1.691533] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[    1.697202] r8169 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    1.704882] eth0: RTL8168c/8111c at 0xdff48000, 00:1c:c0:a9:2b:49, XID 3c4000c0 IRQ 27
[    1.715899] console [netcon0] enabled
[    1.719631] netconsole: network logging started
[    1.724633] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.731302] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[    1.738534] ehci_hcd 0000:00:1d.7: EHCI Host Controller
[    1.744024] ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1
[    1.755481] ehci_hcd 0000:00:1d.7: debug port 1
[    1.760117] ehci_hcd 0000:00:1d.7: irq 23, io mem 0x302c4000
[    1.769812] ata1.00: CFA: InnoDisk Corp. - EDC4000 1GB, 071220b, max UDMA/66
[    1.775023] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00
[    1.775113] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.775119] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.775124] usb usb1: Product: EHCI Host Controller
[    1.775128] usb usb1: Manufacturer: Linux 2.6.31.6 ehci_hcd
[    1.775133] usb usb1: SerialNumber: 0000:00:1d.7
[    1.775383] usb usb1: configuration #1 chosen from 1 choice
[    1.775572] hub 1-0:1.0: USB hub found
[    1.775592] hub 1-0:1.0: 8 ports detected
[    1.775845] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.775995] uhci_hcd: USB Universal Host Controller Interface driver
[    1.776101] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[    1.776125] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[    1.776340] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    1.776353] uhci_hcd 0000:00:1d.0: detected 2 ports
[    1.776402] uhci_hcd 0000:00:1d.0: irq 23, io base 0x00002080
[    1.776511] usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
[    1.776516] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.776522] usb usb2: Product: UHCI Host Controller
[    1.776526] usb usb2: Manufacturer: Linux 2.6.31.6 uhci_hcd
[    1.776530] usb usb2: SerialNumber: 0000:00:1d.0
[    1.776747] usb usb2: configuration #1 chosen from 1 choice
[    1.776920] hub 2-0:1.0: USB hub found
[    1.776940] hub 2-0:1.0: 2 ports detected
[    1.777104] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[    1.777128] uhci_hcd 0000:00:1d.1: UHCI Host Controller
[    1.777306] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
[    1.777319] uhci_hcd 0000:00:1d.1: detected 2 ports
[    1.777364] uhci_hcd 0000:00:1d.1: irq 19, io base 0x00002060
[    1.777459] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
[    1.777464] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.777469] usb usb3: Product: UHCI Host Controller
[    1.777473] usb usb3: Manufacturer: Linux 2.6.31.6 uhci_hcd
[    1.777478] usb usb3: SerialNumber: 0000:00:1d.1
[    1.777677] usb usb3: configuration #1 chosen from 1 choice
[    1.777846] hub 3-0:1.0: USB hub found
[    1.777860] hub 3-0:1.0: 2 ports detected
[    1.777989] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[    1.778029] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[    1.778225] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
[    1.778241] uhci_hcd 0000:00:1d.2: detected 2 ports
[    1.778309] uhci_hcd 0000:00:1d.2: irq 18, io base 0x00002040
[    1.778402] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
[    1.778407] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.778412] usb usb4: Product: UHCI Host Controller
[    1.778417] usb usb4: Manufacturer: Linux 2.6.31.6 uhci_hcd
[    1.778421] usb usb4: SerialNumber: 0000:00:1d.2
[    1.778627] usb usb4: configuration #1 chosen from 1 choice
[    1.778803] hub 4-0:1.0: USB hub found
[    1.778818] hub 4-0:1.0: 2 ports detected
[    1.778949] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16
[    1.778971] uhci_hcd 0000:00:1d.3: UHCI Host Controller
[    1.779181] uhci_hcd 0000:00:1d.3: new USB bus registered, assigned bus number 5
[    1.779197] uhci_hcd 0000:00:1d.3: detected 2 ports
[    1.779262] uhci_hcd 0000:00:1d.3: irq 16, io base 0x00002020
[    1.779365] usb usb5: New USB device found, idVendor=1d6b, idProduct=0001
[    1.779370] usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.779375] usb usb5: Product: UHCI Host Controller
[    1.779380] usb usb5: Manufacturer: Linux 2.6.31.6 uhci_hcd
[    1.779384] usb usb5: SerialNumber: 0000:00:1d.3
[    1.779615] usb usb5: configuration #1 chosen from 1 choice
[    1.779796] hub 5-0:1.0: USB hub found
[    1.779811] hub 5-0:1.0: 2 ports detected
[    1.780215] usbcore: registered new interface driver usblp
[    1.780225] Initializing USB Mass Storage driver...
[    1.780393] usbcore: registered new interface driver usb-storage
[    1.780402] USB Mass Storage support registered.
[    1.780565] usbcore: registered new interface driver libusual
[    1.780834] usbcore: registered new interface driver usbserial
[    1.780840] usbserial: USB Serial Driver core
[    1.781366] PNP: No PS/2 controller found. Probing ports directly.
[    1.784498] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.784514] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.784816] mice: PS/2 mouse device common for all mice
[    1.785713] rtc_cmos 00:03: RTC can wake from S4
[    1.785891] rtc_cmos 00:03: rtc core: registered rtc_cmos as rtc0
[    1.785943] rtc0: alarms up to one month, 114 bytes nvram, hpet irqs
[    1.786108] i801_smbus 0000:00:1f.3: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[    1.786119] ACPI: I/O resource 0000:00:1f.3 [0x2000-0x201f] conflicts with ACPI region SMB1 [0x2000-0x2016]
[    1.786124] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[    1.786973] device-mapper: ioctl: 4.15.0-ioctl (2009-04-01) initialised: dm-devel@redhat.com
[    1.787372] cpuidle: using governor ladder
[    1.791274] usbcore: registered new interface driver hiddev
[    1.791412] usbcore: registered new interface driver usbhid
[    1.791419] usbhid: v2.6:USB HID core driver
[    1.791827] Advanced Linux Sound Architecture Driver Version 1.0.20.
[    1.792746] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[    1.824394] hda_codec: Unknown model for ALC662 rev1, trying auto-probe from BIOS...
[    1.829850] ALSA device list:
[    1.829855]  #0: HDA Intel at 0x302c0000 irq 22
[    1.829964] Netfilter messages via NETLINK v0.30.
[    1.830001] nf_conntrack version 0.5.0 (8048 buckets, 32192 max)
[    1.830654] ctnetlink v0.93: registering with nfnetlink.
[    1.832289] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.832337] TCP cubic registered
[    1.832341] Initializing XFRM netlink socket
[    1.833241] NET: Registered protocol family 10
[    1.835860] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    1.836009] IPv6 over IPv4 tunneling driver
[    1.837771] NET: Registered protocol family 17
[    1.838419] RPC: Registered udp transport module.
[    1.838424] RPC: Registered tcp transport module.
[    1.838518] Using IPI No-Shortcut mode
[    1.839069] registered taskstats version 1
[    1.839347]  Magic number: 5:196:434
[    1.840253] THIS IS MY PRINTK!! 4               
[    2.128155] usb 1-5: new high speed USB device using ehci_hcd and address 3
[    2.173254] THIS IS MY PRINTK!! 5                
[    2.244663] usb 1-5: New USB device found, idVendor=058f, idProduct=6387
[    2.244669] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.244674] usb 1-5: Product: Mass Storage Device
[    2.244678] usb 1-5: Manufacturer: Generic
[    2.244682] usb 1-5: SerialNumber: UZIHOJOMGNG8D5JOPKOZ
[    2.244945] usb 1-5: configuration #1 chosen from 1 choice
[    2.245367] scsi4 : SCSI emulation for USB Mass Storage devices
[    2.419376] ata1.00: 2047248 sectors, multi 2: LBA
[    2.424939] ata1.00: configured for UDMA/66
[    2.429464] scsi 0:0:0:0: Direct-Access    ATA      InnoDisk Corp. - 0712 PQ: 0 ANSI: 5
[    2.442882] sd 0:0:0:0: [sda] 2047248 512-byte logical blocks: (1.04 GB/999 MiB)
[    2.442903] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    2.451036] usb 3-1: new low speed USB device using uhci_hcd and address 2
[    2.462843] sd 0:0:0:0: [sda] Write Protect is off
[    2.467991] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    2.477562]  sda: sda1
[    2.481156] sd 0:0:0:0: [sda] Attached SCSI disk
[    2.485885] md: Waiting for all devices to be available before autodetect
[    2.492743] md: If you don't use raid, use raid=noautodetect
[    2.505252] THIS IS MY PRINTK!! 6               
[    2.612775] md: Autodetecting RAID arrays.
[    2.616961] md: Scanned 0 and added 0 devices.
[    2.621477] md: autorun ...
[    2.622288] usb 3-1: New USB device found, idVendor=0a81, idProduct=0101
[    2.622294] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    2.622301] usb 3-1: Product: USB Keyboard
[    2.622306] usb 3-1: Manufacturer: CHESEN
[    2.646489] md: ... autorun DONE.
[    2.649993] RAMDISK: gzip image found at block 0
[    2.650184] usb 3-1: configuration #1 chosen from 1 choice
[    2.676450] input: CHESEN USB Keyboard as /devices/pci0000:00/0000:00:1d.1/usb3/3-1/3-1:1.0/input/input3
[    2.688725] generic-usb 0003:0A81:0101.0001: input,hidraw0: USB HID v1.10 Keyboard [CHESEN USB Keyboard] on usb-0000:00:1d.1-1/input0
[    2.727801] input: CHESEN USB Keyboard as /devices/pci0000:00/0000:00:1d.1/usb3/3-1/3-1:1.1/input/input4
[    2.740679] generic-usb 0003:0A81:0101.0002: input,hidraw1: USB HID v1.10 Device [CHESEN USB Keyboard] on usb-0000:00:1d.1-1/input1
[    2.780253] THIS IS MY PRINTK!! 7               
[    2.836938] EXT2-fs warning: mounting unchecked fs, running e2fsck is recommended
[    2.844559] VFS: Mounted root (ext2 filesystem) on device 1:0.
[    2.850519] Freeing unused kernel memory: 380k freed
[    2.855865] Write protecting the kernel text: 4436k
[    2.860885] Write protecting the kernel read-only data: 2132k
[    2.874562] request_module: runaway loop modprobe binfmt-464c
[    2.880391] request_module: runaway loop modprobe binfmt-464c
[    2.886486] request_module: runaway loop modprobe binfmt-464c
[    2.892318] request_module: runaway loop modprobe binfmt-464c
[    2.898570] request_module: runaway loop modprobe binfmt-464c
[    2.925381] khelper used greatest stack depth: 7012 bytes left
[    3.048131] THIS IS MY PRINTK!! 8                
[    3.090088] khelper used greatest stack depth: 7004 bytes left
[    3.134834] khelper used greatest stack depth: 6880 bytes left
[    3.305130] THIS IS MY PRINTK!! 9                
[    3.485050] async/4 used greatest stack depth: 6756 bytes left
[    3.560380] THIS IS MY PRINTK!! 10               
[    3.815254] THIS IS MY PRINTK!! 11               
[    4.070131] THIS IS MY PRINTK!! 12               
[    4.325005] THIS IS MY PRINTK!! 13               
[    4.579380] THIS IS MY PRINTK!! 14               
[    4.834255] THIS IS MY PRINTK!! 15               
[    5.089006] THIS IS MY PRINTK!! 16
               
...

Thanks!


All times are GMT -5. The time now is 07:12 AM.