Improve error logging.

Skip-unit-tests: true
Skip-fault-injection-test: true
Test-tag: test_dfuse_caching_check

Signed-off-by: Ashley Pittman <ashley.m.pittman@intel.com>

src/client/dfuse/ops/read.c

@@ -194,8 +194,8 @@ chunk_cb(struct dfuse_event *ev)
 
 	if (cd->rc == 0 && (ev->de_len != CHUNK_SIZE)) {
 		cd->rc = EIO;
-		DS_WARN(cd->rc, "Unexpected short read expected %i got %zi", CHUNK_SIZE,
-			ev->de_len);
+		DS_WARN(cd->rc, "Unexpected short read bucket %d (%#zx) expected %i got %zi",
+			cd->bucket, (off_t)cd->bucket * CHUNK_SIZE, CHUNK_SIZE, ev->de_len);
 	}
 
 	daos_event_fini(&ev->de_ev);
@@ -318,8 +318,6 @@ chunk_read(fuse_req_t req, size_t len, off_t position, struct dfuse_obj_hdl *oh)
 	bool                      submit = false;
 	bool                      rcb;
 
-	last = position + ((position + (K128 - 1)) & -K128);
-
 	if (len != K128)
 		return false;
 
@@ -459,9 +457,7 @@ dfuse_cb_read(fuse_req_t req, fuse_ino_t ino, size_t len, off_t position, struct
 		}
 	}
 
-	if (oh->doh_ie->ie_dfs->dfc_data_timeout != 0 &&
-	    ((atomic_fetch_add(&oh->doh_ie->ie_il_count, 0) == 0)) &&
-	    chunk_read(req, len, position, oh))
+	if (chunk_read(req, len, position, oh))
 		return;
 
 	eqt = pick_eqt(dfuse_info);

src/tests/ftest/dfuse/caching_check.py

@@ -45,13 +45,16 @@ def test_dfuse_caching_check(self):
 
         self.log_step('Write to the dfuse mount point')
         self.run_ior_with_pool(fail_on_warning=False, stop_dfuse=False)
+        self.dfuse.get_stats()
 
         self.log_step('Get baseline read performance from dfuse with caching disabled')
         self.ior_cmd.update_params(flags=flags[1])
         base_read_arr = []
         out = self.run_ior_with_pool(fail_on_warning=False, stop_dfuse=False)
+        self.dfuse.get_stats()
         base_read_arr.append(IorCommand.get_ior_metrics(out))
         out = self.run_ior_with_pool(fail_on_warning=False, stop_dfuse=False)
+        self.dfuse.get_stats()
         base_read_arr.append(IorCommand.get_ior_metrics(out))
 
         # the index of max_mib
@@ -64,10 +67,12 @@ def test_dfuse_caching_check(self):
 
         self.log_step('Get first read performance with caching enabled')
         out = self.run_ior_with_pool(fail_on_warning=False, stop_dfuse=False)
+        self.dfuse.get_stats()
         base_read_arr.append(IorCommand.get_ior_metrics(out))
 
         self.log_step('Get cached read performance')
-        out = self.run_ior_with_pool(fail_on_warning=False)
+        out = self.run_ior_with_pool(fail_on_warning=False, stop_dfuse=False)
+        self.dfuse.get_stats()
         with_caching = IorCommand.get_ior_metrics(out)
 
         self.log_step('Verify cached read performance is greater than first read')

src/tests/ftest/dfuse/caching_check.yaml

@@ -31,3 +31,8 @@ ior:
 dfuse:
   disable_caching: true
   disable_wb_caching: true
+  client:
+    env_vars:
+      - D_LOG_MASK=INFO,DFUSE=DEBUG,DFS=DEBUG
+      - DD_MASK=ALL
+      - DD_SUBSYS=ALL