NVMe dtrace probes (#39)

Add probes for NVMe read/write operations and example dtrace script.

.gitignore

@@ -2,3 +2,4 @@
 /*/target
 **/Cargo.lock
 debug.out
+core

propolis/src/hw/nvme/ns.rs

@@ -156,6 +156,7 @@ impl NvmeNs {
         cq: Arc<Mutex<CompQueue>>,
         sq: Arc<Mutex<SubQueue>>,
     ) {
+        probe_nvme_read_enqueue!(|| (cid, cmd.slba, cmd.nlb));
         let off = self.nlb_to_size(cmd.slba as usize);
         let size = self.nlb_to_size(cmd.nlb as usize);
         // TODO: handles if it gets unmapped?
@@ -180,6 +181,7 @@ impl NvmeNs {
         cq: Arc<Mutex<CompQueue>>,
         sq: Arc<Mutex<SubQueue>>,
     ) {
+        probe_nvme_write_enqueue!(|| (cid, cmd.slba, cmd.nlb));
         let off = self.nlb_to_size(cmd.slba as usize);
         let size = self.nlb_to_size(cmd.nlb as usize);
         // TODO: handles if it gets unmapped?
@@ -257,6 +259,16 @@ impl BlockReq for Request {
             ),
         };
 
+        match self.op {
+            BlockOp::Read => {
+                probe_nvme_read_complete!(|| (self.cid));
+            }
+            BlockOp::Write => {
+                probe_nvme_write_complete!(|| (self.cid));
+            }
+            _ => {}
+        }
+
         let sq = self.sq.lock().unwrap();
         let mut cq = self.cq.lock().unwrap();
 

propolis/usdt.d

@@ -13,4 +13,14 @@ provider propolis {
 
 	/* vm_exit(vcpuid, rip, code) */
 	probe vm_exit(uint32_t, uint64_t, uint32_t);
+
+	/* nvme_read_enqueue(cid, slba, nlb) */
+	probe nvme_read_enqueue(uint16_t, uint64_t, uint16_t);
+	/* nvme_read_complete(cid) */
+	probe nvme_read_complete(uint16_t);
+
+	/* nvme_write_enqueue(cid, slba, nlb) */
+	probe nvme_write_enqueue(uint16_t, uint64_t, uint16_t);
+	/* nvme_write_complete(cid) */
+	probe nvme_write_complete(uint16_t);
 };

scripts/nvme-trace.d

@@ -0,0 +1,50 @@
+#!/usr/sbin/dtrace -s
+
+/*
+ * nvme-trace.d     Print propolis emulated NVMe read/write latency.
+ *
+ * USAGE: ./nvme-trace.d -p propolis-pid
+ */
+
+#pragma D option quiet
+
+dtrace:::BEGIN
+{
+    printf("Tracing propolis PID %d... Hit Ctrl-C to end.\n", $target);
+}
+
+struct io_info {
+    string op;
+    uint64_t ts;
+    uint64_t slba;
+    uint16_t nlb;
+};
+
+struct io_info io[uint64_t];
+
+propolis$target:::nvme_read_enqueue,
+propolis$target:::nvme_write_enqueue
+{
+    this->cid = args[0];
+    this->op = (probename == "nvme_read_enqueue") ? "read" : "write";
+    io[this->cid].op = this->op;
+    io[this->cid].ts = timestamp;
+    io[this->cid].slba = args[1];
+    io[this->cid].nlb = args[2];
+}
+
+propolis$target:::nvme_read_complete,
+propolis$target:::nvme_write_complete
+/io[args[0]].ts != 0/
+{
+    this->cid = args[0];
+    this->elapsed = timestamp - io[this->cid].ts;
+    this->elapsed_us = this->elapsed / 1000;
+    @time[io[this->cid].op] = quantize(this->elapsed_us);
+    printf("%s(cid=%u) %d blocks from LBA 0x%x in %uus\n",
+           io[this->cid].op, this->cid, io[this->cid].nlb, io[this->cid].slba, this->elapsed_us);
+}
+
+dtrace:::END
+{
+}