From: Ali Maredia Date: Wed, 10 Oct 2018 15:14:40 +0000 (-0400) Subject: rgw: refactor logging in gc and lc X-Git-Tag: v14.1.0~972^2 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=bbe489dec4e02a4295da6718ed4063766f6f2a78;p=ceph.git rgw: refactor logging in gc and lc RGWGC and RGWLC are now DoutPrefixProviders Signed-off-by: Ali Maredia --- diff --git a/src/rgw/rgw_gc.cc b/src/rgw/rgw_gc.cc index 9c770ea621be..c6519da74cef 100644 --- a/src/rgw/rgw_gc.cc +++ b/src/rgw/rgw_gc.cc @@ -128,6 +128,7 @@ int RGWGC::list(int *index, string& marker, uint32_t max, bool expired_only, std } class RGWGCIOManager { + const DoutPrefixProvider* dpp; CephContext *cct; RGWGC *gc; @@ -150,7 +151,8 @@ class RGWGCIOManager { size_t max_aio{MAX_AIO_DEFAULT}; public: - RGWGCIOManager(CephContext *_cct, RGWGC *_gc) : cct(_cct), + RGWGCIOManager(const DoutPrefixProvider* _dpp, CephContext *_cct, RGWGC *_gc) : dpp(_dpp), + cct(_cct), gc(_gc), remove_tags(cct->_conf->rgw_gc_max_objs) { max_aio = cct->_conf->rgw_gc_max_concurrent_io; @@ -194,13 +196,13 @@ public: if (io.type == IO::IndexIO) { if (ret < 0) { - ldout(cct, 0) << "WARNING: gc cleanup of tags on gc shard index=" << io.index << " returned error, ret=" << ret << dendl; + ldpp_dout(dpp, 0) << "WARNING: gc cleanup of tags on gc shard index=" << io.index << " returned error, ret=" << ret << dendl; } goto done; } if (ret < 0) { - ldout(cct, 0) << "WARNING: could not remove oid=" << io.oid << ", ret=" << ret << dendl; + ldpp_dout(dpp, 0) << "WARNING: could not remove oid=" << io.oid << ", ret=" << ret << dendl; goto done; } @@ -239,7 +241,7 @@ done: /* we already cleared list of tags, this prevents us from ballooning in case of * a persistent problem */ - ldout(cct, 0) << "WARNING: failed to remove tags on gc shard index=" << index << " ret=" << ret << dendl; + ldpp_dout(dpp, 0) << "WARNING: failed to remove tags on gc shard index=" << index << " ret=" << ret << dendl; return; } ios.push_back(index_io); @@ -273,7 +275,7 @@ int RGWGC::process(int index, int max_secs, bool expired_only, int ret = l.lock_exclusive(&store->gc_pool_ctx, obj_names[index]); if (ret == -EBUSY) { /* already locked by another gc processor */ - dout(10) << "RGWGC::process() failed to acquire lock on " << obj_names[index] << dendl; + ldpp_dout(this, 10) << "RGWGC::process() failed to acquire lock on " << obj_names[index] << dendl; return 0; } if (ret < 0) @@ -313,7 +315,7 @@ int RGWGC::process(int index, int max_secs, bool expired_only, ctx = new IoCtx; ret = rgw_init_ioctx(store->get_rados_handle(), obj.pool, *ctx); if (ret < 0) { - dout(0) << "ERROR: failed to create ioctx pool=" << obj.pool << dendl; + ldpp_dout(this, 0) << "ERROR: failed to create ioctx pool=" << obj.pool << dendl; continue; } last_pool = obj.pool; @@ -323,13 +325,13 @@ int RGWGC::process(int index, int max_secs, bool expired_only, const string& oid = obj.key.name; /* just stored raw oid there */ - dout(5) << "gc::process: removing " << obj.pool << ":" << obj.key.name << dendl; + ldpp_dout(this, 5) << "gc::process: removing " << obj.pool << ":" << obj.key.name << dendl; ObjectWriteOperation op; cls_refcount_put(op, info.tag, true); ret = io_manager.schedule_io(ctx, oid, &op, index, info.tag); if (ret < 0) { - ldout(store->ctx(), 0) << "WARNING: failed to schedule deletion for oid=" << oid << dendl; + ldpp_dout(this, 0) << "WARNING: failed to schedule deletion for oid=" << oid << dendl; } if (going_down()) // leave early, even if tag isn't removed, it's ok @@ -353,7 +355,7 @@ int RGWGC::process(bool expired_only) const int start = ceph::util::generate_random_number(0, max_objs - 1); - RGWGCIOManager io_manager(store->ctx(), this); + RGWGCIOManager io_manager(this, store->ctx(), this); for (int i = 0; i < max_objs; i++) { int index = (i + start) % max_objs; @@ -375,7 +377,7 @@ bool RGWGC::going_down() void RGWGC::start_processor() { - worker = new GCWorker(cct, this); + worker = new GCWorker(this, cct, this); worker->create("rgw_gc"); } @@ -390,15 +392,25 @@ void RGWGC::stop_processor() worker = NULL; } +unsigned RGWGC::get_subsys() const +{ + return dout_subsys; +} + +std::ostream& RGWGC::gen_prefix(std::ostream& out) const +{ + return out << "garbage collection: "; +} + void *RGWGC::GCWorker::entry() { do { utime_t start = ceph_clock_now(); - dout(2) << "garbage collection: start" << dendl; + ldpp_dout(dpp, 2) << "garbage collection: start" << dendl; int r = gc->process(true); if (r < 0) { - dout(0) << "ERROR: garbage collection process() returned error r=" << r << dendl; + ldpp_dout(dpp, 0) << "ERROR: garbage collection process() returned error r=" << r << dendl; } - dout(2) << "garbage collection: stop" << dendl; + ldpp_dout(dpp, 2) << "garbage collection: stop" << dendl; if (gc->going_down()) break; diff --git a/src/rgw/rgw_gc.h b/src/rgw/rgw_gc.h index e9390e8db6c6..f8f24e97e5d3 100644 --- a/src/rgw/rgw_gc.h +++ b/src/rgw/rgw_gc.h @@ -18,7 +18,7 @@ class RGWGCIOManager; -class RGWGC { +class RGWGC : public DoutPrefixProvider { CephContext *cct; RGWRados *store; int max_objs; @@ -28,13 +28,14 @@ class RGWGC { int tag_index(const string& tag); class GCWorker : public Thread { + const DoutPrefixProvider *dpp; CephContext *cct; RGWGC *gc; Mutex lock; Cond cond; public: - GCWorker(CephContext *_cct, RGWGC *_gc) : cct(_cct), gc(_gc), lock("GCWorker") {} + GCWorker(const DoutPrefixProvider *_dpp, CephContext *_cct, RGWGC *_gc) : dpp(_dpp), cct(_cct), gc(_gc), lock("GCWorker") {} void *entry() override; void stop(); }; @@ -64,6 +65,12 @@ public: bool going_down(); void start_processor(); void stop_processor(); + + CephContext *get_cct() const override { return store->ctx(); } + unsigned get_subsys() const; + + std::ostream& gen_prefix(std::ostream& out) const; + }; diff --git a/src/rgw/rgw_lc.cc b/src/rgw/rgw_lc.cc index e44cc76de334..d32fc9add8bd 100644 --- a/src/rgw/rgw_lc.cc +++ b/src/rgw/rgw_lc.cc @@ -148,12 +148,12 @@ void *RGWLC::LCWorker::entry() { do { utime_t start = ceph_clock_now(); if (should_work(start)) { - ldout(cct, 2) << "life cycle: start" << dendl; + ldpp_dout(dpp, 2) << "life cycle: start" << dendl; int r = lc->process(); if (r < 0) { - ldout(cct, 0) << "ERROR: do life cycle process() returned error r=" << r << dendl; + ldpp_dout(dpp, 0) << "ERROR: do life cycle process() returned error r=" << r << dendl; } - ldout(cct, 2) << "life cycle: stop" << dendl; + ldpp_dout(dpp, 2) << "life cycle: stop" << dendl; } if (lc->going_down()) break; @@ -163,7 +163,7 @@ void *RGWLC::LCWorker::entry() { utime_t next; next.set_from_double(end + secs); - ldout(cct, 5) << "schedule life cycle next start time: " << rgw_to_asctime(next) << dendl; + ldpp_dout(dpp, 5) << "schedule life cycle next start time: " << rgw_to_asctime(next) << dendl; lock.Lock(); cond.WaitInterval(lock, utime_t(secs, 0)); @@ -240,7 +240,7 @@ int RGWLC::bucket_lc_prepare(int index) pair entry(iter->first, lc_uninitial); ret = cls_rgw_lc_set_entry(store->lc_pool_ctx, obj_names[index], entry); if (ret < 0) { - ldout(cct, 0) << "RGWLC::bucket_lc_prepare() failed to set entry on " + ldpp_dout(this, 0) << "RGWLC::bucket_lc_prepare() failed to set entry on " << obj_names[index] << dendl; return ret; } @@ -324,7 +324,7 @@ int RGWLC::handle_multipart_expiration(RGWRados::Bucket *target, const maplist_objects():" <list_objects():" <key << dendl; + ldpp_dout(this, 0) << "ERROR: abort_multipart_upload failed, ret=" << ret << ", meta:" << obj_iter->key << dendl; } else if (ret == -ERR_NO_SUCH_UPLOAD) { - ldout(cct, 5) << "ERROR: abort_multipart_upload failed, ret=" << ret << ", meta:" << obj_iter->key << dendl; + ldpp_dout(this, 5) << "ERROR: abort_multipart_upload failed, ret=" << ret << ", meta:" << obj_iter->key << dendl; } if (going_down()) return 0; @@ -377,13 +377,13 @@ int RGWLC::bucket_lc_process(string& shard_id) string bucket_id = result[2]; int ret = store->get_bucket_info(obj_ctx, bucket_tenant, bucket_name, bucket_info, NULL, &bucket_attrs); if (ret < 0) { - ldout(cct, 0) << "LC:get_bucket_info for " << bucket_name << " failed" << dendl; + ldpp_dout(this, 0) << "LC:get_bucket_info for " << bucket_name << " failed" << dendl; return ret; } ret = bucket_info.bucket.bucket_id.compare(bucket_id) ; if (ret != 0) { - ldout(cct, 0) << "LC:old bucket id found. " << bucket_name << " should be deleted" << dendl; + ldpp_dout(this, 0) << "LC:old bucket id found. " << bucket_name << " should be deleted" << dendl; return -ENOENT; } @@ -398,7 +398,7 @@ int RGWLC::bucket_lc_process(string& shard_id) try { config.decode(iter); } catch (const buffer::error& e) { - ldout(cct, 0) << __func__ << "() decode life cycle config failed" << dendl; + ldpp_dout(this, 0) << __func__ << "() decode life cycle config failed" << dendl; return -1; } @@ -427,7 +427,7 @@ int RGWLC::bucket_lc_process(string& shard_id) if (ret < 0) { if (ret == (-ENOENT)) return 0; - ldout(cct, 0) << "ERROR: store->list_objects():" <list_objects():" <second.obj_tags->get_tags().begin(), prefix_iter->second.obj_tags->get_tags().end())){ - ldout(cct, 20) << __func__ << "() skipping obj " << key << " as tags do not match" << dendl; + ldpp_dout(this, 20) << __func__ << "() skipping obj " << key << " as tags do not match" << dendl; continue; } } @@ -479,14 +479,14 @@ int RGWLC::bucket_lc_process(string& shard_id) } if (state->mtime != obj_iter->meta.mtime) { //Check mtime again to avoid delete a recently update object as much as possible - ldout(cct, 20) << __func__ << "() skipping removal: state->mtime " << state->mtime << " obj->mtime " << obj_iter->meta.mtime << dendl; + ldpp_dout(this, 20) << __func__ << "() skipping removal: state->mtime " << state->mtime << " obj->mtime " << obj_iter->meta.mtime << dendl; continue; } ret = remove_expired_obj(bucket_info, obj_iter->key, obj_iter->meta.owner, obj_iter->meta.owner_display_name, true); if (ret < 0) { - ldout(cct, 0) << "ERROR: remove_expired_obj " << dendl; + ldpp_dout(this, 0) << "ERROR: remove_expired_obj " << dendl; } else { - ldout(cct, 2) << "DELETED:" << bucket_name << ":" << key << dendl; + ldpp_dout(this, 2) << "DELETED:" << bucket_name << ":" << key << dendl; } if (going_down()) @@ -524,7 +524,7 @@ int RGWLC::bucket_lc_process(string& shard_id) if (ret < 0) { if (ret == (-ENOENT)) return 0; - ldout(cct, 0) << "ERROR: store->list_objects():" <list_objects():" <key, obj_iter->meta.owner, obj_iter->meta.owner_display_name, remove_indeed); if (ret < 0) { - ldout(cct, 0) << "ERROR: remove_expired_obj " << dendl; + ldpp_dout(this, 0) << "ERROR: remove_expired_obj " << dendl; } else { - ldout(cct, 2) << "DELETED:" << bucket_name << ":" << obj_iter->key << dendl; + ldpp_dout(this, 2) << "DELETED:" << bucket_name << ":" << obj_iter->key << dendl; } if (going_down()) @@ -619,18 +619,18 @@ int RGWLC::bucket_lc_post(int index, int max_lock_sec, pair& entry do { int ret = l.lock_exclusive(&store->lc_pool_ctx, obj_names[index]); if (ret == -EBUSY) { /* already locked by another lc processor */ - ldout(cct, 0) << "RGWLC::bucket_lc_post() failed to acquire lock on " + ldpp_dout(this, 0) << "RGWLC::bucket_lc_post() failed to acquire lock on " << obj_names[index] << ", sleep 5, try again" << dendl; sleep(5); continue; } if (ret < 0) return 0; - ldout(cct, 20) << "RGWLC::bucket_lc_post() lock " << obj_names[index] << dendl; + ldpp_dout(this, 20) << "RGWLC::bucket_lc_post() lock " << obj_names[index] << dendl; if (result == -ENOENT) { ret = cls_rgw_lc_rm_entry(store->lc_pool_ctx, obj_names[index], entry); if (ret < 0) { - ldout(cct, 0) << "RGWLC::bucket_lc_post() failed to remove entry " + ldpp_dout(this, 0) << "RGWLC::bucket_lc_post() failed to remove entry " << obj_names[index] << dendl; } goto clean; @@ -642,12 +642,12 @@ int RGWLC::bucket_lc_post(int index, int max_lock_sec, pair& entry ret = cls_rgw_lc_set_entry(store->lc_pool_ctx, obj_names[index], entry); if (ret < 0) { - ldout(cct, 0) << "RGWLC::process() failed to set entry on " + ldpp_dout(this, 0) << "RGWLC::process() failed to set entry on " << obj_names[index] << dendl; } clean: l.unlock(&store->lc_pool_ctx, obj_names[index]); - ldout(cct, 20) << "RGWLC::bucket_lc_post() unlock " << obj_names[index] << dendl; + ldpp_dout(this, 20) << "RGWLC::bucket_lc_post() unlock " << obj_names[index] << dendl; return 0; } while (true); } @@ -661,7 +661,7 @@ int RGWLC::list_lc_progress(const string& marker, uint32_t max_entries, maplc_pool_ctx, obj_names[index], marker, max_entries, entries); if (ret < 0) { if (ret == -ENOENT) { - ldout(cct, 10) << __func__ << "() ignoring unfound lc object=" + ldpp_dout(this, 10) << __func__ << "() ignoring unfound lc object=" << obj_names[index] << dendl; continue; } else { @@ -706,7 +706,7 @@ int RGWLC::process(int index, int max_lock_secs) int ret = l.lock_exclusive(&store->lc_pool_ctx, obj_names[index]); if (ret == -EBUSY) { /* already locked by another lc processor */ - ldout(cct, 0) << "RGWLC::process() failed to acquire lock on " + ldpp_dout(this, 0) << "RGWLC::process() failed to acquire lock on " << obj_names[index] << ", sleep 5, try again" << dendl; sleep(5); continue; @@ -717,7 +717,7 @@ int RGWLC::process(int index, int max_lock_secs) cls_rgw_lc_obj_head head; ret = cls_rgw_lc_get_head(store->lc_pool_ctx, obj_names[index], head); if (ret < 0) { - ldout(cct, 0) << "RGWLC::process() failed to get obj head " + ldpp_dout(this, 0) << "RGWLC::process() failed to get obj head " << obj_names[index] << ", ret=" << ret << dendl; goto exit; } @@ -727,7 +727,7 @@ int RGWLC::process(int index, int max_lock_secs) head.marker.clear(); ret = bucket_lc_prepare(index); if (ret < 0) { - ldout(cct, 0) << "RGWLC::process() failed to update lc object " + ldpp_dout(this, 0) << "RGWLC::process() failed to update lc object " << obj_names[index] << ", ret=" << ret << dendl; goto exit; } @@ -735,7 +735,7 @@ int RGWLC::process(int index, int max_lock_secs) ret = cls_rgw_lc_get_next_entry(store->lc_pool_ctx, obj_names[index], head.marker, entry); if (ret < 0) { - ldout(cct, 0) << "RGWLC::process() failed to get obj entry " + ldpp_dout(this, 0) << "RGWLC::process() failed to get obj entry " << obj_names[index] << dendl; goto exit; } @@ -746,7 +746,7 @@ int RGWLC::process(int index, int max_lock_secs) entry.second = lc_processing; ret = cls_rgw_lc_set_entry(store->lc_pool_ctx, obj_names[index], entry); if (ret < 0) { - ldout(cct, 0) << "RGWLC::process() failed to set obj entry " << obj_names[index] + ldpp_dout(this, 0) << "RGWLC::process() failed to set obj entry " << obj_names[index] << " (" << entry.first << "," << entry.second << ")" << dendl; goto exit; } @@ -754,7 +754,7 @@ int RGWLC::process(int index, int max_lock_secs) head.marker = entry.first; ret = cls_rgw_lc_put_head(store->lc_pool_ctx, obj_names[index], head); if (ret < 0) { - ldout(cct, 0) << "RGWLC::process() failed to put head " << obj_names[index] << dendl; + ldpp_dout(this, 0) << "RGWLC::process() failed to put head " << obj_names[index] << dendl; goto exit; } l.unlock(&store->lc_pool_ctx, obj_names[index]); @@ -769,7 +769,7 @@ exit: void RGWLC::start_processor() { - worker = new LCWorker(cct, this); + worker = new LCWorker(this, cct, this); worker->create("lifecycle_thr"); } @@ -784,6 +784,17 @@ void RGWLC::stop_processor() worker = NULL; } + +unsigned RGWLC::get_subsys() const +{ + return dout_subsys; +} + +std::ostream& RGWLC::gen_prefix(std::ostream& out) const +{ + return out << "lifecycle: "; +} + void RGWLC::LCWorker::stop() { Mutex::Locker l(lock); diff --git a/src/rgw/rgw_lc.h b/src/rgw/rgw_lc.h index a26862ac9e17..21a00e5b7f69 100644 --- a/src/rgw/rgw_lc.h +++ b/src/rgw/rgw_lc.h @@ -336,7 +336,7 @@ public: }; WRITE_CLASS_ENCODER(RGWLifecycleConfiguration) -class RGWLC { +class RGWLC : public DoutPrefixProvider { CephContext *cct; RGWRados *store; int max_objs{0}; @@ -345,13 +345,14 @@ class RGWLC { string cookie; class LCWorker : public Thread { + const DoutPrefixProvider *dpp; CephContext *cct; RGWLC *lc; Mutex lock; Cond cond; public: - LCWorker(CephContext *_cct, RGWLC *_lc) : cct(_cct), lc(_lc), lock("LCWorker") {} + LCWorker(const DoutPrefixProvider* _dpp, CephContext *_cct, RGWLC *_lc) : dpp(_dpp), cct(_cct), lc(_lc), lock("LCWorker") {} void *entry() override; void stop(); bool should_work(utime_t& now); @@ -380,6 +381,10 @@ class RGWLC { void start_processor(); void stop_processor(); + CephContext *get_cct() const override { return store->ctx(); } + unsigned get_subsys() const; + std::ostream& gen_prefix(std::ostream& out) const; + private: int remove_expired_obj(RGWBucketInfo& bucket_info, rgw_obj_key obj_key, const string& owner, const string& owner_display_name, bool remove_indeed = true); bool obj_has_expired(ceph::real_time mtime, int days);