mirror of
https://github.com/Zygo/bees.git
synced 2025-05-17 13:25:45 +02:00
Logging: Add log levels to output
This commit adds log levels to the output. In systemd, it makes colored lines, otherwise it's probably just a number. Bees is very chatty, so this paves the road for log level filtering. Signed-off-by: Kai Krakow <kai@kaishome.de>
This commit is contained in:
Kai Krakow
parent
4943a07cce
commit
677da5de45
@ -8,6 +8,8 @@
|
||||
#include <string>
|
||||
#include <typeinfo>
|
||||
|
||||
#include <syslog.h>
|
||||
|
||||
/** \brief Chatter wraps a std::ostream reference with a destructor that
|
||||
writes a newline, and inserts timestamp, pid, and tid prefixes on output.
|
||||
|
||||
@ -33,12 +35,13 @@ namespace crucible {
|
||||
using namespace std;
|
||||
|
||||
class Chatter {
|
||||
int m_loglevel;
|
||||
string m_name;
|
||||
ostream &m_os;
|
||||
ostringstream m_oss;
|
||||
|
||||
public:
|
||||
Chatter(string name, ostream &os = cerr);
|
||||
Chatter(int loglevel, string name, ostream &os = cerr);
|
||||
Chatter(Chatter &&c);
|
||||
ostream &get_os() { return m_oss; }
|
||||
|
||||
@ -103,7 +106,7 @@ namespace crucible {
|
||||
|
||||
template <class T> Chatter operator<<(const T &t)
|
||||
{
|
||||
Chatter c(m_pretty_function, m_os);
|
||||
Chatter c(LOG_NOTICE, m_pretty_function, m_os);
|
||||
c << t;
|
||||
return c;
|
||||
}
|
||||
|
||||
@ -44,8 +44,8 @@ namespace crucible {
|
||||
}
|
||||
}
|
||||
|
||||
Chatter::Chatter(string name, ostream &os)
|
||||
: m_name(name), m_os(os)
|
||||
Chatter::Chatter(int loglevel, string name, ostream &os)
|
||||
: m_loglevel(loglevel), m_name(name), m_os(os)
|
||||
{
|
||||
}
|
||||
|
||||
@ -69,9 +69,9 @@ namespace crucible {
|
||||
DIE_IF_ZERO(strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", <m));
|
||||
|
||||
header_stream << buf;
|
||||
header_stream << " " << getpid() << "." << gettid();
|
||||
header_stream << " " << getpid() << "." << gettid() << "<" << m_loglevel << ">";
|
||||
} else {
|
||||
header_stream << "tid " << gettid();
|
||||
header_stream << "<" << m_loglevel << ">tid " << gettid();
|
||||
}
|
||||
|
||||
if (!m_name.empty()) {
|
||||
@ -98,7 +98,7 @@ namespace crucible {
|
||||
}
|
||||
|
||||
Chatter::Chatter(Chatter &&c)
|
||||
: m_name(c.m_name), m_os(c.m_os), m_oss(c.m_oss.str())
|
||||
: m_loglevel(c.m_loglevel), m_name(c.m_name), m_os(c.m_os), m_oss(c.m_oss.str())
|
||||
{
|
||||
c.m_oss.str("");
|
||||
}
|
||||
|
||||
@ -6,7 +6,6 @@
|
||||
#include "crucible/limits.h"
|
||||
#include "crucible/string.h"
|
||||
|
||||
|
||||
namespace crucible {
|
||||
using namespace std;
|
||||
|
||||
|
||||
@ -80,7 +80,7 @@ BeesContext::dump_status()
|
||||
auto status_charp = getenv("BEESSTATUS");
|
||||
if (!status_charp) return;
|
||||
string status_file(status_charp);
|
||||
BEESLOG("Writing status to file '" << status_file << "' every " << BEES_STATUS_INTERVAL << " sec");
|
||||
BEESLOGINFO("Writing status to file '" << status_file << "' every " << BEES_STATUS_INTERVAL << " sec");
|
||||
while (1) {
|
||||
BEESNOTE("waiting " << BEES_STATUS_INTERVAL);
|
||||
sleep(BEES_STATUS_INTERVAL);
|
||||
@ -96,7 +96,7 @@ BeesContext::dump_status()
|
||||
ofs << "\t" << avg_rates << "\n";
|
||||
|
||||
ofs << "THREADS (work queue " << TaskMaster::get_queue_count() << " tasks):\n";
|
||||
for (auto t : BeesNote::get_status()) {
|
||||
for (auto t : BeesNote::get_status()) {
|
||||
ofs << "\ttid " << t.first << ": " << t.second << "\n";
|
||||
}
|
||||
|
||||
@ -129,24 +129,24 @@ BeesContext::show_progress()
|
||||
|
||||
auto thisStats = BeesStats::s_global;
|
||||
auto avg_rates = lastStats / BEES_STATS_INTERVAL;
|
||||
BEESLOG("TOTAL: " << thisStats);
|
||||
BEESLOG("RATES: " << avg_rates);
|
||||
BEESLOGINFO("TOTAL: " << thisStats);
|
||||
BEESLOGINFO("RATES: " << avg_rates);
|
||||
lastStats = thisStats;
|
||||
}
|
||||
|
||||
BEESLOG("ACTIVITY:");
|
||||
BEESLOGINFO("ACTIVITY:");
|
||||
|
||||
auto thisStats = BeesStats::s_global;
|
||||
auto deltaStats = thisStats - lastProgressStats;
|
||||
if (deltaStats) {
|
||||
BEESLOG("\t" << deltaStats / BEES_PROGRESS_INTERVAL);
|
||||
BEESLOGINFO("\t" << deltaStats / BEES_PROGRESS_INTERVAL);
|
||||
};
|
||||
lastProgressStats = thisStats;
|
||||
|
||||
BEESLOG("THREADS:");
|
||||
BEESLOGINFO("THREADS:");
|
||||
|
||||
for (auto t : BeesNote::get_status()) {
|
||||
BEESLOG("\ttid " << t.first << ": " << t.second);
|
||||
for (auto t : BeesNote::get_status()) {
|
||||
BEESLOGINFO("\ttid " << t.first << ": " << t.second);
|
||||
}
|
||||
}
|
||||
}
|
||||
@ -187,8 +187,8 @@ BeesContext::dedup(const BeesRangePair &brp)
|
||||
BeesAddress first_addr(brp.first.fd(), brp.first.begin());
|
||||
BeesAddress second_addr(brp.second.fd(), brp.second.begin());
|
||||
|
||||
BEESLOG("dedup: src " << pretty(brp.first.size()) << " [" << to_hex(brp.first.begin()) << ".." << to_hex(brp.first.end()) << "] {" << first_addr << "} " << name_fd(brp.first.fd()));
|
||||
BEESLOG(" dst " << pretty(brp.second.size()) << " [" << to_hex(brp.second.begin()) << ".." << to_hex(brp.second.end()) << "] {" << second_addr << "} " << name_fd(brp.second.fd()));
|
||||
BEESLOGINFO("dedup: src " << pretty(brp.first.size()) << " [" << to_hex(brp.first.begin()) << ".." << to_hex(brp.first.end()) << "] {" << first_addr << "} " << name_fd(brp.first.fd()));
|
||||
BEESLOGINFO(" dst " << pretty(brp.second.size()) << " [" << to_hex(brp.second.begin()) << ".." << to_hex(brp.second.end()) << "] {" << second_addr << "} " << name_fd(brp.second.fd()));
|
||||
|
||||
if (first_addr.get_physical_or_zero() == second_addr.get_physical_or_zero()) {
|
||||
BEESLOGTRACE("equal physical addresses in dedup");
|
||||
@ -213,7 +213,7 @@ BeesContext::dedup(const BeesRangePair &brp)
|
||||
}
|
||||
} else {
|
||||
BEESCOUNT(dedup_miss);
|
||||
BEESLOG("NO Dedup! " << brp);
|
||||
BEESLOGWARN("NO Dedup! " << brp);
|
||||
}
|
||||
|
||||
return rv;
|
||||
@ -289,7 +289,7 @@ BeesContext::scan_one_extent(const BeesFileRange &bfr, const Extent &e)
|
||||
Extent::OBSCURED | Extent::PREALLOC
|
||||
)) {
|
||||
BEESCOUNT(scan_interesting);
|
||||
BEESLOG("Interesting extent flags " << e << " from fd " << name_fd(bfr.fd()));
|
||||
BEESLOGWARN("Interesting extent flags " << e << " from fd " << name_fd(bfr.fd()));
|
||||
}
|
||||
|
||||
if (e.flags() & Extent::HOLE) {
|
||||
@ -301,7 +301,7 @@ BeesContext::scan_one_extent(const BeesFileRange &bfr, const Extent &e)
|
||||
if (e.flags() & Extent::PREALLOC) {
|
||||
// Prealloc is all zero and we replace it with a hole.
|
||||
// No special handling is required here. Nuke it and move on.
|
||||
BEESLOG("prealloc extent " << e);
|
||||
BEESLOGINFO("prealloc extent " << e);
|
||||
BeesFileRange prealloc_bfr(m_ctx->tmpfile()->make_hole(e.size()));
|
||||
BeesRangePair brp(prealloc_bfr, bfr);
|
||||
// Raw dedup here - nothing else to do with this extent, nothing to merge with
|
||||
@ -375,7 +375,7 @@ BeesContext::scan_one_extent(const BeesFileRange &bfr, const Extent &e)
|
||||
// Do not attempt to lookup hash of zero block
|
||||
continue;
|
||||
} else {
|
||||
BEESLOG("zero bbd " << bbd << "\n\tin extent " << e);
|
||||
BEESLOGINFO("zero bbd " << bbd << "\n\tin extent " << e);
|
||||
BEESCOUNT(scan_zero_uncompressed);
|
||||
rewrite_extent = true;
|
||||
break;
|
||||
@ -514,7 +514,7 @@ BeesContext::scan_one_extent(const BeesFileRange &bfr, const Extent &e)
|
||||
// FIXME: we will thrash if we let multiple references to identical blocks
|
||||
// exist in the hash table. Erase all but the last one.
|
||||
if (last_replaced_addr) {
|
||||
BEESLOG("Erasing redundant hash " << hash << " addr " << last_replaced_addr);
|
||||
BEESLOGINFO("Erasing redundant hash " << hash << " addr " << last_replaced_addr);
|
||||
hash_table->erase_hash_addr(hash, last_replaced_addr);
|
||||
BEESCOUNT(scan_erase_redundant);
|
||||
}
|
||||
@ -676,7 +676,7 @@ BeesContext::scan_one_extent(const BeesFileRange &bfr, const Extent &e)
|
||||
|
||||
// Visualize
|
||||
if (bar != string(block_count, '.')) {
|
||||
BEESLOG("scan: " << pretty(e.size()) << " " << to_hex(e.begin()) << " [" << bar << "] " << to_hex(e.end()) << ' ' << name_fd(bfr.fd()));
|
||||
BEESLOGINFO("scan: " << pretty(e.size()) << " " << to_hex(e.begin()) << " [" << bar << "] " << to_hex(e.end()) << ' ' << name_fd(bfr.fd()));
|
||||
}
|
||||
|
||||
return bfr;
|
||||
@ -713,7 +713,7 @@ BeesContext::scan_forward(const BeesFileRange &bfr)
|
||||
|
||||
// Sanity check
|
||||
if (bfr.begin() >= bfr.file_size()) {
|
||||
BEESLOG("past EOF: " << bfr);
|
||||
BEESLOGWARN("past EOF: " << bfr);
|
||||
BEESCOUNT(scan_eof);
|
||||
return bfr;
|
||||
}
|
||||
@ -786,7 +786,7 @@ BeesContext::resolve_addr_uncached(BeesAddress addr)
|
||||
if (rt_age < BEES_TOXIC_DURATION && log_ino.m_iors.size() < BEES_MAX_EXTENT_REF_COUNT) {
|
||||
rv.m_is_toxic = false;
|
||||
} else {
|
||||
BEESLOG("WORKAROUND: toxic address " << addr << " in " << root_path() << " with " << log_ino.m_iors.size() << " refs took " << rt_age << "s in LOGICAL_INO");
|
||||
BEESLOGWARN("WORKAROUND: toxic address " << addr << " in " << root_path() << " with " << log_ino.m_iors.size() << " refs took " << rt_age << "s in LOGICAL_INO");
|
||||
BEESCOUNT(resolve_toxic);
|
||||
rv.m_is_toxic = true;
|
||||
}
|
||||
@ -811,7 +811,7 @@ void
|
||||
BeesContext::set_root_fd(Fd fd)
|
||||
{
|
||||
uint64_t root_fd_treeid = btrfs_get_root_id(fd);
|
||||
BEESLOG("set_root_fd " << name_fd(fd));
|
||||
BEESLOGINFO("set_root_fd " << name_fd(fd));
|
||||
BEESTRACE("set_root_fd " << name_fd(fd));
|
||||
THROW_CHECK1(invalid_argument, root_fd_treeid, root_fd_treeid == BTRFS_FS_TREE_OBJECTID);
|
||||
Stat st(fd);
|
||||
@ -820,7 +820,7 @@ BeesContext::set_root_fd(Fd fd)
|
||||
BtrfsIoctlFsInfoArgs fsinfo;
|
||||
fsinfo.do_ioctl(fd);
|
||||
m_root_uuid = fsinfo.uuid();
|
||||
BEESLOG("Filesystem UUID is " << m_root_uuid);
|
||||
BEESLOGINFO("Filesystem UUID is " << m_root_uuid);
|
||||
|
||||
// 65536 is big enough for two max-sized extents.
|
||||
// Need enough total space in the cache for the maximum number of active threads.
|
||||
@ -832,13 +832,13 @@ BeesContext::set_root_fd(Fd fd)
|
||||
// Start queue producers
|
||||
roots();
|
||||
|
||||
BEESLOG("returning from set_root_fd in " << name_fd(fd));
|
||||
BEESLOGINFO("returning from set_root_fd in " << name_fd(fd));
|
||||
}
|
||||
|
||||
void
|
||||
BeesContext::blacklist_add(const BeesFileId &fid)
|
||||
{
|
||||
BEESLOG("Adding " << fid << " to blacklist");
|
||||
BEESLOGDEBUG("Adding " << fid << " to blacklist");
|
||||
unique_lock<mutex> lock(m_blacklist_mutex);
|
||||
m_blacklist.insert(fid);
|
||||
}
|
||||
@ -907,7 +907,7 @@ BeesContext::hash_table()
|
||||
void
|
||||
BeesContext::set_root_path(string path)
|
||||
{
|
||||
BEESLOG("set_root_path " << path);
|
||||
BEESLOGINFO("set_root_path " << path);
|
||||
m_root_path = path;
|
||||
set_root_fd(open_or_die(m_root_path, FLAGS_OPEN_DIR));
|
||||
}
|
||||
|
||||
@ -298,7 +298,7 @@ BeesHashTable::prefetch_loop()
|
||||
auto avg_rates = thisStats / m_ctx->total_timer().age();
|
||||
graph_blob << "\t" << avg_rates << "\n";
|
||||
|
||||
BEESLOG(graph_blob.str());
|
||||
BEESLOGINFO(graph_blob.str());
|
||||
catch_all([&]() {
|
||||
m_stats_file.write(graph_blob.str());
|
||||
});
|
||||
@ -306,13 +306,13 @@ BeesHashTable::prefetch_loop()
|
||||
if (not_locked) {
|
||||
// Always do the mlock, whether shared or not
|
||||
THROW_CHECK1(runtime_error, m_size, m_size > 0);
|
||||
BEESLOG("mlock(" << pretty(m_size) << ")...");
|
||||
BEESLOGINFO("mlock(" << pretty(m_size) << ")...");
|
||||
Timer lock_time;
|
||||
catch_all([&]() {
|
||||
BEESNOTE("mlock " << pretty(m_size));
|
||||
DIE_IF_NON_ZERO(mlock(m_byte_ptr, m_size));
|
||||
});
|
||||
BEESLOG("mlock(" << pretty(m_size) << ") done in " << lock_time << " sec");
|
||||
BEESLOGINFO("mlock(" << pretty(m_size) << ") done in " << lock_time << " sec");
|
||||
not_locked = false;
|
||||
}
|
||||
|
||||
@ -591,9 +591,9 @@ BeesHashTable::try_mmap_flags(int flags)
|
||||
THROW_CHECK1(out_of_range, m_size, m_size > 0);
|
||||
Timer map_time;
|
||||
catch_all([&]() {
|
||||
BEESLOG("mapping hash table size " << m_size << " with flags " << mmap_flags_ntoa(flags));
|
||||
BEESLOGINFO("mapping hash table size " << m_size << " with flags " << mmap_flags_ntoa(flags));
|
||||
void *ptr = mmap_or_die(nullptr, m_size, PROT_READ | PROT_WRITE, flags, flags & MAP_ANONYMOUS ? -1 : int(m_fd), 0);
|
||||
BEESLOG("mmap done in " << map_time << " sec");
|
||||
BEESLOGINFO("mmap done in " << map_time << " sec");
|
||||
m_cell_ptr = static_cast<Cell *>(ptr);
|
||||
void *ptr_end = static_cast<uint8_t *>(ptr) + m_size;
|
||||
m_cell_ptr_end = static_cast<Cell *>(ptr_end);
|
||||
@ -662,13 +662,13 @@ BeesHashTable::BeesHashTable(shared_ptr<BeesContext> ctx, string filename, off_t
|
||||
BEESTRACE("hash table bucket size " << BLOCK_SIZE_HASHTAB_BUCKET);
|
||||
BEESTRACE("hash table extent size " << BLOCK_SIZE_HASHTAB_EXTENT);
|
||||
|
||||
BEESLOG("opened hash table filename '" << filename << "' length " << m_size);
|
||||
BEESLOGINFO("opened hash table filename '" << filename << "' length " << m_size);
|
||||
m_buckets = m_size / BLOCK_SIZE_HASHTAB_BUCKET;
|
||||
m_cells = m_buckets * c_cells_per_bucket;
|
||||
m_extents = (m_size + BLOCK_SIZE_HASHTAB_EXTENT - 1) / BLOCK_SIZE_HASHTAB_EXTENT;
|
||||
BEESLOG("\tcells " << m_cells << ", buckets " << m_buckets << ", extents " << m_extents);
|
||||
BEESLOGINFO("\tcells " << m_cells << ", buckets " << m_buckets << ", extents " << m_extents);
|
||||
|
||||
BEESLOG("\tflush rate limit " << BEES_FLUSH_RATE);
|
||||
BEESLOGINFO("\tflush rate limit " << BEES_FLUSH_RATE);
|
||||
|
||||
// Try to mmap that much memory
|
||||
try_mmap_flags(MAP_PRIVATE | MAP_ANONYMOUS);
|
||||
@ -696,7 +696,7 @@ BeesHashTable::BeesHashTable(shared_ptr<BeesContext> ctx, string filename, off_t
|
||||
for (auto fp = madv_flags; fp->value; ++fp) {
|
||||
BEESTOOLONG("madvise(" << fp->name << ")");
|
||||
if (madvise(m_byte_ptr, m_size, fp->value)) {
|
||||
BEESLOG("madvise(..., " << fp->name << "): " << strerror(errno) << " (ignored)");
|
||||
BEESLOGWARN("madvise(..., " << fp->name << "): " << strerror(errno) << " (ignored)");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@ -172,7 +172,7 @@ BeesResolver::adjust_offset(const BeesFileRange &haystack, const BeesBlockData &
|
||||
|
||||
// Found the hash but not the data. Yay!
|
||||
m_found_hash = true;
|
||||
BEESLOG("HASH COLLISION\n"
|
||||
BEESLOGINFO("HASH COLLISION\n"
|
||||
<< "\tneedle " << needle << "\n"
|
||||
<< "\tstraw " << straw);
|
||||
BEESCOUNT(hash_collision);
|
||||
|
||||
@ -67,7 +67,7 @@ BeesRoots::set_scan_mode(ScanMode mode)
|
||||
{
|
||||
THROW_CHECK1(invalid_argument, mode, mode < SCAN_MODE_COUNT);
|
||||
s_scan_mode = mode;
|
||||
BEESLOG("Scan mode set to " << mode << " (" << scan_mode_ntoa(mode) << ")");
|
||||
BEESLOGINFO("Scan mode set to " << mode << " (" << scan_mode_ntoa(mode) << ")");
|
||||
}
|
||||
|
||||
string
|
||||
@ -96,7 +96,7 @@ BeesRoots::state_save()
|
||||
insert_new_crawl();
|
||||
|
||||
BEESNOTE("saving crawl state");
|
||||
BEESLOG("Saving crawl state");
|
||||
BEESLOGINFO("Saving crawl state");
|
||||
BEESTOOLONG("Saving crawl state");
|
||||
|
||||
Timer save_time;
|
||||
@ -107,7 +107,7 @@ BeesRoots::state_save()
|
||||
ostringstream ofs;
|
||||
|
||||
if (!m_crawl_dirty) {
|
||||
BEESLOG("Nothing to save");
|
||||
BEESLOGINFO("Nothing to save");
|
||||
return;
|
||||
}
|
||||
|
||||
@ -125,7 +125,7 @@ BeesRoots::state_save()
|
||||
}
|
||||
|
||||
if (ofs.str().empty()) {
|
||||
BEESLOG("Crawl state empty!");
|
||||
BEESLOGWARN("Crawl state empty!");
|
||||
m_crawl_dirty = false;
|
||||
return;
|
||||
}
|
||||
@ -144,7 +144,7 @@ BeesRoots::state_save()
|
||||
lock.lock();
|
||||
// Not really correct but probably close enough
|
||||
m_crawl_dirty = false;
|
||||
BEESLOG("Saved crawl state in " << save_time << "s");
|
||||
BEESLOGINFO("Saved crawl state in " << save_time << "s");
|
||||
}
|
||||
|
||||
BeesCrawlState
|
||||
@ -227,7 +227,7 @@ BeesRoots::crawl_roots()
|
||||
|
||||
// Nothing to crawl? Seems suspicious...
|
||||
if (m_root_crawl_map.empty()) {
|
||||
BEESLOG("idle: crawl map is empty!");
|
||||
BEESLOGINFO("idle: crawl map is empty!");
|
||||
}
|
||||
|
||||
auto ctx_copy = m_ctx;
|
||||
@ -302,7 +302,7 @@ BeesRoots::crawl_roots()
|
||||
case SCAN_MODE_COUNT: assert(false); break;
|
||||
}
|
||||
|
||||
BEESLOG("Crawl ran out of data after " << m_crawl_timer.lap() << "s, waiting for more...");
|
||||
BEESLOGINFO("Crawl ran out of data after " << m_crawl_timer.lap() << "s, waiting for more...");
|
||||
BEESCOUNT(crawl_done);
|
||||
BEESNOTE("idle, waiting for more data");
|
||||
lock.lock();
|
||||
@ -400,12 +400,12 @@ void
|
||||
BeesRoots::state_load()
|
||||
{
|
||||
BEESNOTE("loading crawl state");
|
||||
BEESLOG("loading crawl state");
|
||||
BEESLOGINFO("loading crawl state");
|
||||
|
||||
string crawl_data = m_crawl_state_file.read();
|
||||
|
||||
for (auto line : split("\n", crawl_data)) {
|
||||
BEESLOG("Read line: " << line);
|
||||
BEESLOGDEBUG("Read line: " << line);
|
||||
map<string, uint64_t> d;
|
||||
auto words = split(" ", line);
|
||||
for (auto it = words.begin(); it < words.end(); ++it) {
|
||||
@ -427,7 +427,7 @@ BeesRoots::state_load()
|
||||
if (d.count("started")) {
|
||||
loaded_state.m_started = d.at("started");
|
||||
}
|
||||
BEESLOG("loaded_state " << loaded_state);
|
||||
BEESLOGDEBUG("loaded_state " << loaded_state);
|
||||
insert_root(loaded_state);
|
||||
}
|
||||
}
|
||||
@ -605,7 +605,7 @@ BeesRoots::open_root_ino_nocache(uint64_t root, uint64_t ino)
|
||||
BEESTRACE("searching paths for root " << root << " ino " << ino);
|
||||
Fd rv;
|
||||
if (ipa.m_paths.empty()) {
|
||||
BEESLOG("No paths for root " << root << " ino " << ino);
|
||||
BEESLOGWARN("No paths for root " << root << " ino " << ino);
|
||||
}
|
||||
for (auto file_path : ipa.m_paths) {
|
||||
BEESTRACE("Looking up root " << root << " ino " << ino << " in dir " << name_fd(root_fd) << " path " << file_path);
|
||||
@ -617,7 +617,7 @@ BeesRoots::open_root_ino_nocache(uint64_t root, uint64_t ino)
|
||||
BEESCOUNT(open_fail);
|
||||
// errno == ENOENT is common during snapshot delete, ignore it
|
||||
if (errno != ENOENT) {
|
||||
BEESLOG("Could not open path '" << file_path << "' at root " << root << " " << name_fd(root_fd) << ": " << strerror(errno));
|
||||
BEESLOGWARN("Could not open path '" << file_path << "' at root " << root << " " << name_fd(root_fd) << ": " << strerror(errno));
|
||||
BEESNOTE("ipa" << ipa);
|
||||
}
|
||||
continue;
|
||||
@ -626,7 +626,7 @@ BeesRoots::open_root_ino_nocache(uint64_t root, uint64_t ino)
|
||||
// Correct inode?
|
||||
Stat file_stat(rv);
|
||||
if (file_stat.st_ino != ino) {
|
||||
BEESLOG("Opening " << name_fd(root_fd) << "/" << file_path << " found wrong inode " << file_stat.st_ino << " instead of " << ino);
|
||||
BEESLOGWARN("Opening " << name_fd(root_fd) << "/" << file_path << " found wrong inode " << file_stat.st_ino << " instead of " << ino);
|
||||
rv = Fd();
|
||||
BEESCOUNT(open_wrong_ino);
|
||||
break;
|
||||
@ -635,7 +635,7 @@ BeesRoots::open_root_ino_nocache(uint64_t root, uint64_t ino)
|
||||
// Correct root?
|
||||
auto file_root = btrfs_get_root_id(rv);
|
||||
if (file_root != root) {
|
||||
BEESLOG("Opening " << name_fd(root_fd) << "/" << file_path << " found wrong root " << file_root << " instead of " << root);
|
||||
BEESLOGWARN("Opening " << name_fd(root_fd) << "/" << file_path << " found wrong root " << file_root << " instead of " << root);
|
||||
rv = Fd();
|
||||
BEESCOUNT(open_wrong_root);
|
||||
break;
|
||||
@ -644,7 +644,7 @@ BeesRoots::open_root_ino_nocache(uint64_t root, uint64_t ino)
|
||||
// Same filesystem?
|
||||
Stat root_stat(root_fd);
|
||||
if (root_stat.st_dev != file_stat.st_dev) {
|
||||
BEESLOG("Opening root " << name_fd(root_fd) << " path " << file_path << " found path st_dev " << file_stat.st_dev << " but root st_dev is " << root_stat.st_dev);
|
||||
BEESLOGWARN("Opening root " << name_fd(root_fd) << " path " << file_path << " found path st_dev " << file_stat.st_dev << " but root st_dev is " << root_stat.st_dev);
|
||||
rv = Fd();
|
||||
BEESCOUNT(open_wrong_dev);
|
||||
break;
|
||||
@ -665,7 +665,7 @@ BeesRoots::open_root_ino_nocache(uint64_t root, uint64_t ino)
|
||||
// create temporary files with the right flags somehow.
|
||||
int attr = ioctl_iflags_get(rv);
|
||||
if (attr & FS_NOCOW_FL) {
|
||||
BEESLOG("Opening " << name_fd(rv) << " found FS_NOCOW_FL flag in " << to_hex(attr));
|
||||
BEESLOGWARN("Opening " << name_fd(rv) << " found FS_NOCOW_FL flag in " << to_hex(attr));
|
||||
rv = Fd();
|
||||
BEESCOUNT(open_wrong_flags);
|
||||
break;
|
||||
@ -702,7 +702,7 @@ BeesCrawl::next_transid()
|
||||
auto elapsed_time = current_time - crawl_state.m_started;
|
||||
if (elapsed_time < BEES_COMMIT_INTERVAL) {
|
||||
if (!m_deferred) {
|
||||
BEESLOG("Deferring next transid in " << get_state());
|
||||
BEESLOGINFO("Deferring next transid in " << get_state());
|
||||
}
|
||||
m_deferred = true;
|
||||
BEESCOUNT(crawl_defer);
|
||||
@ -710,7 +710,7 @@ BeesCrawl::next_transid()
|
||||
}
|
||||
|
||||
// Log performance stats from the old crawl
|
||||
BEESLOG("Next transid in " << get_state());
|
||||
BEESLOGINFO("Next transid in " << get_state());
|
||||
|
||||
// Start new crawl
|
||||
m_deferred = false;
|
||||
@ -720,7 +720,7 @@ BeesCrawl::next_transid()
|
||||
crawl_state.m_objectid = 0;
|
||||
crawl_state.m_offset = 0;
|
||||
crawl_state.m_started = current_time;
|
||||
BEESLOG("Restarting crawl " << get_state());
|
||||
BEESLOGINFO("Restarting crawl " << get_state());
|
||||
BEESCOUNT(crawl_restart);
|
||||
set_state(crawl_state);
|
||||
return true;
|
||||
@ -738,7 +738,7 @@ BeesCrawl::fetch_extents()
|
||||
}
|
||||
|
||||
BEESNOTE("crawling " << get_state());
|
||||
BEESLOG("Crawling " << get_state());
|
||||
BEESLOGINFO("Crawling " << get_state());
|
||||
|
||||
Timer crawl_timer;
|
||||
|
||||
@ -767,17 +767,17 @@ BeesCrawl::fetch_extents()
|
||||
if (ioctl_ok) {
|
||||
BEESCOUNT(crawl_search);
|
||||
} else {
|
||||
BEESLOG("Search ioctl failed: " << strerror(errno));
|
||||
BEESLOGWARN("Search ioctl failed: " << strerror(errno));
|
||||
BEESCOUNT(crawl_fail);
|
||||
}
|
||||
|
||||
if (!ioctl_ok || sk.m_result.empty()) {
|
||||
BEESCOUNT(crawl_empty);
|
||||
BEESLOG("Crawl empty " << get_state());
|
||||
BEESLOGINFO("Crawl empty " << get_state());
|
||||
return next_transid();
|
||||
}
|
||||
|
||||
BEESLOG("Crawling " << sk.m_result.size() << " results from " << get_state());
|
||||
BEESLOGINFO("Crawling " << sk.m_result.size() << " results from " << get_state());
|
||||
auto results_left = sk.m_result.size();
|
||||
BEESNOTE("crawling " << results_left << " results from " << get_state());
|
||||
size_t count_other = 0;
|
||||
@ -873,7 +873,7 @@ BeesCrawl::fetch_extents()
|
||||
}
|
||||
}
|
||||
}
|
||||
BEESLOG("Crawled inline " << count_inline << " data " << count_data << " other " << count_other << " unknown " << count_unknown << " gen_low " << count_low << " gen_high " << count_high << " " << get_state() << " in " << crawl_timer << "s");
|
||||
BEESLOGINFO("Crawled inline " << count_inline << " data " << count_data << " other " << count_other << " unknown " << count_unknown << " gen_low " << count_low << " gen_high " << count_high << " " << get_state() << " in " << crawl_timer << "s");
|
||||
|
||||
return true;
|
||||
}
|
||||
|
||||
@ -13,9 +13,9 @@ void
|
||||
BeesThread::exec(function<void()> func)
|
||||
{
|
||||
m_timer.reset();
|
||||
BEESLOG("BeesThread exec " << m_name);
|
||||
BEESLOGDEBUG("BeesThread exec " << m_name);
|
||||
m_thread_ptr = make_shared<thread>([=]() {
|
||||
BEESLOG("Starting thread " << m_name);
|
||||
BEESLOGDEBUG("Starting thread " << m_name);
|
||||
BeesNote::set_name(m_name);
|
||||
BEESNOTE("thread function");
|
||||
Timer thread_time;
|
||||
@ -25,7 +25,7 @@ BeesThread::exec(function<void()> func)
|
||||
catch_all([&]() {
|
||||
func();
|
||||
});
|
||||
BEESLOG("Exiting thread " << m_name << ", " << thread_time << " sec");
|
||||
BEESLOGDEBUG("Exiting thread " << m_name << ", " << thread_time << " sec");
|
||||
});
|
||||
}
|
||||
|
||||
@ -33,7 +33,7 @@ BeesThread::BeesThread(string name, function<void()> func) :
|
||||
m_name(name)
|
||||
{
|
||||
THROW_CHECK1(invalid_argument, name, !name.empty());
|
||||
BEESLOG("BeesThread construct " << m_name);
|
||||
BEESLOGDEBUG("BeesThread construct " << m_name);
|
||||
exec(func);
|
||||
}
|
||||
|
||||
@ -41,20 +41,20 @@ void
|
||||
BeesThread::join()
|
||||
{
|
||||
if (!m_thread_ptr) {
|
||||
BEESLOG("Thread " << m_name << " no thread ptr");
|
||||
BEESLOGDEBUG("Thread " << m_name << " no thread ptr");
|
||||
return;
|
||||
}
|
||||
|
||||
BEESLOG("BeesThread::join " << m_name);
|
||||
BEESLOGDEBUG("BeesThread::join " << m_name);
|
||||
if (m_thread_ptr->joinable()) {
|
||||
BEESLOG("Joining thread " << m_name);
|
||||
BEESLOGDEBUG("Joining thread " << m_name);
|
||||
Timer thread_time;
|
||||
m_thread_ptr->join();
|
||||
BEESLOG("Waited for " << m_name << ", " << thread_time << " sec");
|
||||
BEESLOGDEBUG("Waited for " << m_name << ", " << thread_time << " sec");
|
||||
} else if (!m_name.empty()) {
|
||||
BEESLOG("BeesThread " << m_name << " not joinable");
|
||||
BEESLOGDEBUG("BeesThread " << m_name << " not joinable");
|
||||
} else {
|
||||
BEESLOG("BeesThread else " << m_name);
|
||||
BEESLOGDEBUG("BeesThread else " << m_name);
|
||||
}
|
||||
}
|
||||
|
||||
@ -67,25 +67,25 @@ BeesThread::set_name(const string &name)
|
||||
BeesThread::~BeesThread()
|
||||
{
|
||||
if (!m_thread_ptr) {
|
||||
BEESLOG("Thread " << m_name << " no thread ptr");
|
||||
BEESLOGDEBUG("Thread " << m_name << " no thread ptr");
|
||||
return;
|
||||
}
|
||||
|
||||
BEESLOG("BeesThread destructor " << m_name);
|
||||
BEESLOGDEBUG("BeesThread destructor " << m_name);
|
||||
if (m_thread_ptr->joinable()) {
|
||||
BEESLOG("Cancelling thread " << m_name);
|
||||
BEESLOGDEBUG("Cancelling thread " << m_name);
|
||||
int rv = pthread_cancel(m_thread_ptr->native_handle());
|
||||
if (rv) {
|
||||
BEESLOG("pthread_cancel returned " << strerror(-rv));
|
||||
BEESLOGDEBUG("pthread_cancel returned " << strerror(-rv));
|
||||
}
|
||||
BEESLOG("Waiting for thread " << m_name);
|
||||
BEESLOGDEBUG("Waiting for thread " << m_name);
|
||||
Timer thread_time;
|
||||
m_thread_ptr->join();
|
||||
BEESLOG("Waited for " << m_name << ", " << thread_time << " sec");
|
||||
BEESLOGDEBUG("Waited for " << m_name << ", " << thread_time << " sec");
|
||||
} else if (!m_name.empty()) {
|
||||
BEESLOG("Thread " << m_name << " not joinable");
|
||||
BEESLOGDEBUG("Thread " << m_name << " not joinable");
|
||||
} else {
|
||||
BEESLOG("Thread destroy else " << m_name);
|
||||
BEESLOGDEBUG("Thread destroy else " << m_name);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@ -428,7 +428,7 @@ BeesRangePair::grow(shared_ptr<BeesContext> ctx, bool constrained)
|
||||
if (!first_addr.is_magic()) {
|
||||
auto first_resolved = ctx->resolve_addr(first_addr);
|
||||
if (first_resolved.is_toxic()) {
|
||||
BEESLOG("WORKAROUND: not growing matching pair backward because src addr is toxic:\n" << *this);
|
||||
BEESLOGWARN("WORKAROUND: not growing matching pair backward because src addr is toxic:\n" << *this);
|
||||
BEESCOUNT(pairbackward_toxic_addr);
|
||||
break;
|
||||
}
|
||||
@ -484,7 +484,7 @@ BeesRangePair::grow(shared_ptr<BeesContext> ctx, bool constrained)
|
||||
}
|
||||
}
|
||||
if (found_toxic) {
|
||||
BEESLOG("WORKAROUND: found toxic hash in " << first_bbd << " while extending backward:\n" << *this);
|
||||
BEESLOGWARN("WORKAROUND: found toxic hash in " << first_bbd << " while extending backward:\n" << *this);
|
||||
BEESCOUNT(pairbackward_toxic_hash);
|
||||
break;
|
||||
}
|
||||
@ -529,7 +529,7 @@ BeesRangePair::grow(shared_ptr<BeesContext> ctx, bool constrained)
|
||||
if (!first_addr.is_magic()) {
|
||||
auto first_resolved = ctx->resolve_addr(first_addr);
|
||||
if (first_resolved.is_toxic()) {
|
||||
BEESLOG("WORKAROUND: not growing matching pair forward because src is toxic:\n" << *this);
|
||||
BEESLOGWARN("WORKAROUND: not growing matching pair forward because src is toxic:\n" << *this);
|
||||
BEESCOUNT(pairforward_toxic);
|
||||
break;
|
||||
}
|
||||
@ -593,7 +593,7 @@ BeesRangePair::grow(shared_ptr<BeesContext> ctx, bool constrained)
|
||||
}
|
||||
}
|
||||
if (found_toxic) {
|
||||
BEESLOG("WORKAROUND: found toxic hash in " << first_bbd << " while extending forward:\n" << *this);
|
||||
BEESLOGWARN("WORKAROUND: found toxic hash in " << first_bbd << " while extending forward:\n" << *this);
|
||||
BEESCOUNT(pairforward_toxic_hash);
|
||||
break;
|
||||
}
|
||||
|
||||
28
src/bees.cc
28
src/bees.cc
@ -71,12 +71,12 @@ BeesTracer::~BeesTracer()
|
||||
try {
|
||||
m_func();
|
||||
} catch (exception &e) {
|
||||
BEESLOG("Nested exception: " << e.what());
|
||||
BEESLOGERR("Nested exception: " << e.what());
|
||||
} catch (...) {
|
||||
BEESLOG("Nested exception ...");
|
||||
BEESLOGERR("Nested exception ...");
|
||||
}
|
||||
if (!m_next_tracer) {
|
||||
BEESLOG("--- END TRACE --- exception ---");
|
||||
BEESLOGERR("--- END TRACE --- exception ---");
|
||||
}
|
||||
}
|
||||
tl_next_tracer = m_next_tracer;
|
||||
@ -93,12 +93,12 @@ void
|
||||
BeesTracer::trace_now()
|
||||
{
|
||||
BeesTracer *tp = tl_next_tracer;
|
||||
BEESLOG("--- BEGIN TRACE ---");
|
||||
BEESLOGERR("--- BEGIN TRACE ---");
|
||||
while (tp) {
|
||||
tp->m_func();
|
||||
tp = tp->m_next_tracer;
|
||||
}
|
||||
BEESLOG("--- END TRACE ---");
|
||||
BEESLOGERR("--- END TRACE ---");
|
||||
}
|
||||
|
||||
thread_local BeesNote *BeesNote::tl_next = nullptr;
|
||||
@ -336,7 +336,7 @@ BeesTooLong::check() const
|
||||
if (age() > m_limit) {
|
||||
ostringstream oss;
|
||||
m_func(oss);
|
||||
BEESLOG("PERFORMANCE: " << *this << " sec: " << oss.str());
|
||||
BEESLOGWARN("PERFORMANCE: " << *this << " sec: " << oss.str());
|
||||
}
|
||||
}
|
||||
|
||||
@ -368,7 +368,7 @@ BeesStringFile::BeesStringFile(Fd dir_fd, string name, size_t limit) :
|
||||
m_name(name),
|
||||
m_limit(limit)
|
||||
{
|
||||
BEESLOG("BeesStringFile " << name_fd(m_dir_fd) << "/" << m_name << " max size " << pretty(m_limit));
|
||||
BEESLOGINFO("BeesStringFile " << name_fd(m_dir_fd) << "/" << m_name << " max size " << pretty(m_limit));
|
||||
}
|
||||
|
||||
void
|
||||
@ -501,7 +501,7 @@ void
|
||||
BeesTempFile::realign()
|
||||
{
|
||||
if (m_end_offset > BLOCK_SIZE_MAX_TEMP_FILE) {
|
||||
BEESLOG("temporary file size " << to_hex(m_end_offset) << " > max " << BLOCK_SIZE_MAX_TEMP_FILE);
|
||||
BEESLOGINFO("temporary file size " << to_hex(m_end_offset) << " > max " << BLOCK_SIZE_MAX_TEMP_FILE);
|
||||
BEESCOUNT(tmp_trunc);
|
||||
return create();
|
||||
}
|
||||
@ -535,7 +535,7 @@ BeesTempFile::make_hole(off_t count)
|
||||
BeesFileRange
|
||||
BeesTempFile::make_copy(const BeesFileRange &src)
|
||||
{
|
||||
BEESLOG("copy: " << src);
|
||||
BEESLOGINFO("copy: " << src);
|
||||
BEESNOTE("Copying " << src);
|
||||
BEESTRACE("Copying " << src);
|
||||
|
||||
@ -601,7 +601,7 @@ int
|
||||
bees_main(int argc, char *argv[])
|
||||
{
|
||||
set_catch_explainer([&](string s) {
|
||||
BEESLOG("\n\n*** EXCEPTION ***\n\t" << s << "\n***\n");
|
||||
BEESLOGERR("\n\n*** EXCEPTION ***\n\t" << s << "\n***\n");
|
||||
BEESCOUNT(exception_caught);
|
||||
});
|
||||
|
||||
@ -672,10 +672,10 @@ bees_main(int argc, char *argv[])
|
||||
Chatter::enable_timestamp(chatter_prefix_timestamp);
|
||||
|
||||
if (!relative_path().empty()) {
|
||||
BEESLOG("using relative path " << relative_path() << "\n");
|
||||
BEESLOGINFO("using relative path " << relative_path() << "\n");
|
||||
}
|
||||
|
||||
BEESLOG("setting rlimit NOFILE to " << BEES_OPEN_FILE_LIMIT);
|
||||
BEESLOGINFO("setting rlimit NOFILE to " << BEES_OPEN_FILE_LIMIT);
|
||||
|
||||
struct rlimit lim = {
|
||||
.rlim_cur = BEES_OPEN_FILE_LIMIT,
|
||||
@ -683,7 +683,7 @@ bees_main(int argc, char *argv[])
|
||||
};
|
||||
int rv = setrlimit(RLIMIT_NOFILE, &lim);
|
||||
if (rv) {
|
||||
BEESLOG("setrlimit(RLIMIT_NOFILE, { " << lim.rlim_cur << " }): " << strerror(errno));
|
||||
BEESLOGINFO("setrlimit(RLIMIT_NOFILE, { " << lim.rlim_cur << " }): " << strerror(errno));
|
||||
};
|
||||
|
||||
// Set up worker thread pool
|
||||
@ -708,7 +708,7 @@ bees_main(int argc, char *argv[])
|
||||
}
|
||||
|
||||
if (!did_subscription) {
|
||||
BEESLOG("WARNING: no filesystems added");
|
||||
BEESLOGWARN("WARNING: no filesystems added");
|
||||
}
|
||||
|
||||
BeesThread status_thread("status", [&]() {
|
||||
|
||||
19
src/bees.h
19
src/bees.h
@ -17,6 +17,7 @@
|
||||
#include <string>
|
||||
#include <thread>
|
||||
|
||||
#include <syslog.h>
|
||||
#include <endian.h>
|
||||
|
||||
using namespace crucible;
|
||||
@ -127,21 +128,25 @@ const int FLAGS_OPEN_FANOTIFY = O_RDWR | O_NOATIME | O_CLOEXEC | O_LARGEFILE;
|
||||
|
||||
// macros ----------------------------------------
|
||||
|
||||
#define BEESLOG(x) do { Chatter c(BeesNote::get_name()); c << x; } while (0)
|
||||
#define BEESLOGTRACE(x) do { BEESLOG(x); BeesTracer::trace_now(); } while (0)
|
||||
#define BEESLOG(lv,x) do { Chatter c(lv, BeesNote::get_name()); c << x; } while (0)
|
||||
#define BEESLOGTRACE(x) do { BEESLOG(LOG_DEBUG, x); BeesTracer::trace_now(); } while (0)
|
||||
|
||||
#define BEESTRACE(x) BeesTracer SRSLY_WTF_C(beesTracer_, __LINE__) ([&]() { BEESLOG(x); })
|
||||
#define BEESTRACE(x) BeesTracer SRSLY_WTF_C(beesTracer_, __LINE__) ([&]() { BEESLOG(LOG_ERR, x); })
|
||||
#define BEESTOOLONG(x) BeesTooLong SRSLY_WTF_C(beesTooLong_, __LINE__) ([&](ostream &_btl_os) { _btl_os << x; })
|
||||
#define BEESNOTE(x) BeesNote SRSLY_WTF_C(beesNote_, __LINE__) ([&](ostream &_btl_os) { _btl_os << x; })
|
||||
#define BEESINFO(x) do { \
|
||||
if (bees_info_rate_limit.is_ready()) { \
|
||||
bees_info_rate_limit.borrow(1); \
|
||||
Chatter c(BeesNote::get_name()); \
|
||||
Chatter c(LOG_INFO, BeesNote::get_name()); \
|
||||
c << x; \
|
||||
} \
|
||||
} while (0)
|
||||
|
||||
#define BEESLOGNOTE(x) BEESLOG(x); BEESNOTE(x)
|
||||
#define BEESLOGERR(x) BEESLOG(LOG_ERR, x)
|
||||
#define BEESLOGWARN(x) BEESLOG(LOG_WARNING, x)
|
||||
#define BEESLOGNOTE(x) BEESLOG(LOG_NOTICE, x); BEESNOTE(x)
|
||||
#define BEESLOGINFO(x) BEESLOG(LOG_INFO, x)
|
||||
#define BEESLOGDEBUG(x) BEESLOG(LOG_DEBUG, x)
|
||||
|
||||
#define BEESCOUNT(stat) do { \
|
||||
BeesStats::s_global.add_count(#stat); \
|
||||
@ -189,7 +194,7 @@ class BeesBlockData;
|
||||
class BeesTracer {
|
||||
function<void()> m_func;
|
||||
BeesTracer *m_next_tracer = 0;
|
||||
|
||||
|
||||
thread_local static BeesTracer *tl_next_tracer;
|
||||
public:
|
||||
BeesTracer(function<void()> f);
|
||||
@ -584,7 +589,7 @@ struct BeesHash {
|
||||
BeesHash& operator=(const Type that) { m_hash = that; return *this; }
|
||||
private:
|
||||
Type m_hash;
|
||||
|
||||
|
||||
};
|
||||
|
||||
ostream & operator<<(ostream &os, const BeesHash &bh);
|
||||
|
||||
@ -32,7 +32,7 @@ void
|
||||
test_chatter_three()
|
||||
{
|
||||
cerr << endl;
|
||||
Chatter c("tct");
|
||||
Chatter c(0, "tct");
|
||||
c << "More complicated";
|
||||
c << "\ncase with\n";
|
||||
c << "some \\ns";
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user