wbt.patch

--- linux-5.13-rc5.clean/block/blk-wbt.c	2021-06-06 22:47:27.000000000 +0000
+++ linux-5.13-rc5/block/blk-wbt.c	2021-06-14 02:26:08.020617220 +0000
@@ -127,6 +127,7 @@
 static void wbt_rqw_done(struct rq_wb *rwb, struct rq_wait *rqw,
 			 enum wbt_flags wb_acct)
 {
+	struct backing_dev_info *bdi = rwb->rqos.q->backing_dev_info;
 	int inflight, limit;
 
 	inflight = atomic_dec_return(&rqw->inflight);
@@ -155,14 +156,23 @@
 	/*
 	 * Don't wake anyone up if we are above the normal limit.
 	 */
-	if (inflight && inflight >= limit)
+	if (inflight && inflight >= limit) {
+		printk(KERN_ERR "[wbt] wbt_rqw_done/%s: no wakeup, inflight = %d >= limit = %d",
+				bdi->dev_name, inflight, limit);
 		return;
+	}
 
 	if (wq_has_sleeper(&rqw->wait)) {
 		int diff = limit - inflight;
 
		if (!inflight || diff >= rwb->wb_background / 2) {
+			printk(KERN_ERR "[wbt] wbt_rqw_done/%s: wake_up_all, wq_has_sleeper, inflight = %d, diff = %d, limit = %d",
+					bdi->dev_name, inflight, diff, limit);
 			wake_up_all(&rqw->wait);
+		} else {
+			printk(KERN_ERR "[wbt] wbt_rqw_done/%s: no wakeup, wq_has_sleeper, inflight = %d, diff = %d, limit = %d",
+					bdi->dev_name, inflight, diff, limit);
+		}
 	}
 }
 
@@ -250,6 +260,8 @@
 	if (thislat > rwb->cur_win_nsec ||
 	    (thislat > rwb->min_lat_nsec && !stat[READ].nr_samples)) {
 		trace_wbt_lat(bdi, thislat);
+		printk(KERN_ERR "[wbt] latency_exceeded/%s: thislat = %llu -> LAT_EXCEEDED",
+				bdi->dev_name, thislat);
 		return LAT_EXCEEDED;
 	}
 
@@ -263,9 +275,17 @@
 		 * waited or still has writes in flights, consider us doing
 		 * just writes as well.
 		 */
-		if (stat[WRITE].nr_samples || wb_recent_wait(rwb) ||
-		    wbt_inflight(rwb))
+		bool recent_wait = wb_recent_wait(rwb);
+		unsigned int inflight = wbt_inflight(rwb);
+		if (stat[WRITE].nr_samples || recent_wait ||
+		    inflight) {
+			printk(KERN_ERR "[wbt] latency_exceeded/%s: thislat = %llu, nr_samples = %d, recent_wait = %d, inflight = %d -> LAT_UNKNOWN_WRITES",
+					bdi->dev_name, thislat, stat[WRITE].nr_samples, recent_wait, inflight);
 			return LAT_UNKNOWN_WRITES;
+		}
+
+		printk(KERN_ERR "[wbt] latency_exceeded/%s: thislat = %llu -> LAT_UNKNOWN",
+				bdi->dev_name, thislat);
 		return LAT_UNKNOWN;
 	}
 
@@ -275,12 +295,16 @@
 	if (stat[READ].min > rwb->min_lat_nsec) {
 		trace_wbt_lat(bdi, stat[READ].min);
 		trace_wbt_stat(bdi, stat);
+		printk(KERN_ERR "[wbt] latency_exceeded/%s: thislat = %llu -> LAT_EXCEEDED",
+				bdi->dev_name, thislat);
 		return LAT_EXCEEDED;
 	}
 
 	if (rqd->scale_step)
 		trace_wbt_stat(bdi, stat);
 
+	printk(KERN_ERR "[wbt] latency_exceeded/%s: thislat = %llu -> LAT_OK",
+			bdi->dev_name, thislat);
 	return LAT_OK;
 }
 
@@ -295,6 +319,8 @@
 
 static void calc_wb_limits(struct rq_wb *rwb)
 {
+	struct backing_dev_info *bdi = rwb->rqos.q->backing_dev_info;
+
 	if (rwb->min_lat_nsec == 0) {
 		rwb->wb_normal = rwb->wb_background = 0;
 	} else if (rwb->rq_depth.max_depth <= 2) {
@@ -304,6 +330,9 @@
 		rwb->wb_normal = (rwb->rq_depth.max_depth + 1) / 2;
 		rwb->wb_background = (rwb->rq_depth.max_depth + 3) / 4;
 	}
+
+	printk(KERN_ERR "[wbt] calc_wb_limits/%s: rwb->wb_normal = %d, rwb->wb_background = %d",
+			bdi->dev_name, rwb->wb_normal, rwb->wb_background);
 }
 
 static void scale_up(struct rq_wb *rwb)
--- linux-5.13-rc5.clean/block/blk-rq-qos.c	2021-06-06 22:47:27.000000000 +0000
+++ linux-5.13-rc5/block/blk-rq-qos.c	2021-06-14 02:25:07.736880404 +0000
@@ -220,9 +220,13 @@
 	 * If we fail to get a budget, return -1 to interrupt the wake up loop
 	 * in __wake_up_common.
 	 */
-	if (!data->cb(data->rqw, data->private_data))
+	if (!data->cb(data->rqw, data->private_data)) {
+		printk(KERN_ERR "[rq-qos] rq_qos_wake_function: pid %i had no budget",
+				task_tgid_nr(data->task));
 		return -1;
+	}
 
+	printk(KERN_ERR "[rq-qos] rq_qos_wake_function: pid %i got token", task_tgid_nr(data->task));
 	data->got_token = true;
 	smp_wmb();
 	list_del_init(&curr->entry);
@@ -263,15 +267,21 @@
 	bool has_sleeper;
 
 	has_sleeper = wq_has_sleeper(&rqw->wait);
-	if (!has_sleeper && acquire_inflight_cb(rqw, private_data))
+	if (!has_sleeper && acquire_inflight_cb(rqw, private_data)) {
+		printk(KERN_ERR "[rq-qos] rq_qos_wait: pid %i in early return", task_tgid_nr(current));
 		return;
+	}
 
 	prepare_to_wait_exclusive(&rqw->wait, &data.wq, TASK_UNINTERRUPTIBLE);
 	has_sleeper = !wq_has_single_sleeper(&rqw->wait);
 	do {
+		printk(KERN_ERR "[rq-qos] rq_qos_wait: pid %i in loop, has_sleeper = %d",
+				task_tgid_nr(current), has_sleeper);
 		/* The memory barrier in set_task_state saves us here. */
-		if (data.got_token)
+		if (data.got_token) {
+			printk(KERN_ERR "[rq-qos] rq_qos_wait: pid %i woke up with token", task_tgid_nr(current));
 			break;
+		}
 		if (!has_sleeper && acquire_inflight_cb(rqw, private_data)) {
 			finish_wait(&rqw->wait, &data.wq);
 
@@ -280,11 +290,13 @@
 			 * which means we now have two. Put our local token
 			 * and wake anyone else potentially waiting for one.
 			 */
+			printk(KERN_ERR "[rq-qos] rq_qos_wait: pid %i in race", task_tgid_nr(current));
 			smp_rmb();
 			if (data.got_token)
 				cleanup_cb(rqw, private_data);
 			break;
 		}
+		printk(KERN_ERR "[rq-qos] rq_qos_wait: pid %i about to sleep", task_tgid_nr(current));
 		io_schedule();
 		has_sleeper = true;
 		set_current_state(TASK_UNINTERRUPTIBLE);