logging: output ioctl debugging info

Instead pushing insane logging infra code into the library, let's keep
this stuff in the frontend. This is done by providing our own version
of the low level ioctl function as the library is exposing this as weak
symbol. This allows us to print the passthru structures and also the
timing information.

Signed-off-by: Daniel Wagner <dwagner@suse.de>

nvme-wrap.c

@@ -428,9 +428,3 @@ int nvme_cli_security_receive(struct nvme_dev *dev,
 
 	return -ENODEV;
 }
-
-void nvme_cli_set_debug(struct nvme_dev *dev, bool set)
-{
-	if (dev->type == NVME_DEV_DIRECT)
-		nvme_set_debug(set);
-}

nvme-wrap.h

@@ -147,5 +147,4 @@ int nvme_cli_security_send(struct nvme_dev *dev,
 int nvme_cli_security_receive(struct nvme_dev *dev,
 			      struct nvme_security_receive_args* args);
 
-void nvme_cli_set_debug(struct nvme_dev *dev, bool set);
 #endif /* _NVME_WRAP_H */

nvme.c

@@ -373,8 +373,8 @@ int parse_and_open(struct nvme_dev **dev, int argc, char **argv,
 	ret = get_dev(dev, argc, argv, O_RDONLY);
 	if (ret < 0)
 		argconfig_print_help(desc, opts);
-	else if (argconfig_parse_seen(opts, "verbose"))
-		nvme_cli_set_debug(*dev, true);
+	else
+		log_level = map_log_level(verbose_level, false);
 
 	return ret;
 }
@@ -3224,7 +3224,6 @@ static int list_subsys(int argc, char **argv, struct command *cmd,
 	if (argconfig_parse_seen(opts, "verbose"))
 		flags |= VERBOSE;
 
-	log_level = map_log_level(verbose_level, false);
 
 	r = nvme_create_root(stderr, log_level);
 	if (!r) {
@@ -3283,8 +3282,6 @@ static int list(int argc, char **argv, struct command *cmd, struct plugin *plugi
 	if (argconfig_parse_seen(opts, "verbose"))
 		flags |= VERBOSE;
 
-	log_level = map_log_level(verbose_level, false);
-
 	r = nvme_create_root(stderr, log_level);
 	if (!r) {
 		nvme_show_error("Failed to create topology root: %s", nvme_strerror(errno));
@@ -8866,8 +8863,6 @@ static int show_topology_cmd(int argc, char **argv, struct command *command, str
 		return -EINVAL;
 	}
 
-	log_level = map_log_level(verbose_level, false);
-
 	r = nvme_create_root(stderr, log_level);
 	if (!r) {
 		nvme_show_error("Failed to create topology root: %s", nvme_strerror(errno));

util/logging.c

@@ -1,5 +1,15 @@
 // SPDX-License-Identifier: GPL-2.0-or-later
 
+#include <inttypes.h>
+
+#include <stdint.h>
+#include <sys/ioctl.h>
+#include <sys/syslog.h>
+#include <sys/time.h>
+#include <linux/types.h>
+
+#include <libnvme.h>
+
 #include "logging.h"
 
 int log_level;
@@ -33,3 +43,92 @@ int map_log_level(int verbose, bool quiet)
 
 	return log_level;
 }
+
+static void nvme_show_common(struct nvme_passthru_cmd *cmd)
+{
+	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);
+}
+
+static void nvme_show_command(struct nvme_passthru_cmd *cmd, int err, struct timeval start,
+			      struct timeval end)
+{
+	nvme_show_common(cmd);
+	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));
+}
+
+static void nvme_show_command64(struct nvme_passthru_cmd64 *cmd, int err, struct timeval start,
+			      struct timeval end)
+{
+	nvme_show_common((struct nvme_passthru_cmd *)cmd);
+	printf("result       : %"PRIx64"\n", (uint64_t)(uintptr_t)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));
+}
+
+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 (log_level >= LOG_DEBUG)
+		gettimeofday(&start, NULL);
+
+	err = ioctl(fd, ioctl_cmd, cmd);
+
+	if (log_level >= LOG_DEBUG) {
+		gettimeofday(&end, NULL);
+		nvme_show_command(cmd, err, start, end);
+	}
+
+	if (err >= 0 && result)
+		*result = cmd->result;
+
+	return err;
+}
+
+int nvme_submit_passthru64(int fd, unsigned long ioctl_cmd,
+			   struct nvme_passthru_cmd64 *cmd,
+			   __u64 *result)
+{
+	struct timeval start;
+	struct timeval end;
+	int err;
+
+	if (log_level >= LOG_DEBUG)
+		gettimeofday(&start, NULL);
+
+
+	err = ioctl(fd, ioctl_cmd, cmd);
+
+	if (log_level >= LOG_DEBUG) {
+		gettimeofday(&end, NULL);
+		nvme_show_command64(cmd, err, start, end);
+	}
+
+	if (err >= 0 && result)
+		*result = cmd->result;
+
+	return err;
+}