From: Jason Dillaman Date: Fri, 8 Jul 2016 19:16:04 +0000 (-0400) Subject: librbd: improve journaling debug log messages X-Git-Tag: ses5-milestone5~364^2~2 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=270cb74bc276bfb1f828a6a6933fa827f6cdce42;p=ceph.git librbd: improve journaling debug log messages Signed-off-by: Jason Dillaman --- diff --git a/src/librbd/Journal.cc b/src/librbd/Journal.cc index 231089f507ae..5b8e305a908a 100644 --- a/src/librbd/Journal.cc +++ b/src/librbd/Journal.cc @@ -50,7 +50,8 @@ struct C_DecodeTag : public Context { int process(int r) { if (r < 0) { - lderr(cct) << "failed to allocate tag: " << cpp_strerror(r) << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to allocate tag: " << cpp_strerror(r) << dendl; return r; } @@ -60,11 +61,13 @@ struct C_DecodeTag : public Context { bufferlist::iterator data_it = tag.data.begin(); r = decode(&data_it, tag_data); if (r < 0) { - lderr(cct) << "failed to decode allocated tag" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to decode allocated tag" << dendl; return r; } - ldout(cct, 20) << "allocated journal tag: " + ldout(cct, 20) << this << " " << __func__ << ": " + << "allocated journal tag: " << "tid=" << tag.tid << ", " << "data=" << *tag_data << dendl; return 0; @@ -106,13 +109,15 @@ struct C_DecodeTags : public Context { int process(int r) { if (r < 0) { - lderr(cct) << "failed to retrieve journal tags: " << cpp_strerror(r) + lderr(cct) << this << " " << __func__ << ": " + << "failed to retrieve journal tags: " << cpp_strerror(r) << dendl; return r; } if (tags.empty()) { - lderr(cct) << "no journal tags retrieved" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "no journal tags retrieved" << dendl; return -ENOENT; } @@ -122,11 +127,13 @@ struct C_DecodeTags : public Context { bufferlist::iterator data_it = tags.back().data.begin(); r = C_DecodeTag::decode(&data_it, tag_data); if (r < 0) { - lderr(cct) << "failed to decode journal tag" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to decode journal tag" << dendl; return r; } - ldout(cct, 20) << "most recent journal tag: " + ldout(cct, 20) << this << " " << __func__ << ": " + << "most recent journal tag: " << "tid=" << *tag_tid << ", " << "data=" << *tag_data << dendl; return 0; @@ -232,7 +239,8 @@ int allocate_journaler_tag(CephContext *cct, J *journaler, int r = allocate_tag_ctx.wait(); if (r < 0) { - lderr(cct) << "failed to allocate tag: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to allocate tag: " << cpp_strerror(r) << dendl; return r; } return 0; @@ -357,7 +365,8 @@ int Journal::create(librados::IoCtx &io_ctx, const std::string &image_id, IoCtx data_io_ctx; int r = rados.ioctx_create(object_pool.c_str(), data_io_ctx); if (r != 0) { - lderr(cct) << "failed to create journal: " + lderr(cct) << __func__ << ": " + << "failed to create journal: " << "error opening journal objects pool '" << object_pool << "': " << cpp_strerror(r) << dendl; return r; @@ -370,7 +379,8 @@ int Journal::create(librados::IoCtx &io_ctx, const std::string &image_id, int r = journaler.create(order, splay_width, pool_id); if (r < 0) { - lderr(cct) << "failed to create journal: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to create journal: " << cpp_strerror(r) << dendl; return r; } @@ -391,7 +401,8 @@ int Journal::create(librados::IoCtx &io_ctx, const std::string &image_id, r = journaler.register_client(client_data); if (r < 0) { - lderr(cct) << "failed to register client: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to register client: " << cpp_strerror(r) << dendl; return r; } return 0; @@ -408,7 +419,8 @@ int Journal::remove(librados::IoCtx &io_ctx, const std::string &image_id) { bool journal_exists; int r = journaler.exists(&journal_exists); if (r < 0) { - lderr(cct) << "failed to stat journal header: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to stat journal header: " << cpp_strerror(r) << dendl; return r; } else if (!journal_exists) { return 0; @@ -424,13 +436,15 @@ int Journal::remove(librados::IoCtx &io_ctx, const std::string &image_id) { if (r == -ENOENT) { return 0; } else if (r < 0) { - lderr(cct) << "failed to initialize journal: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to initialize journal: " << cpp_strerror(r) << dendl; return r; } r = journaler.remove(true); if (r < 0) { - lderr(cct) << "failed to remove journal: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to remove journal: " << cpp_strerror(r) << dendl; return r; } return 0; @@ -454,7 +468,8 @@ int Journal::reset(librados::IoCtx &io_ctx, const std::string &image_id) { if (r == -ENOENT) { return 0; } else if (r < 0) { - lderr(cct) << "failed to initialize journal: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to initialize journal: " << cpp_strerror(r) << dendl; return r; } @@ -467,20 +482,23 @@ int Journal::reset(librados::IoCtx &io_ctx, const std::string &image_id) { librados::Rados rados(io_ctx); r = rados.pool_reverse_lookup(pool_id, &pool_name); if (r < 0) { - lderr(cct) << "failed to lookup data pool: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to lookup data pool: " << cpp_strerror(r) << dendl; return r; } } r = journaler.remove(true); if (r < 0) { - lderr(cct) << "failed to reset journal: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to reset journal: " << cpp_strerror(r) << dendl; return r; } r = create(io_ctx, image_id, order, splay_width, pool_name, false, ""); if (r < 0) { - lderr(cct) << "failed to create journal: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to create journal: " << cpp_strerror(r) << dendl; return r; } return 0; @@ -562,7 +580,8 @@ int Journal::request_resync(I *image_ctx) { r = update_client_ctx.wait(); if (r < 0) { - lderr(cct) << "failed to update client: " << cpp_strerror(r) << dendl; + lderr(cct) << __func__ << ": " + << "failed to update client: " << cpp_strerror(r) << dendl; return r; } return 0; @@ -688,7 +707,8 @@ int Journal::demote() { cls::journal::Client client; int r = m_journaler->get_cached_client(IMAGE_CLIENT_ID, &client); if (r < 0) { - lderr(cct) << "failed to retrieve client: " << cpp_strerror(r) << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to retrieve client: " << cpp_strerror(r) << dendl; return r; } @@ -702,7 +722,8 @@ int Journal::demote() { bufferlist::iterator tag_data_bl_it = new_tag.data.begin(); r = C_DecodeTag::decode(&tag_data_bl_it, &m_tag_data); if (r < 0) { - lderr(cct) << "failed to decode newly allocated tag" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to decode newly allocated tag" << dendl; return r; } @@ -717,7 +738,8 @@ int Journal::demote() { r = ctx.wait(); if (r < 0) { - lderr(cct) << "failed to append demotion journal event: " << cpp_strerror(r) + lderr(cct) << this << " " << __func__ << ": " + << "failed to append demotion journal event: " << cpp_strerror(r) << dendl; return r; } @@ -728,7 +750,8 @@ int Journal::demote() { r = flush_ctx.wait(); if (r < 0) { - lderr(cct) << "failed to flush demotion commit position: " + lderr(cct) << this << " " << __func__ << ": " + << "failed to flush demotion commit position: " << cpp_strerror(r) << dendl; return r; } @@ -751,7 +774,8 @@ void Journal::allocate_local_tag(Context *on_finish) { cls::journal::Client client; int r = m_journaler->get_cached_client(IMAGE_CLIENT_ID, &client); if (r < 0) { - lderr(cct) << "failed to retrieve client: " << cpp_strerror(r) << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to retrieve client: " << cpp_strerror(r) << dendl; m_image_ctx.op_work_queue->queue(on_finish, r); return; } @@ -947,7 +971,8 @@ void Journal::commit_io_event_extent(uint64_t tid, uint64_t offset, event.pending_extents.subtract(intersect); if (!event.pending_extents.empty()) { - ldout(cct, 20) << "pending extents: " << event.pending_extents << dendl; + ldout(cct, 20) << this << " " << __func__ << ": " + << "pending extents: " << event.pending_extents << dendl; return; } complete_event(it, event.ret_val); @@ -1069,7 +1094,8 @@ typename Journal::Future Journal::wait_event(Mutex &lock, uint64_t tid, Event &event = it->second; if (event.safe) { // journal entry already safe - ldout(cct, 20) << "journal entry already safe" << dendl; + ldout(cct, 20) << this << " " << __func__ << ": " + << "journal entry already safe" << dendl; m_image_ctx.op_work_queue->queue(on_safe, event.ret_val); return Future(); } @@ -1115,7 +1141,8 @@ void Journal::handle_start_external_replay(int r, assert(m_journal_replay == nullptr); if (r < 0) { - lderr(cct) << "failed to stop recording: " << cpp_strerror(r) << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to stop recording: " << cpp_strerror(r) << dendl; *journal_replay = nullptr; if (m_on_replay_close_request != nullptr) { @@ -1227,7 +1254,8 @@ void Journal::complete_event(typename Events::iterator it, int r) { // event recorded to journal but failed to update disk, we cannot // commit this IO event. this event must be replayed. assert(event.safe); - lderr(cct) << "failed to commit IO to disk, replay required: " + lderr(cct) << this << " " << __func__ << ": " + << "failed to commit IO to disk, replay required: " << cpp_strerror(r) << dendl; } @@ -1275,7 +1303,8 @@ void Journal::handle_initialized(int r) { r = m_journaler->get_cached_client(Journal::IMAGE_CLIENT_ID, &client); if (r < 0) { - lderr(cct) << "failed to locate master image client" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to locate master image client" << dendl; destroy_journaler(r); return; } @@ -1285,7 +1314,8 @@ void Journal::handle_initialized(int r) { try { ::decode(client_data, bl); } catch (const buffer::error &err) { - lderr(cct) << "failed to decode client meta data: " << err.what() + lderr(cct) << this << " " << __func__ << ": " + << "failed to decode client meta data: " << err.what() << dendl; destroy_journaler(-EINVAL); return; @@ -1294,13 +1324,15 @@ void Journal::handle_initialized(int r) { journal::ImageClientMeta *image_client_meta = boost::get(&client_data.client_meta); if (image_client_meta == nullptr) { - lderr(cct) << "failed to extract client meta data" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to extract client meta data" << dendl; destroy_journaler(-EINVAL); return; } m_tag_class = image_client_meta->tag_class; - ldout(cct, 20) << "client: " << client << ", " + ldout(cct, 20) << this << " " << __func__ << ": " + << "client: " << client << ", " << "image meta: " << *image_client_meta << dendl; C_DecodeTags *tags_ctx = new C_DecodeTags( @@ -1356,8 +1388,8 @@ void Journal::handle_replay_ready() { journal::EventEntry event_entry; int r = m_journal_replay->decode(&it, &event_entry); if (r < 0) { - lderr(cct) << this << " " << __func__ - << ": failed to decode journal event entry" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to decode journal event entry" << dendl; handle_replay_process_safe(replay_entry, r); return; } @@ -1441,7 +1473,8 @@ void Journal::handle_replay_process_safe(ReplayEntry replay_entry, int r) { ldout(cct, 20) << this << " " << __func__ << ": r=" << r << dendl; if (r < 0) { - lderr(cct) << "failed to commit journal event to disk: " << cpp_strerror(r) + lderr(cct) << this << " " << __func__ << ": " + << "failed to commit journal event to disk: " << cpp_strerror(r) << dendl; if (m_state == STATE_REPLAYING) { @@ -1561,7 +1594,8 @@ void Journal::handle_io_event_safe(int r, uint64_t tid) { // journal will be flushed before closing assert(m_state == STATE_READY || m_state == STATE_STOPPING); if (r < 0) { - lderr(cct) << "failed to commit IO event: " << cpp_strerror(r) << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to commit IO event: " << cpp_strerror(r) << dendl; } AioObjectRequests aio_object_requests; @@ -1591,7 +1625,8 @@ void Journal::handle_io_event_safe(int r, uint64_t tid) { } } - ldout(cct, 20) << "completing tid=" << tid << dendl; + ldout(cct, 20) << this << " " << __func__ << ": " + << "completing tid=" << tid << dendl; for (AioObjectRequests::iterator it = aio_object_requests.begin(); it != aio_object_requests.end(); ++it) { if (r < 0) { @@ -1622,7 +1657,8 @@ void Journal::handle_op_event_safe(int r, uint64_t tid, // journal will be flushed before closing assert(m_state == STATE_READY || m_state == STATE_STOPPING); if (r < 0) { - lderr(cct) << "failed to commit op event: " << cpp_strerror(r) << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to commit op event: " << cpp_strerror(r) << dendl; } m_journaler->committed(op_start_future); @@ -1712,7 +1748,8 @@ int Journal::check_resync_requested_internal(bool *do_resync) { cls::journal::Client client; int r = m_journaler->get_cached_client(IMAGE_CLIENT_ID, &client); if (r < 0) { - lderr(cct) << "failed to retrieve client: " << cpp_strerror(r) << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to retrieve client: " << cpp_strerror(r) << dendl; return r; } @@ -1721,14 +1758,16 @@ int Journal::check_resync_requested_internal(bool *do_resync) { try { ::decode(client_data, bl_it); } catch (const buffer::error &err) { - lderr(cct) << "failed to decode client data: " << err << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to decode client data: " << err << dendl; return -EINVAL; } journal::ImageClientMeta *image_client_meta = boost::get(&client_data.client_meta); if (image_client_meta == nullptr) { - lderr(cct) << "failed to access image client meta struct" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to access image client meta struct" << dendl; return -EINVAL; } @@ -1755,7 +1794,8 @@ void Journal::handle_metadata_updated() { bool do_resync = false; int r = check_resync_requested_internal(&do_resync); if (r < 0) { - lderr(cct) << "failed to check if a resync was requested" << dendl; + lderr(cct) << this << " " << __func__ << ": " + << "failed to check if a resync was requested" << dendl; return; } diff --git a/src/librbd/journal/Replay.cc b/src/librbd/journal/Replay.cc index 0228e315a87e..e306b708466f 100644 --- a/src/librbd/journal/Replay.cc +++ b/src/librbd/journal/Replay.cc @@ -15,7 +15,7 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::journal::Replay: " +#define dout_prefix *_dout << "librbd::journal::Replay: " << this << " " namespace librbd { namespace journal { @@ -92,12 +92,12 @@ struct ExecuteOp : public Context { virtual void finish(int r) override { CephContext *cct = image_ctx.cct; if (r < 0) { - lderr(cct) << "ExecuteOp: " << __func__ << ": r=" << r << dendl; + lderr(cct) << ": ExecuteOp::" << __func__ << ": r=" << r << dendl; on_op_complete->complete(r); return; } - ldout(cct, 20) << "ExecuteOp: " << __func__ << dendl; + ldout(cct, 20) << ": ExecuteOp::" << __func__ << dendl; RWLock::RLocker owner_locker(image_ctx.owner_lock); execute(event); } @@ -121,13 +121,13 @@ struct C_RefreshIfRequired : public Context { on_finish = nullptr; if (r < 0) { - lderr(cct) << "C_RefreshIfRequired: " << __func__ << ": r=" << r << dendl; + lderr(cct) << ": C_RefreshIfRequired::" << __func__ << ": r=" << r << dendl; image_ctx.op_work_queue->queue(ctx, r); return; } if (image_ctx.state->is_refresh_required()) { - ldout(cct, 20) << "C_RefreshIfRequired: " << __func__ << ": " + ldout(cct, 20) << ": C_RefreshIfRequired::" << __func__ << ": " << "refresh required" << dendl; image_ctx.state->refresh(ctx); return; @@ -139,6 +139,10 @@ struct C_RefreshIfRequired : public Context { } // anonymous namespace +#undef dout_prefix +#define dout_prefix *_dout << "librbd::journal::Replay: " << this << " " \ + << __func__ + template Replay::Replay(I &image_ctx) : m_image_ctx(image_ctx), m_lock("Replay::m_lock") { @@ -168,8 +172,8 @@ template void Replay::process(const EventEntry &event_entry, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": " - << "on_ready=" << on_ready << ", on_safe=" << on_safe << dendl; + ldout(cct, 20) << ": on_ready=" << on_ready << ", on_safe=" << on_safe + << dendl; on_ready = util::create_async_context_callback(m_image_ctx, on_ready); @@ -181,7 +185,7 @@ void Replay::process(const EventEntry &event_entry, template void Replay::shut_down(bool cancel_ops, Context *on_finish) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << dendl; + ldout(cct, 20) << dendl; AioCompletion *flush_comp = nullptr; on_finish = util::create_async_context_callback( @@ -249,7 +253,7 @@ void Replay::flush(Context *on_finish) { template void Replay::replay_op_ready(uint64_t op_tid, Context *on_resume) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": op_tid=" << op_tid << dendl; + ldout(cct, 20) << ": op_tid=" << op_tid << dendl; Mutex::Locker locker(m_lock); auto op_it = m_op_events.find(op_tid); @@ -289,7 +293,7 @@ template void Replay::handle_event(const journal::AioDiscardEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": AIO discard event" << dendl; + ldout(cct, 20) << ": AIO discard event" << dendl; bool flush_required; AioCompletion *aio_comp = create_aio_modify_completion(on_ready, on_safe, @@ -309,7 +313,7 @@ template void Replay::handle_event(const journal::AioWriteEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": AIO write event" << dendl; + ldout(cct, 20) << ": AIO write event" << dendl; bufferlist data = event.data; bool flush_required; @@ -330,7 +334,7 @@ template void Replay::handle_event(const journal::AioFlushEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": AIO flush event" << dendl; + ldout(cct, 20) << ": AIO flush event" << dendl; AioCompletion *aio_comp; { @@ -346,7 +350,7 @@ template void Replay::handle_event(const journal::OpFinishEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Op finish event: " + ldout(cct, 20) << ": Op finish event: " << "op_tid=" << event.op_tid << dendl; bool op_in_progress; @@ -357,7 +361,7 @@ void Replay::handle_event(const journal::OpFinishEvent &event, Mutex::Locker locker(m_lock); auto op_it = m_op_events.find(event.op_tid); if (op_it == m_op_events.end()) { - ldout(cct, 10) << "unable to locate associated op: assuming previously " + ldout(cct, 10) << ": unable to locate associated op: assuming previously " << "committed." << dendl; on_ready->complete(0); m_image_ctx.op_work_queue->queue(on_safe, 0); @@ -401,7 +405,7 @@ template void Replay::handle_event(const journal::SnapCreateEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Snap create event" << dendl; + ldout(cct, 20) << ": Snap create event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -430,7 +434,7 @@ template void Replay::handle_event(const journal::SnapRemoveEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Snap remove event" << dendl; + ldout(cct, 20) << ": Snap remove event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -454,7 +458,7 @@ template void Replay::handle_event(const journal::SnapRenameEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Snap rename event" << dendl; + ldout(cct, 20) << ": Snap rename event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -478,7 +482,7 @@ template void Replay::handle_event(const journal::SnapProtectEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Snap protect event" << dendl; + ldout(cct, 20) << ": Snap protect event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -502,8 +506,7 @@ template void Replay::handle_event(const journal::SnapUnprotectEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Snap unprotect event" - << dendl; + ldout(cct, 20) << ": Snap unprotect event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -531,8 +534,7 @@ template void Replay::handle_event(const journal::SnapRollbackEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Snap rollback start event" - << dendl; + ldout(cct, 20) << ": Snap rollback start event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -554,7 +556,7 @@ template void Replay::handle_event(const journal::RenameEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Rename event" << dendl; + ldout(cct, 20) << ": Rename event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -578,7 +580,7 @@ template void Replay::handle_event(const journal::ResizeEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Resize start event" << dendl; + ldout(cct, 20) << ": Resize start event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -603,7 +605,7 @@ template void Replay::handle_event(const journal::FlattenEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Flatten start event" << dendl; + ldout(cct, 20) << ": Flatten start event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -627,7 +629,7 @@ template void Replay::handle_event(const journal::DemoteEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Demote event" << dendl; + ldout(cct, 20) << ": Demote event" << dendl; on_ready->complete(0); on_safe->complete(0); } @@ -636,8 +638,7 @@ template void Replay::handle_event(const journal::SnapLimitEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": Snap limit event" - << dendl; + ldout(cct, 20) << ": Snap limit event" << dendl; Mutex::Locker locker(m_lock); OpEvent *op_event; @@ -659,7 +660,7 @@ template void Replay::handle_event(const journal::UnknownEvent &event, Context *on_ready, Context *on_safe) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": unknown event" << dendl; + ldout(cct, 20) << ": unknown event" << dendl; on_ready->complete(0); on_safe->complete(0); } @@ -669,14 +670,14 @@ void Replay::handle_aio_modify_complete(Context *on_ready, Context *on_safe, int r) { Mutex::Locker locker(m_lock); CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": on_ready=" << on_ready << ", " + ldout(cct, 20) << ": on_ready=" << on_ready << ", " << "on_safe=" << on_safe << ", r=" << r << dendl; if (on_ready != nullptr) { on_ready->complete(0); } if (r < 0) { - lderr(cct) << "AIO modify op failed: " << cpp_strerror(r) << dendl; + lderr(cct) << ": AIO modify op failed: " << cpp_strerror(r) << dendl; on_safe->complete(r); return; } @@ -689,10 +690,10 @@ template void Replay::handle_aio_flush_complete(Context *on_flush_safe, Contexts &on_safe_ctxs, int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": " << "r=" << r << dendl; + ldout(cct, 20) << ": r=" << r << dendl; if (r < 0) { - lderr(cct) << "AIO flush failed: " << cpp_strerror(r) << dendl; + lderr(cct) << ": AIO flush failed: " << cpp_strerror(r) << dendl; } Context *on_aio_ready = nullptr; @@ -721,7 +722,7 @@ void Replay::handle_aio_flush_complete(Context *on_flush_safe, } if (on_aio_ready != nullptr) { - ldout(cct, 10) << "resuming paused AIO" << dendl; + ldout(cct, 10) << ": resuming paused AIO" << dendl; on_aio_ready->complete(0); } @@ -729,12 +730,12 @@ void Replay::handle_aio_flush_complete(Context *on_flush_safe, on_safe_ctxs.push_back(on_flush_safe); } for (auto ctx : on_safe_ctxs) { - ldout(cct, 20) << "completing safe context: " << ctx << dendl; + ldout(cct, 20) << ": completing safe context: " << ctx << dendl; ctx->complete(r); } if (on_flush != nullptr) { - ldout(cct, 20) << "completing flush context: " << on_flush << dendl; + ldout(cct, 20) << ": completing flush context: " << on_flush << dendl; on_flush->complete(r); } } @@ -748,7 +749,7 @@ Context *Replay::create_op_context_callback(uint64_t op_tid, assert(m_lock.is_locked()); if (m_op_events.count(op_tid) != 0) { - lderr(cct) << "duplicate op tid detected: " << op_tid << dendl; + lderr(cct) << ": duplicate op tid detected: " << op_tid << dendl; // on_ready is already async but on failure invoke on_safe async // as well @@ -769,7 +770,7 @@ Context *Replay::create_op_context_callback(uint64_t op_tid, template void Replay::handle_op_complete(uint64_t op_tid, int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << this << " " << __func__ << ": op_tid=" << op_tid << ", " + ldout(cct, 20) << ": op_tid=" << op_tid << ", " << "r=" << r << dendl; OpEvent op_event; @@ -851,7 +852,7 @@ AioCompletion *Replay::create_aio_modify_completion(Context *on_ready, *flush_required = (m_aio_modify_unsafe_contexts.size() == IN_FLIGHT_IO_LOW_WATER_MARK); if (*flush_required) { - ldout(cct, 10) << "hit AIO replay low-water mark: scheduling flush" + ldout(cct, 10) << ": hit AIO replay low-water mark: scheduling flush" << dendl; } @@ -861,7 +862,7 @@ AioCompletion *Replay::create_aio_modify_completion(Context *on_ready, // shrink has adjusted clip boundary, etc) -- should have already been // flagged not-ready if (m_in_flight_aio_modify == IN_FLIGHT_IO_HIGH_WATER_MARK) { - ldout(cct, 10) << "hit AIO replay high-water mark: pausing replay" + ldout(cct, 10) << ": hit AIO replay high-water mark: pausing replay" << dendl; assert(m_on_aio_ready == nullptr); std::swap(m_on_aio_ready, on_ready);