SUBSYS(test, 0, 5)
SUBSYS(cephfs_mirror, 0, 5)
SUBSYS(cephsqlite, 0, 5)
+SUBSYS(seastore, 0, 5)
// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*-
// vim: ts=8 sw=2 smarttab
+#include "crimson/os/seastore/logging.h"
#include "crimson/os/seastore/cache.h"
-#include "crimson/common/log.h"
// included for get_extent_by_type
#include "crimson/os/seastore/collection_manager/collection_flat_node.h"
#include "crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h"
#include "test/crimson/seastore/test_block.h"
-namespace {
- seastar::logger& logger() {
- return crimson::get_logger(ceph_subsys_filestore);
- }
-}
-
namespace crimson::os::seastore {
Cache::Cache(SegmentManager &segment_manager) :
Cache::~Cache()
{
+ LOG_PREFIX(Cache::~Cache);
for (auto &i: extents) {
- logger().error("~Cache: extent {} still alive", i);
+ ERROR("extent {} still alive", i);
}
ceph_assert(extents.empty());
}
Cache::retire_extent_ret Cache::retire_extent(
Transaction &t, paddr_t addr, extent_len_t length)
{
+ LOG_PREFIX(Cache::retire_extent);
if (auto ext = t.write_set.find_offset(addr); ext != t.write_set.end()) {
- logger().debug("{}: found {} in t.write_set", __func__, addr);
+ DEBUGT("found {} in t.write_set", t, addr);
t.add_to_retired_set(CachedExtentRef(&*ext));
return retire_extent_ertr::now();
} else if (auto iter = extents.find_offset(addr);
void Cache::add_extent(CachedExtentRef ref)
{
+ LOG_PREFIX(Cache::add_extent);
assert(ref->is_valid());
extents.insert(*ref);
} else {
ceph_assert(!ref->primary_ref_list_hook.is_linked());
}
- logger().debug("add_extent: {}", *ref);
+ DEBUG("extent {}", *ref);
}
void Cache::mark_dirty(CachedExtentRef ref)
{
+ LOG_PREFIX(Cache::mark_dirty);
if (ref->is_dirty()) {
assert(ref->primary_ref_list_hook.is_linked());
return;
add_to_dirty(ref);
ref->state = CachedExtent::extent_state_t::DIRTY;
- logger().debug("mark_dirty: {}", *ref);
+ DEBUG("extent: {}", *ref);
}
void Cache::add_to_dirty(CachedExtentRef ref)
void Cache::remove_extent(CachedExtentRef ref)
{
- logger().debug("remove_extent: {}", *ref);
+ LOG_PREFIX(Cache::remove_extent);
+ DEBUG("extent {}", *ref);
assert(ref->is_valid());
remove_from_dirty(ref);
extents.erase(*ref);
void Cache::retire_extent(CachedExtentRef ref)
{
- logger().debug("retire_extent: {}", *ref);
+ LOG_PREFIX(Cache::retire_extent);
+ DEBUG("extent {}", *ref);
assert(ref->is_valid());
remove_from_dirty(ref);
void Cache::replace_extent(CachedExtentRef next, CachedExtentRef prev)
{
+ LOG_PREFIX(Cache::replace_extent);
+ DEBUG("prev {}, next {}", *prev, *next);
assert(next->get_paddr() == prev->get_paddr());
assert(next->version == prev->version + 1);
extents.replace(*next, *prev);
CachedExtentRef Cache::duplicate_for_write(
Transaction &t,
CachedExtentRef i) {
+ LOG_PREFIX(Cache::duplicate_for_write);
if (i->is_pending())
return i;
ret->version++;
ret->state = CachedExtent::extent_state_t::MUTATION_PENDING;
- logger().debug("Cache::duplicate_for_write: {} -> {}", *i, *ret);
+ DEBUGT("{} -> {}", t, *i, *ret);
return ret;
}
std::optional<record_t> Cache::try_construct_record(Transaction &t)
{
+ LOG_PREFIX(Cache::try_construct_record);
+ DEBUGT("enter", t);
+
// First, validate read set
for (auto &i: t.read_set) {
if (i->state == CachedExtent::extent_state_t::INVALID) {
}
}
+ DEBUGT("read_set validated", t);
+
record_t record;
t.write_set.clear();
record.deltas.reserve(t.mutated_block_list.size());
for (auto &i: t.mutated_block_list) {
if (!i->is_valid()) {
- logger().debug("try_construct_record: ignoring invalid {}", *i);
+ DEBUGT("ignoring invalid {}", t, *i);
continue;
}
- logger().debug("try_construct_record: mutating {}", *i);
+ DEBUGT("mutating {}", t, *i);
assert(i->prior_instance);
replace_extent(i, i->prior_instance);
auto final_crc = i->get_crc32c();
if (i->get_type() == extent_types_t::ROOT) {
root = t.root;
- logger().debug(
- "{}: writing out root delta for {}",
- __func__,
- *t.root);
+ DEBUGT("writing out root delta for {}", t, *t.root);
record.deltas.push_back(
delta_info_t{
extent_types_t::ROOT,
// Transaction is now a go, set up in-memory cache state
// invalidate now invalid blocks
for (auto &i: t.retired_set) {
- logger().debug("try_construct_record: retiring {}", *i);
+ DEBUGT("retiring {}", t, *i);
retire_extent(i);
}
record.extents.reserve(t.fresh_block_list.size());
for (auto &i: t.fresh_block_list) {
- logger().debug("try_construct_record: fresh block {}", *i);
+ DEBUGT("fresh block {}", t, *i);
bufferlist bl;
i->prepare_write();
bl.append(i->get_bptr());
journal_seq_t seq,
SegmentCleaner *cleaner)
{
+ LOG_PREFIX(Cache::complete_commit);
+ DEBUGT("enter", t);
+
for (auto &i: t.fresh_block_list) {
i->set_paddr(final_block_start.add_relative(i->get_paddr()));
i->last_committed_crc = i->get_crc32c();
i->on_initial_write();
if (!i->is_valid()) {
- logger().debug("complete_commit: invalid {}", *i);
+ DEBUGT("invalid {}", t, *i);
continue;
}
i->state = CachedExtent::extent_state_t::CLEAN;
- logger().debug("complete_commit: fresh {}", *i);
+ DEBUGT("fresh {}", t, *i);
add_extent(i);
if (cleaner) {
cleaner->mark_space_used(
// Add new copy of mutated blocks, set_io_wait to block until written
for (auto &i: t.mutated_block_list) {
- logger().debug("complete_commit: mutated {}", *i);
+ DEBUGT("mutated {}", t, *i);
assert(i->prior_instance);
i->on_delta_write(final_block_start);
i->prior_instance = CachedExtentRef();
if (!i->is_valid()) {
- logger().debug("complete_commit: not dirtying invalid {}", *i);
+ DEBUGT("not dirtying invalid {}", t, *i);
continue;
}
i->state = CachedExtent::extent_state_t::DIRTY;
last_commit = seq;
for (auto &i: t.retired_set) {
- logger().debug("try_construct_record: retiring {}", *i);
+ DEBUGT("retiring {}", t, *i);
i->dirty_from_or_retired_at = last_commit;
}
paddr_t record_base,
const delta_info_t &delta)
{
+ LOG_PREFIX(Cache::replay_delta);
if (delta.type == extent_types_t::ROOT) {
- logger().debug("replay_delta: found root delta");
+ DEBUG("found root delta");
remove_extent(root);
root->apply_delta_and_adjust_crc(record_base, delta.bl);
root->dirty_from_or_retired_at = journal_seq;
return extent_fut.safe_then([=, &delta](auto extent) {
if (!extent) {
assert(delta.pversion > 0);
- logger().debug(
- "replay_delta: replaying {}, extent not present so delta is obsolete",
+ DEBUG(
+ "replaying {}, extent not present so delta is obsolete",
delta);
return;
}
- logger().debug(
- "replay_delta: replaying {} on {}",
- *extent,
- delta);
+ DEBUG("replaying {} on {}", *extent, delta);
assert(extent->version == delta.pversion);
journal_seq_t seq,
size_t max_bytes)
{
+ LOG_PREFIX(Cache::get_next_dirty_extents);
std::vector<CachedExtentRef> ret;
size_t bytes_so_far = 0;
for (auto i = dirty.begin();
++i) {
CachedExtentRef cand;
if (i->get_dirty_from() != journal_seq_t() && i->get_dirty_from() < seq) {
- logger().debug(
- "Cache::get_next_dirty_extents: next {}",
- *i);
+ DEBUG("next {}", *i);
if (!(ret.empty() ||
ret.back()->get_dirty_from() <= i->get_dirty_from())) {
- logger().debug(
- "Cache::get_next_dirty_extents: last {}, next {}",
- *ret.back(),
- *i);
+ DEBUG("last {}, next {}", *ret.back(), *i);
}
assert(ret.empty() || ret.back()->get_dirty_from() <= i->get_dirty_from());
bytes_so_far += i->get_length();
}
return seastar::do_with(
std::move(ret),
- [](auto &ret) {
+ [FNAME](auto &ret) {
return seastar::do_for_each(
ret,
- [](auto &ext) {
- logger().debug(
- "get_next_dirty_extents: waiting on {}",
- *ext);
+ [FNAME](auto &ext) {
+ DEBUG("waiting on {}", *ext);
return ext->wait_io();
}).then([&ret]() mutable {
return seastar::make_ready_future<std::vector<CachedExtentRef>>(
Cache::get_root_ret Cache::get_root(Transaction &t)
{
+ LOG_PREFIX(Cache::get_root);
if (t.root) {
+ DEBUGT("root already on transaction {}", t, *t.root);
return get_root_ret(
get_root_ertr::ready_future_marker{},
t.root);
} else {
auto ret = root;
- return ret->wait_io().then([ret, &t] {
+ DEBUGT("waiting root {}", t, *ret);
+ return ret->wait_io().then([FNAME, ret, &t] {
+ DEBUGT("got root read {}", t, *ret);
t.root = ret;
t.add_to_read_set(ret);
return get_root_ret(
#include "seastar/core/shared_future.hh"
#include "include/buffer.h"
+
+#include "crimson/os/seastore/logging.h"
#include "crimson/os/seastore/seastore_types.h"
#include "crimson/os/seastore/transaction.h"
#include "crimson/os/seastore/segment_manager.h"
/// Creates empty transaction
TransactionRef create_transaction() {
+ LOG_PREFIX(Cache::create_transaction);
auto ret = std::make_unique<Transaction>(
get_dummy_ordering_handle(),
false,
last_commit
);
retired_extent_gate.add_token(ret->retired_gate_token);
+ DEBUGT("created", *ret);
return ret;
}
/// Creates empty weak transaction
TransactionRef create_weak_transaction() {
+ LOG_PREFIX(Cache::create_weak_transaction);
auto ret = std::make_unique<Transaction>(
get_dummy_ordering_handle(),
true,
last_commit
);
retired_extent_gate.add_token(ret->retired_gate_token);
+ DEBUGT("created", *ret);
return ret;
}
--- /dev/null
+// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*-
+// vim: ts=8 sw=2 smarttab
+
+#pragma once
+
+#include "crimson/common/log.h"
+
+#define LOGGER crimson::get_logger(ceph_subsys_seastore)
+#define LOG_PREFIX(x) constexpr auto FNAME = #x
+
+#define LOG(LEVEL, MSG, ...) LOGGER . LEVEL("{}: " MSG, FNAME __VA_OPT__(,) __VA_ARGS__)
+#define LOGT(LEVEL, MSG, t, ...) LOGGER . LEVEL("{}({}): " MSG, FNAME, (void*)&t __VA_OPT__(,) __VA_ARGS__)
+
+#define TRACE(...) LOG(trace, __VA_ARGS__)
+#define TRACET(...) LOGT(trace, __VA_ARGS__)
+
+#define DEBUG(...) LOG(debug, __VA_ARGS__)
+#define DEBUGT(...) LOGT(debug, __VA_ARGS__)
+
+#define WARN(...) LOG(warn, __VA_ARGS__)
+#define WARNT(...) LOGT(warn, __VA_ARGS__)
+
+#define ERROR(...) LOG(error, __VA_ARGS__)
+#define ERRORT(...) LOGT(error, __VA_ARGS__)
#include "include/denc.h"
#include "include/intarith.h"
-#include "crimson/common/log.h"
-
+#include "crimson/os/seastore/logging.h"
#include "crimson/os/seastore/transaction_manager.h"
#include "crimson/os/seastore/segment_manager.h"
#include "crimson/os/seastore/journal.h"
-namespace {
- seastar::logger& logger() {
- return crimson::get_logger(ceph_subsys_filestore);
- }
-}
-
namespace crimson::os::seastore {
TransactionManager::TransactionManager(
TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs()
{
- return journal->open_for_write().safe_then([this](auto addr) {
- logger().debug("TransactionManager::mkfs: about to do_with");
+ LOG_PREFIX(TransactionManager::mkfs);
+ return journal->open_for_write().safe_then([this, FNAME](auto addr) {
+ DEBUG("TransactionManager::mkfs: about to do_with");
segment_cleaner->init_mkfs(addr);
return seastar::do_with(
create_transaction(),
- [this](auto &transaction) {
- logger().debug("TransactionManager::mkfs: about to cache->mkfs");
+ [this, FNAME](auto &transaction) {
+ DEBUGT(
+ "about to cache->mkfs",
+ *transaction);
cache->init();
return cache->mkfs(*transaction
).safe_then([this, &transaction] {
return lba_manager->mkfs(*transaction);
- }).safe_then([this, &transaction] {
- logger().debug("TransactionManager::mkfs: about to submit_transaction");
+ }).safe_then([this, FNAME, &transaction] {
+ DEBUGT("about to submit_transaction", *transaction);
return submit_transaction_direct(std::move(transaction)).handle_error(
crimson::ct_error::eagain::handle([] {
ceph_assert(0 == "eagain impossible");
TransactionManager::mount_ertr::future<> TransactionManager::mount()
{
+ LOG_PREFIX(TransactionManager::mount);
cache->init();
return journal->replay([this](auto seq, auto paddr, const auto &e) {
return cache->replay_delta(seq, paddr, e);
}).safe_then([this] {
return journal->open_for_write();
- }).safe_then([this](auto addr) {
+ }).safe_then([this, FNAME](auto addr) {
segment_cleaner->set_journal_head(addr);
return seastar::do_with(
create_weak_transaction(),
- [this](auto &t) {
+ [this, FNAME](auto &t) {
return cache->init_cached_extents(*t, [this](auto &t, auto &e) {
return lba_manager->init_cached_extent(t, e);
- }).safe_then([this, &t] {
+ }).safe_then([this, FNAME, &t] {
assert(segment_cleaner->debug_check_space(
*segment_cleaner->get_empty_space_tracker()));
return lba_manager->scan_mapped_space(
*t,
- [this](paddr_t addr, extent_len_t len) {
- logger().trace("TransactionManager::mount: marking {}~{} used",
- addr,
- len);
- segment_cleaner->mark_space_used(
- addr,
- len ,
- /* init_scan = */ true);
+ [this, FNAME, &t](paddr_t addr, extent_len_t len) {
+ TRACET(
+ "marking {}~{} used",
+ t,
+ addr,
+ len);
+ segment_cleaner->mark_space_used(
+ addr,
+ len ,
+ /* init_scan = */ true);
});
});
});
Transaction &t,
LogicalCachedExtentRef &ref)
{
+ LOG_PREFIX(TransactionManager::dec_ref);
return lba_manager->decref_extent(t, ref->get_laddr()
- ).safe_then([this, &t, ref](auto ret) {
+ ).safe_then([this, FNAME, &t, ref](auto ret) {
if (ret.refcount == 0) {
- logger().debug(
- "TransactionManager::dec_ref: extent {} refcount 0",
+ DEBUGT(
+ "extent {} refcount 0",
+ t,
*ref);
cache->retire_extent(t, ref);
}
Transaction &t,
laddr_t offset)
{
+ LOG_PREFIX(TransactionManager::dec_ref);
return lba_manager->decref_extent(t, offset
- ).safe_then([this, offset, &t](auto result) -> ref_ret {
+ ).safe_then([this, FNAME, offset, &t](auto result) -> ref_ret {
if (result.refcount == 0 && !result.addr.is_zero()) {
- logger().debug(
- "TransactionManager::dec_ref: offset {} refcount 0",
- offset);
+ DEBUGT("offset {} refcount 0", t, offset);
return cache->retire_extent(
t, result.addr, result.length
).safe_then([] {
TransactionManager::submit_transaction(
TransactionRef t)
{
- logger().debug("TransactionManager::submit_transaction");
+ LOG_PREFIX(TransactionManager::submit_transaction);
+ DEBUGT("about to await throttle", *t);
auto &tref = *t;
return tref.handle.enter(write_pipeline.wait_throttle
).then([this] {
TransactionManager::submit_transaction_direct(
TransactionRef t)
{
- logger().debug("TransactionManager::submit_transaction_direct");
+ LOG_PREFIX(TransactionManager::submit_transaction_direct);
+ DEBUGT("about to prepare", *t);
auto &tref = *t;
return tref.handle.enter(write_pipeline.prepare
- ).then([this, &tref]() mutable
+ ).then([this, FNAME, &tref]() mutable
-> submit_transaction_ertr::future<> {
auto record = cache->try_construct_record(tref);
if (!record) {
- logger().debug("TransactionManager::submit_transaction_direct: "
- "conflict detected, returning eagain.");
+ DEBUGT("conflict detected, returning eagain.", tref);
return crimson::ct_error::eagain::make();
}
+ DEBUGT("about to submit to journal", tref);
+
return journal->submit_record(std::move(*record), tref.handle
- ).safe_then([this, &tref](auto p) mutable {
+ ).safe_then([this, FNAME, &tref](auto p) mutable {
auto [addr, journal_seq] = p;
+ DEBUGT("journal commit to {} seq {}", tref, addr, journal_seq);
segment_cleaner->set_journal_head(journal_seq);
cache->complete_commit(tref, addr, journal_seq, segment_cleaner.get());
lba_manager->complete_transaction(tref);
Transaction &t,
CachedExtentRef extent)
{
+ LOG_PREFIX(TransactionManager::rewrite_extent);
{
auto updated = cache->update_extent_from_transaction(t, extent);
if (!updated) {
- logger().debug(
- "{}: {} is already retired, skipping",
- __func__,
- *extent);
+ DEBUGT("{} is already retired, skipping", t, *extent);
return rewrite_extent_ertr::now();
}
extent = updated;
}
if (extent->get_type() == extent_types_t::ROOT) {
- logger().debug(
- "{}: marking root {} for rewrite",
- __func__,
- *extent);
+ DEBUGT("marking root {} for rewrite", t, *extent);
cache->duplicate_for_write(t, extent);
return rewrite_extent_ertr::now();
}
laddr_t laddr,
segment_off_t len)
{
- logger().debug(
- "TransactionManager::get_extent_if_live:"
- " type {}, addr {}, laddr {}, len {}",
- type,
- addr,
- laddr,
- len);
+ LOG_PREFIX(TransactionManager::get_extent_if_live);
+ DEBUGT("type {}, addr {}, laddr {}, len {}", t, type, addr, laddr, len);
return cache->get_extent_if_cached(t, addr
- ).then([this, &t, type, addr, laddr, len](auto extent)
+ ).then([this, FNAME, &t, type, addr, laddr, len](auto extent)
-> get_extent_if_live_ret {
if (extent) {
return get_extent_if_live_ret(
}
});
} else {
- logger().debug(
- "TransactionManager::get_extent_if_live: non-logical extent {}",
- addr);
+ DEBUGT("non-logical extent {}", t, addr);
return lba_manager->get_physical_extent_if_live(
t,
type,
#include "crimson/osd/exceptions.h"
+#include "crimson/os/seastore/logging.h"
#include "crimson/os/seastore/segment_cleaner.h"
#include "crimson/os/seastore/seastore_types.h"
#include "crimson/os/seastore/cache.h"
template <typename F>
auto repeat_eagain(F &&f) {
+ LOG_PREFIX("repeat_eagain");
return seastar::do_with(
std::forward<F>(f),
- [](auto &f) {
+ [FNAME](auto &f) {
return crimson::do_until(
- [&f] {
+ [FNAME, &f] {
return std::invoke(f
).safe_then([] {
return true;
}).handle_error(
- [](const crimson::ct_error::eagain &e) {
+ [FNAME](const crimson::ct_error::eagain &e) {
+ DEBUG("hit eagain, restarting");
return seastar::make_ready_future<bool>(false);
},
crimson::ct_error::pass_further_all{}
pin_to_extent_ret<T> pin_to_extent(
Transaction &t,
LBAPinRef pin) {
+ LOG_PREFIX(TransactionManager::pin_to_extent);
using ret = pin_to_extent_ret<T>;
- crimson::get_logger(ceph_subsys_filestore).debug(
- "pin_to_extent: getting extent {}",
- *pin);
+ DEBUGT("getting extent {}", t, *pin);
return cache->get_extent<T>(
t,
pin->get_paddr(),
pin->get_length()
- ).safe_then([this, pin=std::move(pin)](auto ref) mutable -> ret {
+ ).safe_then([this, FNAME, &t, pin=std::move(pin)](auto ref) mutable -> ret {
if (!ref->has_pin()) {
if (pin->has_been_invalidated() || ref->has_been_invalidated()) {
return crimson::ct_error::eagain::make();
lba_manager->add_pin(ref->get_pin());
}
}
- crimson::get_logger(ceph_subsys_filestore).debug(
- "pin_to_extent: got extent {}",
- *ref);
+ DEBUGT("got extent {}", t, *ref);
return pin_to_extent_ret<T>(
pin_to_extent_ertr::ready_future_marker{},
std::move(ref));
Transaction &t,
laddr_t offset,
extent_len_t length) {
+ LOG_PREFIX(TransactionManager::read_extent);
return get_pins(
t, offset, length
- ).safe_then([this, &t, offset, length](auto pins) {
+ ).safe_then([this, FNAME, &t, offset, length](auto pins) {
if (pins.size() != 1 || !pins.front()->get_paddr().is_real()) {
- auto &logger = crimson::get_logger(ceph_subsys_filestore);
- logger.error(
- "TransactionManager::read_extent offset {} len {} got {} extents:",
- offset,
- length,
- pins.size());
+ ERRORT(
+ "offset {} len {} got {} extents:",
+ t, offset, length, pins.size());
for (auto &i: pins) {
- logger.error("\t{}", *i);
+ ERRORT("\t{}", t, *i);
}
ceph_assert(0 == "Should be impossible");
}
/// Obtain mutable copy of extent
LogicalCachedExtentRef get_mutable_extent(Transaction &t, LogicalCachedExtentRef ref) {
- auto &logger = crimson::get_logger(ceph_subsys_filestore);
+ LOG_PREFIX(TransactionManager::get_mutable_extent);
auto ret = cache->duplicate_for_write(
t,
ref)->cast<LogicalCachedExtent>();
if (!ret->has_pin()) {
- logger.debug(
- "{}: duplicating {} for write: {}",
- __func__,
+ DEBUGT(
+ "duplicating {} for write: {}",
+ t,
*ref,
*ret);
ret->set_pin(ref->get_pin().duplicate());
} else {
- logger.debug(
- "{}: {} already pending",
- __func__,
+ DEBUGT(
+ "{} already pending",
+ t,
*ref);
assert(ref->is_pending());
assert(&*ref == &*ret);
projects / ceph-ci.git / commitdiff