From e001c2007b94deb7f2ee933841f4ac6f48e4b092 Mon Sep 17 00:00:00 2001 From: Oguzhan Ozmen Date: Tue, 23 Jan 2024 10:25:44 -0500 Subject: [PATCH] rgw/lc: decorating log events with more details * some minor typos in the log event strings * correcting the names of the owning functions in some of the log events * adding worker index to the events in LCWorker::entry() * adding worker index to the cycle-finished events * adding bucket name to the interval budget expired events * adding bucket name to the events found in RGWLC::bucket_lc_process() * adding event to capture the end and the return code for the call to bucket_lc_process() Signed-off-by: Oguzhan Ozmen (cherry picked from commit 9d6b463a6442ed5ea3ada5f0926214173f4b7576) --- src/rgw/rgw_lc.cc | 55 ++++++++++++++++++++++++++--------------------- 1 file changed, 30 insertions(+), 25 deletions(-) diff --git a/src/rgw/rgw_lc.cc b/src/rgw/rgw_lc.cc index f98131a59e6..560c1e6c7b5 100644 --- a/src/rgw/rgw_lc.cc +++ b/src/rgw/rgw_lc.cc @@ -220,13 +220,13 @@ void *RGWLC::LCWorker::entry() { std::unique_ptr all_buckets; // empty restriction utime_t start = ceph_clock_now(); if (should_work(start)) { - ldpp_dout(dpp, 2) << "life cycle: start" << dendl; + ldpp_dout(dpp, 2) << "life cycle: start worker=" << ix << dendl; int r = lc->process(this, all_buckets, false /* once */); if (r < 0) { ldpp_dout(dpp, 0) << "ERROR: do life cycle process() returned error r=" - << r << dendl; + << r << " worker=" << ix << dendl; } - ldpp_dout(dpp, 2) << "life cycle: stop" << dendl; + ldpp_dout(dpp, 2) << "life cycle: stop worker=" << ix << dendl; cloud_targets.clear(); // clear cloud targets } if (lc->going_down()) @@ -237,8 +237,8 @@ void *RGWLC::LCWorker::entry() { utime_t next; next.set_from_double(end + secs); - ldpp_dout(dpp, 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) << " worker=" << ix << dendl; std::unique_lock l{lock}; cond.wait_for(l, std::chrono::seconds(secs)); @@ -925,8 +925,8 @@ int RGWLC::handle_multipart_expiration(rgw::sal::Bucket* target, ++prefix_iter) { if (worker_should_stop(stop_at, once)) { - ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker " - << worker->ix + ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker=" + << worker->ix << " bucket=" << target->get_name() << dendl; return 0; } @@ -957,8 +957,8 @@ int RGWLC::handle_multipart_expiration(rgw::sal::Bucket* target, if ((offset % 100) == 0) { if (worker_should_stop(stop_at, once)) { - ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker " - << worker->ix + ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker=" + << worker->ix << " bucket=" << target->get_name() << dendl; return 0; } @@ -1644,7 +1644,7 @@ int RGWLC::bucket_lc_process(string& shard_id, LCWorker* worker, string bucket_name = result[1]; string bucket_marker = result[2]; - ldpp_dout(this, 5) << "RGWLC::bucket_lc_process ENTER " << bucket_name << dendl; + ldpp_dout(this, 5) << "RGWLC::bucket_lc_process ENTER bucket=" << bucket_name << dendl; if (unlikely(cct->_conf->rgwlc_skip_bucket_step)) { return 0; } @@ -1685,7 +1685,7 @@ int RGWLC::bucket_lc_process(string& shard_id, LCWorker* worker, try { config.decode(iter); } catch (const buffer::error& e) { - ldpp_dout(this, 0) << __func__ << "() decode life cycle config failed" + ldpp_dout(this, 0) << __func__ << "() decode life cycle config failed bucket=" << bucket_name << dendl; return -1; } @@ -1693,7 +1693,7 @@ int RGWLC::bucket_lc_process(string& shard_id, LCWorker* worker, /* fetch information for zone checks */ rgw::sal::Zone* zone = driver->get_zone(); - auto pf = [](RGWLC::LCWorker* wk, WorkQ* wq, WorkItem& wi) { + auto pf = [&bucket_name](RGWLC::LCWorker* wk, WorkQ* wq, WorkItem& wi) { auto wt = boost::get>(wi); auto& [op_rule, o] = wt; @@ -1705,7 +1705,8 @@ int RGWLC::bucket_lc_process(string& shard_id, LCWorker* worker, if (ret < 0) { ldpp_dout(wk->get_lc(), 20) << "ERROR: orule.process() returned ret=" << ret - << "thread:" << wq->thr_name() + << " thread=" << wq->thr_name() + << " bucket=" << bucket_name << dendl; } }; @@ -1722,8 +1723,8 @@ int RGWLC::bucket_lc_process(string& shard_id, LCWorker* worker, ++prefix_iter) { if (worker_should_stop(stop_at, once)) { - ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker " - << worker->ix + ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker=" + << worker->ix << " bucket=" << bucket_name << dendl; return 0; } @@ -1769,8 +1770,8 @@ int RGWLC::bucket_lc_process(string& shard_id, LCWorker* worker, worker->workpool->enqueue(WorkItem{t1}); if ((offset % 100) == 0) { if (worker_should_stop(stop_at, once)) { - ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker " - << worker->ix + ldpp_dout(this, 5) << __func__ << " interval budget EXPIRED worker=" + << worker->ix << " bucket=" << bucket_name << dendl; return 0; } @@ -1862,7 +1863,7 @@ int RGWLC::bucket_lc_post(int index, int max_lock_sec, ret = sal_lc->set_entry(obj_names[index], entry); if (ret < 0) { - ldpp_dout(this, 0) << "RGWLC::process() failed to set entry on " + ldpp_dout(this, 0) << "RGWLC::bucket_lc_post() failed to set entry on " << obj_names[index] << dendl; } clean: @@ -2025,7 +2026,7 @@ int RGWLC::process_bucket(int index, int max_lock_secs, LCWorker* worker, ret = serializer->try_lock(this, time, null_yield); if (ret == -EBUSY || ret == -EEXIST) { /* already locked by another lc processor */ - ldpp_dout(this, 0) << "RGWLC::process() failed to acquire lock on " + ldpp_dout(this, 0) << "RGWLC::process_bucket() failed to acquire lock on " << obj_names[index] << dendl; return -EBUSY; } @@ -2078,6 +2079,8 @@ int RGWLC::process_bucket(int index, int max_lock_secs, LCWorker* worker, lock.unlock(); ret = bucket_lc_process(entry->get_bucket(), worker, thread_stop_at(), once); + ldpp_dout(this, 5) << "RGWLC::process_bucket(): END entry 2: " << entry + << " index: " << index << " worker ix: " << worker->ix << " ret: " << ret << dendl; bucket_lc_post(index, max_lock_secs, *entry, ret, worker); return ret; @@ -2267,7 +2270,7 @@ int RGWLC::process(int index, int max_lock_secs, LCWorker* worker, if (head->get_marker().empty()) { ldpp_dout(this, 5) << "RGWLC::process() cycle finished lc_shard=" - << lc_shard + << lc_shard << " worker=" << worker->ix << dendl; head->set_shard_rollover_date(ceph_clock_now()); ret = sal_lc->put_head(lc_shard, *head.get()); @@ -2287,14 +2290,14 @@ int RGWLC::process(int index, int max_lock_secs, LCWorker* worker, if (advance_head(lc_shard, *head.get(), *entry.get(), now) < 0) { goto exit; } - ldpp_dout(this, 5) << "RGWLC::process() worker ix; " << worker->ix + ldpp_dout(this, 5) << "RGWLC::process() worker ix: " << worker->ix << " SKIP processing for already-processed bucket " << entry->get_bucket() << dendl; /* done with this shard */ if (head->get_marker().empty()) { ldpp_dout(this, 5) << "RGWLC::process() cycle finished lc_shard=" - << lc_shard + << lc_shard << " worker=" << worker->ix << dendl; head->set_shard_rollover_date(ceph_clock_now()); ret = sal_lc->put_head(lc_shard, *head.get()); @@ -2347,6 +2350,8 @@ int RGWLC::process(int index, int max_lock_secs, LCWorker* worker, * bucket is being processed */ lock->unlock(); ret = bucket_lc_process(entry->get_bucket(), worker, thread_stop_at(), once); + ldpp_dout(this, 5) << "RGWLC::process(): END entry 2: " << entry + << " index: " << index << " worker ix: " << worker->ix << " ret: " << ret << dendl; /* postamble */ //bucket_lc_post(index, max_lock_secs, entry, ret, worker); @@ -2376,8 +2381,8 @@ int RGWLC::process(int index, int max_lock_secs, LCWorker* worker, } ret = sal_lc->set_entry(lc_shard, *entry); if (ret < 0) { - ldpp_dout(this, 0) << "RGWLC::process() failed to set entry on " - << lc_shard + ldpp_dout(this, 0) << "RGWLC::process() failed to set entry on lc_shard=" + << lc_shard << " entry=" << entry << dendl; /* fatal, locked */ goto exit; @@ -2388,7 +2393,7 @@ int RGWLC::process(int index, int max_lock_secs, LCWorker* worker, if (head->get_marker().empty()) { ldpp_dout(this, 5) << "RGWLC::process() cycle finished lc_shard=" - << lc_shard + << lc_shard << " worker=" << worker->ix << dendl; head->set_shard_rollover_date(ceph_clock_now()); ret = sal_lc->put_head(lc_shard, *head.get()); -- 2.39.5