From owner-freebsd-virtualization@FreeBSD.ORG Sat Jun 1 21:45:11 2013 Return-Path: Delivered-To: freebsd-virtualization@freebsd.org Received: from mx1.freebsd.org (mx1.FreeBSD.org [8.8.178.115]) by hub.freebsd.org (Postfix) with ESMTP id 89FF27FC for ; Sat, 1 Jun 2013 21:45:11 +0000 (UTC) (envelope-from mack@macktronics.com) Received: from coco.macktronics.com (coco.macktronics.com [209.181.253.65]) by mx1.freebsd.org (Postfix) with ESMTP id 339CAFF4 for ; Sat, 1 Jun 2013 21:45:10 +0000 (UTC) Received: from coco.macktronics.com (coco.macktronics.com [209.181.253.65]) by coco.macktronics.com (Postfix) with ESMTP id E28D94AC40 for ; Sat, 1 Jun 2013 16:39:45 -0500 (CDT) Date: Sat, 1 Jun 2013 16:39:45 -0500 (CDT) From: Dan Mack To: freebsd-virtualization@freebsd.org Subject: bhyve: calcru runtime msgs still ocurring ... Message-ID: <20130601163331.B14955@coco.macktronics.com> MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed X-BeenThere: freebsd-virtualization@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: "Discussion of various virtualization techniques FreeBSD supports." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 01 Jun 2013 21:45:11 -0000 Just FYI/FWIW I am still seeing semi-regular messages like this on my bhyve console on releases as late as head-251224: calcru: runtime went backwards from 992 usec to 982 usec for pid 794 (sshd) calcru: runtime went backwards from 702 usec to 695 usec for pid 800 (sendmail) I am not seeing stability issues due to this but they are concerning. Here's a dmesg from the host and from a guest both at 251224: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD is a registered trademark of The FreeBSD Foundation. FreeBSD 10.0-CURRENT #33 r251224: Sat Jun 1 09:48:40 CDT 2013 root@olive.macktronics.com:/usr/obj/usr/src/sys/MACKGEN amd64 FreeBSD clang version 3.3 (trunk 178860) 20130405 CPU: Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz (3200.18-MHz K8-class CPU) Origin = "GenuineIntel" Id = 0x206d7 Family = 0x6 Model = 0x2d Stepping = 7 Features=0xbfebfbff Features2=0x1fbee3bf AMD Features=0x2c100800 AMD Features2=0x1 TSC: P-state invariant, performance statistics real memory = 68719476736 (65536 MB) avail memory = 63216635904 (60288 MB) Event timer "LAPIC" quality 600 ACPI APIC Table: FreeBSD/SMP: Multiprocessor System Detected: 12 CPUs FreeBSD/SMP: 1 package(s) x 6 core(s) x 2 SMT threads cpu0 (BSP): APIC ID: 0 cpu1 (AP): APIC ID: 1 cpu2 (AP): APIC ID: 2 cpu3 (AP): APIC ID: 3 cpu4 (AP): APIC ID: 4 cpu5 (AP): APIC ID: 5 cpu6 (AP): APIC ID: 6 cpu7 (AP): APIC ID: 7 cpu8 (AP): APIC ID: 8 cpu9 (AP): APIC ID: 9 cpu10 (AP): APIC ID: 10 cpu11 (AP): APIC ID: 11 ioapic1 irqs 24-47 on motherboard ioapic0 irqs 0-23 on motherboard lapic0: Forcing LINT1 to edge trigger kbd1 at kbdmux0 ctl: CAM Target Layer loaded acpi0: on motherboard acpi0: Power Button (fixed) acpi0: reservation of f0000000, 18000000 (3) failed cpu0: on acpi0 cpu1: on acpi0 cpu2: on acpi0 cpu3: on acpi0 cpu4: on acpi0 cpu5: on acpi0 cpu6: on acpi0 cpu7: on acpi0 cpu8: on acpi0 cpu9: on acpi0 cpu10: on acpi0 cpu11: on acpi0 atrtc0: port 0x70-0x71,0x74-0x77 irq 8 on acpi0 Event timer "RTC" frequency 32768 Hz quality 0 attimer0: port 0x40-0x43,0x50-0x53 irq 0 on acpi0 Timecounter "i8254" frequency 1193182 Hz quality 0 Event timer "i8254" frequency 1193182 Hz quality 100 hpet0: iomem 0xfed00000-0xfed03fff on acpi0 Timecounter "HPET" frequency 14318180 Hz quality 950 Event timer "HPET" frequency 14318180 Hz quality 350 Event timer "HPET1" frequency 14318180 Hz quality 340 Event timer "HPET2" frequency 14318180 Hz quality 340 Event timer "HPET3" frequency 14318180 Hz quality 340 Event timer "HPET4" frequency 14318180 Hz quality 340 Event timer "HPET5" frequency 14318180 Hz quality 340 Event timer "HPET6" frequency 14318180 Hz quality 340 Event timer "HPET7" frequency 14318180 Hz quality 340 Timecounter "ACPI-fast" frequency 3579545 Hz quality 900 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0 acpi_button0: on acpi0 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 pcib1: at device 1.0 on pci0 pci1: on pcib1 pcib2: at device 1.1 on pci0 pci2: on pcib2 xhci0: mem 0xe3400000-0xe3401fff irq 16 at device 0.0 on pci2 usbus0: waiting for BIOS to give up control xhci0: 32 byte context size. usbus0 on xhci0 pcib3: at device 2.0 on pci0 pci3: on pcib3 vgapci0: port 0x3000-0x307f mem 0xe2000000-0xe2ffffff,0xd0000000-0xdfffffff,0xe0000000-0xe1ffffff irq 16 at device 0.0 on pci3 pci3: at device 0.1 (no driver attached) pcib4: at device 3.0 on pci0 pci4: on pcib4 pci0: at device 5.0 (no driver attached) pci0: at device 5.2 (no driver attached) pcib5: at device 17.0 on pci0 pci5: on pcib5 pci0: at device 22.0 (no driver attached) em0: port 0x4040-0x405f mem 0xe3500000-0xe351ffff,0xe3521000-0xe3521fff irq 20 at device 25.0 on pci0 em0: Using an MSI interrupt em0: Ethernet address: 4c:72:b9:d1:b2:d2 ehci0: mem 0xe3601000-0xe36013ff irq 16 at device 26.0 on pci0 usbus1: EHCI version 1.0 usbus1 on ehci0 pcib6: at device 28.0 on pci0 pci6: on pcib6 pcib7: at device 28.2 on pci0 pci7: on pcib7 pci7: at device 0.0 (no driver attached) pcib8: at device 28.3 on pci0 pci8: on pcib8 xhci1: mem 0xe3200000-0xe3201fff irq 19 at device 0.0 on pci8 usbus2: waiting for BIOS to give up control xhci1: 32 byte context size. usbus2 on xhci1 pcib9: at device 28.5 on pci0 pci9: on pcib9 em1: port 0x1000-0x101f mem 0xe3100000-0xe311ffff,0xe3120000-0xe3123fff irq 17 at device 0.0 on pci9 em1: Using MSIX interrupts with 3 vectors em1: Ethernet address: 4c:72:b9:d1:b2:d3 ehci1: mem 0xe3602000-0xe36023ff irq 23 at device 29.0 on pci0 usbus3: EHCI version 1.0 usbus3 on ehci1 pcib10: at device 30.0 on pci0 pci10: on pcib10 isab0: at device 31.0 on pci0 isa0: on isab0 ahci0: port 0x4068-0x406f,0x4074-0x4077,0x4060-0x4067,0x4070-0x4073,0x4020-0x403f mem 0xe3523000-0xe35237ff irq 18 at device 31.2 on pci0 ahci0: AHCI v1.30 with 6 6Gbps ports, Port Multiplier not supported ahcich0: at channel 0 on ahci0 ahcich1: at channel 1 on ahci0 ahcich2: at channel 2 on ahci0 ahcich3: at channel 3 on ahci0 ahcich4: at channel 4 on ahci0 ahcich5: at channel 5 on ahci0 ahciem0: on ahci0 pci0: at device 31.3 (no driver attached) orm0: at iomem 0xd1000-0xd1fff,0xd2000-0xd2fff on isa0 sc0: at flags 0x100 on isa0 sc0: VGA <16 virtual consoles, flags=0x300> vga0: at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 atkbdc0: at port 0x60,0x64 on isa0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] ppc0: cannot reserve I/O port range est0: on cpu0 p4tcc0: on cpu0 est1: on cpu1 p4tcc1: on cpu1 est2: on cpu2 p4tcc2: on cpu2 est3: on cpu3 p4tcc3: on cpu3 est4: on cpu4 p4tcc4: on cpu4 est5: on cpu5 p4tcc5: on cpu5 est6: on cpu6 p4tcc6: on cpu6 est7: on cpu7 p4tcc7: on cpu7 est8: on cpu8 p4tcc8: on cpu8 est9: on cpu9 p4tcc9: on cpu9 est10: on cpu10 p4tcc10: on cpu10 est11: on cpu11 p4tcc11: on cpu11 ZFS filesystem version: 5 ZFS storage pool version: features support (5000) Timecounters tick every 1.000 msec usbus0: 5.0Gbps Super Speed USB v3.0 usbus1: 480Mbps High Speed USB v2.0 usbus2: 5.0Gbps Super Speed USB v3.0 usbus3: 480Mbps High Speed USB v2.0 ugen1.1: at usbus1 uhub0: on usbus1 ugen0.1: <0x1033> at usbus0 uhub1: <0x1033 XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus0 ugen3.1: at usbus3 uhub2: on usbus3 ugen2.1: <0x1033> at usbus2 uhub3: <0x1033 XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus2 ses0 at ahciem0 bus 0 scbus6 target 0 lun 0 ses0: SEMB S-E-S 2.00 device ses0: SEMB SES Device ada0 at ahcich0 bus 0 scbus0 target 0 lun 0 ada0: ATA-9 SATA 3.x device ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes) ada0: Command Queueing enabled ada0: 122104MB (250069680 512 byte sectors: 16H 63S/T 16383C) ada0: Previously was known as ad4 ada1 at ahcich1 bus 0 scbus1 target 0 lun 0 ada1: ATA-9 SATA 3.x device ada1: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes) ada1: Command Queueing enabled ada1: 114473MB (234441648 512 byte sectors: 16H 63S/T 16383C) ada1: Previously was known as ad6 ada2 at ahcich2 bus 0 scbus2 target 0 lun 0 ada2: ATA-8 SATA 3.x device ada2: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes) ada2: Command Queueing enabled ada2: 1907729MB (3907029168 512 byte sectors: 16H 63S/T 16383C) ada2: Previously was known as ad8 ada3 at ahcich3 bus 0 scbus3 target 0 lun 0 ada3: ATA-8 SATA 3.x device ada3: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes) ada3: Command Queueing enabled ada3: 1907729MB (3907029168 512 byte sectors: 16H 63S/T 16383C) ada3: Previously was known as ad10 ada4 at ahcich4 bus 0 scbus4 target 0 lun 0 ada4: ATA-8 SATA 3.x device ada4: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes) ada4: Command Queueing enabled ada4: 1907729MB (3907029168 512 byte sectors: 16H 63S/T 16383C) ada4: Previously was known as ad12 ada5 at ahcich5 bus 0 scbus5 target 0 lun 0 ada5: ATA-8 SATA 3.x device ada5: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes) ada5: Command Queueing enabled ada5: 1907729MB (3907029168 512 byte sectors: 16H 63S/T 16383C) ada5: Previously was known as ad14 lapic1: Forcing LINT1 to edge trigger SMP: AP CPU #1 Launched! lapic9: Forcing LINT1 to edge trigger SMP: AP CPU #9 Launched! lapic4: Forcing LINT1 to edge trigger SMP: AP CPU #4 Launched! lapic7: Forcing LINT1 to edge trigger SMP: AP CPU #7 Launched! lapic3: Forcing LINT1 to edge trigger SMP: AP CPU #3 Launched! lapic8: Forcing LINT1 to edge trigger SMP: AP CPU #8 Launched! lapic10: Forcing LINT1 to edge trigger SMP: AP CPU #10 Launched! lapic6: Forcing LINT1 to edge trigger SMP: AP CPU #6 Launched! lapic5: Forcing LINT1 to edge trigger SMP: AP CPU #5 Launched! lapic2: Forcing LINT1 to edge trigger SMP: AP CPU #2 Launched! lapic11: Forcing LINT1 to edge trigger SMP: AP CPU #11 Launched! uhub1: 4 ports with 4 removable, self powered uhub3: 4 ports with 4 removable, self powered Root mount waiting for: usbus3 usbus1 uhub2: 2 ports with 2 removable, self powered uhub0: 2 ports with 2 removable, self powered Root mount waiting for: usbus3 usbus1 ugen3.2: at usbus3 uhub4: on usbus3 ugen1.2: at usbus1 uhub5: on usbus1 Root mount waiting for: usbus3 usbus1 uhub5: 6 ports with 6 removable, self powered uhub4: 8 ports with 8 removable, self powered ugen1.3: at usbus1 ukbd0: on usbus1 kbd2 at ukbd0 ugen3.3: at usbus3 Root mount waiting for: usbus3 ugen3.4: at usbus3 Trying to mount root from zfs:tron []... ums0: on usbus1 ums0: 5 buttons and [XYZ] coordinates ID=0 run0: <1.0> on usbus3 run0: MAC/BBP RT3070 (rev 0x0201), RF RT3020 (MIMO 1T1R), address 94:db:c9:e3:6e:c8 ubt0: on usbus3 WARNING: attempt to domain_add(bluetooth) after domainfinalize() WARNING: attempt to domain_add(netgraph) after domainfinalize() tap0: Ethernet address: 00:bd:c6:d3:3a:00 tap1: Ethernet address: 00:bd:c7:d3:3a:01 bridge0: Ethernet address: 02:4c:89:ce:33:00 tap0: promiscuous mode enabled bridge0: link state changed to DOWN em0: promiscuous mode enabled em0: link state changed to DOWN bridge1: Ethernet address: 02:4c:89:ce:33:01 tap1: promiscuous mode enabled bridge1: link state changed to DOWN em1: link state changed to DOWN em1: promiscuous mode enabled em1: link state changed to UP bridge1: link state changed to UP em0: link state changed to UP ==== dmesg from the guest root@drag:~ # dmesg | less Copyright (c) 1992-2013 The FreeBSD Project. Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD is a registered trademark of The FreeBSD Foundation. FreeBSD 10.0-CURRENT #33 r251224: Sat Jun 1 09:48:40 CDT 2013 root@olive.macktronics.com:/usr/obj/usr/src/sys/MACKGEN amd64 FreeBSD clang version 3.3 (trunk 178860) 20130405 CPU: Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz (3199.84-MHz K8-class CPU) Origin = "GenuineIntel" Id = 0x206d7 Family = 0x6 Model = 0x2d Stepping = 7 Features=0x8fa3ab7f Features2=0x83bee217 AMD Features=0x2c100800 AMD Features2=0x1 real memory = 2147483648 (2048 MB) avail memory = 1985380352 (1893 MB) Event timer "LAPIC" quality 400 ACPI APIC Table: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs FreeBSD/SMP: 2 package(s) x 1 core(s) cpu0 (BSP): APIC ID: 0 cpu1 (AP): APIC ID: 1 ioapic0: Changing APIC ID to 2 ioapic0 irqs 0-16 on motherboard module_register_init: MOD_LOAD (vesa, 0xffffffff807bb380, 0) error 19 kbd0 at kbdmux0 acpi0: on motherboard atrtc0: port 0x70-0x71,0x72-0x77 irq 8 on acpi0 Event timer "RTC" frequency 32768 Hz quality 0 Timecounter "ACPI-fast" frequency 3579545 Hz quality 900 acpi_timer0: <32-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 pcib0: no PRT entry for 0.31.INTA virtio_pci0: port 0x2000-0x201f mem 0xc0000000-0xc0001fff at device 1.0 on pci0 vtnet0: on virtio_pci0 virtio_pci0: host features: 0x1018020 virtio_pci0: negotiated features: 0x1018020 vtnet0: Ethernet address: 00:a0:98:58:64:98 virtio_pci1: port 0x2020-0x203f mem 0xc0002000-0xc0003fff at device 2.0 on pci0 vtnet1: on virtio_pci1 virtio_pci1: host features: 0x1018020 virtio_pci1: negotiated features: 0x1018020 vtnet1: Ethernet address: 00:a0:98:ec:d7:5d virtio_pci2: port 0x2040-0x207f mem 0xc0004000-0xc0005fff at device 3.0 on pci0 vtblk0: on virtio_pci2 virtio_pci2: host features: 0x10000004 virtio_pci2: negotiated features: 0x10000004 vtblk0: 24576MB (50331648 512 byte sectors) uart2: <16550 or compatible> port 0x3f8-0x3ff irq 4 at device 31.0 on pci0 uart2: console (9600,n,8,1) ctl: CAM Target Layer loaded Timecounters tick every 10.000 msec g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT SMP: AP CPU #1 Launched! Trying to mount root from ufs:/dev/vtbd0p2 [rw]... g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT g_handleattr: vtbd0 bio_length 24 len 28 -> EFAULT calcru: runtime went backwards from 992 usec to 982 usec for pid 794 (sshd) calcru: runtime went backwards from 702 usec to 695 usec for pid 800 (sendmail) Thanks, hope this might help, Dan