osd: improve debugs on EC paths that turned problematic in testing

We want to have better coverage espcially in the matter of:
  * subchunking,
  * want_to_read handling,
  * result bl trimming.

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

diff --git a/src/osd/ECBackend.cc b/src/osd/ECBackend.cc
index 2a4066d22894b8361aa02663d27987a7040d3555..368447cc291c0414531023ca362401847c66e6c8 100644 (file)
--- a/src/osd/ECBackend.cc
+++ b/src/osd/ECBackend.cc
@@ -1037,7 +1037,7 @@ void ECBackend::handle_sub_read(
       if ((op.subchunks.find(i->first)->second.size() == 1) && 
           (op.subchunks.find(i->first)->second.front().second == 
                                             ec_impl->get_sub_chunk_count())) {
-        dout(25) << __func__ << " case1: reading the complete chunk/shard." << dendl;
+        dout(20) << __func__ << " case1: reading the complete chunk/shard." << dendl;
         r = store->read(
          ch,
          ghobject_t(i->first, ghobject_t::NO_GEN, shard),
@@ -1045,9 +1045,11 @@ void ECBackend::handle_sub_read(
          j->get<1>(),
          bl, j->get<2>()); // Allow EIO return
       } else {
-        dout(25) << __func__ << " case2: going to do fragmented read." << dendl;
         int subchunk_size =
           sinfo.get_chunk_size() / ec_impl->get_sub_chunk_count();
+        dout(20) << __func__ << " case2: going to do fragmented read;"
+                << " subchunk_size=" << subchunk_size
+                << " chunk_size=" << sinfo.get_chunk_size() << dendl;
         bool error = false;
         for (int m = 0; m < (int)j->get<1>() && !error;
              m += sinfo.get_chunk_size()) {
@@ -1626,10 +1628,10 @@ void ECBackend::objects_read_async(
          auto range = got.emap.get_containing_range(offset, length);
          ceph_assert(range.first != range.second);
          ceph_assert(range.first.get_off() <= offset);
-          ldpp_dout(dpp, 30) << "offset: " << offset << dendl;
-          ldpp_dout(dpp, 30) << "range offset: " << range.first.get_off() << dendl;
-          ldpp_dout(dpp, 30) << "length: " << length << dendl;
-          ldpp_dout(dpp, 30) << "range length: " << range.first.get_len()  << dendl;
+          ldpp_dout(dpp, 20) << "offset: " << offset << dendl;
+          ldpp_dout(dpp, 20) << "range offset: " << range.first.get_off() << dendl;
+          ldpp_dout(dpp, 20) << "length: " << length << dendl;
+          ldpp_dout(dpp, 20) << "range length: " << range.first.get_len()  << dendl;
          ceph_assert(
            (offset + length) <=
            (range.first.get_off() + range.first.get_len()));

diff --git a/src/osd/ECCommon.cc b/src/osd/ECCommon.cc
index 9ea14dd18eca13feaf7a89b8d5e66d8e268217c7..02bb04c4a0a719c91202e72e548821d208945940 100644 (file)
--- a/src/osd/ECCommon.cc
+++ b/src/osd/ECCommon.cc
@@ -63,6 +63,7 @@ static ostream& _prefix(std::ostream *_dout,
   // TODO: backref to ECListener?
   return *_dout;
 }
+static ostream& _prefix(std::ostream *_dout, struct ClientReadCompleter *read_completer);
 
 ostream &operator<<(ostream &lhs, const ECCommon::RMWPipeline::pipeline_state_t &rhs) {
   switch (rhs.pipeline_state) {
@@ -123,6 +124,7 @@ ostream &operator<<(ostream &lhs, const ECCommon::ReadOp &rhs)
             << ", priority=" << rhs.priority
             << ", obj_to_source=" << rhs.obj_to_source
             << ", source_to_obj=" << rhs.source_to_obj
+            << ", want_to_read" << rhs.want_to_read
             << ", in_progress=" << rhs.in_progress << ")";
 }
 
@@ -139,6 +141,7 @@ void ECCommon::ReadOp::dump(Formatter *f) const
   f->dump_int("priority", priority);
   f->dump_stream("obj_to_source") << obj_to_source;
   f->dump_stream("source_to_obj") << source_to_obj;
+  f->dump_stream("want_to_read") << want_to_read;
   f->dump_stream("in_progress") << in_progress;
 }
 
@@ -171,6 +174,7 @@ ostream &operator<<(ostream &lhs, const ECCommon::RMWPipeline::Op &rhs)
 
 void ECCommon::ReadPipeline::complete_read_op(ReadOp &rop)
 {
+  dout(20) << __func__ << " completing " << rop << dendl;
   map<hobject_t, read_request_t>::iterator req_iter =
     rop.to_read.begin();
   map<hobject_t, read_result_t>::iterator resiter =
@@ -342,7 +346,7 @@ void ECCommon::ReadPipeline::get_min_want_to_read_shards(
 {
   get_min_want_to_read_shards(
     offset, length, sinfo, ec_impl->get_chunk_mapping(), want_to_read);
-  dout(30) << __func__ << ": offset " << offset << " length " << length
+  dout(20) << __func__ << ": offset " << offset << " length " << length
           << " want_to_read " << *want_to_read << dendl;
 }
 
@@ -518,6 +522,9 @@ struct ClientReadCompleter : ECCommon::ReadCompleter {
     list<ECCommon::ec_align_t> to_read,
     set<int> wanted_to_read) override
   {
+    auto* cct = read_pipeline.cct;
+    dout(20) << __func__ << " completing hoid=" << hoid
+             << " res=" << res << " to_read="  << to_read << dendl;
     extent_map result;
     if (res.r != 0)
       goto out;
@@ -541,6 +548,10 @@ struct ClientReadCompleter : ECCommon::ReadCompleter {
           ++j) {
        to_decode[j->first.shard] = std::move(j->second);
       }
+      dout(20) << __func__ << " going to decode: "
+               << " wanted_to_read=" << wanted_to_read
+               << " to_decode=" << to_decode
+               << dendl;
       int r = ECUtil::decode(
        read_pipeline.sinfo,
        read_pipeline.ec_impl,
@@ -548,19 +559,25 @@ struct ClientReadCompleter : ECCommon::ReadCompleter {
        to_decode,
        &bl);
       if (r < 0) {
+        dout(10) << __func__ << " error on ECUtil::decode r=" << r << dendl;
         res.r = r;
         goto out;
       }
       bufferlist trimmed;
-      ceph_assert(aligned.first <= read.offset);
       auto off = read.offset - aligned.first;
       auto len = std::min(read.size, bl.length() - off);
+      dout(20) << __func__ << " bl.length()=" << bl.length()
+              << " len=" << len << " read.size=" << read.size
+              << " off=" << off << " read.offset=" << read.offset
+              << dendl;
       trimmed.substr_of(bl, off, len);
       result.insert(
        read.offset, trimmed.length(), std::move(trimmed));
       res.returned.pop_front();
     }
 out:
+    dout(20) << __func__ << " calling complete_object with result="
+             << result << dendl;
     status->complete_object(hoid, res.r, std::move(result));
     read_pipeline.kick_reads();
   }
@@ -573,6 +590,9 @@ out:
   ECCommon::ReadPipeline &read_pipeline;
   ECCommon::ClientAsyncReadStatus *status;
 };
+static ostream& _prefix(std::ostream *_dout, ClientReadCompleter *read_completer) {
+  return _prefix(_dout, &read_completer->read_pipeline);
+}
 
 void ECCommon::ReadPipeline::objects_read_and_reconstruct(
   const map<hobject_t, std::list<ECCommon::ec_align_t>> &reads,
@@ -609,6 +629,12 @@ void ECCommon::ReadPipeline::objects_read_and_reconstruct(
       &shards);
     ceph_assert(r == 0);
 
+    int subchunk_size =
+      sinfo.get_chunk_size() / ec_impl->get_sub_chunk_count();
+    dout(20) << __func__
+             << " subchunk_size=" << subchunk_size
+             << " chunk_size=" << sinfo.get_chunk_size() << dendl;
+
     for_read_op.insert(
       make_pair(
        to_read.first,