Debug request tracing

Signed-off-by: Michal Mielewczyk <[email protected]>
Signed-off-by: Robert Baldyga <[email protected]>

src/engine/cache_engine.c

@@ -41,6 +41,9 @@ enum ocf_io_if_type {
 	OCF_IO_FAST_IF,
 	OCF_IO_FLUSH_IF,
 	OCF_IO_DISCARD_IF,
+	OCF_IO_REFRESH_IF,
+	OCF_IO_INVALIDATE_IF,
+	OCF_IO_RD_IF,
 	OCF_IO_PRIV_MAX_IF,
 };
 
@@ -108,6 +111,18 @@ static const struct ocf_io_if IO_IFS[OCF_IO_PRIV_MAX_IF] = {
 		},
 		.name = "Discard",
 	},
+	[OCF_IO_REFRESH_IF] = {
+		.cbs = { },
+		.name = "Refresh",
+	},
+	[OCF_IO_INVALIDATE_IF] = {
+		.cbs = { },
+		.name = "Invalidate",
+	},
+	[OCF_IO_RD_IF] = {
+		.cbs = { },
+		.name = "Read generic",
+	},
 };
 
 static const struct ocf_io_if *cache_mode_io_if_map[ocf_req_cache_mode_max] = {
@@ -118,8 +133,29 @@ static const struct ocf_io_if *cache_mode_io_if_map[ocf_req_cache_mode_max] = {
 	[ocf_req_cache_mode_wo] = &IO_IFS[OCF_IO_WO_IF],
 	[ocf_req_cache_mode_pt] = &IO_IFS[OCF_IO_PT_IF],
 	[ocf_req_cache_mode_fast] = &IO_IFS[OCF_IO_FAST_IF],
+	[ocf_req_refresh] = &IO_IFS[OCF_IO_REFRESH_IF],
+	[ocf_req_cache_mode_discard] = &IO_IFS[OCF_IO_DISCARD_IF],
+	[ocf_req_cache_mode_invalidate] = &IO_IFS[OCF_IO_INVALIDATE_IF],
+	[ocf_req_cache_mode_rd] = &IO_IFS[OCF_IO_RD_IF],
 };
 
+void ocf_debug_request_trace(struct ocf_request *req,
+		ocf_req_cache_mode_t engine, uint8_t origin)
+{
+	ENV_WARN_ONCE(origin & ~0xf, "Invalid req origin origin\n");
+	ENV_WARN_ONCE(engine & ~0xe, "Invalid req engine\n");
+
+	ENV_WARN_ONCE(req->engine_trace & 0xff00000000000000,
+			"Request trace too long\n");
+
+	req->engine_trace <<= 4;
+	// +1 to make sure that WT has a different value than zero
+	req->engine_trace |= (engine + 1);
+
+	req->engine_trace <<= 4;
+	req->engine_trace |= origin;
+}
+
 const char *ocf_get_io_iface_name(ocf_req_cache_mode_t cache_mode)
 {
 	if (cache_mode == ocf_req_cache_mode_max)
@@ -211,6 +247,7 @@ int ocf_engine_hndl_req(struct ocf_request *req)
 	 * to into OCF workers
 	 */
 
+	ocf_debug_request_trace(req, req->cache_mode, 0xf);
 	ocf_queue_push_req(req, OCF_QUEUE_ALLOW_SYNC);
 
 	return 0;
@@ -227,6 +264,7 @@ int ocf_engine_hndl_fast_req(struct ocf_request *req)
 
 	ocf_req_get(req);
 
+	ocf_debug_request_trace(req, req->cache_mode, 0xe);
 	ret = engine_cb(req);
 
 	if (ret == OCF_FAST_PATH_NO)
@@ -239,13 +277,15 @@ void ocf_engine_hndl_discard_req(struct ocf_request *req)
 {
 	ocf_req_get(req);
 
+	ocf_debug_request_trace(req, ocf_req_cache_mode_discard, 0);
 	IO_IFS[OCF_IO_DISCARD_IF].cbs[req->rw](req);
 }
 
 void ocf_engine_hndl_flush_req(struct ocf_request *req)
 {
 	ocf_req_get(req);
 
+	ocf_debug_request_trace(req, ocf_req_cache_mode_flush, 0);
 	req->engine_handler = IO_IFS[OCF_IO_FLUSH_IF].cbs[req->rw];
 
 	ocf_queue_push_req(req, OCF_QUEUE_ALLOW_SYNC);

src/engine/cache_engine.h

@@ -47,4 +47,7 @@ void ocf_engine_hndl_flush_req(struct ocf_request *req);
 
 void ocf_engine_hndl_discard_req(struct ocf_request *req);
 
+void ocf_debug_request_trace(struct ocf_request *req,
+		ocf_req_cache_mode_t engine, uint8_t info);
+
 #endif

src/engine/engine_bf.c

@@ -59,6 +59,7 @@ static void _ocf_backfill_complete(struct ocf_request *req, int error)
 	}
 
 	if (error) {
+		ocf_debug_request_trace(req, ocf_req_cache_mode_invalidate, 1);
 		ocf_engine_invalidate(req);
 	} else {
 		ocf_req_unlock(ocf_cache_line_concurrency(cache), req);

src/engine/engine_common.c

@@ -612,6 +612,7 @@ static int _ocf_engine_refresh(struct ocf_request *req)
 		req->engine_handler = req->priv;
 		req->priv = NULL;
 
+		ocf_debug_request_trace(req, ocf_req_refresh, 0xd);
 		req->engine_handler(req);
 	} else {
 		ENV_WARN(true, "Inconsistent request");

src/engine/engine_discard.c

@@ -181,9 +181,11 @@ static int _ocf_discard_step(struct ocf_request *req)
 
 	if (lock >= 0) {
 		if (OCF_LOCK_ACQUIRED == lock) {
+			ocf_debug_request_trace(req, ocf_req_cache_mode_discard, 0);
 			_ocf_discard_step_do(req);
 		} else {
 			/* WR lock was not acquired, need to wait for resume */
+			ocf_debug_request_trace(req, ocf_req_cache_mode_discard, 1);
 			OCF_DEBUG_RQ(req, "NO LOCK")
 		}
 	} else {

src/engine/engine_fast.c

@@ -38,6 +38,7 @@ static void _ocf_read_fast_complete(struct ocf_request *req, int error)
 
 		OCF_DEBUG_RQ(req, "ERROR");
 
+		ocf_debug_request_trace(req, ocf_req_cache_mode_pt, 1);
 		ocf_queue_push_req_pt(req);
 	} else {
 		ocf_req_unlock(ocf_cache_line_concurrency(req->cache), req);
@@ -55,6 +56,7 @@ static int _ocf_read_fast_do(struct ocf_request *req)
 	if (ocf_engine_is_miss(req)) {
 		/* It seams that after resume, now request is MISS, do PT */
 		OCF_DEBUG_RQ(req, "Switching to read PT");
+		ocf_debug_request_trace(req, ocf_req_cache_mode_pt, 0);
 		ocf_read_pt_do(req);
 		return 0;
 
@@ -129,8 +131,10 @@ int ocf_read_fast(struct ocf_request *req)
 			if (lock != OCF_LOCK_ACQUIRED) {
 				/* Lock was not acquired, need to wait for resume */
 				OCF_DEBUG_RQ(req, "NO LOCK");
+				ocf_debug_request_trace(req, ocf_req_cache_mode_fast, 0);
 			} else {
 				/* Lock was acquired can perform IO */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_fast, 1);
 				_ocf_read_fast_do(req);
 			}
 		} else {
@@ -194,9 +198,12 @@ int ocf_write_fast(struct ocf_request *req)
 
 			if (lock != OCF_LOCK_ACQUIRED) {
 				/* Lock was not acquired, need to wait for resume */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_wb, 0);
 				OCF_DEBUG_RQ(req, "NO LOCK");
 			} else {
 				/* Lock was acquired can perform IO */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_wb, 1);
+
 				ocf_write_wb_do(req);
 			}
 		} else {

src/engine/engine_pt.c

@@ -97,7 +97,6 @@ int ocf_read_pt(struct ocf_request *req)
 
 	OCF_DEBUG_TRACE(req->cache);
 
-
 	/* Get OCF request - increase reference counter */
 	ocf_req_get(req);
 
@@ -136,14 +135,17 @@ int ocf_read_pt(struct ocf_request *req)
 		 * because of this force read data from cache
 		 */
 		ocf_req_clear(req);
+		ocf_debug_request_trace(req, ocf_req_cache_mode_rd, 0);
 		ocf_read_generic(req);
 	} else {
 		if (lock >= 0) {
 			if (lock == OCF_LOCK_ACQUIRED) {
 				/* Lock acquired perform read off operations */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_pt, 2);
 				ocf_read_pt_do(req);
 			} else {
 				/* WR lock was not acquired, need to wait for resume */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_pt, 3);
 				OCF_DEBUG_RQ(req, "NO LOCK");
 			}
 		} else {

src/engine/engine_rd.c

@@ -183,10 +183,10 @@ int ocf_read_generic(struct ocf_request *req)
 	int lock = OCF_LOCK_NOT_ACQUIRED;
 	struct ocf_cache *cache = req->cache;
 
-
 	if (env_atomic_read(&cache->pending_read_misses_list_blocked)) {
 		/* There are conditions to bypass IO */
 		req->force_pt = true;
+		ocf_debug_request_trace(req, ocf_req_cache_mode_pt, 4);
 		ocf_read_pt(req);
 		return 0;
 	}
@@ -204,9 +204,11 @@ int ocf_read_generic(struct ocf_request *req)
 		if (lock >= 0) {
 			if (lock != OCF_LOCK_ACQUIRED) {
 				/* Lock was not acquired, need to wait for resume */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_rd, 1);
 				OCF_DEBUG_RQ(req, "NO LOCK");
 			} else {
 				/* Lock was acquired can perform IO */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_rd, 2);
 				_ocf_read_generic_do(req);
 			}
 		} else {
@@ -217,6 +219,7 @@ int ocf_read_generic(struct ocf_request *req)
 	} else {
 		ocf_req_clear(req);
 		req->force_pt = true;
+		ocf_debug_request_trace(req, ocf_req_cache_mode_pt, 5);
 		ocf_read_pt(req);
 	}
 

src/engine/engine_wa.c

@@ -36,12 +36,14 @@ int ocf_write_wa(struct ocf_request *req)
 		ocf_req_clear(req);
 
 		/* There is HIT, do WT */
+		ocf_debug_request_trace(req, ocf_req_cache_mode_wt, 2);
 		ocf_write_wt(req);
 
 	} else {
 		ocf_req_clear(req);
 
 		/* MISS, do WI */
+		ocf_debug_request_trace(req, ocf_req_cache_mode_wi, 3);
 		ocf_write_wi(req);
 	}
 

src/engine/engine_wb.c

@@ -87,6 +87,7 @@ static void _ocf_write_wb_complete(struct ocf_request *req, int error)
 
 		req->complete(req, error);
 
+		ocf_debug_request_trace(req, ocf_req_cache_mode_invalidate, 0);
 		ocf_engine_invalidate(req);
 	} else {
 		ocf_queue_push_req_cb(req, ocf_write_wb_do_flush_metadata,
@@ -149,7 +150,6 @@ int ocf_write_wb(struct ocf_request *req)
 {
 	int lock = OCF_LOCK_NOT_ACQUIRED;
 
-
 	/* Not sure if we need this. */
 	ocf_req_get(req);
 
@@ -166,7 +166,9 @@ int ocf_write_wb(struct ocf_request *req)
 			if (lock != OCF_LOCK_ACQUIRED) {
 				/* WR lock was not acquired, need to wait for resume */
 				OCF_DEBUG_RQ(req, "NO LOCK");
+				ocf_debug_request_trace(req, ocf_req_cache_mode_wb, 3);
 			} else {
+				ocf_debug_request_trace(req, ocf_req_cache_mode_wb, 2);
 				ocf_write_wb_do(req);
 			}
 		} else {
@@ -176,6 +178,7 @@ int ocf_write_wb(struct ocf_request *req)
 		}
 	} else {
 		ocf_req_clear(req);
+		ocf_debug_request_trace(req, ocf_req_cache_mode_wi, 0);
 		ocf_write_wi(req);
 	}
 

src/engine/engine_wi.c

@@ -194,9 +194,12 @@ int ocf_write_wi(struct ocf_request *req)
 
 	if (lock >= 0) {
 		if (lock == OCF_LOCK_ACQUIRED) {
+			ocf_debug_request_trace(req, ocf_req_cache_mode_wi, 1);
+
 			req->engine_handler(req);
 		} else {
 			/* WR lock was not acquired, need to wait for resume */
+			ocf_debug_request_trace(req, ocf_req_cache_mode_wi, 2);
 			OCF_DEBUG_RQ(req, "NO LOCK");
 		}
 	} else {

src/engine/engine_wo.c

@@ -230,9 +230,12 @@ int ocf_read_wo(struct ocf_request *req)
 	if (lock >= 0) {
 		if (lock != OCF_LOCK_ACQUIRED) {
 			/* Lock was not acquired, need to wait for resume */
+			ocf_debug_request_trace(req, ocf_req_cache_mode_wo, 0);
+
 			OCF_DEBUG_RQ(req, "NO LOCK");
 		} else {
 			/* Lock was acquired can perform IO */
+			ocf_debug_request_trace(req, ocf_req_cache_mode_wo, 1);
 			ocf_read_wo_do(req);
 		}
 	} else {

src/engine/engine_wt.c

@@ -94,6 +94,7 @@ static void _ocf_write_wt_req_complete(struct ocf_request *req)
 
 	if (req->info.cache_error || req->info.core_error) {
 		req->complete(req, req->error);
+		ocf_debug_request_trace(req, ocf_req_cache_mode_invalidate, 6);
 		ocf_engine_invalidate(req);
 		return;
 	}
@@ -199,8 +200,11 @@ int ocf_write_wt(struct ocf_request *req)
 		if (lock >= 0) {
 			if (lock != OCF_LOCK_ACQUIRED) {
 				/* WR lock was not acquired, need to wait for resume */
+				ocf_debug_request_trace(req, ocf_req_cache_mode_wt, 0);
+
 				OCF_DEBUG_RQ(req, "NO LOCK");
 			} else {
+				ocf_debug_request_trace(req, ocf_req_cache_mode_wt, 1);
 				_ocf_write_wt_do(req);
 			}
 		} else {
@@ -210,6 +214,7 @@ int ocf_write_wt(struct ocf_request *req)
 		}
 	} else {
 		ocf_req_clear(req);
+		ocf_debug_request_trace(req, ocf_req_cache_mode_wi, 5);
 		ocf_write_wi(req);
 	}
 

src/ocf_request.h

@@ -28,6 +28,13 @@ typedef enum {
 		/*!< Direct to Core - pass through to core without
 				touching cacheline metadata */
 
+	ocf_req_refresh,
+	ocf_req_cache_mode_discard,
+	ocf_req_cache_mode_flush,
+	ocf_req_cache_mode_invalidate,
+	ocf_req_cache_mode_rd,
+		/*!< Just for debug purposes */
+
 	ocf_req_cache_mode_max,
 } ocf_req_cache_mode_t;
 
@@ -320,6 +327,8 @@ struct ocf_request {
 	uint32_t alock_rw;
 	/*!< Read/Write mode for alock*/
 
+	uint64_t engine_trace;
+
 	uint8_t *alock_status;
 	/*!< Mapping for locked/unlocked alock entries */