vmm, devices: Move logging of 0x80 timestamp to its own device

This is a cleaner approach to handling the I/O port write to 0x80.
Whilst doing this also use generate the timestamp at the start of the VM
creation. For consistency use the same timestamp for the ARM equivalent.

Signed-off-by: Rob Bradford <robert.bradford@intel.com>

devices/src/legacy/debug_port.rs

@@ -0,0 +1,86 @@
+// Copyright © 2022 Intel Corporation
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+
+use std::fmt;
+use std::time::Instant;
+use vm_device::BusDevice;
+
+/// Debug I/O port, see:
+/// https://www.intel.com/content/www/us/en/support/articles/000005500/boards-and-kits.html
+///
+/// Since we're not a physical platform, we can freely assign code ranges for
+/// debugging specific parts of our virtual platform.
+pub enum DebugIoPortRange {
+    Firmware,
+    Bootloader,
+    Kernel,
+    Userspace,
+    Custom,
+}
+
+#[cfg(target_arch = "x86_64")]
+const DEBUG_IOPORT_PREFIX: &str = "Debug I/O port";
+
+#[cfg(target_arch = "x86_64")]
+impl DebugIoPortRange {
+    fn from_u8(value: u8) -> DebugIoPortRange {
+        match value {
+            0x00..=0x1f => DebugIoPortRange::Firmware,
+            0x20..=0x3f => DebugIoPortRange::Bootloader,
+            0x40..=0x5f => DebugIoPortRange::Kernel,
+            0x60..=0x7f => DebugIoPortRange::Userspace,
+            _ => DebugIoPortRange::Custom,
+        }
+    }
+}
+
+#[cfg(target_arch = "x86_64")]
+impl fmt::Display for DebugIoPortRange {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match self {
+            DebugIoPortRange::Firmware => write!(f, "{}: Firmware", DEBUG_IOPORT_PREFIX),
+            DebugIoPortRange::Bootloader => write!(f, "{}: Bootloader", DEBUG_IOPORT_PREFIX),
+            DebugIoPortRange::Kernel => write!(f, "{}: Kernel", DEBUG_IOPORT_PREFIX),
+            DebugIoPortRange::Userspace => write!(f, "{}: Userspace", DEBUG_IOPORT_PREFIX),
+            DebugIoPortRange::Custom => write!(f, "{}: Custom", DEBUG_IOPORT_PREFIX),
+        }
+    }
+}
+
+pub struct DebugPort {
+    timestamp: Instant,
+}
+
+impl DebugPort {
+    pub fn new(timestamp: Instant) -> Self {
+        Self { timestamp }
+    }
+}
+
+impl BusDevice for DebugPort {
+    fn read(&mut self, _base: u64, _offset: u64, _data: &mut [u8]) {
+        error!("Invalid read to debug port")
+    }
+
+    fn write(
+        &mut self,
+        _base: u64,
+        _offset: u64,
+        data: &[u8],
+    ) -> Option<std::sync::Arc<std::sync::Barrier>> {
+        let elapsed = self.timestamp.elapsed();
+
+        let code = data[0];
+        info!(
+            "[{} code 0x{:x}] {}.{:>06} seconds",
+            DebugIoPortRange::from_u8(code),
+            code,
+            elapsed.as_secs(),
+            elapsed.as_micros()
+        );
+
+        None
+    }
+}

devices/src/legacy/mod.rs

@@ -6,6 +6,8 @@
 // found in the LICENSE-BSD-3-Clause file.
 
 mod cmos;
+#[cfg(target_arch = "x86_64")]
+mod debug_port;
 #[cfg(feature = "fwdebug")]
 mod fwdebug;
 #[cfg(target_arch = "aarch64")]
@@ -18,6 +20,8 @@ mod serial;
 mod uart_pl011;
 
 pub use self::cmos::Cmos;
+#[cfg(target_arch = "x86_64")]
+pub use self::debug_port::DebugPort;
 #[cfg(feature = "fwdebug")]
 pub use self::fwdebug::FwDebugDevice;
 pub use self::i8042::I8042Device;

devices/src/legacy/uart_pl011.rs

@@ -10,6 +10,7 @@ use crate::{read_le_u32, write_le_u32};
 use std::collections::VecDeque;
 use std::fmt;
 use std::sync::{Arc, Barrier};
+use std::time::Instant;
 use std::{io, result};
 use versionize::{VersionMap, Versionize, VersionizeResult};
 use versionize_derive::Versionize;
@@ -120,6 +121,7 @@ impl Pl011 {
         id: String,
         irq: Arc<dyn InterruptSourceGroup>,
         out: Option<Box<dyn io::Write + Send>>,
+        timestamp: Instant,
     ) -> Self {
         Self {
             id,
@@ -140,7 +142,7 @@ impl Pl011 {
             read_trigger: 1u32,
             irq,
             out,
-            timestamp: std::time::Instant::now(),
+            timestamp,
         }
     }
 
@@ -495,6 +497,7 @@ mod tests {
             String::from(SERIAL_NAME),
             Arc::new(TestInterrupt::new(intr_evt.try_clone().unwrap())),
             Some(Box::new(pl011_out.clone())),
+            Instant::now(),
         );
 
         pl011.write(0, UARTDR as u64, &[b'x', b'y']);
@@ -515,6 +518,7 @@ mod tests {
             String::from(SERIAL_NAME),
             Arc::new(TestInterrupt::new(intr_evt.try_clone().unwrap())),
             Some(Box::new(pl011_out)),
+            Instant::now(),
         );
 
         // write 1 to the interrupt event fd, so that read doesn't block in case the event fd

vmm/src/device_manager.rs

@@ -83,6 +83,7 @@ use std::os::unix::io::{AsRawFd, FromRawFd, RawFd};
 use std::path::PathBuf;
 use std::result;
 use std::sync::{Arc, Mutex};
+use std::time::Instant;
 use vfio_ioctls::{VfioContainer, VfioDevice};
 use virtio_devices::transport::VirtioPciDevice;
 use virtio_devices::transport::VirtioTransport;
@@ -941,6 +942,9 @@ pub struct DeviceManager {
 
     // List of unique identifiers provided at boot through the configuration.
     boot_id_list: BTreeSet<String>,
+
+    // Start time of the VM
+    timestamp: Instant,
 }
 
 impl DeviceManager {
@@ -957,6 +961,7 @@ impl DeviceManager {
         force_iommu: bool,
         restoring: bool,
         boot_id_list: BTreeSet<String>,
+        timestamp: Instant,
     ) -> DeviceManagerResult<Arc<Mutex<Self>>> {
         let device_tree = Arc::new(Mutex::new(DeviceTree::new()));
 
@@ -1080,6 +1085,7 @@ impl DeviceManager {
             restoring,
             io_uring_supported: None,
             boot_id_list,
+            timestamp,
         };
 
         let device_manager = Arc::new(Mutex::new(device_manager));
@@ -1521,6 +1527,15 @@ impl DeviceManager {
                 .map_err(DeviceManagerError::BusError)?;
         }
 
+        // 0x80 debug port
+        let debug_port = Arc::new(Mutex::new(devices::legacy::DebugPort::new(self.timestamp)));
+        self.bus_devices
+            .push(Arc::clone(&debug_port) as Arc<Mutex<dyn BusDevice>>);
+        self.address_manager
+            .io_bus
+            .insert(debug_port, 0x80, 0x1)
+            .map_err(DeviceManagerError::BusError)?;
+
         Ok(())
     }
 
@@ -1722,6 +1737,7 @@ impl DeviceManager {
             id.clone(),
             interrupt_group,
             serial_writer,
+            self.timestamp,
         )));
 
         self.bus_devices

vmm/src/vm.rs

@@ -66,8 +66,6 @@ use std::cmp;
 use std::collections::BTreeMap;
 use std::collections::HashMap;
 use std::convert::TryInto;
-#[cfg(target_arch = "x86_64")]
-use std::fmt;
 use std::fs::{File, OpenOptions};
 use std::io::{self, Read, Write};
 use std::io::{Seek, SeekFrom};
@@ -78,6 +76,7 @@ use std::ops::Deref;
 use std::os::unix::net::UnixStream;
 use std::panic::AssertUnwindSafe;
 use std::sync::{Arc, Mutex, RwLock};
+use std::time::Instant;
 use std::{result, str, thread};
 use thiserror::Error;
 use vm_device::Bus;
@@ -344,78 +343,15 @@ impl VmState {
     }
 }
 
-// Debug I/O port
-#[cfg(target_arch = "x86_64")]
-const DEBUG_IOPORT: u16 = 0x80;
-#[cfg(target_arch = "x86_64")]
-const DEBUG_IOPORT_PREFIX: &str = "Debug I/O port";
-
-#[cfg(target_arch = "x86_64")]
-/// Debug I/O port, see:
-/// https://www.intel.com/content/www/us/en/support/articles/000005500/boards-and-kits.html
-///
-/// Since we're not a physical platform, we can freely assign code ranges for
-/// debugging specific parts of our virtual platform.
-pub enum DebugIoPortRange {
-    Firmware,
-    Bootloader,
-    Kernel,
-    Userspace,
-    Custom,
-}
-#[cfg(target_arch = "x86_64")]
-impl DebugIoPortRange {
-    fn from_u8(value: u8) -> DebugIoPortRange {
-        match value {
-            0x00..=0x1f => DebugIoPortRange::Firmware,
-            0x20..=0x3f => DebugIoPortRange::Bootloader,
-            0x40..=0x5f => DebugIoPortRange::Kernel,
-            0x60..=0x7f => DebugIoPortRange::Userspace,
-            _ => DebugIoPortRange::Custom,
-        }
-    }
-}
-
-#[cfg(target_arch = "x86_64")]
-impl fmt::Display for DebugIoPortRange {
-    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-        match self {
-            DebugIoPortRange::Firmware => write!(f, "{}: Firmware", DEBUG_IOPORT_PREFIX),
-            DebugIoPortRange::Bootloader => write!(f, "{}: Bootloader", DEBUG_IOPORT_PREFIX),
-            DebugIoPortRange::Kernel => write!(f, "{}: Kernel", DEBUG_IOPORT_PREFIX),
-            DebugIoPortRange::Userspace => write!(f, "{}: Userspace", DEBUG_IOPORT_PREFIX),
-            DebugIoPortRange::Custom => write!(f, "{}: Custom", DEBUG_IOPORT_PREFIX),
-        }
-    }
-}
-
 struct VmOps {
     memory: GuestMemoryAtomic<GuestMemoryMmap>,
     #[cfg(target_arch = "x86_64")]
     io_bus: Arc<Bus>,
     mmio_bus: Arc<Bus>,
     #[cfg(target_arch = "x86_64")]
-    timestamp: std::time::Instant,
-    #[cfg(target_arch = "x86_64")]
     pci_config_io: Arc<Mutex<dyn BusDevice>>,
 }
 
-impl VmOps {
-    #[cfg(target_arch = "x86_64")]
-    // Log debug io port codes.
-    fn log_debug_ioport(&self, code: u8) {
-        let elapsed = self.timestamp.elapsed();
-
-        info!(
-            "[{} code 0x{:x}] {}.{:>06} seconds",
-            DebugIoPortRange::from_u8(code),
-            code,
-            elapsed.as_secs(),
-            elapsed.as_micros()
-        );
-    }
-}
-
 impl VmmOps for VmOps {
     fn guest_mem_write(&self, gpa: u64, buf: &[u8]) -> hypervisor::vm::Result<usize> {
         self.memory
@@ -476,11 +412,6 @@ impl VmmOps for VmOps {
     fn pio_write(&self, port: u64, data: &[u8]) -> hypervisor::vm::Result<()> {
         use pci::{PCI_CONFIG_IO_PORT, PCI_CONFIG_IO_PORT_SIZE};
 
-        if port == DEBUG_IOPORT as u64 && data.len() == 1 {
-            self.log_debug_ioport(data[0]);
-            return Ok(());
-        }
-
         if (PCI_CONFIG_IO_PORT..(PCI_CONFIG_IO_PORT + PCI_CONFIG_IO_PORT_SIZE)).contains(&port) {
             self.pci_config_io.lock().unwrap().write(
                 PCI_CONFIG_IO_PORT,
@@ -553,6 +484,7 @@ impl Vm {
         hypervisor: Arc<dyn hypervisor::Hypervisor>,
         activate_evt: EventFd,
         restoring: bool,
+        timestamp: Instant,
     ) -> Result<Self> {
         let kernel = config
             .lock()
@@ -604,6 +536,7 @@ impl Vm {
             force_iommu,
             restoring,
             boot_id_list,
+            timestamp,
         )
         .map_err(Error::DeviceManager)?;
 
@@ -623,8 +556,6 @@ impl Vm {
             io_bus,
             mmio_bus,
             #[cfg(target_arch = "x86_64")]
-            timestamp: std::time::Instant::now(),
-            #[cfg(target_arch = "x86_64")]
             pci_config_io,
         });
 
@@ -780,6 +711,8 @@ impl Vm {
         console_pty: Option<PtyPair>,
         console_resize_pipe: Option<File>,
     ) -> Result<Self> {
+        let timestamp = Instant::now();
+
         #[cfg(feature = "tdx")]
         let tdx_enabled = config.lock().unwrap().tdx.is_some();
         hypervisor.check_required_extensions().unwrap();
@@ -833,6 +766,7 @@ impl Vm {
             hypervisor,
             activate_evt,
             false,
+            timestamp,
         )?;
 
         // The device manager must create the devices from here as it is part
@@ -859,6 +793,8 @@ impl Vm {
         hypervisor: Arc<dyn hypervisor::Hypervisor>,
         activate_evt: EventFd,
     ) -> Result<Self> {
+        let timestamp = Instant::now();
+
         hypervisor.check_required_extensions().unwrap();
         let vm = hypervisor.create_vm().unwrap();
 
@@ -907,6 +843,7 @@ impl Vm {
             hypervisor,
             activate_evt,
             true,
+            timestamp,
         )
     }
 
@@ -922,6 +859,8 @@ impl Vm {
         memory_manager_data: &MemoryManagerSnapshotData,
         existing_memory_files: Option<HashMap<u32, File>>,
     ) -> Result<Self> {
+        let timestamp = Instant::now();
+
         hypervisor.check_required_extensions().unwrap();
         let vm = hypervisor.create_vm().unwrap();
 
@@ -961,6 +900,7 @@ impl Vm {
             hypervisor,
             activate_evt,
             true,
+            timestamp,
         )
     }