summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorRaghavendra G <rgowdapp@redhat.com>2016-12-26 15:16:10 +0530
committerRaghavendra G <rgowdapp@redhat.com>2017-01-08 20:33:43 -0800
commit521c55c53bd42bfdcc0919019ee81c81305382a2 (patch)
tree68705d1130d7e3045db57ffa54796e647a80e9d7
parent83117c71482c9f87a0b6812094cbb22497eb3faa (diff)
performance/write-behind: Add debug messages
Change-Id: I2ea1350fcbe4b6c06dcb8093b28316f734cd3b48 BUG: 1379655 Signed-off-by: Raghavendra G <rgowdapp@redhat.com> Reviewed-on: http://review.gluster.org/16285 Smoke: Gluster Build System <jenkins@build.gluster.org> NetBSD-regression: NetBSD Build System <jenkins@build.gluster.org> CentOS-regression: Gluster Build System <jenkins@build.gluster.org>
-rw-r--r--xlators/performance/write-behind/src/write-behind.c185
1 files changed, 168 insertions, 17 deletions
diff --git a/xlators/performance/write-behind/src/write-behind.c b/xlators/performance/write-behind/src/write-behind.c
index b9bcaa89744..cf8dd1f9e00 100644
--- a/xlators/performance/write-behind/src/write-behind.c
+++ b/xlators/performance/write-behind/src/write-behind.c
@@ -164,6 +164,12 @@ typedef struct wb_request {
int fulfilled:1; /* got server acknowledgement */
int go:1; /* enough aggregating, good to go */
} ordering;
+
+ /* for debug purposes. A request might outlive the fop it is
+ * representing. So, preserve essential info for logging.
+ */
+ uint64_t unique;
+ uuid_t gfid;
} wb_request_t;
@@ -318,14 +324,14 @@ wb_liability_has_conflict (wb_inode_t *wb_inode, wb_request_t *req)
}
-gf_boolean_t
+wb_request_t *
wb_wip_has_conflict (wb_inode_t *wb_inode, wb_request_t *req)
{
wb_request_t *each = NULL;
if (req->stub->fop != GF_FOP_WRITE)
/* non-writes fundamentally never conflict with WIP requests */
- return _gf_false;
+ return NULL;
list_for_each_entry (each, &wb_inode->wip, wip) {
if (each == req)
@@ -335,30 +341,44 @@ wb_wip_has_conflict (wb_inode_t *wb_inode, wb_request_t *req)
continue;
if (wb_requests_overlap (each, req))
- return _gf_true;
+ return each;
}
- return _gf_false;
+ return NULL;
}
static int
__wb_request_unref (wb_request_t *req)
{
- int ret = -1;
+ int ret = -1;
wb_inode_t *wb_inode = NULL;
+ char gfid[64] = {0, };
wb_inode = req->wb_inode;
if (req->refcount <= 0) {
+ uuid_utoa_r (req->gfid, gfid);
+
gf_msg ("wb-request", GF_LOG_WARNING,
0, WRITE_BEHIND_MSG_RES_UNAVAILABLE,
- "refcount(%d) is <= 0", req->refcount);
+ "(unique=%"PRIu64", fop=%s, gfid=%s, gen=%"PRIu64"): "
+ "refcount(%d) is <= 0 ",
+ req->unique, gf_fop_list[req->fop], gfid, req->gen,
+ req->refcount);
goto out;
}
ret = --req->refcount;
if (req->refcount == 0) {
+ uuid_utoa_r (req->gfid, gfid);
+
+ gf_log_callingfn (wb_inode->this->name, GF_LOG_DEBUG,
+ "(unique = %"PRIu64", fop=%s, gfid=%s, "
+ "gen=%"PRIu64"): destroying request, "
+ "removing from all queues", req->unique,
+ gf_fop_list[req->fop], gfid, req->gen);
+
list_del_init (&req->todo);
list_del_init (&req->lie);
list_del_init (&req->wip);
@@ -455,6 +475,7 @@ gf_boolean_t
wb_enqueue_common (wb_inode_t *wb_inode, call_stub_t *stub, int tempted)
{
wb_request_t *req = NULL;
+ inode_t *inode = NULL;
GF_VALIDATE_OR_GOTO ("write-behind", wb_inode, out);
GF_VALIDATE_OR_GOTO (wb_inode->this->name, stub, out);
@@ -474,6 +495,13 @@ wb_enqueue_common (wb_inode_t *wb_inode, call_stub_t *stub, int tempted)
req->wb_inode = wb_inode;
req->fop = stub->fop;
req->ordering.tempted = tempted;
+ req->unique = stub->frame->root->unique;
+
+ inode = ((stub->args.fd != NULL) ? stub->args.fd->inode
+ : stub->args.loc.inode);
+
+ if (inode)
+ gf_uuid_copy (req->gfid, inode->gfid);
if (stub->fop == GF_FOP_WRITE) {
req->write_size = iov_length (stub->args.vector,
@@ -669,6 +697,7 @@ void
__wb_fulfill_request (wb_request_t *req)
{
wb_inode_t *wb_inode = NULL;
+ char gfid[64] = {0, };
wb_inode = req->wb_inode;
@@ -676,6 +705,15 @@ __wb_fulfill_request (wb_request_t *req)
wb_inode->window_current -= req->total_size;
wb_inode->transit -= req->total_size;
+ uuid_utoa_r (req->gfid, gfid);
+
+ gf_log_callingfn (wb_inode->this->name, GF_LOG_DEBUG,
+ "(unique=%"PRIu64", fop=%s, gfid=%s, "
+ "gen=%"PRIu64"): request fulfilled. "
+ "removing the request from liability queue? = %s",
+ req->unique, gf_fop_list[req->fop], gfid, req->gen,
+ req->ordering.lied ? "yes" : "no");
+
if (req->ordering.lied) {
/* 1. If yes, request is in liability queue and hence can be
safely removed from list.
@@ -1179,8 +1217,9 @@ wb_do_unwinds (wb_inode_t *wb_inode, list_head_t *lies)
void
__wb_pick_unwinds (wb_inode_t *wb_inode, list_head_t *lies)
{
- wb_request_t *req = NULL;
- wb_request_t *tmp = NULL;
+ wb_request_t *req = NULL;
+ wb_request_t *tmp = NULL;
+ char gfid[64] = {0,};
list_for_each_entry_safe (req, tmp, &wb_inode->temptation, lie) {
if (!req->ordering.fulfilled &&
@@ -1199,6 +1238,15 @@ __wb_pick_unwinds (wb_inode_t *wb_inode, list_head_t *lies)
req->ordering.lied = 1;
wb_inode->gen++;
+
+ uuid_utoa_r (req->gfid, gfid);
+ gf_msg_debug (wb_inode->this->name, 0,
+ "(unique=%"PRIu64", fop=%s, gfid=%s, "
+ "gen=%"PRIu64"): added req to liability "
+ "queue. inode-generation-number=%"PRIu64,
+ req->stub->frame->root->unique,
+ gf_fop_list[req->fop], gfid, req->gen,
+ wb_inode->gen);
}
}
@@ -1287,6 +1335,7 @@ __wb_preprocess_winds (wb_inode_t *wb_inode)
wb_conf_t *conf = NULL;
int ret = 0;
ssize_t page_size = 0;
+ char gfid[64] = {0, };
/* With asynchronous IO from a VM guest (as a file), there
can be two sequential writes happening in two regions
@@ -1309,6 +1358,14 @@ __wb_preprocess_winds (wb_inode_t *wb_inode)
* winding so that application wont block indefinitely
* waiting for write result.
*/
+
+ uuid_utoa_r (req->gfid, gfid);
+ gf_msg_debug (wb_inode->this->name, 0,
+ "(unique=%"PRIu64", fop=%s, gfid=%s, "
+ "gen=%"PRIu64"): not setting ordering.go"
+ "as dontsync is set", req->unique,
+ gf_fop_list[req->fop], gfid, req->gen);
+
continue;
}
@@ -1393,10 +1450,13 @@ int
__wb_handle_failed_conflict (wb_request_t *req, wb_request_t *conflict,
list_head_t *tasks)
{
- wb_conf_t *conf = NULL;
+ wb_conf_t *conf = NULL;
+ char gfid[64] = {0, };
conf = req->wb_inode->this->private;
+ uuid_utoa_r (req->gfid, gfid);
+
if ((req->stub->fop != GF_FOP_FLUSH)
&& ((req->stub->fop != GF_FOP_FSYNC) || conf->resync_after_fsync)) {
if (!req->ordering.lied && list_empty (&conflict->wip)) {
@@ -1413,17 +1473,45 @@ __wb_handle_failed_conflict (wb_request_t *req, wb_request_t *conflict,
list_del_init (&req->todo);
list_add_tail (&req->winds, tasks);
+ gf_msg_debug (req->wb_inode->this->name, 0,
+ "(unique=%"PRIu64", fop=%s, gfid=%s, "
+ "gen=%"PRIu64"): A conflicting write "
+ "request in liability queue has failed "
+ "to sync (error = \"%s\"), "
+ "unwinding this request as a failure",
+ req->unique, gf_fop_list[req->fop], gfid,
+ req->gen, strerror (req->op_errno));
+
if (req->ordering.tempted) {
/* make sure that it won't be unwound in
* wb_do_unwinds too. Otherwise there'll be
* a double wind.
*/
list_del_init (&req->lie);
+
+ gf_msg_debug (req->wb_inode->this->name, 0,
+ "(unique=%"PRIu64", fop=%s, "
+ "gfid=%s, gen=%"PRIu64"): "
+ "removed from liability queue",
+ req->unique,
+ gf_fop_list[req->fop], gfid,
+ req->gen);
+
__wb_fulfill_request (req);
}
-
}
} else {
+ gf_msg_debug (req->wb_inode->this->name, 0,
+ "(unique=%"PRIu64", fop=%s, gfid=%s, "
+ "gen=%"PRIu64"): A conflicting write request "
+ "in liability queue has failed to sync "
+ "(error = \"%s\"). This is an "
+ "FSYNC/FLUSH and we need to maintain ordering "
+ "guarantees with other writes in TODO queue. "
+ "Hence doing nothing now", req->unique,
+ gf_fop_list[req->fop], gfid, req->gen,
+ strerror (conflict->op_errno));
+
/* flush and fsync (without conf->resync_after_fsync) act as
barriers. We cannot unwind them out of
order, when there are earlier generation writes just because
@@ -1462,10 +1550,32 @@ __wb_pick_winds (wb_inode_t *wb_inode, list_head_t *tasks,
wb_request_t *req = NULL;
wb_request_t *tmp = NULL;
wb_request_t *conflict = NULL;
+ char req_gfid[64] = {0, }, conflict_gfid[64] = {0, };
list_for_each_entry_safe (req, tmp, &wb_inode->todo, todo) {
+ uuid_utoa_r (req->gfid, req_gfid);
+
conflict = wb_liability_has_conflict (wb_inode, req);
if (conflict) {
+ uuid_utoa_r (conflict->gfid, conflict_gfid);
+
+ gf_msg_debug (wb_inode->this->name, 0,
+ "Not winding request due to a "
+ "conflicting write in liability queue. "
+ "REQ: unique=%"PRIu64", fop=%s, "
+ "gen=%"PRIu64", gfid=%s. "
+ "CONFLICT: unique=%"PRIu64", fop=%s, "
+ "gen=%"PRIu64", gfid=%s, "
+ "conflicts-sync-failed?=%s, "
+ "conflicts-error=%s",
+ req->unique, gf_fop_list[req->fop],
+ req->gen, req_gfid,
+ conflict->unique,
+ gf_fop_list[conflict->fop], conflict->gen,
+ conflict_gfid,
+ (conflict->op_ret == 1) ? "yes" : "no",
+ strerror (conflict->op_errno));
+
if (conflict->op_ret == -1) {
/* There is a conflicting liability which failed
* to sync in previous attempts, resume the req
@@ -1484,13 +1594,40 @@ __wb_pick_winds (wb_inode_t *wb_inode, list_head_t *tasks,
continue;
}
- if (req->ordering.tempted && !req->ordering.go)
+ if (req->ordering.tempted && !req->ordering.go) {
/* wait some more */
+ gf_msg_debug (wb_inode->this->name, 0,
+ "(unique=%"PRIu64", fop=%s, gen=%"PRIu64
+ ", gfid=%s): ordering.go is not set, "
+ "hence not winding", req->unique,
+ gf_fop_list[req->fop], req->gen,
+ req_gfid);
continue;
+ }
if (req->stub->fop == GF_FOP_WRITE) {
- if (wb_wip_has_conflict (wb_inode, req))
+ conflict = wb_wip_has_conflict (wb_inode, req);
+
+ if (conflict) {
+ uuid_utoa_r (conflict->gfid, conflict_gfid);
+
+ gf_msg_debug (wb_inode->this->name, 0,
+ "Not winding write request as "
+ "a conflicting write is being "
+ "synced to backend. "
+ "REQ: unique=%"PRIu64" fop=%s,"
+ " gen=%"PRIu64", gfid=%s. "
+ "CONFLICT: unique=%"PRIu64" "
+ "fop=%s, gen=%"PRIu64", "
+ "gfid=%s",
+ req->unique,
+ gf_fop_list[req->fop],
+ req->gen, req_gfid,
+ conflict->unique,
+ gf_fop_list[conflict->fop],
+ conflict->gen, conflict_gfid);
continue;
+ }
list_add_tail (&req->wip, &wb_inode->wip);
req->wind_count++;
@@ -1501,12 +1638,19 @@ __wb_pick_winds (wb_inode_t *wb_inode, list_head_t *tasks,
__wb_request_ref (req);
}
+ gf_msg_debug (wb_inode->this->name, 0,
+ "(unique=%"PRIu64", fop=%s, gfid=%s, "
+ "gen=%"PRIu64"): picking the request for "
+ "winding", req->unique, gf_fop_list[req->fop],
+ req_gfid, req->gen);
+
list_del_init (&req->todo);
- if (req->ordering.tempted)
+ if (req->ordering.tempted) {
list_add_tail (&req->winds, liabilities);
- else
+ } else {
list_add_tail (&req->winds, tasks);
+ }
}
return 0;
@@ -1548,6 +1692,9 @@ wb_process_queue (wb_inode_t *wb_inode)
INIT_LIST_HEAD (&liabilities);
do {
+ gf_log_callingfn (wb_inode->this->name, GF_LOG_DEBUG,
+ "processing queues");
+
LOCK (&wb_inode->lock);
{
__wb_preprocess_winds (wb_inode);
@@ -2644,7 +2791,7 @@ __wb_dump_requests (struct list_head *head, char *prefix)
gf_proc_dump_add_section(key_prefix);
- gf_proc_dump_write ("request-ptr", "%p", req);
+ gf_proc_dump_write ("unique", "%"PRIu64, req->unique);
gf_proc_dump_write ("refcount", "%d", req->refcount);
@@ -2708,6 +2855,8 @@ wb_inode_dump (xlator_t *this, inode_t *inode)
goto out;
}
+ uuid_utoa_r (inode->gfid, uuid_str);
+
gf_proc_dump_build_key (key_prefix, "xlator.performance.write-behind",
"wb_inode");
@@ -2721,6 +2870,8 @@ wb_inode_dump (xlator_t *this, inode_t *inode)
gf_proc_dump_write ("inode", "%p", inode);
+ gf_proc_dump_write ("gfid", "%s", uuid_str);
+
gf_proc_dump_write ("window_conf", "%"GF_PRI_SIZET,
wb_inode->window_conf);
@@ -2745,8 +2896,8 @@ wb_inode_dump (xlator_t *this, inode_t *inode)
if (ret && wb_inode)
gf_proc_dump_write ("Unable to dump the inode information",
"(Lock acquisition failed) %p (gfid: %s)",
- wb_inode,
- uuid_utoa_r (inode->gfid, uuid_str));
+ wb_inode, uuid_str);
+
ret = 0;
out:
return ret;