Recent changes (master)

[Jens Axboe <axboe@kernel.dk>]

The following changes since commit db4f6340e04716285ea56fe26d76381c3adabe58:

  btt_plot.py: Use `with open() as ...` context manager (2020-03-20 15:53:50 -0600)

are available in the Git repository at:

  git://git.kernel.dk/blktrace.git master

for you to fetch changes up to e81829a565162d41e2f551dc5e0f74f22f319554:

  blkparse: Fix up the sector and length of split completions (2020-05-07 12:22:37 -0600)

----------------------------------------------------------------
Andreas Gruenbacher (4):
      blkparse: Fix device in event tracking error messages
      blkparse: Allow request tracking on non md/dm devices
      blkparse: Initialize and test for undefined request tracking timestamps
      blkparse: Fix up the sector and length of split completions

 blkparse.c | 169 +++++++++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 130 insertions(+), 39 deletions(-)

---

Diff of recent changes:

diff --git a/blkparse.c b/blkparse.c
index 28bdf15..796059b 100644
--- a/blkparse.c
+++ b/blkparse.c
@@ -25,6 +25,7 @@
 #include <stdio.h>
 #include <fcntl.h>
 #include <stdlib.h>
+#include <stdarg.h>
 #include <string.h>
 #include <getopt.h>
 #include <errno.h>
@@ -261,17 +262,21 @@ static struct trace *t_alloc_list;
 /*
  * for tracking individual ios
  */
-struct io_track {
-	struct rb_node rb_node;
-
+struct io_track_req {
 	struct process_pid_map *ppm;
-	__u64 sector;
 	unsigned long long allocation_time;
 	unsigned long long queue_time;
 	unsigned long long dispatch_time;
 	unsigned long long completion_time;
 };
 
+struct io_track {
+	struct rb_node rb_node;
+	struct io_track_req *req;
+	struct io_track *next;
+	__u64 sector;
+};
+
 static int ndevices;
 static struct per_dev_info *devices;
 static char *get_dev_name(struct per_dev_info *, char *, int);
@@ -326,6 +331,21 @@ static int have_drv_data = 0;
 #define CPU_IDX(cpu)	((cpu) / CPUS_PER_LONG)
 #define CPU_BIT(cpu)	((cpu) & (CPUS_PER_LONG - 1))
 
+static void io_warn_unless(struct blk_io_trace *t, int condition,
+			   const char *fmt, ...)
+{
+	va_list ap;
+
+	if (condition)
+		return;
+	va_start(ap, fmt);
+	printf("(%d,%d) request %llu + %u: ",
+	       MAJOR(t->device), MINOR(t->device),
+	       t->sector, t->bytes);
+	vfprintf(stderr, fmt, ap);
+	va_end(ap);
+}
+
 static void output_binary(void *buf, int len)
 {
 	if (dump_binary) {
@@ -976,6 +996,11 @@ static struct io_track *__find_track(struct per_dev_info *pdi, __u64 sector)
 	return NULL;
 }
 
+static inline struct io_track *first_iot(struct io_track_req *req)
+{
+	return (struct io_track *)(req + 1);
+}
+
 static struct io_track *find_track(struct per_dev_info *pdi, pid_t pid,
 				   __u64 sector)
 {
@@ -983,10 +1008,19 @@ static struct io_track *find_track(struct per_dev_info *pdi, pid_t pid,
 
 	iot = __find_track(pdi, sector);
 	if (!iot) {
-		iot = malloc(sizeof(*iot));
-		iot->ppm = find_ppm(pid);
-		if (!iot->ppm)
-			iot->ppm = add_ppm_hash(pid, "unknown");
+		struct io_track_req *req;
+
+		req = malloc(sizeof(*req) + sizeof(*iot));
+		req->ppm = find_ppm(pid);
+		if (!req->ppm)
+			req->ppm = add_ppm_hash(pid, "unknown");
+		req->allocation_time = -1ULL;
+		req->queue_time = -1ULL;
+		req->dispatch_time = -1ULL;
+		req->completion_time = -1ULL;
+		iot = first_iot(req);
+		iot->req = req;
+		iot->next = NULL;
 		iot->sector = sector;
 		track_rb_insert(pdi, iot);
 	}
@@ -1006,7 +1040,7 @@ static void log_track_frontmerge(struct per_dev_info *pdi,
 	if (!iot) {
 		if (verbose)
 			fprintf(stderr, "merge not found for (%d,%d): %llu\n",
-				MAJOR(pdi->dev), MINOR(pdi->dev),
+				MAJOR(t->device), MINOR(t->device),
 				(unsigned long long) t->sector + t_sec(t));
 		return;
 	}
@@ -1019,19 +1053,16 @@ static void log_track_frontmerge(struct per_dev_info *pdi,
 static void log_track_getrq(struct per_dev_info *pdi, struct blk_io_trace *t)
 {
 	struct io_track *iot;
+	struct io_track_req *req;
 
 	if (!track_ios)
 		return;
 
 	iot = find_track(pdi, t->pid, t->sector);
-	iot->allocation_time = t->time;
-}
-
-static inline int is_remapper(struct per_dev_info *pdi)
-{
-	int major = MAJOR(pdi->dev);
-
-	return (major = 253 || major = 9);
+	req = iot->req;
+	io_warn_unless(t, req->allocation_time = -1ULL,
+		       "confused about %s time", "allocation");
+	req->allocation_time = t->time;
 }
 
 /*
@@ -1041,14 +1072,34 @@ static inline int is_remapper(struct per_dev_info *pdi)
 static void log_track_queue(struct per_dev_info *pdi, struct blk_io_trace *t)
 {
 	struct io_track *iot;
+	struct io_track_req *req;
 
 	if (!track_ios)
 		return;
-	if (!is_remapper(pdi))
-		return;
 
 	iot = find_track(pdi, t->pid, t->sector);
-	iot->dispatch_time = t->time;
+	req = iot->req;
+	io_warn_unless(t, req->dispatch_time = -1ULL,
+		       "confused about %s time", "dispatch");
+	req->dispatch_time = t->time;
+}
+
+static void log_track_split(struct per_dev_info *pdi, struct blk_io_trace *t)
+{
+	struct io_track *iot, *split;
+
+	/*
+	 * With a split request, the completion event will refer to the last
+	 * part of the original request, but other events might refer to other
+	 * parts.
+	 */
+	iot = find_track(pdi, t->pid, t->sector);
+	split = malloc(sizeof(*iot));
+	split->req = iot->req;
+	split->next = iot->next;
+	iot->next = split;
+	split->sector = iot->sector + t_sec(t);
+	track_rb_insert(pdi, split);
 }
 
 /*
@@ -1059,20 +1110,24 @@ static unsigned long long log_track_insert(struct per_dev_info *pdi,
 {
 	unsigned long long elapsed;
 	struct io_track *iot;
+	struct io_track_req *req;
 
 	if (!track_ios)
 		return -1;
 
 	iot = find_track(pdi, t->pid, t->sector);
-	iot->queue_time = t->time;
+	req = iot->req;
+	io_warn_unless(t, req->queue_time = -1ULL,
+		       "confused about %s time", "queue");
+	req->queue_time = t->time;
 
-	if (!iot->allocation_time)
+	if (req->allocation_time = -1ULL)
 		return -1;
 
-	elapsed = iot->queue_time - iot->allocation_time;
+	elapsed = req->queue_time - req->allocation_time;
 
 	if (per_process_stats) {
-		struct per_process_info *ppi = find_ppi(iot->ppm->pid);
+		struct per_process_info *ppi = find_ppi(req->ppm->pid);
 		int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 
 		if (ppi && elapsed > ppi->longest_allocation_wait[w])
@@ -1088,8 +1143,9 @@ static unsigned long long log_track_insert(struct per_dev_info *pdi,
 static unsigned long long log_track_issue(struct per_dev_info *pdi,
 					  struct blk_io_trace *t)
 {
-	unsigned long long elapsed;
+	unsigned long long elapsed = -1ULL;
 	struct io_track *iot;
+	struct io_track_req *req;
 
 	if (!track_ios)
 		return -1;
@@ -1100,16 +1156,20 @@ static unsigned long long log_track_issue(struct per_dev_info *pdi,
 	if (!iot) {
 		if (verbose)
 			fprintf(stderr, "issue not found for (%d,%d): %llu\n",
-				MAJOR(pdi->dev), MINOR(pdi->dev),
+				MAJOR(t->device), MINOR(t->device),
 				(unsigned long long) t->sector);
 		return -1;
 	}
 
-	iot->dispatch_time = t->time;
-	elapsed = iot->dispatch_time - iot->queue_time;
+	req = iot->req;
+	io_warn_unless(t, req->dispatch_time = -1ULL,
+		       "confused about %s time", "dispatch");
+	req->dispatch_time = t->time;
+	if (req->queue_time != -1ULL)
+		elapsed = req->dispatch_time - req->queue_time;
 
-	if (per_process_stats) {
-		struct per_process_info *ppi = find_ppi(iot->ppm->pid);
+	if (elapsed != -1ULL && per_process_stats) {
+		struct per_process_info *ppi = find_ppi(req->ppm->pid);
 		int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 
 		if (ppi && elapsed > ppi->longest_dispatch_wait[w])
@@ -1119,14 +1179,34 @@ static unsigned long long log_track_issue(struct per_dev_info *pdi,
 	return elapsed;
 }
 
+static void fixup_complete(struct per_dev_info *pdi, struct blk_io_trace *t)
+{
+	struct io_track *iot;
+	__u64 start_sector;
+
+	iot = __find_track(pdi, t->sector);
+	if (!iot)
+		return;
+
+	/*
+	 * When a split io completes, the sector and length of the completion
+	 * refer to the last part of the original request.  Fix the sector and
+	 * length of the complete event to match the original request.
+	 */
+	start_sector = first_iot(iot->req)->sector;
+	t->bytes += (t->sector - start_sector) << 9;
+	t->sector = start_sector;
+}
+
 /*
  * return time between dispatch and complete
  */
 static unsigned long long log_track_complete(struct per_dev_info *pdi,
 					     struct blk_io_trace *t)
 {
-	unsigned long long elapsed;
-	struct io_track *iot;
+	unsigned long long elapsed = -1ULL;
+	struct io_track *iot, *next;
+	struct io_track_req *req;
 
 	if (!track_ios)
 		return -1;
@@ -1135,16 +1215,20 @@ static unsigned long long log_track_complete(struct per_dev_info *pdi,
 	if (!iot) {
 		if (verbose)
 			fprintf(stderr,"complete not found for (%d,%d): %llu\n",
-				MAJOR(pdi->dev), MINOR(pdi->dev),
+				MAJOR(t->device), MINOR(t->device),
 				(unsigned long long) t->sector);
 		return -1;
 	}
 
-	iot->completion_time = t->time;
-	elapsed = iot->completion_time - iot->dispatch_time;
+	req = iot->req;
+	io_warn_unless(t, req->completion_time = -1ULL,
+		       "confused about %s time", "completion");
+	req->completion_time = t->time;
+	if (req->dispatch_time != -1ULL)
+		elapsed = req->completion_time - req->dispatch_time;
 
-	if (per_process_stats) {
-		struct per_process_info *ppi = find_ppi(iot->ppm->pid);
+	if (elapsed != -1ULL && per_process_stats) {
+		struct per_process_info *ppi = find_ppi(req->ppm->pid);
 		int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 
 		if (ppi && elapsed > ppi->longest_completion_wait[w])
@@ -1154,8 +1238,13 @@ static unsigned long long log_track_complete(struct per_dev_info *pdi,
 	/*
 	 * kill the trace, we don't need it after completion
 	 */
-	rb_erase(&iot->rb_node, &pdi->rb_track);
-	free(iot);
+	for (iot = first_iot(req); iot; iot = next) {
+		next = iot->next;
+		rb_erase(&iot->rb_node, &pdi->rb_track);
+		if (iot != first_iot(req))
+			free(iot);
+	}
+	free(req);
 
 	return elapsed;
 }
@@ -1606,6 +1695,7 @@ static void dump_trace_fs(struct blk_io_trace *t, struct per_dev_info *pdi,
 		case __BLK_TA_COMPLETE:
 			if (pdi->cur_depth[w])
 				pdi->cur_depth[w]--;
+			fixup_complete(pdi, t);
 			account_c(t, pci, w, t->bytes);
 			log_complete(pdi, pci, t, "C");
 			break;
@@ -1621,6 +1711,7 @@ static void dump_trace_fs(struct blk_io_trace *t, struct per_dev_info *pdi,
 			log_unplug(pci, t, "UT");
 			break;
 		case __BLK_TA_SPLIT:
+			log_track_split(pdi, t);
 			log_split(pci, t, "X");
 			break;
 		case __BLK_TA_BOUNCE: