Re: 2.6.17-mm2 hrtimer code wedges at boot?
From: Valdis . Kletnieks
Date: Mon Jun 26 2006 - 22:11:27 EST
On Tue, 27 Jun 2006 01:27:09 +0200, Thomas Gleixner said:
> On Mon, 2006-06-26 at 17:41 -0400, Valdis.Kletnieks@xxxxxx wrote:
> > On Sat, 24 Jun 2006 06:19:14 PDT, Andrew Morton said:
> > >
> > > ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17/2.6.
17-mm2/
> >
> > I'm seeing a 2-minute or so hang at system startup, seems to be hrtimer
> > related.
>
> hrtimer is not really involved here.
OK, the fact that it was continually in kernel/hrtimer.c was a red herring? :)
(2.6.17-mm1 worked OK on this...)
> ktime_get_ts() has not been touched since it was merged in 2.6.16
>
> Can you provide the complete boot log up to this point please ? -
> Preferably over serial console.
Can't manage a serial console, you'll have to settle for the dmesg output
once we get up and running:
[ 0.000000] Linux version 2.6.17-mm2-test (valdis@xxxxxxxxxxxxxxxxxxxxxxx) (gcc version 4.1.1 20060619 (Red Hat 4.1.1-5)) #1 PREEMPT Mon Jun 26 20:20:32 EDT 2006
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
[ 0.000000] BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
[ 0.000000] BIOS-e820: 0000000000100000 - 000000002ffe2800 (usable)
[ 0.000000] BIOS-e820: 000000002ffe2800 - 0000000030000000 (reserved)
[ 0.000000] BIOS-e820: 00000000feda0000 - 00000000fee00000 (reserved)
[ 0.000000] BIOS-e820: 00000000ffb80000 - 0000000100000000 (reserved)
[ 0.000000] 767MB LOWMEM available.
[ 0.000000] On node 0 totalpages: 196578
[ 0.000000] DMA zone: 4096 pages, LIFO batch:0
[ 0.000000] Normal zone: 192482 pages, LIFO batch:31
[ 0.000000] DMI 2.3 present.
[ 0.000000] ACPI: RSDP (v000 DELL ) @ 0x000fde50
[ 0.000000] ACPI: RSDT (v001 DELL CPi R 0x27d40107 ASL 0x00000061) @ 0x000fde64
[ 0.000000] ACPI: FADT (v001 DELL CPi R 0x27d40107 ASL 0x00000061) @ 0x000fde90
[ 0.000000] ACPI: DSDT (v001 INT430 SYSFexxx 0x00001001 MSFT 0x0100000e) @ 0x00000000
[ 0.000000] ACPI: PM-Timer IO Port: 0x808
[ 0.000000] Allocating PCI resources starting at 40000000 (gap: 30000000:ceda0000)
[ 0.000000] Detected 1595.395 MHz processor.
[ 17.076049] Built 1 zonelists. Total pages: 196578
[ 17.076053] Kernel command line: console=tty0 vga=794 single
[ 17.076524] Local APIC disabled by BIOS -- you can enable it with "lapic"
[ 17.076537] mapped APIC to ffffd000 (01603000)
[ 17.076543] Enabling fast FPU save and restore... done.
[ 17.076547] Enabling unmasked SIMD FPU exception support... done.
[ 17.076553] Initializing CPU#0
[ 17.076661] CPU 0 irqstacks, hard=c04ec000 soft=c04eb000
[ 17.076666] PID hash table entries: 4096 (order: 12, 16384 bytes)
[ 17.076790] Console: colour dummy device 80x25
[ 17.077842] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 17.079004] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 17.106571] Memory: 773400k/786312k available (2308k kernel code, 12312k reserved, 989k data, 192k init, 0k highmem)
[ 17.106585] Checking if this processor honours the WP bit even in supervisor mode... Ok.
[ 17.166527] Calibrating delay using timer specific routine.. 3192.23 BogoMIPS (lpj=1596116)
[ 17.166576] Security Framework v1.0.0 initialized
[ 17.166585] SELinux: Initializing.
[ 17.166603] SELinux: Starting in permissive mode
[ 17.166615] selinux_register_security: Registering secondary module capability
[ 17.166623] Capability LSM initialized as secondary
[ 17.166642] Mount-cache hash table entries: 512
[ 17.166791] CPU: After generic identify, caps: 3febf9ff 00000000 00000000 00000000 00000000 00000000 00000000
[ 17.166805] CPU: After vendor identify, caps: 3febf9ff 00000000 00000000 00000000 00000000 00000000 00000000
[ 17.166819] CPU: Trace cache: 12K uops, L1 D cache: 8K
[ 17.166825] CPU: L2 cache: 512K
[ 17.166830] CPU: After all inits, caps: 3febf9ff 00000000 00000000 00000080 00000000 00000000 00000000
[ 17.166840] Intel machine check architecture supported.
[ 17.166850] Intel machine check reporting enabled on CPU#0.
[ 17.166857] CPU0: Intel P4/Xeon Extended MCE MSRs (12) available
[ 17.166865] CPU0: Thermal monitoring enabled
[ 17.166885] CPU: Intel(R) Pentium(R) 4 Mobile CPU 1.60GHz stepping 04
[ 17.166899] Checking 'hlt' instruction... OK.
[ 17.170623] SMP alternatives: switching to UP code
[ 17.170630] Freeing SMP alternatives: 0k freed
[ 17.170636] ACPI: Core revision 20060608
[ 17.213523] ACPI: setting ELCR to 0200 (from 0800)
[ 17.219183] checking if image is initramfs... it is
[ 17.365993] Freeing initrd memory: 1031k freed
[ 17.366492] NET: Registered protocol family 16
[ 17.367056] ACPI: ACPI Dock Station Driver
[ 17.367520] ACPI: bus type pci registered
[ 17.381009] PCI: PCI BIOS revision 2.10 entry at 0xfbfee, last bus=2
[ 17.381016] Setting up standard PCI resources
[ 17.411263] ACPI: Interpreter enabled
[ 17.411276] ACPI: Using PIC for interrupt routing
[ 17.415489] ACPI: PCI Root Bridge [PCI0] (0000:00)
[ 17.415503] PCI: Probing PCI hardware (bus 00)
[ 17.415912] ACPI: Assume root bridge [\_SB_.PCI0] bus is 0
[ 17.490877] PCI quirk: region 0800-087f claimed by ICH4 ACPI/GPIO/TCO
[ 17.490889] PCI quirk: region 0880-08bf claimed by ICH4 GPIO
[ 17.490990] PCI: Ignoring BAR0-3 of IDE controller 0000:00:1f.1
[ 17.491566] Boot video device is 0000:01:00.0
[ 17.492357] PCI: Transparent bridge - 0000:00:1e.0
[ 17.493327] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[ 17.643870] ACPI: PCI Interrupt Link [LNKA] (IRQs 9 10 *11)
[ 17.645210] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 7) *11
[ 17.646534] ACPI: PCI Interrupt Link [LNKC] (IRQs 9 10 *11)
[ 17.647875] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 7 9 10 *11)
[ 17.651329] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.AGP_._PRT]
[ 17.652545] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCIE._PRT]
[ 17.655595] ACPI: Power Resource [PADA] (on)
[ 17.657068] Linux Plug and Play Support v0.97 (c) Adam Belay
[ 17.657090] pnp: PnP ACPI init
[ 17.883045] pnp: PnP ACPI: found 17 devices
[ 17.883086] Intel 82802 RNG detected
[ 17.883685] usbcore: registered new driver usbfs
[ 17.883950] usbcore: registered new driver hub
[ 17.884558] PCI: Using ACPI for IRQ routing
[ 17.884568] PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report
[ 17.927252] pnp: 00:02: ioport range 0x4d0-0x4d1 has been reserved
[ 17.927264] pnp: 00:02: ioport range 0x800-0x805 could not be reserved
[ 17.927273] pnp: 00:02: ioport range 0x808-0x80f could not be reserved
[ 17.927286] pnp: 00:03: ioport range 0x806-0x807 has been reserved
[ 17.927295] pnp: 00:03: ioport range 0x810-0x85f could not be reserved
[ 17.927303] pnp: 00:03: ioport range 0x860-0x87f has been reserved
[ 17.927311] pnp: 00:03: ioport range 0x880-0x8bf has been reserved
[ 17.927319] pnp: 00:03: ioport range 0x8c0-0x8df has been reserved
[ 17.927326] pnp: 00:03: ioport range 0x8e0-0x8ff has been reserved
[ 17.927341] pnp: 00:04: ioport range 0xf000-0xf0fe has been reserved
[ 17.927349] pnp: 00:04: ioport range 0xf100-0xf1fe has been reserved
[ 17.927370] pnp: 00:04: ioport range 0xf200-0xf2fe has been reserved
[ 17.927379] pnp: 00:04: ioport range 0xf400-0xf4fe has been reserved
[ 17.927387] pnp: 00:04: ioport range 0xf500-0xf5fe has been reserved
[ 17.927396] pnp: 00:04: ioport range 0xf600-0xf6fe has been reserved
[ 17.927405] pnp: 00:04: ioport range 0xf800-0xf8fe has been reserved
[ 17.927413] pnp: 00:04: ioport range 0xf900-0xf9fe has been reserved
[ 17.927431] pnp: 00:09: ioport range 0x900-0x91f has been reserved
[ 17.927438] pnp: 00:09: ioport range 0x3f0-0x3f1 has been reserved
[ 17.927454] pnp: 00:0f: ioport range 0xbf40-0xbf5f has been reserved
[ 17.929718] PCI: Bridge: 0000:00:01.0
[ 17.929729] IO window: c000-cfff
[ 17.929740] MEM window: fc000000-fdffffff
[ 17.929750] PREFETCH window: d8000000-e7ffffff
[ 17.929792] PCI: Bus 3, cardbus bridge: 0000:02:01.0
[ 17.929799] IO window: 0000e000-0000e0ff
[ 17.929808] IO window: 0000e400-0000e4ff
[ 17.929818] PREFETCH window: 40000000-41ffffff
[ 17.929829] MEM window: f4000000-f5ffffff
[ 17.929838] PCI: Bus 7, cardbus bridge: 0000:02:01.1
[ 17.929844] IO window: 0000e800-0000e8ff
[ 17.929853] IO window: 00001000-000010ff
[ 17.929863] PREFETCH window: 42000000-43ffffff
[ 17.929873] MEM window: f6000000-f7ffffff
[ 17.929882] PCI: Bus 11, cardbus bridge: 0000:02:03.0
[ 17.929888] IO window: 00001400-000014ff
[ 17.929897] IO window: 00001800-000018ff
[ 17.929907] PREFETCH window: 44000000-45ffffff
[ 17.929917] MEM window: fa000000-fbffffff
[ 17.929926] PCI: Bridge: 0000:00:1e.0
[ 17.929934] IO window: e000-ffff
[ 17.929946] MEM window: f4000000-fbffffff
[ 17.929956] PREFETCH window: 40000000-46ffffff
[ 17.929991] PCI: Setting latency timer of device 0000:00:1e.0 to 64
[ 17.930019] PCI: Enabling device 0000:02:01.0 (0000 -> 0003)
[ 17.930959] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
[ 17.930967] PCI: setting IRQ 11 as level-triggered
[ 17.930973] ACPI: PCI Interrupt 0000:02:01.0[A] -> Link [LNKD] -> GSI 11 (level, low) -> IRQ 11
[ 17.931011] PCI: Enabling device 0000:02:01.1 (0000 -> 0003)
[ 17.931020] ACPI: PCI Interrupt 0000:02:01.1[A] -> Link [LNKD] -> GSI 11 (level, low) -> IRQ 11
[ 17.931055] ACPI: PCI Interrupt 0000:02:03.0[A] -> Link [LNKD] -> GSI 11 (level, low) -> IRQ 11
[ 17.931103] NET: Registered protocol family 2
[ 17.939416] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 17.939725] TCP established hash table entries: 131072 (order: 7, 524288 bytes)
[ 17.940277] TCP bind hash table entries: 65536 (order: 6, 262144 bytes)
[ 17.940808] TCP: Hash tables configured (established 131072 bind 65536)
[ 17.940816] TCP reno registered
[ 17.942193] Machine check exception polling timer started.
[ 17.942330] speedstep: frequency transition measured seems out of range (0 nSec), falling back to a safe one of 500000 nSec.
[ 17.954033] audit: initializing netlink socket (disabled)
[ 17.954062] audit(1151368037.173:1): initialized
[ 17.954290] VFS: Disk quotas dquot_6.5.1
[ 17.954321] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 17.954433] SELinux: Registering netfilter hooks
[ 17.960062] Initializing Cryptographic API
[ 17.960073] io scheduler noop registered
[ 17.960086] io scheduler anticipatory registered (default)
[ 17.960096] io scheduler deadline registered
[ 17.960113] io scheduler cfq registered
[ 17.961187] vesafb: framebuffer at 0xe0000000, mapped to 0xf0880000, using 5120k, total 32768k
[ 17.961199] vesafb: mode is 1280x1024x16, linelength=2560, pages=1
[ 17.961206] vesafb: protected mode interface info at c000:e140
[ 17.961213] vesafb: pmi: set display start = c00ce185, set palette = c00ce20a
[ 17.961218] vesafb: pmi: ports = b4c3 b503 ba03 c003 c103 c403 c503 c603 c703 c803 c903 cc03 ce03 cf03 d003 d103 d203 d303 d403 d503 da03 ff03
[ 17.961246] vesafb: scrolling: redraw
[ 17.961253] vesafb: Truecolor: size=0:5:6:5, shift=0:11:5:0
[ 18.042761] Console: switching to colour frame buffer device 160x64
[ 18.118229] fb0: VESA VGA frame buffer device
[ 18.119853] ACPI: Video Device [VID] (multi-head: yes rom: no post: no)
[ 18.137796] Hangcheck: starting hangcheck timer 0.9.0 (tick is 180 seconds, margin is 60 seconds).
[ 18.138627] Hangcheck: Using get_cycles().
[ 18.139017] Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
[ 18.140389] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 18.143041] 00:0d: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 18.145096] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 5
[ 18.145622] PCI: setting IRQ 5 as level-triggered
[ 18.145628] ACPI: PCI Interrupt 0000:00:1f.6[B] -> Link [LNKB] -> GSI 5 (level, low) -> IRQ 5
[ 18.150711] RAMDISK driver initialized: 16 RAM disks of 10240K size 1024 blocksize
[ 18.153515] loop: loaded (max 8 devices)
[ 18.155121] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
[ 18.155653] ACPI: PCI Interrupt 0000:02:00.0[A] -> Link [LNKC] -> GSI 11 (level, low) -> IRQ 11
[ 18.156511] 3c59x: Donald Becker and others. www.scyld.com/network/vortex.html
[ 18.157184] 0000:02:00.0: 3Com PCI 3c905C Tornado at f0804c00.
[ 18.180566] Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
[ 18.181173] ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
[ 18.181949] ICH3M: IDE controller at PCI slot 0000:00:1f.1
[ 18.182459] PCI: Enabling device 0000:00:1f.1 (0005 -> 0007)
[ 18.183917] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
[ 18.184443] ACPI: PCI Interrupt 0000:00:1f.1[A] -> Link [LNKA] -> GSI 11 (level, low) -> IRQ 11
[ 18.185291] ICH3M: chipset revision 2
[ 18.185626] ICH3M: not 100% native mode: will probe irqs later
[ 18.186180] ide0: BM-DMA at 0xbfa0-0xbfa7, BIOS settings: hda:DMA, hdb:DMA
[ 18.186891] ICH3M: too many IDE interfaces, no room in table
[ 18.187409] Probing IDE interface ide0...
[ 18.450439] hda: FUJITSU MHV2060AH, ATA DISK drive
[ 18.857812] hdb: TOSHIBA CD-RW/DVD-ROM SD-R2102, ATAPI CD/DVD-ROM drive
[ 18.913058] ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
[ 18.914653] hda: max request size: 128KiB
[ 18.945264] hda: 117210240 sectors (60011 MB) w/8192KiB Cache, CHS=65535/16/63, UDMA(100)
[ 18.950740] hda: cache flushes supported
[ 18.951152] hda: hda1 hda2
[ 18.961383] hdb: ATAPI 24X DVD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
[ 18.962142] Uniform CD-ROM driver Revision: 3.20
[ 18.995085] ohci_hcd: 2006 May 24 USB 1.1 'Open' Host Controller (OHCI) Driver (PCI)
[ 18.995333] USB Universal Host Controller Interface driver v3.0
[ 19.023273] ACPI: PCI Interrupt 0000:00:1d.0[A] -> Link [LNKA] -> GSI 11 (level, low) -> IRQ 11
[ 19.051304] PCI: Setting latency timer of device 0000:00:1d.0 to 64
[ 19.051312] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[ 19.079265] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 1
[ 19.106918] uhci_hcd 0000:00:1d.0: irq 11, io base 0x0000bf80
[ 19.134365] usb usb1: new device found, idVendor=0000, idProduct=0000
[ 19.161938] usb usb1: new device strings: Mfr=3, Product=2, SerialNumber=1
[ 19.189672] usb usb1: Product: UHCI Host Controller
[ 19.217323] usb usb1: Manufacturer: Linux 2.6.17-mm2-test uhci_hcd
[ 19.244946] usb usb1: SerialNumber: 0000:00:1d.0
[ 19.273170] usb usb1: configuration #1 chosen from 1 choice
[ 19.301075] hub 1-0:1.0: USB hub found
[ 19.329130] hub 1-0:1.0: 2 ports detected
[ 19.457331] ACPI: PCI Interrupt 0000:00:1d.2[C] -> Link [LNKC] -> GSI 11 (level, low) -> IRQ 11
[ 19.485837] PCI: Setting latency timer of device 0000:00:1d.2 to 64
[ 19.485845] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[ 19.514259] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 2
[ 19.542782] uhci_hcd 0000:00:1d.2: irq 11, io base 0x0000bf20
[ 19.570654] usb usb2: new device found, idVendor=0000, idProduct=0000
[ 19.598622] usb usb2: new device strings: Mfr=3, Product=2, SerialNumber=1
[ 19.626613] usb usb2: Product: UHCI Host Controller
[ 19.654475] usb usb2: Manufacturer: Linux 2.6.17-mm2-test uhci_hcd
[ 19.682341] usb usb2: SerialNumber: 0000:00:1d.2
[ 19.710556] usb usb2: configuration #1 chosen from 1 choice
[ 19.738543] hub 2-0:1.0: USB hub found
[ 19.766078] hub 2-0:1.0: 2 ports detected
[ 20.099723] usb 2-1: new low speed USB device using uhci_hcd and address 2
[ 20.295519] usb 2-1: new device found, idVendor=045e, idProduct=0023
[ 20.322578] usb 2-1: new device strings: Mfr=1, Product=2, SerialNumber=0
[ 20.349770] usb 2-1: Product: Microsoft Trackball Optical®
[ 20.376744] usb 2-1: Manufacturer: Microsoft
[ 20.404665] usb 2-1: configuration #1 chosen from 1 choice
[ 20.448492] input: Microsoft Microsoft Trackball Optical® as /class/input/input0
[ 20.475250] input: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.2-1
[ 20.502548] usbcore: registered new driver usbhid
[ 20.529495] drivers/usb/input/hid-core.c: v2.6:USB HID core driver
[ 20.557090] PNP: PS/2 Controller [PNP0303:KBC,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
[ 20.588872] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 20.616419] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 20.643830] mice: PS/2 mouse device common for all mice
[ 20.671744] input: PC Speaker as /class/input/input1
[ 20.703182] input: AT Translated Set 2 keyboard as /class/input/input2
[ 20.729296] i2c /dev entries driver
[ 20.756733] device-mapper: ioctl: 4.8.0-ioctl (2006-06-24) initialised: dm-devel@xxxxxxxxxx
[ 20.783167] EDAC MC: Ver: 2.0.0 Jun 26 2006
[ 20.809776] Advanced Linux Sound Architecture Driver Version 1.0.12rc1 (Thu Jun 22 13:55:50 2006 UTC).
[ 20.838718] ACPI: PCI Interrupt 0000:00:1f.5[B] -> Link [LNKB] -> GSI 5 (level, low) -> IRQ 5
[ 20.866066] PCI: Setting latency timer of device 0000:00:1f.5 to 64
[ 21.394886] input: DualPoint Stick as /class/input/input3
[ 21.440329] input: AlpsPS/2 ALPS DualPoint TouchPad as /class/input/input4
[ 21.477604] intel8x0_measure_ac97_clock: measured 50992 usecs
[ 21.504570] intel8x0: measured clock 96446 rejected
[ 21.531559] intel8x0: clocking to 48000
[ 21.561232] ALSA device list:
[ 21.587477] #0: Intel 82801CA-ICH3 with CS4205 at 0xd800, irq 5
[ 21.614454] TCP bic registered
[ 21.640610] Initializing IPsec netlink socket
[ 21.666716] NET: Registered protocol family 1
[ 21.692833] NET: Registered protocol family 10
[ 21.718628] lo: Disabled Privacy Extensions
[ 21.744152] IPv6 over IPv4 tunneling driver
[ 21.769925] NET: Registered protocol family 17
[ 21.794964] NET: Registered protocol family 15
[ 21.819751] Using IPI Shortcut mode
[ 21.844980] Freeing unused kernel memory: 192k freed
[ 21.869356] Time: tsc clocksource has been installed.
[ 21.893677] Write protecting the kernel read-only data: 406k
[ 23.024849] kjournald starting. Commit interval 5 seconds
[ 23.047661] EXT3-fs: mounted filesystem with ordered data mode.
[ 23.744042] security: 6 users, 5 roles, 1965 types, 81 bools, 1 sens, 256 cats
[ 23.766353] security: 58 classes, 123884 rules
[ 23.790135] SELinux: Completing initialization.
[ 23.811527] SELinux: Setting up existing superblocks.
[ 23.887619] SELinux: initialized (dev dm-0, type ext3), uses xattr
[ 24.028866] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
[ 24.050014] SELinux: initialized (dev usbfs, type usbfs), uses genfs_contexts
[ 24.071108] SELinux: initialized (dev selinuxfs, type selinuxfs), uses genfs_contexts
[ 24.092316] SELinux: initialized (dev mqueue, type mqueue), uses transition SIDs
[ 24.113511] SELinux: initialized (dev devpts, type devpts), uses transition SIDs
[ 24.134412] SELinux: initialized (dev eventpollfs, type eventpollfs), uses genfs_contexts
[ 24.155337] SELinux: initialized (dev inotifyfs, type inotifyfs), uses genfs_contexts
[ 24.176033] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
[ 24.196440] SELinux: initialized (dev debugfs, type debugfs), uses genfs_contexts
[ 24.216556] SELinux: initialized (dev futexfs, type futexfs), uses genfs_contexts
[ 24.236170] SELinux: initialized (dev pipefs, type pipefs), uses task SIDs
[ 24.255380] SELinux: initialized (dev sockfs, type sockfs), uses task SIDs
[ 24.274225] SELinux: initialized (dev proc, type proc), uses genfs_contexts
[ 24.292902] SELinux: initialized (dev bdev, type bdev), uses genfs_contexts
[ 24.311432] SELinux: initialized (dev rootfs, type rootfs), uses genfs_contexts
[ 24.330082] SELinux: initialized (dev sysfs, type sysfs), uses genfs_contexts
[ 24.351494] audit(1151368041.674:2): policy loaded auid=4294967295
[ 24.370664] audit(1151368041.666:3): avc: granted { load_policy } for pid=1 comm="init" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
[ 47.325645] SysRq : Show Regs
[ 47.346690]
[ 47.367719] Pid: 4, comm: khelper
[ 47.390642] EIP: 0060:[<c0119ee8>] CPU: 0
[ 47.412044] EIP is at getnstimeofday+0x9e/0xb8
[ 47.433443] EFLAGS: 00000283 Not tainted (2.6.17-mm2-test #1)
[ 47.455170] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 47.477049] ESI: 49972cca EDI: aebbd096 EBP: effd0e5c DS: 007b ES: 007b
[ 47.499328] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 47.521783] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 47.544819] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 47.567843] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 47.591251] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 47.614703] <c01006c5> kernel_thread_helper+0x5/0xb
[ 50.090792] SysRq : Show Regs
[ 50.114039]
[ 50.137151] Pid: 4, comm: khelper
[ 50.162186] EIP: 0060:[<c0119ee8>] CPU: 0
[ 50.185615] EIP is at getnstimeofday+0x9e/0xb8
[ 50.209150] EFLAGS: 00000283 Not tainted (2.6.17-mm2-test #1)
[ 50.233053] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 50.257138] ESI: 5e71e8ca EDI: a36f8e9d EBP: effd0e5c DS: 007b ES: 007b
[ 50.281259] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 50.305453] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 50.330131] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 50.354773] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 50.379825] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 50.405258] <c01006c5> kernel_thread_helper+0x5/0xb
[ 55.545338] SysRq : Show Regs
[ 55.569994]
[ 55.594154] Pid: 1, comm: init
[ 55.618624] EIP: 0060:[<c0119f93>] CPU: 0
[ 55.643037] EIP is at do_gettimeofday+0x91/0xc5
[ 55.667460] EFLAGS: 00000286 Not tainted (2.6.17-mm2-test #1)
[ 55.692237] EAX: e22faad7 EBX: 8ef8e1d2 ECX: db50bbaa EDX: 62dc8f7e
[ 55.717439] ESI: ffffffff EDI: 00000000 EBP: c16d7fa4 DS: 007b ES: 007b
[ 55.743054] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 55.768593] <c0116992> sys_time+0xe/0x2f <c0102261> sysenter_past_esp+0x56/0x79
[ 58.448886] SysRq : Show Regs
[ 58.474391]
[ 58.499617] Pid: 4, comm: khelper
[ 58.526676] EIP: 0060:[<c0119ee8>] CPU: 0
[ 58.551892] EIP is at getnstimeofday+0x9e/0xb8
[ 58.577215] EFLAGS: 00000207 Not tainted (2.6.17-mm2-test #1)
[ 58.602764] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 58.628351] ESI: 5216c0ca EDI: 7fd02419 EBP: effd0e5c DS: 007b ES: 007b
[ 58.654222] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 58.680144] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 58.706517] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 58.732893] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 58.759698] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 58.786851] <c01006c5> kernel_thread_helper+0x5/0xb
[ 64.039899] SysRq : Show Regs
[ 64.066806]
[ 64.093395] Pid: 4, comm: khelper
[ 64.122191] EIP: 0060:[<c0119ee8>] CPU: 0
[ 64.149014] EIP is at getnstimeofday+0x9e/0xb8
[ 64.175793] EFLAGS: 00000283 Not tainted (2.6.17-mm2-test #1)
[ 64.202650] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 64.229018] ESI: f0575aca EDI: 67ff297e EBP: effd0e5c DS: 007b ES: 007b
[ 64.254673] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 64.280580] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 64.307101] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 64.333709] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 64.360724] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 64.388065] <c01006c5> kernel_thread_helper+0x5/0xb
[ 67.461531] SysRq : Show Regs
[ 67.488572]
[ 67.515345] Pid: 4, comm: khelper
[ 67.543903] EIP: 0060:[<c0119ee8>] CPU: 0
[ 67.570469] EIP is at getnstimeofday+0x9e/0xb8
[ 67.596952] EFLAGS: 00000207 Not tainted (2.6.17-mm2-test #1)
[ 67.623641] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 67.650193] ESI: e3ae9cca EDI: 59fc3768 EBP: effd0e5c DS: 007b ES: 007b
[ 67.676652] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 67.702990] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 67.729631] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 67.756234] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 67.783266] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 67.810608] <c01006c5> kernel_thread_helper+0x5/0xb
[ 71.047876] SysRq : Show Regs
[ 71.074931]
[ 71.101725] Pid: 4, comm: khelper
[ 71.130292] EIP: 0060:[<c0119ee8>] CPU: 0
[ 71.156873] EIP is at getnstimeofday+0x9e/0xb8
[ 71.183369] EFLAGS: 00000207 Not tainted (2.6.17-mm2-test #1)
[ 71.210065] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 71.236614] ESI: ee5cdaca EDI: 4b118ebe EBP: effd0e5c DS: 007b ES: 007b
[ 71.263068] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 71.289404] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 71.316037] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 71.342641] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 71.369699] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 71.397075] <c01006c5> kernel_thread_helper+0x5/0xb
[ 73.446308] SysRq : Show Regs
[ 73.473414]
[ 73.500205] Pid: 1, comm: init
[ 73.526997] EIP: 0060:[<c0119f93>] CPU: 0
[ 73.553564] EIP is at do_gettimeofday+0x91/0xc5
[ 73.580059] EFLAGS: 00000286 Not tainted (2.6.17-mm2-test #1)
[ 73.606786] EAX: 274c0afb EBX: 8ef8e1d2 ECX: cb3967e7 EDX: dd58277e
[ 73.633399] ESI: ffffffff EDI: 00000000 EBP: c16d7fa4 DS: 007b ES: 007b
[ 73.659894] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 73.686698] <c0116992> sys_time+0xe/0x2f <c0102261> sysenter_past_esp+0x56/0x79
[ 76.464785] SysRq : Show Regs
[ 76.491801]
[ 76.518628] Pid: 4, comm: khelper
[ 76.547291] EIP: 0060:[<c0119ee8>] CPU: 0
[ 76.573824] EIP is at getnstimeofday+0x9e/0xb8
[ 76.600283] EFLAGS: 00000287 Not tainted (2.6.17-mm2-test #1)
[ 76.626966] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 76.653500] ESI: 447068ca EDI: 3531262b EBP: effd0e5c DS: 007b ES: 007b
[ 76.679940] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 76.706240] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 76.732842] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 76.759412] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 76.786408] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 76.813729] <c01006c5> kernel_thread_helper+0x5/0xb
[ 79.214850] SysRq : Show Regs
[ 79.241901]
[ 79.268685] Pid: 4, comm: khelper
[ 79.297242] EIP: 0060:[<c0119ee8>] CPU: 0
[ 79.323800] EIP is at getnstimeofday+0x9e/0xb8
[ 79.350280] EFLAGS: 00000283 Not tainted (2.6.17-mm2-test #1)
[ 79.376960] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 79.403485] ESI: 585bd6ca EDI: 2a54f33c EBP: effd0e5c DS: 007b ES: 007b
[ 79.429916] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 79.456234] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 79.482858] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 79.509452] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 79.536486] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 79.563846] <c01006c5> kernel_thread_helper+0x5/0xb
[ 81.520148] SysRq : Show Regs
[ 81.547171]
[ 81.573927] Pid: 4, comm: khelper
[ 81.602450] EIP: 0060:[<c0119ee8>] CPU: 0
[ 81.628985] EIP is at getnstimeofday+0x9e/0xb8
[ 81.655440] EFLAGS: 00000203 Not tainted (2.6.17-mm2-test #1)
[ 81.682098] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 81.708598] ESI: 8bd8a4ca EDI: 215de670 EBP: effd0e5c DS: 007b ES: 007b
[ 81.734997] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 81.761260] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 81.787828] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 81.814364] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 81.841334] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 81.868611] <c01006c5> kernel_thread_helper+0x5/0xb
[ 85.189743] SysRq : Show Regs
[ 85.216706]
[ 85.243406] Pid: 4, comm: khelper
[ 85.271856] EIP: 0060:[<c0119ee8>] CPU: 0
[ 85.298313] EIP is at getnstimeofday+0x9e/0xb8
[ 85.324694] EFLAGS: 00000207 Not tainted (2.6.17-mm2-test #1)
[ 85.351280] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 85.377718] ESI: ede792ca EDI: 12898677 EBP: effd0e5c DS: 007b ES: 007b
[ 85.404047] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 85.430268] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 85.456795] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 85.483292] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 85.510218] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 85.537472] <c01006c5> kernel_thread_helper+0x5/0xb
[ 88.115373] SysRq : Show Regs
[ 88.142335]
[ 88.169013] Pid: 4, comm: khelper
[ 88.197456] EIP: 0060:[<c0119ee8>] CPU: 0
[ 88.223929] EIP is at getnstimeofday+0x9e/0xb8
[ 88.250315] EFLAGS: 00000203 Not tainted (2.6.17-mm2-test #1)
[ 88.276932] EAX: efd562dc EBX: efd562dc ECX: 00000000 EDX: 07e3c408
[ 88.303435] ESI: 809e10ca EDI: 06b30ece EBP: effd0e5c DS: 007b ES: 007b
[ 88.329807] CR0: 8005003b CR2: 08069000 CR3: 2ffb8000 CR4: 000006d0
[ 88.356469] <c0125bac> ktime_get_ts+0x14/0x3f <c0110f68> copy_process+0x395/0x1111
[ 88.383810] <c0111f20> do_fork+0x8d/0x16a <c0100a27> kernel_thread+0x6c/0x74
[ 88.411220] <c01203d1> __call_usermodehelper+0x2b/0x44 <c0120922> run_workqueue+0x94/0xe9
[ 88.439162] <c0120e04> worker_thread+0xe1/0x115 <c0123252> kthread+0xb0/0xdc
[ 88.467114] <c01006c5> kernel_thread_helper+0x5/0xb
[ 89.913214] Real Time Clock Driver v1.12ac
[ 90.489593] audit(1151368108.794:4): avc: denied { dac_override } for pid=452 comm="dmesg" capability=1 scontext=system_u:system_r:dmesg_t:s0 tcontext=system_u:system_r:dmesg_t:s0 tclass=capability
And after that, things move along OK.
Attachment:
pgp00000.pgp
Description: PGP signature