diff --git a/include/crucible/chatter.h b/include/crucible/chatter.h index f00e1e4..44d314f 100644 --- a/include/crucible/chatter.h +++ b/include/crucible/chatter.h @@ -8,6 +8,8 @@ #include #include +#include + /** \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 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; } diff --git a/lib/chatter.cc b/lib/chatter.cc index 696c274..203e06b 100644 --- a/lib/chatter.cc +++ b/lib/chatter.cc @@ -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(""); } diff --git a/lib/extentwalker.cc b/lib/extentwalker.cc index 3f6001b..31ecf3f 100644 --- a/lib/extentwalker.cc +++ b/lib/extentwalker.cc @@ -6,7 +6,6 @@ #include "crucible/limits.h" #include "crucible/string.h" - namespace crucible { using namespace std; diff --git a/src/bees-context.cc b/src/bees-context.cc index 4c1c324..9f09307 100644 --- a/src/bees-context.cc +++ b/src/bees-context.cc @@ -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 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)); } diff --git a/src/bees-hash.cc b/src/bees-hash.cc index cb5b4f1..f77f7ad 100644 --- a/src/bees-hash.cc +++ b/src/bees-hash.cc @@ -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(ptr); void *ptr_end = static_cast(ptr) + m_size; m_cell_ptr_end = static_cast(ptr_end); @@ -662,13 +662,13 @@ BeesHashTable::BeesHashTable(shared_ptr 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 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)"); } } diff --git a/src/bees-resolve.cc b/src/bees-resolve.cc index d7b258e..bb7cd75 100644 --- a/src/bees-resolve.cc +++ b/src/bees-resolve.cc @@ -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); diff --git a/src/bees-roots.cc b/src/bees-roots.cc index 40f90eb..6e07ea8 100644 --- a/src/bees-roots.cc +++ b/src/bees-roots.cc @@ -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 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; } diff --git a/src/bees-thread.cc b/src/bees-thread.cc index a702231..de7e4cd 100644 --- a/src/bees-thread.cc +++ b/src/bees-thread.cc @@ -13,9 +13,9 @@ void BeesThread::exec(function func) { m_timer.reset(); - BEESLOG("BeesThread exec " << m_name); + BEESLOGDEBUG("BeesThread exec " << m_name); m_thread_ptr = make_shared([=]() { - 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 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 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); } } diff --git a/src/bees-types.cc b/src/bees-types.cc index df2d2b4..2eaa1b5 100644 --- a/src/bees-types.cc +++ b/src/bees-types.cc @@ -428,7 +428,7 @@ BeesRangePair::grow(shared_ptr 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 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 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 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; } diff --git a/src/bees.cc b/src/bees.cc index 89085a5..d66ddaa 100644 --- a/src/bees.cc +++ b/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", [&]() { diff --git a/src/bees.h b/src/bees.h index 109872d..b8ad80f 100644 --- a/src/bees.h +++ b/src/bees.h @@ -17,6 +17,7 @@ #include #include +#include #include 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 m_func; BeesTracer *m_next_tracer = 0; - + thread_local static BeesTracer *tl_next_tracer; public: BeesTracer(function 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); diff --git a/test/chatter.cc b/test/chatter.cc index f838b5e..644f7bc 100644 --- a/test/chatter.cc +++ b/test/chatter.cc @@ -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";