From 8c014fbde20a518f9e734a3df961fe910907d1c1 Mon Sep 17 00:00:00 2001 From: Michal Mielewczyk Date: Wed, 16 Oct 2024 15:31:00 +0200 Subject: [PATCH] Debug request tracing Signed-off-by: Michal Mielewczyk --- src/engine/cache_engine.c | 38 +++++++++++++++++++++++++++++++++++++ src/engine/cache_engine.h | 3 +++ src/engine/engine_bf.c | 1 + src/engine/engine_common.c | 1 + src/engine/engine_discard.c | 2 ++ src/engine/engine_fast.c | 7 +++++++ src/engine/engine_pt.c | 4 +++- src/engine/engine_rd.c | 5 ++++- src/engine/engine_wa.c | 2 ++ src/engine/engine_wb.c | 5 ++++- src/engine/engine_wi.c | 3 +++ src/engine/engine_wo.c | 3 +++ src/engine/engine_wt.c | 5 +++++ src/ocf_request.h | 8 ++++++++ 14 files changed, 84 insertions(+), 3 deletions(-) diff --git a/src/engine/cache_engine.c b/src/engine/cache_engine.c index f7f160e0..ff2b2b52 100644 --- a/src/engine/cache_engine.c +++ b/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) diff --git a/src/engine/cache_engine.h b/src/engine/cache_engine.h index f9c7c7d2..c950fbe1 100644 --- a/src/engine/cache_engine.h +++ b/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 diff --git a/src/engine/engine_bf.c b/src/engine/engine_bf.c index 2d80d78a..10957940 100644 --- a/src/engine/engine_bf.c +++ b/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); diff --git a/src/engine/engine_common.c b/src/engine/engine_common.c index e25eb4f7..f098e39a 100644 --- a/src/engine/engine_common.c +++ b/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"); diff --git a/src/engine/engine_discard.c b/src/engine/engine_discard.c index 250da03d..aef63b8c 100644 --- a/src/engine/engine_discard.c +++ b/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 { diff --git a/src/engine/engine_fast.c b/src/engine/engine_fast.c index b35788e5..e54b048c 100644 --- a/src/engine/engine_fast.c +++ b/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 { diff --git a/src/engine/engine_pt.c b/src/engine/engine_pt.c index f15c0559..abb21e05 100644 --- a/src/engine/engine_pt.c +++ b/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 { diff --git a/src/engine/engine_rd.c b/src/engine/engine_rd.c index bbc90cb2..23564a2a 100644 --- a/src/engine/engine_rd.c +++ b/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); } diff --git a/src/engine/engine_wa.c b/src/engine/engine_wa.c index c7813186..35df3f8e 100644 --- a/src/engine/engine_wa.c +++ b/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); } diff --git a/src/engine/engine_wb.c b/src/engine/engine_wb.c index 1860de46..59fd800b 100644 --- a/src/engine/engine_wb.c +++ b/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); } diff --git a/src/engine/engine_wi.c b/src/engine/engine_wi.c index a72c5924..2b562953 100644 --- a/src/engine/engine_wi.c +++ b/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 { diff --git a/src/engine/engine_wo.c b/src/engine/engine_wo.c index 16a93625..bec7c9c1 100644 --- a/src/engine/engine_wo.c +++ b/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 { diff --git a/src/engine/engine_wt.c b/src/engine/engine_wt.c index 303dc077..ca9e82f5 100644 --- a/src/engine/engine_wt.c +++ b/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); } diff --git a/src/ocf_request.h b/src/ocf_request.h index 36ab4d80..ffd46e63 100644 --- a/src/ocf_request.h +++ b/src/ocf_request.h @@ -28,6 +28,12 @@ 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_invalidate, + ocf_req_cache_mode_rd, + /*!< Just for debug purposes */ + ocf_req_cache_mode_max, } ocf_req_cache_mode_t; @@ -320,6 +326,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 */