journal: improve logging on recorder append path

Signed-off-by: Jason Dillaman <dillaman@redhat.com>
(cherry picked from commit 84e48ddbf58d4028c4195d9c80634f895f62f2be)

diff --git a/src/journal/JournalRecorder.cc b/src/journal/JournalRecorder.cc
index d4b023c3d5eb23c0886c9b842db27372896591e1..ab5aa68605e58777252d7672deed4aea2f9fb1a9 100644 (file)
--- a/src/journal/JournalRecorder.cc
+++ b/src/journal/JournalRecorder.cc
@@ -10,7 +10,8 @@
 
 #define dout_subsys ceph_subsys_journaler
 #undef dout_prefix
-#define dout_prefix *_dout << "JournalRecorder: " << this << " "
+#define dout_prefix *_dout << "JournalRecorder: " << this << " " << __func__ \
+                           << ": "
 
 using std::shared_ptr;
 
@@ -110,6 +111,7 @@ void JournalRecorder::shut_down(Context *on_safe) {
 
 Future JournalRecorder::append(uint64_t tag_tid,
                                const bufferlist &payload_bl) {
+  ldout(m_cct, 20) << "tag_tid=" << tag_tid << dendl;
 
   m_lock.Lock();
 
@@ -143,6 +145,8 @@ Future JournalRecorder::append(uint64_t tag_tid,
 }
 
 void JournalRecorder::flush(Context *on_safe) {
+  ldout(m_cct, 20) << dendl;
+
   C_Flush *ctx;
   {
     Mutex::Locker locker(m_lock);
@@ -172,7 +176,7 @@ void JournalRecorder::close_and_advance_object_set(uint64_t object_set) {
 
   // entry overflow from open object
   if (m_current_set != object_set) {
-    ldout(m_cct, 20) << __func__ << ": close already in-progress" << dendl;
+    ldout(m_cct, 20) << "close already in-progress" << dendl;
     return;
   }
 
@@ -186,8 +190,7 @@ void JournalRecorder::close_and_advance_object_set(uint64_t object_set) {
   ++m_current_set;
   ++m_in_flight_advance_sets;
 
-  ldout(m_cct, 20) << __func__ << ": closing active object set "
-                   << object_set << dendl;
+  ldout(m_cct, 10) << "closing active object set " << object_set << dendl;
   if (close_object_set(m_current_set)) {
     advance_object_set();
   }
@@ -197,8 +200,7 @@ void JournalRecorder::advance_object_set() {
   ceph_assert(m_lock.is_locked());
 
   ceph_assert(m_in_flight_object_closes == 0);
-  ldout(m_cct, 20) << __func__ << ": advance to object set " << m_current_set
-                   << dendl;
+  ldout(m_cct, 10) << "advance to object set " << m_current_set << dendl;
   m_journal_metadata->set_active_set(m_current_set, new C_AdvanceObjectSet(
     this));
 }
@@ -213,8 +215,8 @@ void JournalRecorder::handle_advance_object_set(int r) {
     --m_in_flight_advance_sets;
 
     if (r < 0 && r != -ESTALE) {
-      lderr(m_cct) << __func__ << ": failed to advance object set: "
-                   << cpp_strerror(r) << dendl;
+      lderr(m_cct) << "failed to advance object set: " << cpp_strerror(r)
+                   << dendl;
     }
 
     if (m_in_flight_advance_sets == 0 && m_in_flight_object_closes == 0) {
@@ -230,8 +232,7 @@ void JournalRecorder::handle_advance_object_set(int r) {
 void JournalRecorder::open_object_set() {
   ceph_assert(m_lock.is_locked());
 
-  ldout(m_cct, 10) << __func__ << ": opening object set " << m_current_set
-                   << dendl;
+  ldout(m_cct, 10) << "opening object set " << m_current_set << dendl;
 
   uint8_t splay_width = m_journal_metadata->get_splay_width();
 
@@ -253,6 +254,7 @@ void JournalRecorder::open_object_set() {
 }
 
 bool JournalRecorder::close_object_set(uint64_t active_set) {
+  ldout(m_cct, 10) << "active_set=" << active_set << dendl;
   ceph_assert(m_lock.is_locked());
 
   // object recorders will invoke overflow handler as they complete
@@ -263,14 +265,14 @@ bool JournalRecorder::close_object_set(uint64_t active_set) {
        it != m_object_ptrs.end(); ++it) {
     ObjectRecorderPtr object_recorder = it->second;
     if (object_recorder->get_object_number() / splay_width != active_set) {
-      ldout(m_cct, 10) << __func__ << ": closing object "
-                       << object_recorder->get_oid() << dendl;
+      ldout(m_cct, 10) << "closing object " << object_recorder->get_oid()
+                       << dendl;
       // flush out all queued appends and hold future appends
       if (!object_recorder->close()) {
         ++m_in_flight_object_closes;
       } else {
-        ldout(m_cct, 20) << __func__ << ": object "
-                         << object_recorder->get_oid() << " closed" << dendl;
+        ldout(m_cct, 10) << "object " << object_recorder->get_oid() << " closed"
+                         << dendl;
       }
     }
   }
@@ -280,6 +282,7 @@ bool JournalRecorder::close_object_set(uint64_t active_set) {
 
 ObjectRecorderPtr JournalRecorder::create_object_recorder(
     uint64_t object_number, shared_ptr<Mutex> lock) {
+  ldout(m_cct, 10) << "object_number=" << object_number << dendl;
   ObjectRecorderPtr object_recorder(new ObjectRecorder(
     m_ioctx, utils::get_object_name(m_object_oid_prefix, object_number),
     object_number, lock, m_journal_metadata->get_work_queue(),
@@ -296,14 +299,14 @@ void JournalRecorder::create_next_object_recorder_unlock(
   uint64_t object_number = object_recorder->get_object_number();
   uint8_t splay_width = m_journal_metadata->get_splay_width();
   uint8_t splay_offset = object_number % splay_width;
+  ldout(m_cct, 10) << "object_number=" << object_number << dendl;
 
   ceph_assert(m_object_locks[splay_offset]->is_locked());
 
   ObjectRecorderPtr new_object_recorder = create_object_recorder(
      (m_current_set * splay_width) + splay_offset, m_object_locks[splay_offset]);
 
-  ldout(m_cct, 10) << __func__ << ": "
-                   << "old oid=" << object_recorder->get_oid() << ", "
+  ldout(m_cct, 10) << "old oid=" << object_recorder->get_oid() << ", "
                    << "new oid=" << new_object_recorder->get_oid() << dendl;
   AppendBuffers append_buffers;
   object_recorder->claim_append_buffers(&append_buffers);
@@ -325,15 +328,13 @@ void JournalRecorder::handle_update() {
   uint64_t active_set = m_journal_metadata->get_active_set();
   if (m_current_set < active_set) {
     // peer journal client advanced the active set
-    ldout(m_cct, 20) << __func__ << ": "
-                     << "current_set=" << m_current_set << ", "
+    ldout(m_cct, 10) << "current_set=" << m_current_set << ", "
                      << "active_set=" << active_set << dendl;
 
     uint64_t current_set = m_current_set;
     m_current_set = active_set;
     if (m_in_flight_advance_sets == 0 && m_in_flight_object_closes == 0) {
-      ldout(m_cct, 20) << __func__ << ": closing current object set "
-                       << current_set << dendl;
+      ldout(m_cct, 10) << "closing current object set " << current_set << dendl;
       if (close_object_set(active_set)) {
         open_object_set();
       }
@@ -342,7 +343,7 @@ void JournalRecorder::handle_update() {
 }
 
 void JournalRecorder::handle_closed(ObjectRecorder *object_recorder) {
-  ldout(m_cct, 10) << __func__ << ": " << object_recorder->get_oid() << dendl;
+  ldout(m_cct, 10) << object_recorder->get_oid() << dendl;
 
   Mutex::Locker locker(m_lock);
 
@@ -356,8 +357,8 @@ void JournalRecorder::handle_closed(ObjectRecorder *object_recorder) {
   --m_in_flight_object_closes;
 
   // object closed after advance active set committed
-  ldout(m_cct, 20) << __func__ << ": object "
-                   << active_object_recorder->get_oid() << " closed" << dendl;
+  ldout(m_cct, 10) << "object " << active_object_recorder->get_oid()
+                   << " closed" << dendl;
   if (m_in_flight_object_closes == 0) {
     if (m_in_flight_advance_sets == 0) {
       // peer forced closing of object set
@@ -370,7 +371,7 @@ void JournalRecorder::handle_closed(ObjectRecorder *object_recorder) {
 }
 
 void JournalRecorder::handle_overflow(ObjectRecorder *object_recorder) {
-  ldout(m_cct, 10) << __func__ << ": " << object_recorder->get_oid() << dendl;
+  ldout(m_cct, 10) << object_recorder->get_oid() << dendl;
 
   Mutex::Locker locker(m_lock);
 
@@ -380,9 +381,8 @@ void JournalRecorder::handle_overflow(ObjectRecorder *object_recorder) {
   ObjectRecorderPtr active_object_recorder = m_object_ptrs[splay_offset];
   ceph_assert(active_object_recorder->get_object_number() == object_number);
 
-  ldout(m_cct, 20) << __func__ << ": object "
-                   << active_object_recorder->get_oid() << " overflowed"
-                   << dendl;
+  ldout(m_cct, 10) << "object " << active_object_recorder->get_oid()
+                   << " overflowed" << dendl;
   close_and_advance_object_set(object_number / splay_width);
 }
 

diff --git a/src/journal/ObjectRecorder.cc b/src/journal/ObjectRecorder.cc
index e4049df65207ceea019a7ded9245e47fc527a0d5..eca0ea5655dbd41a89f3ce4a86c904352c933947 100644 (file)
--- a/src/journal/ObjectRecorder.cc
+++ b/src/journal/ObjectRecorder.cc
@@ -10,7 +10,8 @@
 
 #define dout_subsys ceph_subsys_journaler
 #undef dout_prefix
-#define dout_prefix *_dout << "ObjectRecorder: " << this << " "
+#define dout_prefix *_dout << "ObjectRecorder: " << this << " " \
+                           << __func__ << " (" << m_oid << "): "
 
 using namespace cls::journal;
 using std::shared_ptr;
@@ -36,9 +37,11 @@ ObjectRecorder::ObjectRecorder(librados::IoCtx &ioctx, const std::string &oid,
   m_ioctx.dup(ioctx);
   m_cct = reinterpret_cast<CephContext*>(m_ioctx.cct());
   ceph_assert(m_handler != NULL);
+  ldout(m_cct, 20) << dendl;
 }
 
 ObjectRecorder::~ObjectRecorder() {
+  ldout(m_cct, 20) << dendl;
   ceph_assert(m_append_task == NULL);
   ceph_assert(m_append_buffers.empty());
   ceph_assert(m_in_flight_tids.empty());
@@ -48,6 +51,7 @@ ObjectRecorder::~ObjectRecorder() {
 
 bool ObjectRecorder::append_unlock(AppendBuffers &&append_buffers) {
   ceph_assert(m_lock->is_locked());
+  ldout(m_cct, 20) << "count=" << append_buffers.size() << dendl;
 
   FutureImplPtr last_flushed_future;
   bool schedule_append = false;
@@ -56,6 +60,7 @@ bool ObjectRecorder::append_unlock(AppendBuffers &&append_buffers) {
     m_append_buffers.insert(m_append_buffers.end(),
                             append_buffers.begin(), append_buffers.end());
     m_lock->Unlock();
+    ldout(m_cct, 20) << "already overflowed" << dendl;
     return false;
   }
 
@@ -82,7 +87,7 @@ bool ObjectRecorder::append_unlock(AppendBuffers &&append_buffers) {
 }
 
 void ObjectRecorder::flush(Context *on_safe) {
-  ldout(m_cct, 20) << __func__ << ": " << m_oid << dendl;
+  ldout(m_cct, 20) << dendl;
 
   cancel_append_task();
   Future future;
@@ -118,8 +123,7 @@ void ObjectRecorder::flush(Context *on_safe) {
 }
 
 void ObjectRecorder::flush(const FutureImplPtr &future) {
-  ldout(m_cct, 20) << __func__ << ": " << m_oid << " flushing " << *future
-                   << dendl;
+  ldout(m_cct, 20) << "flushing " << *future << dendl;
 
   ceph_assert(m_lock->is_locked());
 
@@ -156,7 +160,7 @@ void ObjectRecorder::flush(const FutureImplPtr &future) {
 }
 
 void ObjectRecorder::claim_append_buffers(AppendBuffers *append_buffers) {
-  ldout(m_cct, 20) << __func__ << ": " << m_oid << dendl;
+  ldout(m_cct, 20) << dendl;
 
   ceph_assert(m_lock->is_locked());
   ceph_assert(m_in_flight_tids.empty());
@@ -169,7 +173,7 @@ void ObjectRecorder::claim_append_buffers(AppendBuffers *append_buffers) {
 bool ObjectRecorder::close() {
   ceph_assert(m_lock->is_locked());
 
-  ldout(m_cct, 20) << __func__ << ": " << m_oid << dendl;
+  ldout(m_cct, 20) << dendl;
 
   cancel_append_task();
 
@@ -191,6 +195,7 @@ void ObjectRecorder::handle_append_task() {
 void ObjectRecorder::cancel_append_task() {
   Mutex::Locker locker(m_timer_lock);
   if (m_append_task != NULL) {
+    ldout(m_cct, 20) << dendl;
     m_timer.cancel_event(m_append_task);
     m_append_task = NULL;
   }
@@ -199,6 +204,7 @@ void ObjectRecorder::cancel_append_task() {
 void ObjectRecorder::schedule_append_task() {
   Mutex::Locker locker(m_timer_lock);
   if (m_append_task == nullptr && m_flush_age > 0) {
+    ldout(m_cct, 20) << dendl;
     m_append_task = m_timer.add_event_after(
       m_flush_age, new FunctionContext([this](int) {
          handle_append_task();
@@ -209,6 +215,7 @@ void ObjectRecorder::schedule_append_task() {
 bool ObjectRecorder::append(const AppendBuffer &append_buffer,
                             bool *schedule_append) {
   ceph_assert(m_lock->is_locked());
+  ldout(m_cct, 20) << "bytes=" << append_buffer.second.length() << dendl;
 
   bool flush_requested = false;
   if (!m_object_closed && !m_overflowed) {
@@ -226,7 +233,9 @@ bool ObjectRecorder::append(const AppendBuffer &append_buffer,
 
 bool ObjectRecorder::flush_appends(bool force) {
   ceph_assert(m_lock->is_locked());
+  ldout(m_cct, 20) << "force=" << force << dendl;
   if (m_object_closed || m_overflowed) {
+    ldout(m_cct, 20) << "already closed or overflowed" << dendl;
     return true;
   }
 
@@ -235,6 +244,7 @@ bool ObjectRecorder::flush_appends(bool force) {
        m_size + m_pending_bytes < m_soft_max_size &&
        (m_flush_interval > 0 && m_append_buffers.size() < m_flush_interval) &&
        (m_flush_bytes > 0 && m_pending_bytes < m_flush_bytes))) {
+    ldout(m_cct, 20) << "batching append" << dendl;
     return false;
   }
 
@@ -246,8 +256,7 @@ bool ObjectRecorder::flush_appends(bool force) {
 }
 
 void ObjectRecorder::handle_append_flushed(uint64_t tid, int r) {
-  ldout(m_cct, 10) << __func__ << ": " << m_oid << " tid=" << tid
-                   << ", r=" << r << dendl;
+  ldout(m_cct, 20) << "tid=" << tid << ", r=" << r << dendl;
 
   AppendBuffers append_buffers;
   {
@@ -259,6 +268,7 @@ void ObjectRecorder::handle_append_flushed(uint64_t tid, int r) {
     InFlightAppends::iterator iter = m_in_flight_appends.find(tid);
     if (r == -EOVERFLOW || m_overflowed) {
       if (iter != m_in_flight_appends.end()) {
+        ldout(m_cct, 10) << "append overflowed" << dendl;
         m_overflowed = true;
       } else {
         // must have seen an overflow on a previous append op
@@ -288,8 +298,7 @@ void ObjectRecorder::handle_append_flushed(uint64_t tid, int r) {
   // Flag the associated futures as complete.
   for (AppendBuffers::iterator buf_it = append_buffers.begin();
        buf_it != append_buffers.end(); ++buf_it) {
-    ldout(m_cct, 20) << __func__ << ": " << *buf_it->first << " marked safe"
-                     << dendl;
+    ldout(m_cct, 20) << *buf_it->first << " marked safe" << dendl;
     buf_it->first->safe(r);
   }
 
@@ -302,8 +311,7 @@ void ObjectRecorder::handle_append_flushed(uint64_t tid, int r) {
     if (m_in_flight_appends.empty() &&
         (m_object_closed || m_aio_sent_size >= m_soft_max_size)) {
       if (m_aio_sent_size >= m_soft_max_size) {
-        ldout(m_cct, 20) << __func__ << ": " << m_oid
-                         << " soft max size reached, notifying overflow"
+        ldout(m_cct, 20) << " soft max size reached, notifying overflow"
                          << dendl;
         m_overflowed = true;
       }
@@ -323,8 +331,7 @@ void ObjectRecorder::handle_append_flushed(uint64_t tid, int r) {
 }
 
 void ObjectRecorder::append_overflowed() {
-  ldout(m_cct, 10) << __func__ << ": " << m_oid << " append overflowed"
-                   << dendl;
+  ldout(m_cct, 10) << dendl;
 
   ceph_assert(m_lock->is_locked());
   ceph_assert(!m_in_flight_appends.empty());
@@ -349,20 +356,19 @@ void ObjectRecorder::append_overflowed() {
 
   for (AppendBuffers::const_iterator it = m_append_buffers.begin();
        it != m_append_buffers.end(); ++it) {
-    ldout(m_cct, 20) << __func__ << ": overflowed " << *it->first
-                     << dendl;
+    ldout(m_cct, 20) << "overflowed " << *it->first << dendl;
     it->first->detach();
   }
 }
 
 void ObjectRecorder::send_appends(AppendBuffers *append_buffers) {
+  ldout(m_cct, 20) << dendl;
   ceph_assert(m_lock->is_locked());
   ceph_assert(!append_buffers->empty());
 
   for (AppendBuffers::iterator it = append_buffers->begin();
        it != append_buffers->end(); ++it) {
-    ldout(m_cct, 20) << __func__ << ": flushing " << *it->first
-                     << dendl;
+    ldout(m_cct, 20) << "flushing " << *it->first << dendl;
     it->first->set_flush_in_progress();
     m_size += it->second.length();
   }
@@ -378,45 +384,44 @@ void ObjectRecorder::send_appends(AppendBuffers *append_buffers) {
 }
 
 void ObjectRecorder::send_appends_aio() {
+  ldout(m_cct, 20) << dendl;
   librados::AioCompletion *rados_completion;
   {
     Mutex::Locker locker(*m_lock);
     m_aio_scheduled = false;
 
     if (m_pending_buffers.empty()) {
-      ldout(m_cct, 20) << __func__ << ": " << m_oid << " pending buffers empty"
-                       << dendl;
+      ldout(m_cct, 10) << "pending buffers empty" << dendl;
       return;
     }
 
     if (m_max_in_flight_appends != 0 &&
         m_in_flight_tids.size() >= m_max_in_flight_appends) {
-      ldout(m_cct, 20) << __func__ << ": " << m_oid
-                       << " max in flight appends reached" << dendl;
+      ldout(m_cct, 10) << "max in flight appends reached" << dendl;
       return;
     }
 
     if (m_aio_sent_size >= m_soft_max_size) {
-      ldout(m_cct, 20) << __func__ << ": " << m_oid
-                       << " soft max size reached" << dendl;
+      ldout(m_cct, 10) << "soft max size reached" << dendl;
       return;
     }
 
     uint64_t append_tid = m_append_tid++;
     m_in_flight_tids.insert(append_tid);
 
-    ldout(m_cct, 10) << __func__ << ": " << m_oid << " flushing journal tid="
-                     << append_tid << dendl;
+    ldout(m_cct, 10) << "flushing journal tid=" << append_tid << dendl;
 
     librados::ObjectWriteOperation op;
     client::guard_append(&op, m_soft_max_size);
     auto append_buffers = &m_in_flight_appends[append_tid];
 
+    size_t append_bytes = 0;
     for (auto it = m_pending_buffers.begin(); it != m_pending_buffers.end(); ) {
-      ldout(m_cct, 20) << __func__ << ": flushing " << *it->first << dendl;
+      ldout(m_cct, 20) << "flushing " << *it->first << dendl;
       op.append(it->second);
       op.set_op_flags2(CEPH_OSD_OP_FLAG_FADVISE_DONTNEED);
       m_aio_sent_size += it->second.length();
+      append_bytes += it->second.length();
       append_buffers->push_back(*it);
       it = m_pending_buffers.erase(it);
       if (m_aio_sent_size >= m_soft_max_size) {
@@ -428,6 +433,7 @@ void ObjectRecorder::send_appends_aio() {
         utils::rados_ctx_callback);
     int r = m_ioctx.aio_operate(m_oid, rados_completion, &op);
     ceph_assert(r == 0);
+    ldout(m_cct, 20) << "append_bytes=" << append_bytes << dendl;
   }
   rados_completion->release();
 }