From 0bb74024f1c87037323bd18bf81e7e5450794ddb Mon Sep 17 00:00:00 2001 From: runsisi Date: Fri, 5 May 2017 19:01:37 +0800 Subject: [PATCH] librbd: cleanup logging code under librbd/io Signed-off-by: runsisi --- src/librbd/io/AioCompletion.cc | 12 ++--- src/librbd/io/CopyupRequest.cc | 32 +++++-------- src/librbd/io/ImageRequest.cc | 20 ++++---- src/librbd/io/ImageRequestWQ.cc | 41 ++++++++-------- src/librbd/io/ObjectRequest.cc | 85 +++++++++++++++------------------ src/librbd/io/ReadResult.cc | 7 +-- 6 files changed, 92 insertions(+), 105 deletions(-) diff --git a/src/librbd/io/AioCompletion.cc b/src/librbd/io/AioCompletion.cc index 7f83f4deab5a4..cc40e8ffbe1af 100644 --- a/src/librbd/io/AioCompletion.cc +++ b/src/librbd/io/AioCompletion.cc @@ -23,7 +23,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::io::AioCompletion: " +#define dout_prefix *_dout << "librbd::io::AioCompletion: " << this \ + << " " << __func__ << ": " namespace librbd { namespace io { @@ -44,7 +45,7 @@ void AioCompletion::finalize(ssize_t rval) assert(ictx != nullptr); CephContext *cct = ictx->cct; - ldout(cct, 20) << this << " " << __func__ << ": r=" << rval << dendl; + ldout(cct, 20) << "r=" << rval << dendl; if (rval >= 0 && aio_type == AIO_TYPE_READ) { read_result.assemble_result(cct); } @@ -133,8 +134,7 @@ void AioCompletion::fail(int r) assert(ictx != nullptr); CephContext *cct = ictx->cct; - lderr(cct) << this << " " << __func__ << ": " << cpp_strerror(r) - << dendl; + lderr(cct) << cpp_strerror(r) << dendl; assert(pending_count == 0); rval = r; complete(); @@ -146,7 +146,7 @@ void AioCompletion::set_request_count(uint32_t count) { assert(ictx != nullptr); CephContext *cct = ictx->cct; - ldout(cct, 20) << this << " " << __func__ << ": pending=" << count << dendl; + ldout(cct, 20) << "pending=" << count << dendl; assert(pending_count == 0); pending_count = count; lock.Unlock(); @@ -170,7 +170,7 @@ void AioCompletion::complete_request(ssize_t r) assert(pending_count); int count = --pending_count; - ldout(cct, 20) << this << " " << __func__ << ": cb=" << complete_cb << ", " + ldout(cct, 20) << "cb=" << complete_cb << ", " << "pending=" << pending_count << dendl; if (!count && blockers == 0) { finalize(rval); diff --git a/src/librbd/io/CopyupRequest.cc b/src/librbd/io/CopyupRequest.cc index 9ce36388d080a..0f1d34f207574 100644 --- a/src/librbd/io/CopyupRequest.cc +++ b/src/librbd/io/CopyupRequest.cc @@ -23,7 +23,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::io::CopyupRequest: " +#define dout_prefix *_dout << "librbd::io::CopyupRequest: " << this \ + << " " << __func__ << ": " namespace librbd { namespace io { @@ -93,7 +94,7 @@ CopyupRequest::~CopyupRequest() { } void CopyupRequest::append_request(ObjectRequest<> *req) { - ldout(m_ictx->cct, 20) << __func__ << " " << this << ": " << req << dendl; + ldout(m_ictx->cct, 20) << req << dendl; m_pending_requests.push_back(req); } @@ -101,8 +102,7 @@ void CopyupRequest::complete_requests(int r) { while (!m_pending_requests.empty()) { vector *>::iterator it = m_pending_requests.begin(); ObjectRequest<> *req = *it; - ldout(m_ictx->cct, 20) << __func__ << " completing request " << req - << dendl; + ldout(m_ictx->cct, 20) << "completing request " << req << dendl; req->complete(r); m_pending_requests.erase(it); } @@ -117,8 +117,7 @@ bool CopyupRequest::send_copyup() { add_copyup_op = true; } - ldout(m_ictx->cct, 20) << __func__ << " " << this - << ": oid " << m_oid << dendl; + ldout(m_ictx->cct, 20) << "oid " << m_oid << dendl; m_state = STATE_COPYUP; m_ictx->snap_lock.get_read(); @@ -145,8 +144,7 @@ bool CopyupRequest::send_copyup() { // actual modification. m_pending_copyups++; - ldout(m_ictx->cct, 20) << __func__ << " " << this << " copyup with " - << "empty snapshot context" << dendl; + ldout(m_ictx->cct, 20) << "copyup with empty snapshot context" << dendl; librados::AioCompletion *comp = util::create_rados_callback(this); librados::Rados rados(m_ictx->data_ctx); @@ -168,8 +166,7 @@ bool CopyupRequest::send_copyup() { // merge all pending write ops into this single RADOS op for (size_t i=0; i *req = m_pending_requests[i]; - ldout(m_ictx->cct, 20) << __func__ << " add_copyup_ops " << req - << dendl; + ldout(m_ictx->cct, 20) << "add_copyup_ops " << req << dendl; req->add_copyup_ops(&write_op); } assert(write_op.size() != 0); @@ -201,8 +198,7 @@ void CopyupRequest::send() AioCompletion *comp = AioCompletion::create_and_start( this, m_ictx, AIO_TYPE_READ); - ldout(m_ictx->cct, 20) << __func__ << " " << this - << ": completion " << comp + ldout(m_ictx->cct, 20) << "completion " << comp << ", oid " << m_oid << ", extents " << m_image_extents << dendl; @@ -221,8 +217,7 @@ void CopyupRequest::complete(int r) bool CopyupRequest::should_complete(int r) { CephContext *cct = m_ictx->cct; - ldout(cct, 20) << __func__ << " " << this - << ": oid " << m_oid + ldout(cct, 20) << "oid " << m_oid << ", r " << r << dendl; uint64_t pending_copyups; @@ -232,7 +227,7 @@ bool CopyupRequest::should_complete(int r) remove_from_list(); if (r >= 0 || r == -ENOENT) { if (is_copyup_required()) { - ldout(cct, 20) << __func__ << " " << this << " nop, skipping" << dendl; + ldout(cct, 20) << "nop, skipping" << dendl; return true; } @@ -285,7 +280,7 @@ void CopyupRequest::remove_from_list() bool CopyupRequest::send_object_map_head() { CephContext *cct = m_ictx->cct; - ldout(cct, 20) << __func__ << " " << this << dendl; + ldout(cct, 20) << dendl; m_state = STATE_OBJECT_MAP_HEAD; @@ -321,7 +316,7 @@ bool CopyupRequest::send_object_map_head() { } current_state = (*m_ictx->object_map)[m_object_no]; - ldout(cct, 20) << __func__ << " " << req->get_op_type() << " object no " + ldout(cct, 20) << req->get_op_type() << " object no " << m_object_no << " current state " << stringify(static_cast(current_state)) << " new state " << stringify(static_cast(new_state)) @@ -348,8 +343,7 @@ bool CopyupRequest::send_object_map() { return send_copyup(); } else { // update object maps for HEAD and all existing snapshots - ldout(m_ictx->cct, 20) << __func__ << " " << this - << ": oid " << m_oid << dendl; + ldout(m_ictx->cct, 20) << "oid " << m_oid << dendl; m_state = STATE_OBJECT_MAP; RWLock::RLocker owner_locker(m_ictx->owner_lock); diff --git a/src/librbd/io/ImageRequest.cc b/src/librbd/io/ImageRequest.cc index 71ae944240e80..e1a5ae1ca8b70 100644 --- a/src/librbd/io/ImageRequest.cc +++ b/src/librbd/io/ImageRequest.cc @@ -16,7 +16,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::io::ImageRequest: " +#define dout_prefix *_dout << "librbd::io::ImageRequest: " << this \ + << " " << __func__ << ": " namespace librbd { namespace io { @@ -38,8 +39,7 @@ struct C_DiscardJournalCommit : public Context { : image_ctx(_image_ctx), aio_comp(_aio_comp), object_extents(_object_extents) { CephContext *cct = image_ctx.cct; - ldout(cct, 20) << this << " C_DiscardJournalCommit: " - << "delaying cache discard until journal tid " << tid << " " + ldout(cct, 20) << "delaying cache discard until journal tid " << tid << " " << "safe" << dendl; aio_comp->add_request(); @@ -47,7 +47,7 @@ struct C_DiscardJournalCommit : public Context { void finish(int r) override { CephContext *cct = image_ctx.cct; - ldout(cct, 20) << this << " C_DiscardJournalCommit: " + ldout(cct, 20) << "C_DiscardJournalCommit: " << "journal committed: discarding from cache" << dendl; Mutex::Locker cache_locker(image_ctx.cache_lock); @@ -65,8 +65,7 @@ struct C_FlushJournalCommit : public Context { uint64_t tid) : image_ctx(_image_ctx), aio_comp(_aio_comp) { CephContext *cct = image_ctx.cct; - ldout(cct, 20) << this << " C_FlushJournalCommit: " - << "delaying flush until journal tid " << tid << " " + ldout(cct, 20) << "delaying flush until journal tid " << tid << " " << "safe" << dendl; aio_comp->add_request(); @@ -74,8 +73,7 @@ struct C_FlushJournalCommit : public Context { void finish(int r) override { CephContext *cct = image_ctx.cct; - ldout(cct, 20) << this << " C_FlushJournalCommit: journal committed" - << dendl; + ldout(cct, 20) << "C_FlushJournalCommit: journal committed" << dendl; aio_comp->complete_request(r); } }; @@ -273,7 +271,7 @@ void ImageReadRequest::send_request() { // issue the requests for (auto &object_extent : object_extents) { for (auto &extent : object_extent.second) { - ldout(cct, 20) << " oid " << extent.oid << " " << extent.offset << "~" + ldout(cct, 20) << "oid " << extent.oid << " " << extent.offset << "~" << extent.length << " from " << extent.buffer_extents << dendl; @@ -395,7 +393,7 @@ void AbstractImageWriteRequest::send_object_requests( AioCompletion *aio_comp = this->m_aio_comp; for (ObjectExtents::const_iterator p = object_extents.begin(); p != object_extents.end(); ++p) { - ldout(cct, 20) << " oid " << p->oid << " " << p->offset << "~" << p->length + ldout(cct, 20) << "oid " << p->oid << " " << p->offset << "~" << p->length << " from " << p->buffer_extents << dendl; C_AioRequest *req_comp = new C_AioRequest(aio_comp); ObjectRequestHandle *request = create_object_request(*p, snapc, @@ -543,7 +541,7 @@ void ImageDiscardRequest::prune_object_extents(ObjectExtents &object_extents) for (auto p = object_extents.begin(); p != object_extents.end(); ) { if (p->offset + p->length < image_ctx.layout.object_size) { - ldout(cct, 20) << " oid " << p->oid << " " << p->offset << "~" + ldout(cct, 20) << "oid " << p->oid << " " << p->offset << "~" << p->length << " from " << p->buffer_extents << ": skip partial discard" << dendl; p = object_extents.erase(p); diff --git a/src/librbd/io/ImageRequestWQ.cc b/src/librbd/io/ImageRequestWQ.cc index d45a658bca219..d7c9fa3524779 100644 --- a/src/librbd/io/ImageRequestWQ.cc +++ b/src/librbd/io/ImageRequestWQ.cc @@ -14,7 +14,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::io::ImageRequestWQ: " +#define dout_prefix *_dout << "librbd::io::ImageRequestWQ: " << this \ + << " " << __func__ << ": " namespace librbd { namespace io { @@ -28,14 +29,14 @@ ImageRequestWQ::ImageRequestWQ(ImageCtx *image_ctx, const string &name, m_queued_writes(0), m_in_flight_ops(0), m_refresh_in_progress(false), m_shutdown(false), m_on_shutdown(nullptr) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 5) << this << " " << ": ictx=" << image_ctx << dendl; + ldout(cct, 5) << "ictx=" << image_ctx << dendl; tp->add_work_queue(this); } ssize_t ImageRequestWQ::read(uint64_t off, uint64_t len, ReadResult &&read_result, int op_flags) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "read: ictx=" << &m_image_ctx << ", off=" << off << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", off=" << off << ", " << "len = " << len << dendl; C_SaferCond cond; @@ -47,7 +48,7 @@ ssize_t ImageRequestWQ::read(uint64_t off, uint64_t len, ssize_t ImageRequestWQ::write(uint64_t off, uint64_t len, bufferlist &&bl, int op_flags) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "write: ictx=" << &m_image_ctx << ", off=" << off << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", off=" << off << ", " << "len = " << len << dendl; m_image_ctx.snap_lock.get_read(); @@ -71,7 +72,7 @@ ssize_t ImageRequestWQ::write(uint64_t off, uint64_t len, ssize_t ImageRequestWQ::discard(uint64_t off, uint64_t len, bool skip_partial_discard) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "discard: ictx=" << &m_image_ctx << ", off=" << off << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", off=" << off << ", " << "len = " << len << dendl; m_image_ctx.snap_lock.get_read(); @@ -96,7 +97,7 @@ ssize_t ImageRequestWQ::discard(uint64_t off, uint64_t len, bool skip_partial_di ssize_t ImageRequestWQ::writesame(uint64_t off, uint64_t len, bufferlist &&bl, int op_flags) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "writesame ictx=" << &m_image_ctx << ", off=" << off << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", off=" << off << ", " << "len = " << len << ", data_len " << bl.length() << dendl; m_image_ctx.snap_lock.get_read(); @@ -123,7 +124,7 @@ void ImageRequestWQ::aio_read(AioCompletion *c, uint64_t off, uint64_t len, bool native_async) { c->init_time(&m_image_ctx, AIO_TYPE_READ); CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "aio_read: ictx=" << &m_image_ctx << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", " << "completion=" << c << ", off=" << off << ", " << "len=" << len << ", " << "flags=" << op_flags << dendl; @@ -162,7 +163,7 @@ void ImageRequestWQ::aio_write(AioCompletion *c, uint64_t off, uint64_t len, bool native_async) { c->init_time(&m_image_ctx, AIO_TYPE_WRITE); CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "aio_write: ictx=" << &m_image_ctx << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", " << "completion=" << c << ", off=" << off << ", " << "len=" << len << ", flags=" << op_flags << dendl; @@ -191,7 +192,7 @@ void ImageRequestWQ::aio_discard(AioCompletion *c, uint64_t off, bool native_async) { c->init_time(&m_image_ctx, AIO_TYPE_DISCARD); CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "aio_discard: ictx=" << &m_image_ctx << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", " << "completion=" << c << ", off=" << off << ", len=" << len << dendl; @@ -216,7 +217,7 @@ void ImageRequestWQ::aio_discard(AioCompletion *c, uint64_t off, void ImageRequestWQ::aio_flush(AioCompletion *c, bool native_async) { c->init_time(&m_image_ctx, AIO_TYPE_FLUSH); CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "aio_flush: ictx=" << &m_image_ctx << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", " << "completion=" << c << dendl; if (native_async && m_image_ctx.event_socket.is_valid()) { @@ -241,7 +242,7 @@ void ImageRequestWQ::aio_writesame(AioCompletion *c, uint64_t off, uint64_t len, bool native_async) { c->init_time(&m_image_ctx, AIO_TYPE_WRITESAME); CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << "aio_writesame: ictx=" << &m_image_ctx << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", " << "completion=" << c << ", off=" << off << ", " << "len=" << len << ", data_len = " << bl.length() << ", " << "flags=" << op_flags << dendl; @@ -306,8 +307,8 @@ void ImageRequestWQ::block_writes(Context *on_blocked) { { RWLock::WLocker locker(m_lock); ++m_write_blockers; - ldout(cct, 5) << __func__ << ": " << &m_image_ctx << ", " - << "num=" << m_write_blockers << dendl; + ldout(cct, 5) << &m_image_ctx << ", " << "num=" + << m_write_blockers << dendl; if (!m_write_blocker_contexts.empty() || m_in_progress_writes > 0) { m_write_blocker_contexts.push_back(on_blocked); return; @@ -327,8 +328,8 @@ void ImageRequestWQ::unblock_writes() { assert(m_write_blockers > 0); --m_write_blockers; - ldout(cct, 5) << __func__ << ": " << &m_image_ctx << ", " - << "num=" << m_write_blockers << dendl; + ldout(cct, 5) << &m_image_ctx << ", " << "num=" + << m_write_blockers << dendl; if (m_write_blockers == 0) { wake_up = true; } @@ -341,7 +342,7 @@ void ImageRequestWQ::unblock_writes() { void ImageRequestWQ::set_require_lock_on_read() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << __func__ << dendl; + ldout(cct, 20) << dendl; RWLock::WLocker locker(m_lock); m_require_lock_on_read = true; @@ -349,7 +350,7 @@ void ImageRequestWQ::set_require_lock_on_read() { void ImageRequestWQ::clear_require_lock_on_read() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << __func__ << dendl; + ldout(cct, 20) << dendl; { RWLock::WLocker locker(m_lock); @@ -410,7 +411,7 @@ void *ImageRequestWQ::_void_dequeue() { void ImageRequestWQ::process(ImageRequest<> *req) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << __func__ << ": ictx=" << &m_image_ctx << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", " << "req=" << req << dendl; req->send(); @@ -477,7 +478,7 @@ void ImageRequestWQ::finish_in_flight_op() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 5) << __func__ << ": completing shut down" << dendl; + ldout(cct, 5) << "completing shut down" << dendl; assert(on_shutdown != nullptr); m_image_ctx.flush(on_shutdown); @@ -494,7 +495,7 @@ bool ImageRequestWQ::is_lock_required() const { void ImageRequestWQ::queue(ImageRequest<> *req) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 20) << __func__ << ": ictx=" << &m_image_ctx << ", " + ldout(cct, 20) << "ictx=" << &m_image_ctx << ", " << "req=" << req << dendl; assert(m_image_ctx.owner_lock.is_locked()); diff --git a/src/librbd/io/ObjectRequest.cc b/src/librbd/io/ObjectRequest.cc index 2b2b030c052d7..97cd2e4088146 100644 --- a/src/librbd/io/ObjectRequest.cc +++ b/src/librbd/io/ObjectRequest.cc @@ -24,7 +24,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::io::ObjectRequest: " +#define dout_prefix *_dout << "librbd::io::ObjectRequest: " << this \ + << " " << __func__ << ": " namespace librbd { namespace io { @@ -105,7 +106,7 @@ template void ObjectRequest::complete(int r) { if (should_complete(r)) { - ldout(m_ictx->cct, 20) << "complete " << this << dendl; + ldout(m_ictx->cct, 20) << dendl; if (m_hide_enoent && r == -ENOENT) { r = 0; } @@ -124,8 +125,8 @@ bool ObjectRequest::compute_parent_extents() { if (r < 0) { // NOTE: it's possible for a snapshot to be deleted while we are // still reading from it - lderr(m_ictx->cct) << this << " compute_parent_extents: failed to " - << "retrieve parent overlap: " << cpp_strerror(r) + lderr(m_ictx->cct) << "failed to retrieve parent overlap: " + << cpp_strerror(r) << dendl; m_has_parent = false; m_parent_extents.clear(); @@ -135,8 +136,7 @@ bool ObjectRequest::compute_parent_extents() { uint64_t object_overlap = m_ictx->prune_parent_extents( m_parent_extents, parent_overlap); if (object_overlap > 0) { - ldout(m_ictx->cct, 20) << this << " compute_parent_extents: " - << "overlap " << parent_overlap << " " + ldout(m_ictx->cct, 20) << "overlap " << parent_overlap << " " << "extents " << m_parent_extents << dendl; m_has_parent = !m_parent_extents.empty(); return true; @@ -175,7 +175,7 @@ void ObjectReadRequest::guard_read() RWLock::RLocker parent_locker(image_ctx->parent_lock); if (this->has_parent()) { - ldout(image_ctx->cct, 20) << __func__ << " guarding read" << dendl; + ldout(image_ctx->cct, 20) << "guarding read" << dendl; m_state = LIBRBD_AIO_READ_GUARD; } } @@ -184,8 +184,7 @@ template bool ObjectReadRequest::should_complete(int r) { ImageCtx *image_ctx = this->m_ictx; - ldout(image_ctx->cct, 20) << "should_complete " << this << " " - << this->m_oid << " " + ldout(image_ctx->cct, 20) << this->m_oid << " " << this->m_object_off << "~" << this->m_object_len << " r = " << r << dendl; @@ -193,8 +192,7 @@ bool ObjectReadRequest::should_complete(int r) switch (m_state) { case LIBRBD_AIO_READ_GUARD: - ldout(image_ctx->cct, 20) << "should_complete " << this - << " READ_CHECK_GUARD" << dendl; + ldout(image_ctx->cct, 20) << "READ_CHECK_GUARD" << dendl; // This is the step to read from parent if (!m_tried_parent && r == -ENOENT) { @@ -235,8 +233,7 @@ bool ObjectReadRequest::should_complete(int r) } break; case LIBRBD_AIO_READ_COPYUP: - ldout(image_ctx->cct, 20) << "should_complete " << this << " READ_COPYUP" - << dendl; + ldout(image_ctx->cct, 20) << "READ_COPYUP" << dendl; // This is the extra step for copy-on-read: kick off an asynchronous copyup. // It is different from copy-on-write as asynchronous copyup will finish // by itself so state won't go back to LIBRBD_AIO_READ_GUARD. @@ -250,8 +247,7 @@ bool ObjectReadRequest::should_complete(int r) } break; case LIBRBD_AIO_READ_FLAT: - ldout(image_ctx->cct, 20) << "should_complete " << this << " READ_FLAT" - << dendl; + ldout(image_ctx->cct, 20) << "READ_FLAT" << dendl; // The read content should be deposit in m_read_data break; default: @@ -265,8 +261,8 @@ bool ObjectReadRequest::should_complete(int r) template void ObjectReadRequest::send() { ImageCtx *image_ctx = this->m_ictx; - ldout(image_ctx->cct, 20) << "send " << this << " " << this->m_oid << " " - << this->m_object_off << "~" << this->m_object_len + ldout(image_ctx->cct, 20) << this->m_oid << " " << this->m_object_off + << "~" << this->m_object_len << dendl; { @@ -304,6 +300,9 @@ template void ObjectReadRequest::send_copyup() { ImageCtx *image_ctx = this->m_ictx; + ldout(image_ctx->cct, 20) << this->m_oid << " " << this->m_object_off + << "~" << this->m_object_len << dendl; + { RWLock::RLocker snap_locker(image_ctx->snap_lock); RWLock::RLocker parent_locker(image_ctx->parent_lock); @@ -336,10 +335,8 @@ void ObjectReadRequest::read_from_parent(Extents&& parent_extents) AioCompletion *parent_completion = AioCompletion::create_and_start< ObjectRequest >(this, image_ctx, AIO_TYPE_READ); - ldout(image_ctx->cct, 20) << "read_from_parent this = " << this - << " parent completion " << parent_completion - << " extents " << parent_extents - << dendl; + ldout(image_ctx->cct, 20) << "parent completion " << parent_completion + << " extents " << parent_extents << dendl; ImageRequest<>::aio_read(image_ctx->parent, parent_completion, std::move(parent_extents), ReadResult{&m_read_data}, 0); @@ -367,15 +364,15 @@ void AbstractObjectWriteRequest::guard_write() if (has_parent()) { m_state = LIBRBD_AIO_WRITE_GUARD; m_write.assert_exists(); - ldout(m_ictx->cct, 20) << __func__ << " guarding write" << dendl; + ldout(m_ictx->cct, 20) << "guarding write" << dendl; } } bool AbstractObjectWriteRequest::should_complete(int r) { - ldout(m_ictx->cct, 20) << get_op_type() << " " << this << " " << m_oid - << " " << m_object_off << "~" << m_object_len - << " should_complete: r = " << r << dendl; + ldout(m_ictx->cct, 20) << get_op_type() << m_oid << " " + << m_object_off << "~" << m_object_len + << " r = " << r << dendl; bool finished = true; switch (m_state) { @@ -443,9 +440,8 @@ bool AbstractObjectWriteRequest::should_complete(int r) } void AbstractObjectWriteRequest::send() { - ldout(m_ictx->cct, 20) << "send " << get_op_type() << " " << this <<" " - << m_oid << " " << m_object_off << "~" - << m_object_len << dendl; + ldout(m_ictx->cct, 20) << get_op_type() << " " << m_oid << " " + << m_object_off << "~" << m_object_len << dendl; { RWLock::RLocker snap_lock(m_ictx->snap_lock); if (m_ictx->object_map == nullptr) { @@ -461,7 +457,7 @@ void AbstractObjectWriteRequest::send() { } void AbstractObjectWriteRequest::send_pre_object_map_update() { - ldout(m_ictx->cct, 20) << __func__ << dendl; + ldout(m_ictx->cct, 20) << dendl; { RWLock::RLocker snap_lock(m_ictx->snap_lock); @@ -469,9 +465,8 @@ void AbstractObjectWriteRequest::send_pre_object_map_update() { uint8_t new_state; pre_object_map_update(&new_state); RWLock::WLocker object_map_locker(m_ictx->object_map_lock); - ldout(m_ictx->cct, 20) << __func__ << this << " " << m_oid << " " - << m_object_off << "~" << m_object_len - << dendl; + ldout(m_ictx->cct, 20) << m_oid << " " << m_object_off + << "~" << m_object_len << dendl; m_state = LIBRBD_AIO_WRITE_PRE; if (m_ictx->object_map->aio_update( @@ -485,6 +480,8 @@ void AbstractObjectWriteRequest::send_pre_object_map_update() { } bool AbstractObjectWriteRequest::send_post_object_map_update() { + ldout(m_ictx->cct, 20) << dendl; + RWLock::RLocker snap_locker(m_ictx->snap_lock); if (m_ictx->object_map == nullptr || !post_object_map_update()) { return true; @@ -494,8 +491,8 @@ bool AbstractObjectWriteRequest::send_post_object_map_update() { assert(m_ictx->exclusive_lock->is_lock_owner()); RWLock::WLocker object_map_locker(m_ictx->object_map_lock); - ldout(m_ictx->cct, 20) << __func__ << this << " " << m_oid << " " - << m_object_off << "~" << m_object_len << dendl; + ldout(m_ictx->cct, 20) << m_oid << " " << m_object_off + << "~" << m_object_len << dendl; m_state = LIBRBD_AIO_WRITE_POST; if (m_ictx->object_map->aio_update( @@ -507,8 +504,7 @@ bool AbstractObjectWriteRequest::send_post_object_map_update() { } void AbstractObjectWriteRequest::send_write() { - ldout(m_ictx->cct, 20) << "send_write " << this << " " << m_oid << " " - << m_object_off << "~" << m_object_len + ldout(m_ictx->cct, 20) << m_oid << " " << m_object_off << "~" << m_object_len << " object exist " << m_object_exist << dendl; if (!m_object_exist && has_parent()) { @@ -521,8 +517,8 @@ void AbstractObjectWriteRequest::send_write() { void AbstractObjectWriteRequest::send_copyup() { - ldout(m_ictx->cct, 20) << "send_copyup " << this << " " << m_oid << " " - << m_object_off << "~" << m_object_len << dendl; + ldout(m_ictx->cct, 20) << m_oid << " " << m_object_off + << "~" << m_object_len << dendl; m_state = LIBRBD_AIO_WRITE_COPYUP; m_ictx->copyup_list_lock.Lock(); @@ -598,8 +594,7 @@ void ObjectWriteRequest::add_write_ops(librados::ObjectWriteOperation *wr) { void ObjectWriteRequest::send_write() { bool write_full = (m_object_off == 0 && m_object_len == m_ictx->get_object_size()); - ldout(m_ictx->cct, 20) << "send_write " << this << " " << m_oid << " " - << m_object_off << "~" << m_object_len + ldout(m_ictx->cct, 20) << m_oid << " " << m_object_off << "~" << m_object_len << " object exist " << m_object_exist << " write_full " << write_full << dendl; if (write_full && !has_parent()) { @@ -617,14 +612,13 @@ void ObjectRemoveRequest::guard_write() { } } void ObjectRemoveRequest::send_write() { - ldout(m_ictx->cct, 20) << "send_write " << this << " " << m_oid << " " - << m_object_off << "~" << m_object_len << dendl; + ldout(m_ictx->cct, 20) << m_oid << " " << m_object_off + << "~" << m_object_len << dendl; send_pre_object_map_update(); } void ObjectTruncateRequest::send_write() { - ldout(m_ictx->cct, 20) << "send_write " << this << " " << m_oid - << " truncate " << m_object_off << dendl; + ldout(m_ictx->cct, 20) << m_oid << " truncate " << m_object_off << dendl; if (!m_object_exist && ! has_parent()) { m_state = LIBRBD_AIO_WRITE_FLAT; Context *ctx = util::create_context_callback(this); @@ -647,8 +641,7 @@ void ObjectWriteSameRequest::add_write_ops(librados::ObjectWriteOperation *wr) { void ObjectWriteSameRequest::send_write() { bool write_full = (m_object_off == 0 && m_object_len == m_ictx->get_object_size()); - ldout(m_ictx->cct, 20) << "send_write " << this << " " << m_oid << " " - << m_object_off << "~" << m_object_len + ldout(m_ictx->cct, 20) << m_oid << " " << m_object_off << "~" << m_object_len << " write_full " << write_full << dendl; if (write_full && !has_parent()) { m_guard = false; diff --git a/src/librbd/io/ReadResult.cc b/src/librbd/io/ReadResult.cc index 433dac73ca84a..1b8cdb0e6acf2 100644 --- a/src/librbd/io/ReadResult.cc +++ b/src/librbd/io/ReadResult.cc @@ -10,7 +10,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::io::ReadResult: " +#define dout_prefix *_dout << "librbd::io::ReadResult: " << this \ + << " " << __func__ << ": " namespace librbd { namespace io { @@ -89,7 +90,7 @@ void ReadResult::C_ReadRequest::finish(int r) { void ReadResult::C_ImageReadRequest::finish(int r) { CephContext *cct = aio_completion->ictx->cct; - ldout(cct, 10) << "C_ImageReadRequest::finish() " << this << ": r=" << r + ldout(cct, 10) << "C_ImageReadRequest: r=" << r << dendl; if (r >= 0) { size_t length = 0; @@ -114,7 +115,7 @@ void ReadResult::C_SparseReadRequestBase::finish(ExtentMap &extent_map, bufferlist &bl, int r) { aio_completion->lock.Lock(); CephContext *cct = aio_completion->ictx->cct; - ldout(cct, 10) << "C_SparseReadRequest::finish() " << this << " r = " << r + ldout(cct, 10) << "C_SparseReadRequestBase: r = " << r << dendl; if (r >= 0 || r == -ENOENT) { // this was a sparse_read operation -- 2.39.5