[PATCH 10/10] blk-throttle: add trace log

From: Shaohua Li
Date: Tue May 10 2016 - 20:17:01 EST


Add trace log in new low/high logic to help dignose issues.

Signed-off-by: Shaohua Li <shli@xxxxxx>
---
block/blk-throttle.c | 43 +++++++++++++++++++++++++++++++++++++++++--
1 file changed, 41 insertions(+), 2 deletions(-)

diff --git a/block/blk-throttle.c b/block/blk-throttle.c
index a5f3435..d35bbf1 100644
--- a/block/blk-throttle.c
+++ b/block/blk-throttle.c
@@ -2,6 +2,7 @@
* Interface for controlling IO bandwidth on a request queue
*
* Copyright (C) 2010 Vivek Goyal <vgoyal@xxxxxxxxxx>
+ * Shaohua Li <shli@xxxxxx> adds low/high limit
*/

#include <linux/module.h>
@@ -92,6 +93,12 @@ enum {
LIMIT_CNT = 3,
};

+static char *limit_name[LIMIT_CNT] = {
+ [LIMIT_LOW] = "low",
+ [LIMIT_HIGH] = "high",
+ [LIMIT_MAX] = "max",
+};
+
struct throtl_grp {
/* must be the first member */
struct blkg_policy_data pd;
@@ -1565,6 +1572,8 @@ static ssize_t tg_set_limit(struct kernfs_open_file *of,
if (index == LIMIT_MAX && tg->td->limit_index == LIMIT_MAX &&
tg->td->limit_valid[LIMIT_HIGH])
tg->td->limit_index = LIMIT_HIGH;
+ throtl_log(&tg->td->service_queue, "switch state to %s",
+ limit_name[tg->td->limit_index]);
tg_conf_updated(tg);
ret = 0;
out_finish:
@@ -1710,6 +1719,9 @@ static void throtl_calculate_low_interval(struct throtl_data *td)
td->low_upgrade_interval = cg_check_time;
td->low_downgrade_interval = dbits / ubits * cg_check_time;
}
+ throtl_log(&td->service_queue,
+ "low upgrade interval=%u, downgrade interval=%u",
+ td->low_upgrade_interval, td->low_downgrade_interval);
}

static void throtl_calculate_high_interval(struct throtl_data *td)
@@ -1729,6 +1741,9 @@ static void throtl_calculate_high_interval(struct throtl_data *td)
td->high_upgrade_interval = cg_check_time;
td->high_downgrade_interval = dbits / ubits * cg_check_time;
}
+ throtl_log(&td->service_queue,
+ "high upgrade interval=%u, downgrade interval=%u",
+ td->high_upgrade_interval, td->high_downgrade_interval);
}

static bool throtl_upgrade_check_one(struct throtl_grp *tg, bool *idle)
@@ -1745,6 +1760,8 @@ static bool throtl_upgrade_check_one(struct throtl_grp *tg, bool *idle)
/* if cgroup is below low limit for a long time, consider it idle */
if (time_after(jiffies,
tg_last_low_overflow_time(tg) + tg->td->low_upgrade_interval)) {
+ throtl_log(&tg->service_queue, "idle upgrade, hit low time=%lu jiffies=%lu",
+ tg_last_low_overflow_time(tg), jiffies);
*idle = true;
return true;
}
@@ -1757,18 +1774,23 @@ static bool throtl_upgrade_check_one(struct throtl_grp *tg, bool *idle)
return false;
if (tg->iops[WRITE][LIMIT_LOW] != 0 && !sq->nr_queued[WRITE])
return false;
+ throtl_log(&tg->service_queue, "reach low limit upgrade");
return true;
check_high:
/* if cgroup is below high limit for a long time, consider it idle */
if (time_after(jiffies,
tg_last_high_overflow_time(tg) + tg->td->high_upgrade_interval)) {
+ throtl_log(&tg->service_queue, "idle upgrade, hit high time=%lu jiffies=%lu",
+ tg_last_high_overflow_time(tg), jiffies);
*idle = true;
return true;
}

/* if cgroup reaches high/max limit, it's ok to next limit */
- if (sq->nr_queued[READ] || sq->nr_queued[WRITE])
+ if (sq->nr_queued[READ] || sq->nr_queued[WRITE]) {
+ throtl_log(&tg->service_queue, "reach high/max limit upgrade");
return true;
+ }
return false;
}

@@ -1838,6 +1860,8 @@ static void throtl_upgrade_state(struct throtl_data *td)
td->limit_index++;
while (!td->limit_valid[td->limit_index])
td->limit_index++;
+ throtl_log(&td->service_queue, "upgrade state to %s",
+ limit_name[td->limit_index]);
td->low_upgrade_time = jiffies;
if (td->limit_index == LIMIT_HIGH)
td->high_downgrade_time = jiffies;
@@ -1886,6 +1910,8 @@ static void throtl_downgrade_state(struct throtl_data *td, int new)
int old = td->limit_index;

td->limit_index = new;
+ throtl_log(&td->service_queue, "downgrade state to %s",
+ limit_name[td->limit_index]);
/* max crosses high to low */
if (new == LIMIT_LOW && old == LIMIT_MAX && td->limit_valid[LIMIT_HIGH]) {
td->low_downgrade_time = jiffies;
@@ -1926,8 +1952,17 @@ static bool throtl_downgrade_check_one(struct throtl_grp *tg, bool check_low)
time_after(now,
td->high_upgrade_time + td->high_downgrade_interval) &&
time_after(now,
- tg_last_high_overflow_time(tg) + td->high_downgrade_interval)))
+ tg_last_high_overflow_time(tg) + td->high_downgrade_interval))) {
+ throtl_log(&tg->service_queue,
+ "%s idle downgrade, last hit limit time=%lu upgrade time=%lu jiffies=%lu",
+ check_low ? "low" : "high",
+ check_low ? tg_last_low_overflow_time(tg) :
+ tg_last_high_overflow_time(tg),
+ check_low ? td->low_upgrade_time :
+ td->high_upgrade_time,
+ jiffies);
return true;
+ }
return false;
}

@@ -1986,6 +2021,7 @@ static void throtl_downgrade_check(struct throtl_grp *tg)

bps = tg->last_bytes_disp[READ] * HZ;
do_div(bps, elapsed_time);
+ throtl_log(&tg->service_queue, "rbps=%llu", bps);
if (tg->bps[READ][LIMIT_LOW] != 0 &&
bps >= tg->bps[READ][LIMIT_LOW])
tg->last_low_overflow_time[READ] = now;
@@ -1996,6 +2032,7 @@ static void throtl_downgrade_check(struct throtl_grp *tg)

bps = tg->last_bytes_disp[WRITE] * HZ;
do_div(bps, elapsed_time);
+ throtl_log(&tg->service_queue, "wbps=%llu", bps);
if (tg->bps[WRITE][LIMIT_LOW] != 0 &&
bps >= tg->bps[WRITE][LIMIT_LOW])
tg->last_low_overflow_time[WRITE] = now;
@@ -2005,6 +2042,7 @@ static void throtl_downgrade_check(struct throtl_grp *tg)
tg->last_high_overflow_time[WRITE] = now;

iops = tg->last_io_disp[READ] * HZ / elapsed_time;
+ throtl_log(&tg->service_queue, "riops=%u", iops);
if (tg->iops[READ][LIMIT_LOW] != 0 &&
iops >= tg->iops[READ][LIMIT_LOW])
tg->last_low_overflow_time[READ] = now;
@@ -2014,6 +2052,7 @@ static void throtl_downgrade_check(struct throtl_grp *tg)
tg->last_high_overflow_time[READ] = now;

iops = tg->last_io_disp[WRITE] * HZ / elapsed_time;
+ throtl_log(&tg->service_queue, "wiops=%u", iops);
if (tg->iops[WRITE][LIMIT_LOW] != 0 &&
iops >= tg->iops[WRITE][LIMIT_LOW])
tg->last_low_overflow_time[WRITE] = now;
--
2.8.0.rc2