ioctl: Split latency outputs from debugging feature to show command

src/libnvme.map

@@ -5,6 +5,11 @@ LIBNVME_1_7 {
 		nvme_init_copy_range_f3;
 		nvme_insert_tls_key_versioned;
 		nvme_generate_tls_key_identity;
+		nvme_set_latency;
+		nvme_get_latency;
+		nvme_admin_to_string;
+		nvme_nvm_to_string;
+		nvme_ioctl_to_string;
 };
 
 LIBNVME_1_6 {

src/nvme/ioctl.c

@@ -14,6 +14,7 @@
 #include <string.h>
 #include <unistd.h>
 #include <inttypes.h>
+#include <stdarg.h>
 
 #include <sys/ioctl.h>
 #include <sys/stat.h>
@@ -26,6 +27,7 @@
 #include "util.h"
 
 static bool nvme_debug;
+static bool nvme_latency;
 
 static int nvme_verify_chr(int fd)
 {
@@ -42,14 +44,110 @@ static int nvme_verify_chr(int fd)
 	return 0;
 }
 
+static bool nvme_ioctl_cmd_admin(unsigned long req)
+{
+	return req == NVME_IOCTL_ADMIN_CMD || req == NVME_IOCTL_ADMIN64_CMD;
+}
+
+static bool nvme_ioctl_cmd_64(unsigned long req)
+{
+	return req == NVME_IOCTL_ADMIN64_CMD || req == NVME_IOCTL_IO64_CMD;
+}
+
+static const char *nvme_cmd_to_string(unsigned long req, __u8 opcode)
+{
+	const char *cmd_name;
+
+	if (nvme_ioctl_cmd_admin(req))
+		cmd_name = nvme_admin_to_string(opcode);
+	else
+		cmd_name = nvme_nvm_to_string(opcode);
+
+	if (!cmd_name)
+		return "Unknown";
+
+	return cmd_name;
+}
+
+static void nvme_show_latency(unsigned long req, __u8 *opcode, struct timeval *start,
+			      struct timeval *end)
+{
+	struct timeval latency;
+
+	timersub(end, start, &latency);
+
+	if (opcode)
+		printf("%s%s Command opcode: %02x (%s) ",
+		       nvme_ioctl_cmd_admin(req) ? "Admin" : "IO",
+		       nvme_ioctl_cmd_64(req) ? "64" : "", *opcode,
+		       nvme_cmd_to_string(req, *opcode));
+	else
+		printf("ioctl: %lx (%s) ", req, nvme_ioctl_to_string(req));
+
+	printf("latency: %lu us\n", latency.tv_sec * 1000000 + latency.tv_usec);
+}
+
+static bool nvme_ioctl_cmd(unsigned long req)
+{
+	bool ioctl_cmd = false;
+
+	switch (req) {
+	case NVME_IOCTL_ADMIN_CMD:
+		fallthrough;
+	case NVME_IOCTL_IO_CMD:
+		fallthrough;
+	case NVME_IOCTL_ADMIN64_CMD:
+		fallthrough;
+	case NVME_IOCTL_IO64_CMD:
+		ioctl_cmd = true;
+		break;
+	default:
+		break;
+	}
+
+	return ioctl_cmd;
+}
+
+static int nvme_ioctl(int fd, unsigned long req, ...)
+{
+	struct timeval start;
+	struct timeval end;
+	int err;
+	va_list ap;
+	__u8 *opcode = NULL;
+	void *ioctl_cmd = NULL;
+
+	if (nvme_ioctl_cmd(req)) {
+		va_start(ap, req);
+		ioctl_cmd = va_arg(ap, void *);
+		va_end(ap);
+		if (nvme_ioctl_cmd_64(req))
+			opcode = &((struct nvme_passthru_cmd64 *)ioctl_cmd)->opcode;
+		else
+			opcode = &((struct nvme_passthru_cmd *)ioctl_cmd)->opcode;
+	}
+
+	if (nvme_get_latency())
+		gettimeofday(&start, NULL);
+
+	err = ioctl_cmd ? ioctl(fd, req, ioctl_cmd) : ioctl(fd, req);
+
+	if (nvme_get_latency()) {
+		gettimeofday(&end, NULL);
+		nvme_show_latency(req, opcode, &start, &end);
+	}
+
+	return err;
+}
+
 int nvme_subsystem_reset(int fd)
 {
 	int ret;
 
 	ret = nvme_verify_chr(fd);
 	if (ret)
 		return ret;
-	return ioctl(fd, NVME_IOCTL_SUBSYS_RESET);
+	return nvme_ioctl(fd, NVME_IOCTL_SUBSYS_RESET);
 }
 
 int nvme_ctrl_reset(int fd)
@@ -59,7 +157,7 @@ int nvme_ctrl_reset(int fd)
 	ret = nvme_verify_chr(fd);
 	if (ret)
 		return ret;
-	return ioctl(fd, NVME_IOCTL_RESET);
+	return nvme_ioctl(fd, NVME_IOCTL_RESET);
 }
 
 int nvme_ns_rescan(int fd)
@@ -69,53 +167,59 @@ int nvme_ns_rescan(int fd)
 	ret = nvme_verify_chr(fd);
 	if (ret)
 		return ret;
-	return ioctl(fd, NVME_IOCTL_RESCAN);
+	return nvme_ioctl(fd, NVME_IOCTL_RESCAN);
 }
 
 int nvme_get_nsid(int fd, __u32 *nsid)
 {
 	errno = 0;
-	*nsid = ioctl(fd, NVME_IOCTL_ID);
+	*nsid = nvme_ioctl(fd, NVME_IOCTL_ID);
 	return -1 * (errno != 0);
 }
 
+static void nvme_show_command(unsigned long ioctl_cmd, void *cmd, int err)
+{
+	struct nvme_passthru_cmd *cmd32 = cmd;
+	struct nvme_passthru_cmd64 *cmd64 = cmd;
+
+	printf("opcode       : %02x\n", cmd32->opcode);
+	printf("flags        : %02x\n", cmd32->flags);
+	printf("rsvd1        : %04x\n", cmd32->rsvd1);
+	printf("nsid         : %08x\n", cmd32->nsid);
+	printf("cdw2         : %08x\n", cmd32->cdw2);
+	printf("cdw3         : %08x\n", cmd32->cdw3);
+	printf("data_len     : %08x\n", cmd32->data_len);
+	printf("metadata_len : %08x\n", cmd32->metadata_len);
+	printf("addr         : %"PRIx64"\n", (uint64_t)(uintptr_t)cmd32->addr);
+	printf("metadata     : %"PRIx64"\n", (uint64_t)(uintptr_t)cmd32->metadata);
+	printf("cdw10        : %08x\n", cmd32->cdw10);
+	printf("cdw11        : %08x\n", cmd32->cdw11);
+	printf("cdw12        : %08x\n", cmd32->cdw12);
+	printf("cdw13        : %08x\n", cmd32->cdw13);
+	printf("cdw14        : %08x\n", cmd32->cdw14);
+	printf("cdw15        : %08x\n", cmd32->cdw15);
+	printf("timeout_ms   : %08x\n", cmd32->timeout_ms);
+	if (nvme_ioctl_cmd_64(ioctl_cmd))
+		printf("result       : %"PRIx64"\n", (uint64_t)(uintptr_t)cmd64->result);
+	else
+		printf("result       : %08x\n", cmd32->result);
+	printf("err          : %d\n", err);
+}
+
 static int nvme_submit_passthru64(int fd, unsigned long ioctl_cmd,
 				  struct nvme_passthru_cmd64 *cmd,
 				  __u64 *result)
 {
-	int err = ioctl(fd, ioctl_cmd, cmd);
+	int err = nvme_ioctl(fd, ioctl_cmd, cmd);
+
+	if (nvme_get_debug())
+		nvme_show_command(ioctl_cmd, cmd, err);
 
 	if (err >= 0 && result)
 		*result = cmd->result;
 	return err;
 }
 
-static void nvme_show_command(struct nvme_passthru_cmd *cmd, int err, struct timeval start,
-			      struct timeval end)
-{
-	printf("opcode       : %02x\n", cmd->opcode);
-	printf("flags        : %02x\n", cmd->flags);
-	printf("rsvd1        : %04x\n", cmd->rsvd1);
-	printf("nsid         : %08x\n", cmd->nsid);
-	printf("cdw2         : %08x\n", cmd->cdw2);
-	printf("cdw3         : %08x\n", cmd->cdw3);
-	printf("data_len     : %08x\n", cmd->data_len);
-	printf("metadata_len : %08x\n", cmd->metadata_len);
-	printf("addr         : %"PRIx64"\n", (uint64_t)(uintptr_t)cmd->addr);
-	printf("metadata     : %"PRIx64"\n", (uint64_t)(uintptr_t)cmd->metadata);
-	printf("cdw10        : %08x\n", cmd->cdw10);
-	printf("cdw11        : %08x\n", cmd->cdw11);
-	printf("cdw12        : %08x\n", cmd->cdw12);
-	printf("cdw13        : %08x\n", cmd->cdw13);
-	printf("cdw14        : %08x\n", cmd->cdw14);
-	printf("cdw15        : %08x\n", cmd->cdw15);
-	printf("timeout_ms   : %08x\n", cmd->timeout_ms);
-	printf("result       : %08x\n", cmd->result);
-	printf("err          : %d\n", err);
-	printf("latency      : %lu us\n",
-	       (end.tv_sec - start.tv_sec) * 1000000 + (end.tv_usec - start.tv_usec));
-}
-
 void nvme_set_debug(bool debug)
 {
 	nvme_debug = debug;
@@ -126,22 +230,25 @@ bool nvme_get_debug(void)
 	return nvme_debug;
 }
 
+void nvme_set_latency(bool latency)
+{
+	nvme_latency = latency;
+}
+
+bool nvme_get_latency(void)
+{
+	return nvme_latency;
+}
+
 static int nvme_submit_passthru(int fd, unsigned long ioctl_cmd,
 				struct nvme_passthru_cmd *cmd, __u32 *result)
 {
-	struct timeval start;
-	struct timeval end;
 	int err;
 
-	if (nvme_get_debug())
-		gettimeofday(&start, NULL);
-
-	err = ioctl(fd, ioctl_cmd, cmd);
+	err = nvme_ioctl(fd, ioctl_cmd, cmd);
 
-	if (nvme_get_debug()) {
-		gettimeofday(&end, NULL);
-		nvme_show_command(cmd, err, start, end);
-	}
+	if (nvme_get_debug())
+		nvme_show_command(ioctl_cmd, cmd, err);
 
 	if (err >= 0 && result)
 		*result = cmd->result;

src/nvme/ioctl.h

@@ -4049,7 +4049,7 @@ int nvme_dim_send(struct nvme_dim_args *args);
 
 /**
  * nvme_set_debug - Set NVMe command debugging output
- * @debug:	true to enable or false to disable
+ * @debug: true to enable or false to disable
  */
 void nvme_set_debug(bool debug);
 
@@ -4059,4 +4059,17 @@ void nvme_set_debug(bool debug);
  * Return: false if disabled or true if enabled.
  */
 bool nvme_get_debug(void);
+
+/**
+ * nvme_set_latency - Set NVMe command latency output
+ * @latency: true to enable or false to disable
+ */
+void nvme_set_latency(bool latency);
+
+/**
+ * nvme_get_latency - Get NVMe command latency output
+ *
+ * Return: false if disabled or true if enabled.
+ */
+bool nvme_get_latency(void);
 #endif /* _LIBNVME_IOCTL_H */

src/nvme/util.c

@@ -1116,3 +1116,94 @@ void *__nvme_alloc(size_t len)
 	memset(p, 0, _len);
 	return p;
 }
+
+static const char * const admin_opcode[] = {
+	[nvme_admin_delete_sq] = "Delete I/O Submission Queue",
+	[nvme_admin_create_sq] = "Create I/O Submission Queue",
+	[nvme_admin_get_log_page] = "Get Log Page",
+	[nvme_admin_delete_cq] = "Delete I/O Completion Queue",
+	[nvme_admin_create_cq] = "Create I/O Completion Queue",
+	[nvme_admin_identify] = "Identify",
+	[nvme_admin_abort_cmd] = "Abort",
+	[nvme_admin_set_features] = "Set Features",
+	[nvme_admin_get_features] = "Get Features",
+	[nvme_admin_async_event] = "Asynchronous Event Request",
+	[nvme_admin_ns_mgmt] = "Namespace Management",
+	[nvme_admin_fw_commit] = "Firmware Commit",
+	[nvme_admin_fw_download] = "Firmware Image Download",
+	[nvme_admin_dev_self_test] = "Device Self-test",
+	[nvme_admin_ns_attach] = "Namespace Attachment",
+	[nvme_admin_keep_alive] = "Keep Alive",
+	[nvme_admin_directive_send] = "Directive Send",
+	[nvme_admin_directive_recv] = "Directive Receive",
+	[nvme_admin_virtual_mgmt] = "Virtualization Management",
+	[nvme_admin_nvme_mi_send] = "NVMe-MI Send",
+	[nvme_admin_nvme_mi_recv] = "NVMe-MI Receive",
+	[nvme_admin_dbbuf] = "Doorbell Buffer Config",
+	[nvme_admin_format_nvm] = "Format NVM",
+	[nvme_admin_security_send] = "Security Send",
+	[nvme_admin_security_recv] = "Security Receive",
+	[nvme_admin_sanitize_nvm] = "Sanitize",
+	[nvme_admin_get_lba_status] = "Get LBA Status",
+};
+
+static const char * const nvm_opcode[] = {
+	[nvme_cmd_flush] = "Flush",
+	[nvme_cmd_write] = "Write",
+	[nvme_cmd_read] = "Read",
+	[nvme_cmd_write_uncor] = "Write Uncorrectable",
+	[nvme_cmd_compare] = "Compare",
+	[nvme_cmd_write_zeroes] = "Write Zeroes",
+	[nvme_cmd_dsm] = "Dataset Management",
+	[nvme_cmd_resv_register] = "Reservation Register",
+	[nvme_cmd_resv_report] = "Reservation Report",
+	[nvme_cmd_resv_acquire] = "Reservation Acquire",
+	[nvme_cmd_resv_release] = "Reservation Release",
+	[nvme_cmd_verify] = "Verify",
+	[nvme_cmd_copy] = "Copy",
+	[nvme_zns_cmd_mgmt_send] = "Zone Management Send",
+	[nvme_zns_cmd_mgmt_recv] = "Zone Management Receive",
+	[nvme_zns_cmd_append] = "Zone Append",
+};
+
+const char *nvme_admin_to_string(__u8 opcode)
+{
+	if (opcode < ARRAY_SIZE(admin_opcode))
+		return admin_opcode[opcode];
+
+	return NULL;
+}
+
+const char *nvme_nvm_to_string(__u8 opcode)
+{
+	if (opcode < ARRAY_SIZE(nvm_opcode))
+		return nvm_opcode[opcode];
+
+	return NULL;
+}
+
+const char *nvme_ioctl_to_string(unsigned long req)
+{
+	switch (req) {
+	case NVME_IOCTL_ID:
+		return "ID";
+	case NVME_IOCTL_RESET:
+		return "Reset";
+	case NVME_IOCTL_SUBSYS_RESET:
+		return "Subsystem reset";
+	case NVME_IOCTL_RESCAN:
+		return "Rescan";
+	case NVME_IOCTL_ADMIN_CMD:
+		return "Admin command";
+	case NVME_IOCTL_IO_CMD:
+		return "IO command";
+	case NVME_IOCTL_ADMIN64_CMD:
+		return "Admin64 command";
+	case NVME_IOCTL_IO64_CMD:
+		return "IO64 command";
+	default:
+		break;
+	}
+
+	return NULL;
+}