diff --git a/include/tscore/Trie.h b/include/tscore/Trie.h index d043eab6d71..bb37ac4053a 100644 --- a/include/tscore/Trie.h +++ b/include/tscore/Trie.h @@ -30,9 +30,16 @@ #include "tscore/List.h" #include "tscore/Diags.h" +class TrieImpl +{ +protected: + inline static DbgCtl dbg_ctl_insert{"Trie::Insert"}; + inline static DbgCtl dbg_ctl_search{"Trie::Search"}; +}; + // Note that you should provide the class to use here, but we'll store // pointers to such objects internally. -template class Trie +template class Trie : private TrieImpl { public: Trie() { m_root.Clear(); } @@ -84,7 +91,7 @@ template class Trie ink_zero(children); } - void Print(const char *debug_tag) const; + void Print(const DbgCtl &dbg_ctl) const; inline Node * GetChild(char index) const { @@ -142,9 +149,9 @@ Trie::Insert(const char *key, T *value, int rank, int key_len /* = -1 */) int i = 0; while (true) { - if (is_debug_tag_set("Trie::Insert")) { - Debug("Trie::Insert", "Visiting Node..."); - curr_node->Print("Trie::Insert"); + if (is_dbg_ctl_enabled(dbg_ctl_insert)) { + Dbg(dbg_ctl_insert, "Visiting Node..."); + curr_node->Print(dbg_ctl_insert); } if (i == key_len) { @@ -154,7 +161,7 @@ Trie::Insert(const char *key, T *value, int rank, int key_len /* = -1 */) next_node = curr_node->GetChild(key[i]); if (!next_node) { while (i < key_len) { - Debug("Trie::Insert", "Creating child node for char %c (%d)", key[i], key[i]); + Dbg(dbg_ctl_insert, "Creating child node for char %c (%d)", key[i], key[i]); curr_node = curr_node->AllocateChild(key[i]); ++i; } @@ -165,7 +172,7 @@ Trie::Insert(const char *key, T *value, int rank, int key_len /* = -1 */) } if (curr_node->occupied) { - Debug("Trie::Insert", "Cannot insert duplicate!"); + Dbg(dbg_ctl_insert, "Cannot insert duplicate!"); return false; } @@ -173,7 +180,7 @@ Trie::Insert(const char *key, T *value, int rank, int key_len /* = -1 */) curr_node->value = value; curr_node->rank = rank; m_value_list.enqueue(curr_node->value); - Debug("Trie::Insert", "inserted new element!"); + Dbg(dbg_ctl_insert, "inserted new element!"); return true; } @@ -188,9 +195,9 @@ Trie::Search(const char *key, int key_len /* = -1 */) const int i = 0; while (curr_node) { - if (is_debug_tag_set("Trie::Search")) { - Debug("Trie::Search", "Visiting node..."); - curr_node->Print("Trie::Search"); + if (is_dbg_ctl_enabled(dbg_ctl_search)) { + DbgPrint(dbg_ctl_search, "Visiting node..."); + curr_node->Print(dbg_ctl_search); } if (curr_node->occupied) { if (!found_node || curr_node->rank <= found_node->rank) { @@ -205,7 +212,7 @@ Trie::Search(const char *key, int key_len /* = -1 */) const } if (found_node) { - Debug("Trie::Search", "Returning element with rank %d", found_node->rank); + Dbg(dbg_ctl_search, "Returning element with rank %d", found_node->rank); return found_node->value; } @@ -250,18 +257,18 @@ Trie::Print() const template void -Trie::Node::Print(const char *debug_tag) const +Trie::Node::Print(const DbgCtl &dbg_ctl) const { if (occupied) { - Debug(debug_tag, "Node is occupied"); - Debug(debug_tag, "Node has rank %d", rank); + Dbg(dbg_ctl, "Node is occupied"); + Dbg(dbg_ctl, "Node has rank %d", rank); } else { - Debug(debug_tag, "Node is not occupied"); + Dbg(dbg_ctl, "Node is not occupied"); } for (int i = 0; i < N_NODE_CHILDREN; ++i) { if (GetChild(i)) { - Debug(debug_tag, "Node has child for char %c", static_cast(i)); + Dbg(dbg_ctl, "Node has child for char %c", static_cast(i)); } } } diff --git a/iocore/aio/AIO.cc b/iocore/aio/AIO.cc index 415cdd37b84..95e0209b890 100644 --- a/iocore/aio/AIO.cc +++ b/iocore/aio/AIO.cc @@ -639,7 +639,7 @@ DiskHandler::mainAIOEvent(int event, Event *e) if (errno == EINTR) goto Lagain; if (errno == EFAULT || errno == ENOSYS) - Debug("aio", "io_getevents failed: %s (%d)", strerror(-ret), -ret); + Dbg(_dbg_ctl_aio, "io_getevents failed: %s (%d)", strerror(-ret), -ret); } ink_aiocb *cbs[MAX_AIO_EVENTS]; @@ -658,7 +658,7 @@ DiskHandler::mainAIOEvent(int event, Event *e) if (ret != num) { if (ret < 0) { - Debug("aio", "io_submit failed: %s (%d)", strerror(-ret), -ret); + Dbg(_dbg_ctl_aio, "io_submit failed: %s (%d)", strerror(-ret), -ret); } else { Fatal("could not submit IOs, io_submit(%p, %d, %p) returned %d", ctx, num, cbs, ret); } diff --git a/iocore/aio/I_AIO.h b/iocore/aio/I_AIO.h index b6ecc82133f..d978f8d0eec 100644 --- a/iocore/aio/I_AIO.h +++ b/iocore/aio/I_AIO.h @@ -150,9 +150,12 @@ struct DiskHandler : public Continuation { memset(&ctx, 0, sizeof(ctx)); int ret = io_setup(MAX_AIO_EVENTS, &ctx); if (ret < 0) { - Debug("aio", "io_setup error: %s (%d)", strerror(-ret), -ret); + Dbg(_dbg_ctl_aio, "io_setup error: %s (%d)", strerror(-ret), -ret); } } + +private: + inline static DbgCtl _dbg_ctl_aio{"aio"}; }; #endif diff --git a/iocore/cache/Cache.cc b/iocore/cache/Cache.cc index 5bb6b9a5758..e9cc244b2a9 100644 --- a/iocore/cache/Cache.cc +++ b/iocore/cache/Cache.cc @@ -112,6 +112,26 @@ ClassAllocator evacuationKeyAllocator("evacuationKey"); int CacheVC::size_to_init = -1; CacheKey zero_key; +namespace +{ + +DbgCtl dbg_ctl_cache_init{"cache_init"}; +DbgCtl dbg_ctl_cache_remove{"cache_remove"}; +DbgCtl dbg_ctl_cache_hosting{"cache_hosting"}; +DbgCtl dbg_ctl_cache_bc{"cache_bc"}; +DbgCtl dbg_ctl_cache_read{"cache_read"}; +DbgCtl dbg_ctl_cache_disk_error{"cache_disk_error"}; +DbgCtl dbg_ctl_ram_cache{"ram_cache"}; + +#ifdef DEBUG + +DbgCtl dbg_ctl_cache_close{"cache_close"}; +DbgCtl dbg_ctl_cache_reenable{"cache_reenable"}; + +#endif + +} // end anonymous namespace + struct VolInitInfo { off_t recover_pos; AIOCallbackInternal vol_aio[4]; @@ -357,7 +377,7 @@ CacheVC::do_io_close(int alerrno) ink_assert(mutex->thread_holding == this_ethread()); int previous_closed = closed; closed = (alerrno == -1) ? 1 : -1; // Stupid default arguments - DDebug("cache_close", "do_io_close %p %d %d", this, alerrno, closed); + DDbg(dbg_ctl_cache_close, "do_io_close %p %d %d", this, alerrno, closed); if (!previous_closed && !recursive) { die(); } @@ -366,7 +386,7 @@ CacheVC::do_io_close(int alerrno) void CacheVC::reenable(VIO *avio) { - DDebug("cache_reenable", "reenable %p", this); + DDbg(dbg_ctl_cache_reenable, "reenable %p", this); (void)avio; #ifdef DEBUG ink_assert(avio->mutex->thread_holding); @@ -386,7 +406,7 @@ CacheVC::reenable(VIO *avio) void CacheVC::reenable_re(VIO *avio) { - DDebug("cache_reenable", "reenable_re %p", this); + DDbg(dbg_ctl_cache_reenable, "reenable_re %p", this); (void)avio; #ifdef DEBUG ink_assert(avio->mutex->thread_holding); @@ -744,7 +764,7 @@ CacheProcessor::start_internal(int flags) gdisks[j]->open(paths[j], blocks, skip, sector_sizes[j], fds[j], clear); #endif - Debug("cache_hosting", "Disk: %d:%s, blocks: %" PRId64 "", gndisks, paths[j], blocks); + Dbg(dbg_ctl_cache_hosting, "Disk: %d:%s, blocks: %" PRId64 "", gndisks, paths[j], blocks); } return 0; @@ -828,16 +848,16 @@ CacheProcessor::diskInitialized() gnvol = 0; for (i = 0; i < gndisks; i++) { CacheDisk *d = gdisks[i]; - if (is_debug_tag_set("cache_hosting")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_hosting)) { int j; - Debug("cache_hosting", "Disk: %d:%s: Vol Blocks: %u: Free space: %" PRIu64, i, d->path, d->header->num_diskvol_blks, - d->free_space); + DbgPrint(dbg_ctl_cache_hosting, "Disk: %d:%s: Vol Blocks: %u: Free space: %" PRIu64, i, d->path, d->header->num_diskvol_blks, + d->free_space); for (j = 0; j < static_cast(d->header->num_volumes); j++) { - Debug("cache_hosting", "\tVol: %d Size: %" PRIu64, d->disk_vols[j]->vol_number, d->disk_vols[j]->size); + DbgPrint(dbg_ctl_cache_hosting, "\tVol: %d Size: %" PRIu64, d->disk_vols[j]->vol_number, d->disk_vols[j]->size); } for (j = 0; j < static_cast(d->header->num_diskvol_blks); j++) { - Debug("cache_hosting", "\tBlock No: %d Size: %" PRIu64 " Free: %u", d->header->vol_info[j].number, - d->header->vol_info[j].len, d->header->vol_info[j].free); + DbgPrint(dbg_ctl_cache_hosting, "\tBlock No: %d Size: %" PRIu64 " Free: %u", d->header->vol_info[j].number, + d->header->vol_info[j].len, d->header->vol_info[j].free); } } if (!check) { @@ -883,10 +903,10 @@ CacheProcessor::cacheInitialized() if (theCache) { total_size += theCache->cache_size; - Debug("cache_init", "CacheProcessor::cacheInitialized - theCache, total_size = %" PRId64 " = %" PRId64 " MB", total_size, - total_size / ((1024 * 1024) / STORE_BLOCK_SIZE)); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - theCache, total_size = %" PRId64 " = %" PRId64 " MB", total_size, + total_size / ((1024 * 1024) / STORE_BLOCK_SIZE)); if (theCache->ready == CACHE_INIT_FAILED) { - Debug("cache_init", "CacheProcessor::cacheInitialized - failed to initialize the cache for http: cache disabled"); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - failed to initialize the cache for http: cache disabled"); Warning("failed to initialize the cache for http: cache disabled\n"); } else { caches_ready = caches_ready | (1 << CACHE_FRAG_TYPE_HTTP); @@ -912,8 +932,8 @@ CacheProcessor::cacheInitialized() } if (caches_ready) { - Debug("cache_init", "CacheProcessor::cacheInitialized - caches_ready=0x%0X, gnvol=%d", (unsigned int)caches_ready, - gnvol.load()); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - caches_ready=0x%0X, gnvol=%d", (unsigned int)caches_ready, + gnvol.load()); int64_t ram_cache_bytes = 0; @@ -932,21 +952,21 @@ CacheProcessor::cacheInitialized() } // let us calculate the Size if (cache_config_ram_cache_size == AUTO_SIZE_RAM_CACHE) { - Debug("cache_init", "CacheProcessor::cacheInitialized - cache_config_ram_cache_size == AUTO_SIZE_RAM_CACHE"); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - cache_config_ram_cache_size == AUTO_SIZE_RAM_CACHE"); for (i = 0; i < gnvol; i++) { vol = gvol[i]; if (gvol[i]->cache_vol->ramcache_enabled) { gvol[i]->ram_cache->init(vol->dirlen() * DEFAULT_RAM_CACHE_MULTIPLIER, vol); ram_cache_bytes += gvol[i]->dirlen(); - Debug("cache_init", "CacheProcessor::cacheInitialized - ram_cache_bytes = %" PRId64 " = %" PRId64 "Mb", ram_cache_bytes, - ram_cache_bytes / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - ram_cache_bytes = %" PRId64 " = %" PRId64 "Mb", + ram_cache_bytes, ram_cache_bytes / (1024 * 1024)); CACHE_VOL_SUM_DYN_STAT(cache_ram_cache_bytes_total_stat, (int64_t)gvol[i]->dirlen()); } vol_total_cache_bytes = gvol[i]->len - gvol[i]->dirlen(); total_cache_bytes += vol_total_cache_bytes; - Debug("cache_init", "CacheProcessor::cacheInitialized - total_cache_bytes = %" PRId64 " = %" PRId64 "Mb", - total_cache_bytes, total_cache_bytes / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - total_cache_bytes = %" PRId64 " = %" PRId64 "Mb", + total_cache_bytes, total_cache_bytes / (1024 * 1024)); CACHE_VOL_SUM_DYN_STAT(cache_bytes_total_stat, vol_total_cache_bytes); @@ -963,20 +983,21 @@ CacheProcessor::cacheInitialized() // we got configured memory size // TODO, should we check the available system memories, or you will // OOM or swapout, that is not a good situation for the server - Debug("cache_init", "CacheProcessor::cacheInitialized - %" PRId64 " != AUTO_SIZE_RAM_CACHE", cache_config_ram_cache_size); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - %" PRId64 " != AUTO_SIZE_RAM_CACHE", + cache_config_ram_cache_size); int64_t http_ram_cache_size = (theCache) ? static_cast((static_cast(theCache->cache_size) / total_size) * cache_config_ram_cache_size) : 0; - Debug("cache_init", "CacheProcessor::cacheInitialized - http_ram_cache_size = %" PRId64 " = %" PRId64 "Mb", - http_ram_cache_size, http_ram_cache_size / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - http_ram_cache_size = %" PRId64 " = %" PRId64 "Mb", + http_ram_cache_size, http_ram_cache_size / (1024 * 1024)); int64_t stream_ram_cache_size = cache_config_ram_cache_size - http_ram_cache_size; - Debug("cache_init", "CacheProcessor::cacheInitialized - stream_ram_cache_size = %" PRId64 " = %" PRId64 "Mb", - stream_ram_cache_size, stream_ram_cache_size / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - stream_ram_cache_size = %" PRId64 " = %" PRId64 "Mb", + stream_ram_cache_size, stream_ram_cache_size / (1024 * 1024)); // Dump some ram_cache size information in debug mode. - Debug("ram_cache", "config: size = %" PRId64 ", cutoff = %" PRId64 "", cache_config_ram_cache_size, - cache_config_ram_cache_cutoff); + Dbg(dbg_ctl_ram_cache, "config: size = %" PRId64 ", cutoff = %" PRId64 "", cache_config_ram_cache_size, + cache_config_ram_cache_cutoff); for (i = 0; i < gnvol; i++) { vol = gvol[i]; @@ -984,21 +1005,21 @@ CacheProcessor::cacheInitialized() if (gvol[i]->cache == theCache && gvol[i]->cache_vol->ramcache_enabled) { ink_assert(gvol[i]->cache != nullptr); factor = static_cast(static_cast(gvol[i]->len >> STORE_BLOCK_SHIFT)) / theCache->cache_size; - Debug("cache_init", "CacheProcessor::cacheInitialized - factor = %f", factor); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - factor = %f", factor); gvol[i]->ram_cache->init(static_cast(http_ram_cache_size * factor), vol); ram_cache_bytes += static_cast(http_ram_cache_size * factor); CACHE_VOL_SUM_DYN_STAT(cache_ram_cache_bytes_total_stat, (int64_t)(http_ram_cache_size * factor)); } else if (gvol[i]->cache_vol->ramcache_enabled) { ink_release_assert(!"Unexpected non-HTTP cache volume"); } - Debug("cache_init", "CacheProcessor::cacheInitialized[%d] - ram_cache_bytes = %" PRId64 " = %" PRId64 "Mb", i, - ram_cache_bytes, ram_cache_bytes / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized[%d] - ram_cache_bytes = %" PRId64 " = %" PRId64 "Mb", i, + ram_cache_bytes, ram_cache_bytes / (1024 * 1024)); vol_total_cache_bytes = gvol[i]->len - gvol[i]->dirlen(); total_cache_bytes += vol_total_cache_bytes; CACHE_VOL_SUM_DYN_STAT(cache_bytes_total_stat, vol_total_cache_bytes); CACHE_VOL_SUM_DYN_STAT(cache_stripes_stat, 1); // Count the cache stripes - Debug("cache_init", "CacheProcessor::cacheInitialized - total_cache_bytes = %" PRId64 " = %" PRId64 "Mb", - total_cache_bytes, total_cache_bytes / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "CacheProcessor::cacheInitialized - total_cache_bytes = %" PRId64 " = %" PRId64 "Mb", + total_cache_bytes, total_cache_bytes / (1024 * 1024)); vol_total_direntries = gvol[i]->buckets * gvol[i]->segments * DIR_DEPTH; total_direntries += vol_total_direntries; @@ -1096,7 +1117,7 @@ CacheProcessor::open_write(Continuation *cont, CacheKey *key, CacheFragType frag Action * CacheProcessor::remove(Continuation *cont, const CacheKey *key, CacheFragType frag_type, const char *hostname, int host_len) { - Debug("cache_remove", "[CacheProcessor::remove] Issuing cache delete for %u", cache_hash(*key)); + Dbg(dbg_ctl_cache_remove, "[CacheProcessor::remove] Issuing cache delete for %u", cache_hash(*key)); return caches[frag_type]->remove(cont, key, frag_type, hostname, host_len); } @@ -1250,8 +1271,8 @@ Vol::init(char *s, off_t blocks, off_t dir_skip, bool clear) evacuate = static_cast *>(ats_malloc(evac_len)); memset(static_cast(evacuate), 0, evac_len); - Debug("cache_init", "Vol %s: allocating %zu directory bytes for a %lld byte volume (%lf%%)", hash_text.get(), dirlen(), - (long long)this->len, (double)dirlen() / (double)this->len * 100.0); + Dbg(dbg_ctl_cache_init, "Vol %s: allocating %zu directory bytes for a %lld byte volume (%lf%%)", hash_text.get(), dirlen(), + (long long)this->len, (double)dirlen() / (double)this->len * 100.0); raw_dir = nullptr; if (ats_hugepage_enabled()) { @@ -1276,7 +1297,7 @@ Vol::init(char *s, off_t blocks, off_t dir_skip, bool clear) // try A off_t as = skip; - Debug("cache_init", "reading directory '%s'", hash_text.get()); + Dbg(dbg_ctl_cache_init, "reading directory '%s'", hash_text.get()); SET_HANDLER(&Vol::handle_header_read); init_info->vol_aio[0].aiocb.aio_offset = as; init_info->vol_aio[1].aiocb.aio_offset = as + footer_offset; @@ -1594,7 +1615,7 @@ Ldone : { /* if we come back to the starting position, then we don't have to recover anything */ if (recover_pos == header->write_pos && recover_wrapped) { SET_HANDLER(&Vol::handle_recover_write_dir); - if (is_debug_tag_set("cache_init")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_init)) { Note("recovery wrapped around. nothing to clear\n"); } return handle_recover_write_dir(EVENT_IMMEDIATE, nullptr); @@ -1602,7 +1623,8 @@ Ldone : { recover_pos += EVACUATION_SIZE; // safely cover the max write size if (recover_pos < header->write_pos && (recover_pos + EVACUATION_SIZE >= header->write_pos)) { - Debug("cache_init", "Head Pos: %" PRIu64 ", Rec Pos: %" PRIu64 ", Wrapped:%d", header->write_pos, recover_pos, recover_wrapped); + Dbg(dbg_ctl_cache_init, "Head Pos: %" PRIu64 ", Rec Pos: %" PRIu64 ", Wrapped:%d", header->write_pos, recover_pos, + recover_wrapped); Warning("no valid directory found while recovering '%s', clearing", hash_text.get()); goto Lclear; } @@ -1714,7 +1736,7 @@ Vol::handle_header_read(int event, void *data) if (hf[0]->sync_serial == hf[1]->sync_serial && (hf[0]->sync_serial >= hf[2]->sync_serial || hf[2]->sync_serial != hf[3]->sync_serial)) { SET_HANDLER(&Vol::handle_dir_read); - if (is_debug_tag_set("cache_init")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_init)) { Note("using directory A for '%s'", hash_text.get()); } io.aiocb.aio_offset = skip; @@ -1723,7 +1745,7 @@ Vol::handle_header_read(int event, void *data) // try B else if (hf[2]->sync_serial == hf[3]->sync_serial) { SET_HANDLER(&Vol::handle_dir_read); - if (is_debug_tag_set("cache_init")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_init)) { Note("using directory B for '%s'", hash_text.get()); } io.aiocb.aio_offset = skip + this->dirlen(); @@ -1874,7 +1896,7 @@ build_vol_hash_table(CacheHostRecord *cp) gotvol[rtable[i].idx]++; } for (int i = 0; i < num_vols; i++) { - Debug("cache_init", "build_vol_hash_table index %d mapped to %d requested %d got %d", i, mapping[i], forvol[i], gotvol[i]); + Dbg(dbg_ctl_cache_init, "build_vol_hash_table index %d mapped to %d requested %d got %d", i, mapping[i], forvol[i], gotvol[i]); } // install new table if (nullptr != (old_table = ink_atomic_swap(&(cp->vol_hash_table), ttable))) { @@ -2059,7 +2081,8 @@ Cache::open(bool clear, bool /* fix ATS_UNUSED */) total_good_nvol = 0; REC_EstablishStaticConfigInt32(cache_config_min_average_object_size, "proxy.config.cache.min_average_object_size"); - Debug("cache_init", "Cache::open - proxy.config.cache.min_average_object_size = %d", (int)cache_config_min_average_object_size); + Dbg(dbg_ctl_cache_init, "Cache::open - proxy.config.cache.min_average_object_size = %d", + (int)cache_config_min_average_object_size); CacheVol *cp = cp_list.head; for (; cp; cp = cp->link.next) { @@ -2167,10 +2190,10 @@ CacheVC::handleReadDone(int event, Event *e) } if ((!dir_valid(vol, &dir)) || (!io.ok())) { if (!io.ok()) { - Debug("cache_disk_error", "Read error on disk %s\n \ + Dbg(dbg_ctl_cache_disk_error, "Read error on disk %s\n \ read range : [%" PRIu64 " - %" PRIu64 " bytes] [%" PRIu64 " - %" PRIu64 " blocks] \n", - vol->hash_text.get(), (uint64_t)io.aiocb.aio_offset, (uint64_t)io.aiocb.aio_offset + io.aiocb.aio_nbytes, - (uint64_t)io.aiocb.aio_offset / 512, (uint64_t)(io.aiocb.aio_offset + io.aiocb.aio_nbytes) / 512); + vol->hash_text.get(), (uint64_t)io.aiocb.aio_offset, (uint64_t)io.aiocb.aio_offset + io.aiocb.aio_nbytes, + (uint64_t)io.aiocb.aio_offset / 512, (uint64_t)(io.aiocb.aio_offset + io.aiocb.aio_nbytes) / 512); } goto Ldone; } @@ -2182,8 +2205,8 @@ CacheVC::handleReadDone(int event, Event *e) if (ts::VersionNumber(doc->v_major, doc->v_minor) > CACHE_DB_VERSION) { // future version, count as corrupted doc->magic = DOC_CORRUPT; - Debug("cache_bc", "Object is future version %d:%d - disk %s - doc id = %" PRIx64 ":%" PRIx64 "", doc->v_major, doc->v_minor, - vol->hash_text.get(), read_key->slice64(0), read_key->slice64(1)); + Dbg(dbg_ctl_cache_bc, "Object is future version %d:%d - disk %s - doc id = %" PRIx64 ":%" PRIx64 "", doc->v_major, + doc->v_minor, vol->hash_text.get(), read_key->slice64(0), read_key->slice64(1)); goto Ldone; } @@ -2199,10 +2222,11 @@ CacheVC::handleReadDone(int event, Event *e) } #endif - if (is_debug_tag_set("cache_read")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_read)) { char xt[CRYPTO_HEX_SIZE]; - Debug("cache_read", "Read complete on fragment %s. Length: data payload=%d this fragment=%d total doc=%" PRId64 " prefix=%d", - doc->key.toHexStr(xt), doc->data_len(), doc->len, doc->total_len, doc->prefix_len()); + Dbg(dbg_ctl_cache_read, + "Read complete on fragment %s. Length: data payload=%d this fragment=%d total doc=%" PRId64 " prefix=%d", + doc->key.toHexStr(xt), doc->data_len(), doc->len, doc->total_len, doc->prefix_len()); } // put into ram cache? @@ -2630,7 +2654,7 @@ fillExclusiveDisks(CacheVol *cp) int diskCount = 0; int volume_number = cp->vol_number; - Debug("cache_init", "volume %d", volume_number); + Dbg(dbg_ctl_cache_init, "volume %d", volume_number); for (int i = 0; i < gndisks; i++) { if (gdisks[i]->forced_volume_num != volume_number) { continue; @@ -2671,7 +2695,7 @@ fillExclusiveDisks(CacheVol *cp) cp->size += dpb->len; cp->num_vols++; } else { - Debug("cache_init", "create_volume failed"); + Dbg(dbg_ctl_cache_init, "create_volume failed"); break; } } while ((size_diff > 0)); @@ -2712,7 +2736,7 @@ cplist_reconfigure() int vols = (free_space / MAX_VOL_SIZE) + 1; for (int p = 0; p < vols; p++) { off_t b = gdisks[i]->free_space / (vols - p); - Debug("cache_hosting", "blocks = %" PRId64, (int64_t)b); + Dbg(dbg_ctl_cache_hosting, "blocks = %" PRId64, (int64_t)b); DiskVolBlock *dpb = gdisks[i]->create_volume(0, b, CACHE_HTTP_TYPE); ink_assert(dpb && dpb->len == (uint64_t)b); } @@ -2793,8 +2817,8 @@ cplist_reconfigure() (int64_t)config_vol->size, 128); Warning("volume %d is not created", config_vol->number); } - Debug("cache_hosting", "Volume: %d Size: %" PRId64 " Ramcache: %d", config_vol->number, (int64_t)config_vol->size, - config_vol->ramcache_enabled); + Dbg(dbg_ctl_cache_hosting, "Volume: %d Size: %" PRId64 " Ramcache: %d", config_vol->number, (int64_t)config_vol->size, + config_vol->ramcache_enabled); } cplist_update(); @@ -2933,7 +2957,7 @@ create_volume(int volume_number, off_t size_in_blocks, int scheme, CacheVol *cp) cp->vol_number = volume_number; cp->scheme = scheme; if (fillExclusiveDisks(cp)) { - Debug("cache_init", "volume successfully filled from forced disks: volume_number=%d", volume_number); + Dbg(dbg_ctl_cache_init, "volume successfully filled from forced disks: volume_number=%d", volume_number); return 0; } @@ -3019,20 +3043,20 @@ Cache::key_to_vol(const CacheKey *key, const char *hostname, int host_len) if (res.record) { unsigned short *host_hash_table = res.record->vol_hash_table; if (host_hash_table) { - if (is_debug_tag_set("cache_hosting")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_hosting)) { char format_str[50]; snprintf(format_str, sizeof(format_str), "Volume: %%xd for host: %%.%ds", host_len); - Debug("cache_hosting", format_str, res.record, hostname); + Dbg(dbg_ctl_cache_hosting, format_str, res.record, hostname); } return res.record->vols[host_hash_table[h]]; } } } if (hash_table) { - if (is_debug_tag_set("cache_hosting")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_hosting)) { char format_str[50]; snprintf(format_str, sizeof(format_str), "Generic volume: %%xd for host: %%.%ds", host_len); - Debug("cache_hosting", format_str, host_rec, hostname); + Dbg(dbg_ctl_cache_hosting, format_str, host_rec, hostname); } return host_rec->vols[hash_table[h]]; } else { @@ -3134,8 +3158,8 @@ ink_cache_init(ts::ModuleVersion v) cache_rsb = RecAllocateRawStatBlock(static_cast(cache_stat_count)); REC_EstablishStaticConfigInteger(cache_config_ram_cache_size, "proxy.config.cache.ram_cache.size"); - Debug("cache_init", "proxy.config.cache.ram_cache.size = %" PRId64 " = %" PRId64 "Mb", cache_config_ram_cache_size, - cache_config_ram_cache_size / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.ram_cache.size = %" PRId64 " = %" PRId64 "Mb", cache_config_ram_cache_size, + cache_config_ram_cache_size / (1024 * 1024)); REC_EstablishStaticConfigInt32(cache_config_ram_cache_algorithm, "proxy.config.cache.ram_cache.algorithm"); REC_EstablishStaticConfigInt32(cache_config_ram_cache_compress, "proxy.config.cache.ram_cache.compress"); @@ -3143,42 +3167,42 @@ ink_cache_init(ts::ModuleVersion v) REC_ReadConfigInt32(cache_config_ram_cache_use_seen_filter, "proxy.config.cache.ram_cache.use_seen_filter"); REC_EstablishStaticConfigInt32(cache_config_http_max_alts, "proxy.config.cache.limits.http.max_alts"); - Debug("cache_init", "proxy.config.cache.limits.http.max_alts = %d", cache_config_http_max_alts); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.limits.http.max_alts = %d", cache_config_http_max_alts); REC_EstablishStaticConfigInt32(cache_config_log_alternate_eviction, "proxy.config.cache.log.alternate.eviction"); - Debug("cache_init", "proxy.config.cache.log.alternate.eviction = %d", cache_config_log_alternate_eviction); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.log.alternate.eviction = %d", cache_config_log_alternate_eviction); REC_EstablishStaticConfigInteger(cache_config_ram_cache_cutoff, "proxy.config.cache.ram_cache_cutoff"); - Debug("cache_init", "cache_config_ram_cache_cutoff = %" PRId64 " = %" PRId64 "Mb", cache_config_ram_cache_cutoff, - cache_config_ram_cache_cutoff / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "cache_config_ram_cache_cutoff = %" PRId64 " = %" PRId64 "Mb", cache_config_ram_cache_cutoff, + cache_config_ram_cache_cutoff / (1024 * 1024)); REC_EstablishStaticConfigInt32(cache_config_permit_pinning, "proxy.config.cache.permit.pinning"); - Debug("cache_init", "proxy.config.cache.permit.pinning = %d", cache_config_permit_pinning); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.permit.pinning = %d", cache_config_permit_pinning); REC_EstablishStaticConfigInt32(cache_config_dir_sync_frequency, "proxy.config.cache.dir.sync_frequency"); - Debug("cache_init", "proxy.config.cache.dir.sync_frequency = %d", cache_config_dir_sync_frequency); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.dir.sync_frequency = %d", cache_config_dir_sync_frequency); REC_EstablishStaticConfigInt32(cache_config_select_alternate, "proxy.config.cache.select_alternate"); - Debug("cache_init", "proxy.config.cache.select_alternate = %d", cache_config_select_alternate); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.select_alternate = %d", cache_config_select_alternate); REC_EstablishStaticConfigInt32(cache_config_max_doc_size, "proxy.config.cache.max_doc_size"); - Debug("cache_init", "proxy.config.cache.max_doc_size = %d = %dMb", cache_config_max_doc_size, - cache_config_max_doc_size / (1024 * 1024)); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.max_doc_size = %d = %dMb", cache_config_max_doc_size, + cache_config_max_doc_size / (1024 * 1024)); REC_EstablishStaticConfigInt32(cache_config_mutex_retry_delay, "proxy.config.cache.mutex_retry_delay"); - Debug("cache_init", "proxy.config.cache.mutex_retry_delay = %dms", cache_config_mutex_retry_delay); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.mutex_retry_delay = %dms", cache_config_mutex_retry_delay); REC_EstablishStaticConfigInt32(cache_config_read_while_writer_max_retries, "proxy.config.cache.read_while_writer.max_retries"); - Debug("cache_init", "proxy.config.cache.read_while_writer.max_retries = %d", cache_config_read_while_writer_max_retries); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.read_while_writer.max_retries = %d", cache_config_read_while_writer_max_retries); REC_EstablishStaticConfigInt32(cache_read_while_writer_retry_delay, "proxy.config.cache.read_while_writer_retry.delay"); - Debug("cache_init", "proxy.config.cache.read_while_writer_retry.delay = %dms", cache_read_while_writer_retry_delay); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.read_while_writer_retry.delay = %dms", cache_read_while_writer_retry_delay); REC_EstablishStaticConfigInt32(cache_config_hit_evacuate_percent, "proxy.config.cache.hit_evacuate_percent"); - Debug("cache_init", "proxy.config.cache.hit_evacuate_percent = %d", cache_config_hit_evacuate_percent); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.hit_evacuate_percent = %d", cache_config_hit_evacuate_percent); REC_EstablishStaticConfigInt32(cache_config_hit_evacuate_size_limit, "proxy.config.cache.hit_evacuate_size_limit"); - Debug("cache_init", "proxy.config.cache.hit_evacuate_size_limit = %d", cache_config_hit_evacuate_size_limit); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.hit_evacuate_size_limit = %d", cache_config_hit_evacuate_size_limit); REC_EstablishStaticConfigInt32(cache_config_force_sector_size, "proxy.config.cache.force_sector_size"); @@ -3191,21 +3215,21 @@ ink_cache_init(ts::ModuleVersion v) } REC_EstablishStaticConfigInt32(cache_config_max_disk_errors, "proxy.config.cache.max_disk_errors"); - Debug("cache_init", "proxy.config.cache.max_disk_errors = %d", cache_config_max_disk_errors); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.max_disk_errors = %d", cache_config_max_disk_errors); REC_EstablishStaticConfigInt32(cache_config_agg_write_backlog, "proxy.config.cache.agg_write_backlog"); - Debug("cache_init", "proxy.config.cache.agg_write_backlog = %d", cache_config_agg_write_backlog); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.agg_write_backlog = %d", cache_config_agg_write_backlog); REC_EstablishStaticConfigInt32(cache_config_enable_checksum, "proxy.config.cache.enable_checksum"); - Debug("cache_init", "proxy.config.cache.enable_checksum = %d", cache_config_enable_checksum); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.enable_checksum = %d", cache_config_enable_checksum); REC_EstablishStaticConfigInt32(cache_config_alt_rewrite_max_size, "proxy.config.cache.alt_rewrite_max_size"); - Debug("cache_init", "proxy.config.cache.alt_rewrite_max_size = %d", cache_config_alt_rewrite_max_size); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.alt_rewrite_max_size = %d", cache_config_alt_rewrite_max_size); REC_EstablishStaticConfigInt32(cache_config_read_while_writer, "proxy.config.cache.enable_read_while_writer"); cache_config_read_while_writer = validate_rww(cache_config_read_while_writer); REC_RegisterConfigUpdateFunc("proxy.config.cache.enable_read_while_writer", update_cache_config, nullptr); - Debug("cache_init", "proxy.config.cache.enable_read_while_writer = %d", cache_config_read_while_writer); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.enable_read_while_writer = %d", cache_config_read_while_writer); register_cache_stats(cache_rsb, "proxy.process.cache"); diff --git a/iocore/cache/CacheDir.cc b/iocore/cache/CacheDir.cc index 63d38af3b80..cd79ac5c9d1 100644 --- a/iocore/cache/CacheDir.cc +++ b/iocore/cache/CacheDir.cc @@ -51,6 +51,27 @@ CACHE_INCREMENT_DYN_STAT(cache_directory_collision_count_stat); \ } while (0); +namespace +{ + +DbgCtl dbg_ctl_cache_dir_sync{"dir_sync"}; +DbgCtl dbg_ctl_cache_check_dir{"cache_check_dir"}; +DbgCtl dbg_ctl_dir_clean{"dir_clean"}; + +#ifdef DEBUG + +DbgCtl dbg_ctl_cache_stats{"cache_stats"}; +DbgCtl dbg_ctl_dir_probe_hit{"dir_probe_hit"}; +DbgCtl dbg_ctl_dir_probe_tag{"dir_probe_tag"}; +DbgCtl dbg_ctl_dir_probe_miss{"dir_probe_miss"}; +DbgCtl dbg_ctl_dir_insert{"dir_insert"}; +DbgCtl dbg_ctl_dir_overwrite{"dir_overwrite"}; +DbgCtl dbg_ctl_dir_lookaside{"dir_lookaside"}; + +#endif + +} // end anonymous namespace + // Globals ClassAllocator openDirEntryAllocator("openDirEntry"); @@ -279,7 +300,7 @@ int check_dir(Vol *vol) { int i, s; - Debug("cache_check_dir", "inside check dir"); + Dbg(dbg_ctl_cache_check_dir, "inside check dir"); for (s = 0; s < vol->segments; s++) { Dir *seg = vol->dir_segment(s); for (i = 0; i < vol->buckets; i++) { @@ -361,9 +382,9 @@ dir_clean_bucket(Dir *b, int s, Vol *vol) } #endif if (!dir_valid(vol, e) || !dir_offset(e)) { - if (is_debug_tag_set("dir_clean")) { - Debug("dir_clean", "cleaning Vol:%s: %p tag %X boffset %" PRId64 " b %p p %p bucket len %d", vol->hash_text.get(), e, - dir_tag(e), dir_offset(e), b, p, dir_bucket_length(b, s, vol)); + if (is_dbg_ctl_enabled(dbg_ctl_dir_clean)) { + Dbg(dbg_ctl_dir_clean, "cleaning Vol:%s: %p tag %X boffset %" PRId64 " b %p p %p bucket len %d", vol->hash_text.get(), e, + dir_tag(e), dir_offset(e), b, p, dir_bucket_length(b, s, vol)); } if (dir_offset(e)) { CACHE_DEC_DIR_USED(vol->mutex); @@ -562,14 +583,14 @@ dir_probe(const CacheKey *key, Vol *vol, Dir *result, Dir **last_collision) // for the same document and so the collision stat // may not accurately reflect the number of documents // having the same first_key - DDebug("cache_stats", "Incrementing dir collisions"); + DDbg(dbg_ctl_cache_stats, "Incrementing dir collisions"); CACHE_INC_DIR_COLLISIONS(vol->mutex); } goto Lcont; } if (dir_valid(vol, e)) { - DDebug("dir_probe_hit", "found %X %X vol %d bucket %d boffset %" PRId64 "", key->slice32(0), key->slice32(1), vol->fd, b, - dir_offset(e)); + DDbg(dbg_ctl_dir_probe_hit, "found %X %X vol %d bucket %d boffset %" PRId64 "", key->slice32(0), key->slice32(1), vol->fd, + b, dir_offset(e)); dir_assign(result, e); *last_collision = e; ink_assert(dir_offset(e) * CACHE_BLOCK_SIZE < vol->len); @@ -580,7 +601,7 @@ dir_probe(const CacheKey *key, Vol *vol, Dir *result, Dir **last_collision) continue; } } else { - DDebug("dir_probe_tag", "tag mismatch %p %X vs expected %X", e, dir_tag(e), key->slice32(3)); + DDbg(dbg_ctl_dir_probe_tag, "tag mismatch %p %X vs expected %X", e, dir_tag(e), key->slice32(3)); } Lcont: p = e; @@ -588,12 +609,12 @@ dir_probe(const CacheKey *key, Vol *vol, Dir *result, Dir **last_collision) } while (e); } if (collision) { // last collision no longer in the list, retry - DDebug("cache_stats", "Incrementing dir collisions"); + DDbg(dbg_ctl_cache_stats, "Incrementing dir collisions"); CACHE_INC_DIR_COLLISIONS(vol->mutex); collision = nullptr; goto Lagain; } - DDebug("dir_probe_miss", "missed %X %X on vol %d bucket %d at %p", key->slice32(0), key->slice32(1), vol->fd, b, seg); + DDbg(dbg_ctl_dir_probe_miss, "missed %X %X on vol %d bucket %d at %p", key->slice32(0), key->slice32(1), vol->fd, b, seg); CHECK_DIR(d); return 0; } @@ -656,8 +677,8 @@ dir_insert(const CacheKey *key, Vol *vol, Dir *to_part) dir_assign_data(e, to_part); dir_set_tag(e, key->slice32(2)); ink_assert(vol->vol_offset(e) < (vol->skip + vol->len)); - DDebug("dir_insert", "insert %p %X into vol %d bucket %d at %p tag %X %X boffset %" PRId64 "", e, key->slice32(0), vol->fd, bi, e, - key->slice32(1), dir_tag(e), dir_offset(e)); + DDbg(dbg_ctl_dir_insert, "insert %p %X into vol %d bucket %d at %p tag %X %X boffset %" PRId64 "", e, key->slice32(0), vol->fd, + bi, e, key->slice32(1), dir_tag(e), dir_offset(e)); CHECK_DIR(d); vol->header->dirty = 1; CACHE_INC_DIR_USED(vol->mutex); @@ -742,8 +763,8 @@ dir_overwrite(const CacheKey *key, Vol *vol, Dir *dir, Dir *overwrite, bool must dir_assign_data(e, dir); dir_set_tag(e, t); ink_assert(vol->vol_offset(e) < vol->skip + vol->len); - DDebug("dir_overwrite", "overwrite %p %X into vol %d bucket %d at %p tag %X %X boffset %" PRId64 "", e, key->slice32(0), vol->fd, - bi, e, t, dir_tag(e), dir_offset(e)); + DDbg(dbg_ctl_dir_overwrite, "overwrite %p %X into vol %d bucket %d at %p tag %X %X boffset %" PRId64 "", e, key->slice32(0), + vol->fd, bi, e, t, dir_tag(e), dir_offset(e)); CHECK_DIR(d); vol->header->dirty = 1; return res; @@ -798,7 +819,7 @@ dir_lookaside_probe(const CacheKey *key, Vol *vol, Dir *result, EvacuationBlock if (b->evac_frags.key == *key) { if (dir_valid(vol, &b->new_dir)) { *result = b->new_dir; - DDebug("dir_lookaside", "probe %X success", key->slice32(0)); + DDbg(dbg_ctl_dir_lookaside, "probe %X success", key->slice32(0)); if (eblock) { *eblock = b; } @@ -807,7 +828,7 @@ dir_lookaside_probe(const CacheKey *key, Vol *vol, Dir *result, EvacuationBlock } b = b->link.next; } - DDebug("dir_lookaside", "probe %X failed", key->slice32(0)); + DDbg(dbg_ctl_dir_lookaside, "probe %X failed", key->slice32(0)); return 0; } @@ -815,8 +836,8 @@ int dir_lookaside_insert(EvacuationBlock *eblock, Vol *vol, Dir *to) { CacheKey *key = &eblock->evac_frags.earliest_key; - DDebug("dir_lookaside", "insert %X %X, offset %d phase %d", key->slice32(0), key->slice32(1), (int)dir_offset(to), - (int)dir_phase(to)); + DDbg(dbg_ctl_dir_lookaside, "insert %X %X, offset %d phase %d", key->slice32(0), key->slice32(1), (int)dir_offset(to), + (int)dir_phase(to)); ink_assert(vol->mutex->thread_holding == this_ethread()); int i = key->slice32(3) % LOOKASIDE_SIZE; EvacuationBlock *b = new_EvacuationBlock(vol->mutex->thread_holding); @@ -839,8 +860,8 @@ dir_lookaside_fixup(const CacheKey *key, Vol *vol) while (b) { if (b->evac_frags.key == *key) { int res = dir_overwrite(key, vol, &b->new_dir, &b->dir, false); - DDebug("dir_lookaside", "fixup %X %X offset %" PRId64 " phase %d %d", key->slice32(0), key->slice32(1), - dir_offset(&b->new_dir), dir_phase(&b->new_dir), res); + DDbg(dbg_ctl_dir_lookaside, "fixup %X %X offset %" PRId64 " phase %d %d", key->slice32(0), key->slice32(1), + dir_offset(&b->new_dir), dir_phase(&b->new_dir), res); int64_t o = dir_offset(&b->dir), n = dir_offset(&b->new_dir); vol->ram_cache->fixup(key, static_cast(o), static_cast(n)); vol->lookaside[i].remove(b); @@ -849,7 +870,7 @@ dir_lookaside_fixup(const CacheKey *key, Vol *vol) } b = b->link.next; } - DDebug("dir_lookaside", "fixup %X %X failed", key->slice32(0), key->slice32(1)); + DDbg(dbg_ctl_dir_lookaside, "fixup %X %X failed", key->slice32(0), key->slice32(1)); return 0; } @@ -862,8 +883,8 @@ dir_lookaside_cleanup(Vol *vol) while (b) { if (!dir_valid(vol, &b->new_dir)) { EvacuationBlock *nb = b->link.next; - DDebug("dir_lookaside", "cleanup %X %X cleaned up", b->evac_frags.earliest_key.slice32(0), - b->evac_frags.earliest_key.slice32(1)); + DDbg(dbg_ctl_dir_lookaside, "cleanup %X %X cleaned up", b->evac_frags.earliest_key.slice32(0), + b->evac_frags.earliest_key.slice32(1)); i.remove(b); free_CacheVC(b->earliest_evacuator); free_EvacuationBlock(b, vol->mutex->thread_holding); @@ -884,15 +905,15 @@ dir_lookaside_remove(const CacheKey *key, Vol *vol) EvacuationBlock *b = vol->lookaside[i].head; while (b) { if (b->evac_frags.key == *key) { - DDebug("dir_lookaside", "remove %X %X offset %" PRId64 " phase %d", key->slice32(0), key->slice32(1), dir_offset(&b->new_dir), - dir_phase(&b->new_dir)); + DDbg(dbg_ctl_dir_lookaside, "remove %X %X offset %" PRId64 " phase %d", key->slice32(0), key->slice32(1), + dir_offset(&b->new_dir), dir_phase(&b->new_dir)); vol->lookaside[i].remove(b); free_EvacuationBlock(b, vol->mutex->thread_holding); return; } b = b->link.next; } - DDebug("dir_lookaside", "remove %X %X failed", key->slice32(0), key->slice32(1)); + DDbg(dbg_ctl_dir_lookaside, "remove %X %X failed", key->slice32(0), key->slice32(1)); return; } @@ -955,7 +976,7 @@ dir_entries_used(Vol *vol) void sync_cache_dir_on_shutdown() { - Debug("cache_dir_sync", "sync started"); + Dbg(dbg_ctl_cache_dir_sync, "sync started"); char *buf = nullptr; size_t buflen = 0; bool buf_huge = false; @@ -969,13 +990,13 @@ sync_cache_dir_on_shutdown() Vol *vol = gvol[i]; if (DISK_BAD(vol->disk)) { - Debug("cache_dir_sync", "Dir %s: ignoring -- bad disk", vol->hash_text.get()); + Dbg(dbg_ctl_cache_dir_sync, "Dir %s: ignoring -- bad disk", vol->hash_text.get()); continue; } size_t dirlen = vol->dirlen(); ink_assert(dirlen > 0); // make clang happy - if not > 0 the vol is seriously messed up if (!vol->header->dirty && !vol->dir_sync_in_progress) { - Debug("cache_dir_sync", "Dir %s: ignoring -- not dirty", vol->hash_text.get()); + Dbg(dbg_ctl_cache_dir_sync, "Dir %s: ignoring -- not dirty", vol->hash_text.get()); continue; } // recompute hit_evacuate_window @@ -985,7 +1006,7 @@ sync_cache_dir_on_shutdown() // dont worry about the cachevc s in the agg queue // directories have not been inserted for these writes if (vol->agg_buf_pos) { - Debug("cache_dir_sync", "Dir %s: flushing agg buffer first", vol->hash_text.get()); + Dbg(dbg_ctl_cache_dir_sync, "Dir %s: flushing agg buffer first", vol->hash_text.get()); // set write limit vol->header->agg_pos = vol->header->write_pos + vol->agg_buf_pos; @@ -1025,7 +1046,7 @@ sync_cache_dir_on_shutdown() if (!vol->dir_sync_in_progress) { vol->header->sync_serial++; } else { - Debug("cache_dir_sync", "Periodic dir sync in progress -- overwriting"); + Dbg(dbg_ctl_cache_dir_sync, "Periodic dir sync in progress -- overwriting"); } vol->footer->sync_serial = vol->header->sync_serial; @@ -1035,9 +1056,9 @@ sync_cache_dir_on_shutdown() off_t start = vol->skip + (B ? dirlen : 0); B = pwrite(vol->fd, buf, dirlen, start); ink_assert(B == dirlen); - Debug("cache_dir_sync", "done syncing dir for vol %s", vol->hash_text.get()); + Dbg(dbg_ctl_cache_dir_sync, "done syncing dir for vol %s", vol->hash_text.get()); } - Debug("cache_dir_sync", "sync done"); + Dbg(dbg_ctl_cache_dir_sync, "sync done"); if (buf) { if (buf_huge) { ats_free_hugepage(buf, buflen); @@ -1069,7 +1090,7 @@ CacheSync::mainEvent(int event, Event *e) buf = nullptr; buf_huge = false; } - Debug("cache_dir_sync", "sync done"); + Dbg(dbg_ctl_cache_dir_sync, "sync done"); if (event == EVENT_INTERVAL) { trigger = e->ethread->schedule_in(this, HRTIME_SECONDS(cache_config_dir_sync_frequency)); } else { @@ -1114,25 +1135,25 @@ CacheSync::mainEvent(int event, Event *e) size_t dirlen = vol->dirlen(); if (!writepos) { // start - Debug("cache_dir_sync", "sync started"); + Dbg(dbg_ctl_cache_dir_sync, "sync started"); /* Don't sync the directory to disk if its not dirty. Syncing the clean directory to disk is also the cause of INKqa07151. Increasing the serial number causes the cache to recover more data than necessary. The dirty bit it set in dir_insert, dir_overwrite and dir_delete_entry */ if (!vol->header->dirty) { - Debug("cache_dir_sync", "Dir %s not dirty", vol->hash_text.get()); + Dbg(dbg_ctl_cache_dir_sync, "Dir %s not dirty", vol->hash_text.get()); goto Ldone; } if (vol->is_io_in_progress() || vol->agg_buf_pos) { - Debug("cache_dir_sync", "Dir %s: waiting for agg buffer", vol->hash_text.get()); + Dbg(dbg_ctl_cache_dir_sync, "Dir %s: waiting for agg buffer", vol->hash_text.get()); vol->dir_sync_waiting = true; if (!vol->is_io_in_progress()) { vol->aggWrite(EVENT_IMMEDIATE, nullptr); } return EVENT_CONT; } - Debug("cache_dir_sync", "pos: %" PRIu64 " Dir %s dirty...syncing to disk", vol->header->write_pos, vol->hash_text.get()); + Dbg(dbg_ctl_cache_dir_sync, "pos: %" PRIu64 " Dir %s dirty...syncing to disk", vol->header->write_pos, vol->hash_text.get()); vol->header->dirty = 0; if (buflen < dirlen) { if (buf) { diff --git a/iocore/cache/CacheRead.cc b/iocore/cache/CacheRead.cc index eb53637c5cf..967d1ae7ef6 100644 --- a/iocore/cache/CacheRead.cc +++ b/iocore/cache/CacheRead.cc @@ -25,6 +25,21 @@ #include "HttpCacheSM.h" //Added to get the scope of HttpCacheSM object. +namespace +{ + +DbgCtl dbg_ctl_cache_read{"cache_read"}; +DbgCtl dbg_ctl_cache_seek{"cache_seek"}; + +#ifdef DEBUG + +DbgCtl dbg_ctl_cache_read_agg{"cache_read_agg"}; +DbgCtl dbg_ctl_cache_hit_evac{"cache_hit_evac"}; + +#endif + +} // end anonymous namespace + Action * Cache::open_read(Continuation *cont, const CacheKey *key, CacheFragType type, const char *hostname, int host_len) { @@ -284,13 +299,13 @@ CacheVC::openReadChooseWriter(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSE } vector.clear(false); if (!write_vc) { - DDebug("cache_read_agg", "%p: key: %X writer alternate different: %d", this, first_key.slice32(1), alternate_index); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X writer alternate different: %d", this, first_key.slice32(1), alternate_index); od = nullptr; return EVENT_RETURN; } - DDebug("cache_read_agg", "%p: key: %X eKey: %d # alts: %d, ndx: %d, # writers: %d writer: %p", this, first_key.slice32(1), - write_vc->earliest_key.slice32(1), vector.count(), alternate_index, od->num_writers, write_vc); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X eKey: %d # alts: %d, ndx: %d, # writers: %d writer: %p", this, first_key.slice32(1), + write_vc->earliest_key.slice32(1), vector.count(), alternate_index, od->num_writers, write_vc); } return EVENT_NONE; } @@ -312,7 +327,7 @@ CacheVC::openReadFromWriter(int event, Event *e) } cancel_trigger(); intptr_t err = ECACHE_DOC_BUSY; - DDebug("cache_read_agg", "%p: key: %X In openReadFromWriter", this, first_key.slice32(1)); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X In openReadFromWriter", this, first_key.slice32(1)); if (_action.cancelled) { od = nullptr; // only open for read so no need to close return free_CacheVC(this); @@ -353,7 +368,8 @@ CacheVC::openReadFromWriter(int event, Event *e) } else { if (writer_done()) { MUTEX_RELEASE(lock); - DDebug("cache_read_agg", "%p: key: %X writer %p has left, continuing as normal read", this, first_key.slice32(1), write_vc); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X writer %p has left, continuing as normal read", this, first_key.slice32(1), + write_vc); od = nullptr; write_vc = nullptr; SET_HANDLER(&CacheVC::openReadStartHead); @@ -378,14 +394,14 @@ CacheVC::openReadFromWriter(int event, Event *e) MUTEX_RELEASE(lock); return openReadFromWriterFailure(CACHE_EVENT_OPEN_READ_FAILED, (Event *)-err); } - DDebug("cache_read_agg", "%p: key: %X writer: closed:%d, fragment:%d, retry: %d", this, first_key.slice32(1), write_vc->closed, - write_vc->fragment, writer_lock_retry); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X writer: closed:%d, fragment:%d, retry: %d", this, first_key.slice32(1), + write_vc->closed, write_vc->fragment, writer_lock_retry); VC_SCHED_WRITER_RETRY(); } CACHE_TRY_LOCK(writer_lock, write_vc->mutex, mutex->thread_holding); if (!writer_lock.is_locked()) { - DDebug("cache_read_agg", "%p: key: %X lock miss", this, first_key.slice32(1)); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X lock miss", this, first_key.slice32(1)); VC_SCHED_LOCK_RETRY(); } MUTEX_RELEASE(lock); @@ -394,8 +410,8 @@ CacheVC::openReadFromWriter(int event, Event *e) return openReadFromWriterFailure(CACHE_EVENT_OPEN_READ_FAILED, (Event *)-err); } if (frag_type == CACHE_FRAG_TYPE_HTTP) { - DDebug("cache_read_agg", "%p: key: %X http passed stage 1, closed: %d, frag: %d", this, first_key.slice32(1), write_vc->closed, - write_vc->fragment); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X http passed stage 1, closed: %d, frag: %d", this, first_key.slice32(1), + write_vc->closed, write_vc->fragment); if (!write_vc->alternate.valid()) { return openReadFromWriterFailure(CACHE_EVENT_OPEN_READ_FAILED, (Event *)-err); } @@ -413,7 +429,7 @@ CacheVC::openReadFromWriter(int event, Event *e) } else { key = write_vc->update_key; ink_assert(write_vc->closed); - DDebug("cache_read_agg", "%p: key: %X writer header update", this, first_key.slice32(1)); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X writer header update", this, first_key.slice32(1)); // Update case (b) : grab doc_len from the writer's alternate doc_len = alternate.object_size_get(); if (write_vc->update_key == cod->single_doc_key && (cod->move_resident_alt || write_vc->f.rewrite_resident_alt) && @@ -443,14 +459,14 @@ CacheVC::openReadFromWriter(int event, Event *e) return openReadStartEarliest(event, e); } } else { - DDebug("cache_read_agg", "%p: key: %X non-http passed stage 1", this, first_key.slice32(1)); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X non-http passed stage 1", this, first_key.slice32(1)); key = write_vc->earliest_key; } if (write_vc->fragment) { doc_len = write_vc->vio.nbytes; last_collision = nullptr; - DDebug("cache_read_agg", "%p: key: %X closed: %d, fragment: %d, len: %d starting first fragment", this, first_key.slice32(1), - write_vc->closed, write_vc->fragment, (int)doc_len); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X closed: %d, fragment: %d, len: %d starting first fragment", this, + first_key.slice32(1), write_vc->closed, write_vc->fragment, (int)doc_len); MUTEX_RELEASE(writer_lock); // either a header + body update or a new document SET_HANDLER(&CacheVC::openReadStartEarliest); @@ -467,7 +483,7 @@ CacheVC::openReadFromWriter(int event, Event *e) doc_len = write_vc->total_len; dir_clean(&first_dir); dir_clean(&earliest_dir); - DDebug("cache_read_agg", "%p: key: %X %X: single fragment read", this, first_key.slice32(1), key.slice32(0)); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X %X: single fragment read", this, first_key.slice32(1), key.slice32(0)); MUTEX_RELEASE(writer_lock); SET_HANDLER(&CacheVC::openReadFromWriterMain); CACHE_INCREMENT_DYN_STAT(cache_read_busy_success_stat); @@ -488,7 +504,7 @@ CacheVC::openReadFromWriterMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNU return EVENT_CONT; } if (length < (static_cast(doc_len)) - vio.ndone) { - DDebug("cache_read_agg", "truncation %X", first_key.slice32(1)); + DDbg(dbg_ctl_cache_read_agg, "truncation %X", first_key.slice32(1)); if (is_action_tag_set("cache")) { ink_release_assert(false); } @@ -596,20 +612,20 @@ CacheVC::openReadReadDone(int event, Event *e) last_collision = nullptr; while (dir_probe(&earliest_key, vol, &dir, &last_collision)) { if (dir_offset(&dir) == dir_offset(&earliest_dir)) { - DDebug("cache_read_agg", "%p: key: %X ReadRead complete: %d", this, first_key.slice32(1), (int)vio.ndone); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadRead complete: %d", this, first_key.slice32(1), (int)vio.ndone); doc_len = vio.ndone; goto Ldone; } } - DDebug("cache_read_agg", "%p: key: %X ReadRead writer aborted: %d", this, first_key.slice32(1), (int)vio.ndone); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadRead writer aborted: %d", this, first_key.slice32(1), (int)vio.ndone); goto Lerror; } if (writer_lock_retry < cache_config_read_while_writer_max_retries) { - DDebug("cache_read_agg", "%p: key: %X ReadRead retrying: %d", this, first_key.slice32(1), (int)vio.ndone); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadRead retrying: %d", this, first_key.slice32(1), (int)vio.ndone); VC_SCHED_WRITER_RETRY(); // wait for writer } else { - DDebug("cache_read_agg", "%p: key: %X ReadRead retries exhausted, bailing..: %d", this, first_key.slice32(1), - (int)vio.ndone); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadRead retries exhausted, bailing..: %d", this, first_key.slice32(1), + (int)vio.ndone); goto Ldone; } } @@ -653,10 +669,10 @@ CacheVC::openReadMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) return calluser(VC_EVENT_EOS); } HTTPInfo::FragOffset *frags = alternate.get_frag_table(); - if (is_debug_tag_set("cache_seek")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_seek)) { char b[CRYPTO_HEX_SIZE], c[CRYPTO_HEX_SIZE]; - Debug("cache_seek", "Seek @ %" PRId64 " in %s from #%d @ %" PRId64 "/%d:%s", seek_to, first_key.toHexStr(b), fragment, - doc_pos, doc->len, doc->key.toHexStr(c)); + Dbg(dbg_ctl_cache_seek, "Seek @ %" PRId64 " in %s from #%d @ %" PRId64 "/%d:%s", seek_to, first_key.toHexStr(b), fragment, + doc_pos, doc->len, doc->key.toHexStr(c)); } /* Because single fragment objects can migrate to hang off an alt vector they can appear to the VC as multi-fragment when they are not really. @@ -699,10 +715,11 @@ CacheVC::openReadMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) --fragment; } - if (is_debug_tag_set("cache_seek")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_seek)) { char target_key_str[CRYPTO_HEX_SIZE]; key.toHexStr(target_key_str); - Debug("cache_seek", "Seek #%d @ %" PRId64 " -> #%d @ %" PRId64 ":%s", cfi, doc_pos, target, seek_to, target_key_str); + DbgPrint(dbg_ctl_cache_seek, "Seek #%d @ %" PRId64 " -> #%d @ %" PRId64 ":%s", cfi, doc_pos, target, seek_to, + target_key_str); } goto Lread; } @@ -715,10 +732,10 @@ CacheVC::openReadMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) seek_to = 0; ntodo = vio.ntodo(); bytes = doc->len - doc_pos; - if (is_debug_tag_set("cache_seek")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_seek)) { char target_key_str[CRYPTO_HEX_SIZE]; - Debug("cache_seek", "Read # %d @ %" PRId64 "/%d for %" PRId64 " %s", fragment, doc_pos, doc->len, bytes, - key.toHexStr(target_key_str)); + DbgPrint(dbg_ctl_cache_seek, "Read # %d @ %" PRId64 "/%d for %" PRId64 " %s", fragment, doc_pos, doc->len, bytes, + key.toHexStr(target_key_str)); } // This shouldn't happen for HTTP assets but it does @@ -820,15 +837,15 @@ Lread : { last_collision = nullptr; while (dir_probe(&earliest_key, vol, &dir, &last_collision)) { if (dir_offset(&dir) == dir_offset(&earliest_dir)) { - DDebug("cache_read_agg", "%p: key: %X ReadMain complete: %d", this, first_key.slice32(1), (int)vio.ndone); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadMain complete: %d", this, first_key.slice32(1), (int)vio.ndone); doc_len = vio.ndone; goto Leos; } } - DDebug("cache_read_agg", "%p: key: %X ReadMain writer aborted: %d", this, first_key.slice32(1), (int)vio.ndone); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadMain writer aborted: %d", this, first_key.slice32(1), (int)vio.ndone); goto Lerror; } - DDebug("cache_read_agg", "%p: key: %X ReadMain retrying: %d", this, first_key.slice32(1), (int)vio.ndone); + DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadMain retrying: %d", this, first_key.slice32(1), (int)vio.ndone); SET_HANDLER(&CacheVC::openReadMain); VC_SCHED_WRITER_RETRY(); } @@ -912,8 +929,8 @@ CacheVC::openReadStartEarliest(int /* event ATS_UNUSED */, Event * /* e ATS_UNUS vol->begin_read(this); if (vol->within_hit_evacuate_window(&earliest_dir) && (!cache_config_hit_evacuate_size_limit || doc_len <= static_cast(cache_config_hit_evacuate_size_limit))) { - DDebug("cache_hit_evac", "dir: %" PRId64 ", write: %" PRId64 ", phase: %d", dir_offset(&earliest_dir), - vol->offset_to_vol_offset(vol->header->write_pos), vol->header->phase); + DDbg(dbg_ctl_cache_hit_evac, "dir: %" PRId64 ", write: %" PRId64 ", phase: %d", dir_offset(&earliest_dir), + vol->offset_to_vol_offset(vol->header->write_pos), vol->header->phase); f.hit_evacuate = 1; } goto Lsuccess; @@ -1197,11 +1214,11 @@ CacheVC::openReadStartHead(int event, Event *e) doc_len = doc->total_len; } - if (is_debug_tag_set("cache_read")) { // amc debug + if (is_dbg_ctl_enabled(dbg_ctl_cache_read)) { // amc debug char xt[CRYPTO_HEX_SIZE], yt[CRYPTO_HEX_SIZE]; - Debug("cache_read", "CacheReadStartHead - read %s target %s - %s %d of %" PRId64 " bytes, %d fragments", - doc->key.toHexStr(xt), key.toHexStr(yt), f.single_fragment ? "single" : "multi", doc->len, doc->total_len, - alternate.get_frag_offset_count()); + DbgPrint(dbg_ctl_cache_read, "CacheReadStartHead - read %s target %s - %s %d of %" PRId64 " bytes, %d fragments", + doc->key.toHexStr(xt), key.toHexStr(yt), f.single_fragment ? "single" : "multi", doc->len, doc->total_len, + alternate.get_frag_offset_count()); } // the first fragment might have been gc'ed. Make sure the first // fragment is there before returning CACHE_EVENT_OPEN_READ @@ -1211,8 +1228,8 @@ CacheVC::openReadStartHead(int event, Event *e) if (vol->within_hit_evacuate_window(&dir) && (!cache_config_hit_evacuate_size_limit || doc_len <= static_cast(cache_config_hit_evacuate_size_limit))) { - DDebug("cache_hit_evac", "dir: %" PRId64 ", write: %" PRId64 ", phase: %d", dir_offset(&dir), - vol->offset_to_vol_offset(vol->header->write_pos), vol->header->phase); + DDbg(dbg_ctl_cache_hit_evac, "dir: %" PRId64 ", write: %" PRId64 ", phase: %d", dir_offset(&dir), + vol->offset_to_vol_offset(vol->header->write_pos), vol->header->phase); f.hit_evacuate = 1; } diff --git a/iocore/cache/CacheWrite.cc b/iocore/cache/CacheWrite.cc index 57783ac8d9c..10d9bbdf208 100644 --- a/iocore/cache/CacheWrite.cc +++ b/iocore/cache/CacheWrite.cc @@ -27,6 +27,26 @@ #define UINT_WRAP_GTE(_x, _y) (((_x) - (_y)) < INT_MAX) // exploit overflow #define UINT_WRAP_LT(_x, _y) (((_x) - (_y)) >= INT_MAX) // exploit overflow +namespace +{ + +DbgCtl dbg_ctl_cache_evac{"cache_evac"}; +DbgCtl dbg_ctl_cache_update{"cache_update"}; +DbgCtl dbg_ctl_cache_disk_error{"cache_disk_error"}; +DbgCtl dbg_ctl_cache_update_alt{"cache_update_alt"}; + +#ifdef DEBUG + +DbgCtl dbg_ctl_cache_agg{"cache_agg"}; +DbgCtl dbg_ctl_cache_stats{"cache_stats"}; +DbgCtl dbg_ctl_cache_write{"cache_write"}; +DbgCtl dbg_ctl_cache_insert{"cache_insert"}; +DbgCtl dbg_ctl_agg_read{"agg_read"}; + +#endif + +} // end anonymous namespace + // Given a key, finds the index of the alternate which matches // used to get the alternate which is actually present in the document int @@ -40,7 +60,6 @@ get_alternate_index(CacheHTTPInfoVector *cache_vector, CacheKey key) for (int i = 0; i < alt_count; i++) { obj = cache_vector->get(i); if (obj->compare_object_key(&key)) { - // Debug("cache_key", "Resident alternate key %X", key.slice32(0)); return i; } } @@ -71,8 +90,8 @@ CacheVC::updateVector(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) if (f.update) { // all Update cases. Need to get the alternate index. alternate_index = get_alternate_index(write_vector, update_key); - Debug("cache_update", "updating alternate index %d frags %d", alternate_index, - alternate_index >= 0 ? write_vector->get(alternate_index)->get_frag_offset_count() : -1); + Dbg(dbg_ctl_cache_update, "updating alternate index %d frags %d", alternate_index, + alternate_index >= 0 ? write_vector->get(alternate_index)->get_frag_offset_count() : -1); // if its an alternate delete if (!vec) { ink_assert(!total_len); @@ -167,8 +186,8 @@ CacheVC::updateVector(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) od->move_resident_alt = false; f.rewrite_resident_alt = 1; write_len = doc->data_len(); - Debug("cache_update_alt", "rewriting resident alt size: %d key: %X, first_key: %X", write_len, doc->key.slice32(0), - first_key.slice32(0)); + Dbg(dbg_ctl_cache_update_alt, "rewriting resident alt size: %d key: %X, first_key: %X", write_len, doc->key.slice32(0), + first_key.slice32(0)); } } header_len = write_vector->marshal_length(); @@ -290,8 +309,8 @@ Vol::force_evacuate_head(Dir *evac_dir, int pinned) { auto bucket = dir_evac_bucket(evac_dir); if (!evac_bucket_valid(bucket)) { - DDebug("cache_evac", "dir_evac_bucket out of bounds, skipping evacuate: %" PRId64 "(%d), %d, %d", bucket, evacuate_size, - (int)dir_offset(evac_dir), (int)dir_phase(evac_dir)); + DDbg(dbg_ctl_cache_evac, "dir_evac_bucket out of bounds, skipping evacuate: %" PRId64 "(%d), %d, %d", bucket, evacuate_size, + (int)dir_offset(evac_dir), (int)dir_phase(evac_dir)); return nullptr; } @@ -306,7 +325,7 @@ Vol::force_evacuate_head(Dir *evac_dir, int pinned) if (!b) { b = new_EvacuationBlock(mutex->thread_holding); b->dir = *evac_dir; - DDebug("cache_evac", "force: %d, %d", (int)dir_offset(evac_dir), (int)dir_phase(evac_dir)); + DDbg(dbg_ctl_cache_evac, "force: %d, %d", (int)dir_offset(evac_dir), (int)dir_phase(evac_dir)); evacuate[bucket].push(b); } b->f.pinned = pinned; @@ -327,7 +346,7 @@ Vol::scan_for_pinned_documents() int pe = this->offset_to_vol_offset(header->write_pos + 2 * EVACUATION_SIZE + (len / PIN_SCAN_EVERY)); int vol_end_offset = this->offset_to_vol_offset(len + skip); int before_end_of_vol = pe < vol_end_offset; - DDebug("cache_evac", "scan %d %d", ps, pe); + DDbg(dbg_ctl_cache_evac, "scan %d %d", ps, pe); for (int i = 0; i < this->direntries(); i++) { // is it a valid pinned object? if (!dir_is_empty(&dir[i]) && dir_pinned(&dir[i]) && dir_head(&dir[i])) { @@ -343,8 +362,6 @@ Vol::scan_for_pinned_documents() } } force_evacuate_head(&dir[i], 1); - // DDebug("cache_evac", "scan pinned at offset %d %d %d %d %d %d", - // (int)dir_offset(&b->dir), ps, o , pe, i, (int)b->f.done); } } } @@ -371,8 +388,8 @@ Vol::aggWriteDone(int event, Event *e) header->last_write_pos = header->write_pos; header->write_pos += io.aiocb.aio_nbytes; ink_assert(header->write_pos >= start); - DDebug("cache_agg", "Dir %s, Write: %" PRIu64 ", last Write: %" PRIu64 "", hash_text.get(), header->write_pos, - header->last_write_pos); + DDbg(dbg_ctl_cache_agg, "Dir %s, Write: %" PRIu64 ", last Write: %" PRIu64 "", hash_text.get(), header->write_pos, + header->last_write_pos); ink_assert(header->write_pos == header->agg_pos); if (header->write_pos + EVACUATION_SIZE > scan_pos) { periodic_scan(); @@ -382,11 +399,10 @@ Vol::aggWriteDone(int event, Event *e) } else { // delete all the directory entries that we inserted // for fragments is this aggregation buffer - Debug("cache_disk_error", "Write error on disk %s\n \ - write range : [%" PRIu64 " - %" PRIu64 " bytes] [%" PRIu64 " - %" PRIu64 " blocks] \n", - hash_text.get(), (uint64_t)io.aiocb.aio_offset, (uint64_t)io.aiocb.aio_offset + io.aiocb.aio_nbytes, - (uint64_t)io.aiocb.aio_offset / CACHE_BLOCK_SIZE, - (uint64_t)(io.aiocb.aio_offset + io.aiocb.aio_nbytes) / CACHE_BLOCK_SIZE); + Dbg(dbg_ctl_cache_disk_error, "Write error on disk %s\n \ + write range : [%" PRIu64 " - %" PRIu64 " bytes] [%" PRIu64 " - %" PRIu64 " blocks] \n", + hash_text.get(), (uint64_t)io.aiocb.aio_offset, (uint64_t)io.aiocb.aio_offset + io.aiocb.aio_nbytes, + (uint64_t)io.aiocb.aio_offset / CACHE_BLOCK_SIZE, (uint64_t)(io.aiocb.aio_offset + io.aiocb.aio_nbytes) / CACHE_BLOCK_SIZE); Dir del_dir; dir_clear(&del_dir); for (int done = 0; done < agg_buf_pos;) { @@ -465,8 +481,8 @@ CacheVC::evacuateReadHead(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */ } alternate_tmp = vector.get(alternate_index); doc_len = alternate_tmp->object_size_get(); - Debug("cache_evac", "evacuateReadHead http earliest %X first: %X len: %" PRId64, earliest_key.slice32(0), first_key.slice32(0), - doc_len); + Dbg(dbg_ctl_cache_evac, "evacuateReadHead http earliest %X first: %X len: %" PRId64, earliest_key.slice32(0), + first_key.slice32(0), doc_len); } else { // non-http document CacheKey next_key; @@ -475,8 +491,8 @@ CacheVC::evacuateReadHead(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */ goto Ldone; } doc_len = doc->total_len; - DDebug("cache_evac", "evacuateReadHead non-http earliest %X first: %X len: %" PRId64, earliest_key.slice32(0), - first_key.slice32(0), doc_len); + DDbg(dbg_ctl_cache_evac, "evacuateReadHead non-http earliest %X first: %X len: %" PRId64, earliest_key.slice32(0), + first_key.slice32(0), doc_len); } if (doc_len == total_len) { // the whole document has been evacuated. Insert the directory @@ -503,8 +519,8 @@ CacheVC::evacuateDocDone(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { ink_assert(vol->mutex->thread_holding == this_ethread()); Doc *doc = reinterpret_cast(buf->data()); - DDebug("cache_evac", "evacuateDocDone %X o %d p %d new_o %d new_p %d", (int)key.slice32(0), (int)dir_offset(&overwrite_dir), - (int)dir_phase(&overwrite_dir), (int)dir_offset(&dir), (int)dir_phase(&dir)); + DDbg(dbg_ctl_cache_evac, "evacuateDocDone %X o %d p %d new_o %d new_p %d", (int)key.slice32(0), (int)dir_offset(&overwrite_dir), + (int)dir_phase(&overwrite_dir), (int)dir_offset(&dir), (int)dir_phase(&dir)); int i = dir_evac_bucket(&overwrite_dir); // nasty beeping race condition, need to have the EvacuationBlock here EvacuationBlock *b = vol->evac_bucket_valid(i) ? vol->evacuate[i].head : nullptr; @@ -528,7 +544,8 @@ CacheVC::evacuateDocDone(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) break; } if (evac->earliest_key.fold()) { - DDebug("cache_evac", "evacdocdone: evacuating key %X earliest %X", evac->key.slice32(0), evac->earliest_key.slice32(0)); + DDbg(dbg_ctl_cache_evac, "evacdocdone: evacuating key %X earliest %X", evac->key.slice32(0), + evac->earliest_key.slice32(0)); EvacuationBlock *eblock = nullptr; Dir dir_tmp; dir_lookaside_probe(&evac->earliest_key, vol, &dir_tmp, &eblock); @@ -549,16 +566,16 @@ CacheVC::evacuateDocDone(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) // Cache::open_write). Once we know its the vector, we can // safely overwrite the first_key in the directory. if (dir_head(&overwrite_dir) && b->f.evacuate_head) { - DDebug("cache_evac", "evacuateDocDone evacuate_head %X %X hlen %d offset %d", (int)key.slice32(0), (int)doc->key.slice32(0), - doc->hlen, (int)dir_offset(&overwrite_dir)); + DDbg(dbg_ctl_cache_evac, "evacuateDocDone evacuate_head %X %X hlen %d offset %d", (int)key.slice32(0), + (int)doc->key.slice32(0), doc->hlen, (int)dir_offset(&overwrite_dir)); if (dir_compare_tag(&overwrite_dir, &doc->first_key)) { OpenDirEntry *cod; - DDebug("cache_evac", "evacuating vector: %X %d", (int)doc->first_key.slice32(0), (int)dir_offset(&overwrite_dir)); + DDbg(dbg_ctl_cache_evac, "evacuating vector: %X %d", (int)doc->first_key.slice32(0), (int)dir_offset(&overwrite_dir)); if ((cod = vol->open_read(&doc->first_key))) { // writer exists - DDebug("cache_evac", "overwriting the open directory %X %d %d", (int)doc->first_key.slice32(0), - (int)dir_offset(&cod->first_dir), (int)dir_offset(&dir)); + DDbg(dbg_ctl_cache_evac, "overwriting the open directory %X %d %d", (int)doc->first_key.slice32(0), + (int)dir_offset(&cod->first_dir), (int)dir_offset(&dir)); cod->first_dir = dir; } if (dir_overwrite(&doc->first_key, vol, &dir, &overwrite_dir)) { @@ -566,7 +583,7 @@ CacheVC::evacuateDocDone(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) vol->ram_cache->fixup(&doc->first_key, static_cast(o), static_cast(n)); } } else { - DDebug("cache_evac", "evacuating earliest: %X %d", (int)doc->key.slice32(0), (int)dir_offset(&overwrite_dir)); + DDbg(dbg_ctl_cache_evac, "evacuating earliest: %X %d", (int)doc->key.slice32(0), (int)dir_offset(&overwrite_dir)); ink_assert(dir_compare_tag(&overwrite_dir, &doc->key)); ink_assert(b->earliest_evacuator == this); total_len += doc->data_len(); @@ -621,8 +638,8 @@ evacuate_fragments(CacheKey *key, CacheKey *earliest_key, int force, Vol *vol) if (force) { b->readers = 0; } - DDebug("cache_evac", "next fragment %X Earliest: %X offset %d phase %d force %d", (int)key->slice32(0), - (int)earliest_key->slice32(0), (int)dir_offset(&dir), (int)dir_phase(&dir), force); + DDbg(dbg_ctl_cache_evac, "next fragment %X Earliest: %X offset %d phase %d force %d", (int)key->slice32(0), + (int)earliest_key->slice32(0), (int)dir_offset(&dir), (int)dir_phase(&dir), force); } return i; } @@ -660,13 +677,13 @@ Vol::evacuateDocReadDone(int event, Event *e) EvacuationBlock *b = nullptr; auto bucket = dir_evac_bucket(&doc_evacuator->overwrite_dir); if (doc->magic != DOC_MAGIC) { - Debug("cache_evac", "DOC magic: %X %d", (int)dir_tag(&doc_evacuator->overwrite_dir), - (int)dir_offset(&doc_evacuator->overwrite_dir)); + Dbg(dbg_ctl_cache_evac, "DOC magic: %X %d", (int)dir_tag(&doc_evacuator->overwrite_dir), + (int)dir_offset(&doc_evacuator->overwrite_dir)); ink_assert(doc->magic == DOC_MAGIC); goto Ldone; } - DDebug("cache_evac", "evacuateDocReadDone %X offset %d", (int)doc->key.slice32(0), - (int)dir_offset(&doc_evacuator->overwrite_dir)); + DDbg(dbg_ctl_cache_evac, "evacuateDocReadDone %X offset %d", (int)doc->key.slice32(0), + (int)dir_offset(&doc_evacuator->overwrite_dir)); if (evac_bucket_valid(bucket)) { b = evacuate[bucket].head; @@ -691,8 +708,8 @@ Vol::evacuateDocReadDone(int event, Event *e) if (dir_compare_tag(&b->dir, &doc->first_key)) { doc_evacuator->key = doc->first_key; b->evac_frags.key = doc->first_key; - DDebug("cache_evac", "evacuating vector %X offset %d", (int)doc->first_key.slice32(0), - (int)dir_offset(&doc_evacuator->overwrite_dir)); + DDbg(dbg_ctl_cache_evac, "evacuating vector %X offset %d", (int)doc->first_key.slice32(0), + (int)dir_offset(&doc_evacuator->overwrite_dir)); b->f.unused = 57; } else { // if its an earliest fragment (alternate) evacuation, things get @@ -704,8 +721,8 @@ Vol::evacuateDocReadDone(int event, Event *e) b->evac_frags.key = doc->key; b->evac_frags.earliest_key = doc->key; b->earliest_evacuator = doc_evacuator; - DDebug("cache_evac", "evacuating earliest %X %X evac: %p offset: %d", (int)b->evac_frags.key.slice32(0), - (int)doc->key.slice32(0), doc_evacuator, (int)dir_offset(&doc_evacuator->overwrite_dir)); + DDbg(dbg_ctl_cache_evac, "evacuating earliest %X %X evac: %p offset: %d", (int)b->evac_frags.key.slice32(0), + (int)doc->key.slice32(0), doc_evacuator, (int)dir_offset(&doc_evacuator->overwrite_dir)); b->f.unused = 67; } } else { @@ -720,7 +737,7 @@ Vol::evacuateDocReadDone(int event, Event *e) } doc_evacuator->key = ek->key; doc_evacuator->earliest_key = ek->earliest_key; - DDebug("cache_evac", "evacuateDocReadDone key: %X earliest: %X", (int)ek->key.slice32(0), (int)ek->earliest_key.slice32(0)); + DDbg(dbg_ctl_cache_evac, "evacuateDocReadDone key: %X earliest: %X", (int)ek->key.slice32(0), (int)ek->earliest_key.slice32(0)); b->f.unused = 87; } // if the tag in the c->dir does match the first_key in the @@ -774,7 +791,7 @@ Vol::evac_range(off_t low, off_t high, int evac_phase) io.aiocb.aio_buf = doc_evacuator->buf->data(); io.action = this; io.thread = AIO_CALLBACK_THREAD_ANY; - DDebug("cache_evac", "evac_range evacuating %X %d", (int)dir_tag(&first->dir), (int)dir_offset(&first->dir)); + DDbg(dbg_ctl_cache_evac, "evac_range evacuating %X %d", (int)dir_tag(&first->dir), (int)dir_offset(&first->dir)); SET_HANDLER(&Vol::evacuateDocReadDone); ink_assert(ink_aio_read(&io) >= 0); return -1; @@ -943,7 +960,7 @@ Vol::evacuate_cleanup_blocks(int i) if (b->f.done && ((header->phase != dir_phase(&b->dir) && header->write_pos > this->vol_offset(&b->dir)) || (header->phase == dir_phase(&b->dir) && header->write_pos <= this->vol_offset(&b->dir)))) { EvacuationBlock *x = b; - DDebug("cache_evac", "evacuate cleanup free %X offset %d", (int)b->evac_frags.key.slice32(0), (int)dir_offset(&b->dir)); + DDbg(dbg_ctl_cache_evac, "evacuate cleanup free %X offset %d", (int)b->evac_frags.key.slice32(0), (int)dir_offset(&b->dir)); b = b->link.next; evacuate[i].remove(x); free_EvacuationBlock(x, mutex->thread_holding); @@ -1039,7 +1056,8 @@ Vol::aggWrite(int event, void * /* e ATS_UNUSED */) if (agg_buf_pos + writelen > AGG_SIZE || header->write_pos + agg_buf_pos + writelen > (skip + len)) { break; } - DDebug("agg_read", "copying: %d, %" PRIu64 ", key: %d", agg_buf_pos, header->write_pos + agg_buf_pos, c->first_key.slice32(0)); + DDbg(dbg_ctl_agg_read, "copying: %d, %" PRIu64 ", key: %d", agg_buf_pos, header->write_pos + agg_buf_pos, + c->first_key.slice32(0)); int wrotelen = agg_copy(agg_buffer + agg_buf_pos, c); ink_assert(writelen == wrotelen); agg_todo_size -= writelen; @@ -1158,18 +1176,18 @@ CacheVC::openWriteCloseDir(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED * dir_delete(&earliest_key, vol, &earliest_dir); } } - if (is_debug_tag_set("cache_update")) { + if (is_dbg_ctl_enabled(dbg_ctl_cache_update)) { if (f.update && closed > 0) { if (!total_len && !f.allow_empty_doc && alternate_index != CACHE_ALT_REMOVED) { - Debug("cache_update", "header only %d (%" PRIu64 ", %" PRIu64 ")", DIR_MASK_TAG(first_key.slice32(2)), update_key.b[0], - update_key.b[1]); + Dbg(dbg_ctl_cache_update, "header only %d (%" PRIu64 ", %" PRIu64 ")", DIR_MASK_TAG(first_key.slice32(2)), update_key.b[0], + update_key.b[1]); } else if ((total_len || f.allow_empty_doc) && alternate_index != CACHE_ALT_REMOVED) { - Debug("cache_update", "header body, %d, (%" PRIu64 ", %" PRIu64 "), (%" PRIu64 ", %" PRIu64 ")", - DIR_MASK_TAG(first_key.slice32(2)), update_key.b[0], update_key.b[1], earliest_key.b[0], earliest_key.b[1]); + Dbg(dbg_ctl_cache_update, "header body, %d, (%" PRIu64 ", %" PRIu64 "), (%" PRIu64 ", %" PRIu64 ")", + DIR_MASK_TAG(first_key.slice32(2)), update_key.b[0], update_key.b[1], earliest_key.b[0], earliest_key.b[1]); } else if (!total_len && alternate_index == CACHE_ALT_REMOVED) { - Debug("cache_update", "alt delete, %d, (%" PRIu64 ", %" PRIu64 ")", DIR_MASK_TAG(first_key.slice32(2)), update_key.b[0], - update_key.b[1]); + Dbg(dbg_ctl_cache_update, "alt delete, %d, (%" PRIu64 ", %" PRIu64 ")", DIR_MASK_TAG(first_key.slice32(2)), update_key.b[0], + update_key.b[1]); } } } @@ -1179,7 +1197,7 @@ CacheVC::openWriteCloseDir(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED * // updates we dont decrement the variable corresponding the old // size of the document if ((closed == 1) && (total_len > 0 || f.allow_empty_doc)) { - DDebug("cache_stats", "Fragment = %d", fragment); + DDbg(dbg_ctl_cache_stats, "Fragment = %d", fragment); switch (fragment) { case 0: CACHE_INCREMENT_DYN_STAT(cache_single_fragment_document_count_stat); @@ -1402,7 +1420,7 @@ CacheVC::openWriteWriteDone(int event, Event *e) ++fragment; write_pos += write_len; dir_insert(&key, vol, &dir); - DDebug("cache_insert", "WriteDone: %X, %X, %d", key.slice32(0), first_key.slice32(0), write_len); + DDbg(dbg_ctl_cache_insert, "WriteDone: %X, %X, %d", key.slice32(0), first_key.slice32(0), write_len); blocks = iobufferblock_skip(blocks.get(), &offset, &length, write_len); next_CacheKey(&key, &key); } @@ -1579,8 +1597,8 @@ CacheVC::openWriteStartDone(int event, Event *e) to nullptr. */ if (!dir_valid(vol, &dir)) { - DDebug("cache_write", "OpenReadStartDone: Dir not valid: Write Head: %" PRId64 ", Dir: %" PRId64, - (int64_t)vol->offset_to_vol_offset(vol->header->write_pos), dir_offset(&dir)); + DDbg(dbg_ctl_cache_write, "OpenReadStartDone: Dir not valid: Write Head: %" PRId64 ", Dir: %" PRId64, + (int64_t)vol->offset_to_vol_offset(vol->header->write_pos), dir_offset(&dir)); last_collision = nullptr; goto Lcollision; } @@ -1812,7 +1830,7 @@ Cache::open_write(Continuation *cont, const CacheKey *key, CacheHTTPInfo *info, */ c->f.update = 1; c->base_stat = cache_update_active_stat; - DDebug("cache_update", "Update called"); + DDbg(dbg_ctl_cache_update, "Update called"); info->object_key_get(&c->update_key); ink_assert(!(c->update_key == zero_key)); c->update_len = info->object_size_get(); diff --git a/iocore/cache/P_CacheInternal.h b/iocore/cache/P_CacheInternal.h index ae2c998642e..63186f9be36 100644 --- a/iocore/cache/P_CacheInternal.h +++ b/iocore/cache/P_CacheInternal.h @@ -49,9 +49,9 @@ struct EvacuationBlock; #endif #ifdef DEBUG -#define DDebug(tag, fmt, ...) Debug(tag, fmt, ##__VA_ARGS__) +#define DDbg(dbg_ctl, fmt, ...) Dbg(dbg_ctl, fmt, ##__VA_ARGS__) #else -#define DDebug(tag, fmt, ...) +#define DDbg(dbg_ctl, fmt, ...) #endif #define AIO_SOFT_FAILURE -100000 @@ -563,7 +563,8 @@ new_CacheVC(Continuation *cont) c->start_time = Thread::get_hrtime(); c->setThreadAffinity(t); ink_assert(c->trigger == nullptr); - Debug("cache_new", "new %p", c); + static DbgCtl dbg_ctl{"cache_new"}; + Dbg(dbg_ctl, "new %p", c); #ifdef CACHE_STAT_PAGES ink_assert(!c->stat_link.next); ink_assert(!c->stat_link.prev); @@ -575,7 +576,8 @@ new_CacheVC(Continuation *cont) inline int free_CacheVC(CacheVC *cont) { - Debug("cache_free", "free %p", cont); + static DbgCtl dbg_ctl{"cache_free"}; + Dbg(dbg_ctl, "free %p", cont); ProxyMutex *mutex = cont->mutex.get(); Vol *vol = cont->vol; if (vol) { diff --git a/iocore/cache/RamCacheCLFUS.cc b/iocore/cache/RamCacheCLFUS.cc index 7ccb75b9bc0..093a4082475 100644 --- a/iocore/cache/RamCacheCLFUS.cc +++ b/iocore/cache/RamCacheCLFUS.cc @@ -48,6 +48,18 @@ #define AVERAGE_VALUE_OVER 100 #define REQUEUE_LIMIT 100 +#ifdef DEBUG + +namespace +{ + +DbgCtl dbg_ctl_ram_cache{"ram_cache"}; +DbgCtl dbg_ctl_ram_cache_compare{"ram_cache_compare"}; + +} // end anonymous namespace + +#endif + struct RamCacheCLFUSEntry { CryptoHash key; uint64_t auxkey; @@ -171,7 +183,7 @@ void RamCacheCLFUS::_resize_hashtable() { int anbuckets = bucket_sizes[this->_ibuckets]; - DDebug("ram_cache", "resize hashtable %d", anbuckets); + DDbg(dbg_ctl_ram_cache, "resize hashtable %d", anbuckets); int64_t s = anbuckets * sizeof(DList(RamCacheCLFUSEntry, hash_link)); DList(RamCacheCLFUSEntry, hash_link) *new_bucket = static_cast(ats_malloc(s)); memset(static_cast(new_bucket), 0, s); @@ -200,7 +212,7 @@ RamCacheCLFUS::init(int64_t abytes, Vol *avol) ink_assert(avol != nullptr); vol = avol; this->_max_bytes = abytes; - DDebug("ram_cache", "initializing ram_cache %" PRId64 " bytes", abytes); + DDbg(dbg_ctl_ram_cache, "initializing ram_cache %" PRId64 " bytes", abytes); if (!this->_max_bytes) { return; } @@ -311,25 +323,25 @@ RamCacheCLFUS::get(CryptoHash *key, Ptr *ret_data, uint64_t auxkey (*ret_data) = data; } CACHE_SUM_DYN_STAT_THREAD(cache_ram_cache_hits_stat, 1); - DDebug("ram_cache", "get %X %" PRId64 " size %d HIT", key->slice32(3), auxkey, e->size); + DDbg(dbg_ctl_ram_cache, "get %X %" PRId64 " size %d HIT", key->slice32(3), auxkey, e->size); return ram_hit_state; } else { CACHE_SUM_DYN_STAT_THREAD(cache_ram_cache_misses_stat, 1); - DDebug("ram_cache", "get %X %" PRId64 " HISTORY", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "get %X %" PRId64 " HISTORY", key->slice32(3), auxkey); return 0; } } assert(e != e->hash_link.next); e = e->hash_link.next; } - DDebug("ram_cache", "get %X %" PRId64 " MISS", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "get %X %" PRId64 " MISS", key->slice32(3), auxkey); Lerror: CACHE_SUM_DYN_STAT_THREAD(cache_ram_cache_misses_stat, 1); return 0; Lfailed: ats_free(b); this->_destroy(e); - DDebug("ram_cache", "get %X %" PRId64 " Z_ERR", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "get %X %" PRId64 " Z_ERR", key->slice32(3), auxkey); goto Lerror; } @@ -359,7 +371,7 @@ RamCacheCLFUS::_tick() this->_history--; uint32_t b = e->key.slice32(3) % this->_nbuckets; this->_bucket[b].remove(e); - DDebug("ram_cache", "put %X %" PRId64 " size %d FREED", e->key.slice32(3), e->auxkey, e->size); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " size %d FREED", e->key.slice32(3), e->auxkey, e->size); THREAD_FREE(e, ramCacheCLFUSEntryAllocator, this_thread()); } @@ -367,7 +379,7 @@ void RamCacheCLFUS::_victimize(RamCacheCLFUSEntry *e) { this->_objects--; - DDebug("ram_cache", "put %X %" PRId64 " size %d VICTIMIZED", e->key.slice32(3), e->auxkey, e->size); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " size %d VICTIMIZED", e->key.slice32(3), e->auxkey, e->size); e->data = nullptr; e->flag_bits.lru = 1; this->_lru[1].enqueue(e); @@ -403,7 +415,7 @@ RamCacheCLFUS::_destroy(RamCacheCLFUSEntry *e) } uint32_t b = e->key.slice32(3) % this->_nbuckets; this->_bucket[b].remove(e); - DDebug("ram_cache", "put %X %" PRId64 " DESTROYED", e->key.slice32(3), e->auxkey); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " DESTROYED", e->key.slice32(3), e->auxkey); THREAD_FREE(e, ramCacheCLFUSEntryAllocator, this_thread()); return ret; } @@ -550,8 +562,8 @@ RamCacheCLFUS::compress_entries(EThread *thread, int do_at_most) ats_free(b); e->flag_bits.incompressible = 1; Lcontinue:; - DDebug("ram_cache", "compress %X %" PRId64 " %d %d %d %d %d", e->key.slice32(3), e->auxkey, e->flag_bits.incompressible, - e->flag_bits.compressed, e->len, e->compressed_len, this->_ncompressed); + DDbg(dbg_ctl_ram_cache, "compress %X %" PRId64 " %d %d %d %d %d", e->key.slice32(3), e->auxkey, e->flag_bits.incompressible, + e->flag_bits.compressed, e->len, e->compressed_len, this->_ncompressed); if (!e->lru_link.next) { break; } @@ -617,7 +629,7 @@ RamCacheCLFUS::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool copy, check_accounting(this); e->flag_bits.copy = copy; e->flag_bits.compressed = 0; - DDebug("ram_cache", "put %X %" PRId64 " size %d HIT", key->slice32(3), auxkey, e->size); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " size %d HIT", key->slice32(3), auxkey, e->size); return 1; } else { this->_lru[1].remove(e); @@ -641,7 +653,7 @@ RamCacheCLFUS::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool copy, uint16_t kk = this->_seen[s]; this->_seen[s] = k; if (this->_history >= this->_objects && kk != k) { - DDebug("ram_cache", "put %X %" PRId64 " size %d UNSEEN", key->slice32(3), auxkey, size); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " size %d UNSEEN", key->slice32(3), auxkey, size); return 0; } } @@ -655,7 +667,7 @@ RamCacheCLFUS::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool copy, this->_lru[1].enqueue(e); } this->_requeue_victims(victims); - DDebug("ram_cache", "put %X %" PRId64 " NO VICTIM", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " NO VICTIM", key->slice32(3), auxkey); return 0; } this->_average_value = (CACHE_VALUE(victim) + (this->_average_value * (AVERAGE_VALUE_OVER - 1))) / AVERAGE_VALUE_OVER; @@ -676,11 +688,11 @@ RamCacheCLFUS::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool copy, if (!e) { goto Lhistory; } else { // e from history - DDebug("ram_cache_compare", "put %f %f", victim_value, CACHE_VALUE(e)); + DDbg(dbg_ctl_ram_cache_compare, "put %f %f", victim_value, CACHE_VALUE(e)); if (this->_bytes + victim->size + size > this->_max_bytes && victim_value > CACHE_VALUE(e)) { this->_requeue_victims(victims); this->_lru[1].enqueue(e); - DDebug("ram_cache", "put %X %" PRId64 " size %d INC %" PRId64 " HISTORY", key->slice32(3), auxkey, e->size, e->hits); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " size %d INC %" PRId64 " HISTORY", key->slice32(3), auxkey, e->size, e->hits); return 0; } } @@ -730,7 +742,7 @@ RamCacheCLFUS::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool copy, this->_lru[0].enqueue(e); e->len = len; check_accounting(this); - DDebug("ram_cache", "put %X %" PRId64 " size %d INSERTED", key->slice32(3), auxkey, e->size); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " size %d INSERTED", key->slice32(3), auxkey, e->size); return 1; Lhistory: this->_requeue_victims(victims); @@ -745,7 +757,7 @@ RamCacheCLFUS::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool copy, e->flag_bits.lru = 1; this->_lru[1].enqueue(e); this->_history++; - DDebug("ram_cache", "put %X %" PRId64 " HISTORY", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "put %X %" PRId64 " HISTORY", key->slice32(3), auxkey); return 0; } diff --git a/iocore/cache/RamCacheLRU.cc b/iocore/cache/RamCacheLRU.cc index 1103ee612a2..f62da888e98 100644 --- a/iocore/cache/RamCacheLRU.cc +++ b/iocore/cache/RamCacheLRU.cc @@ -58,6 +58,17 @@ struct RamCacheLRU : public RamCache { RamCacheLRUEntry *remove(RamCacheLRUEntry *e); }; +#ifdef DEBUG + +namespace +{ + +DbgCtl dbg_ctl_ram_cache{"ram_cache"}; + +} // end anonymous namespace + +#endif + int64_t RamCacheLRU::size() const { @@ -81,7 +92,7 @@ void RamCacheLRU::resize_hashtable() { int anbuckets = bucket_sizes[ibuckets]; - DDebug("ram_cache", "resize hashtable %d", anbuckets); + DDbg(dbg_ctl_ram_cache, "resize hashtable %d", anbuckets); int64_t s = anbuckets * sizeof(DList(RamCacheLRUEntry, hash_link)); DList(RamCacheLRUEntry, hash_link) *new_bucket = static_cast(ats_malloc(s)); memset(static_cast(new_bucket), 0, s); @@ -109,7 +120,7 @@ RamCacheLRU::init(int64_t abytes, Vol *avol) { vol = avol; max_bytes = abytes; - DDebug("ram_cache", "initializing ram_cache %" PRId64 " bytes", abytes); + DDbg(dbg_ctl_ram_cache, "initializing ram_cache %" PRId64 " bytes", abytes); if (!max_bytes) { return; } @@ -129,13 +140,13 @@ RamCacheLRU::get(CryptoHash *key, Ptr *ret_data, uint64_t auxkey) lru.remove(e); lru.enqueue(e); (*ret_data) = e->data; - DDebug("ram_cache", "get %X %" PRIu64 " HIT", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "get %X %" PRIu64 " HIT", key->slice32(3), auxkey); CACHE_SUM_DYN_STAT_THREAD(cache_ram_cache_hits_stat, 1); return 1; } e = e->hash_link.next; } - DDebug("ram_cache", "get %X %" PRIu64 " MISS", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "get %X %" PRIu64 " MISS", key->slice32(3), auxkey); CACHE_SUM_DYN_STAT_THREAD(cache_ram_cache_misses_stat, 1); return 0; } @@ -149,7 +160,7 @@ RamCacheLRU::remove(RamCacheLRUEntry *e) lru.remove(e); bytes -= ENTRY_OVERHEAD + e->data->block_size(); CACHE_SUM_DYN_STAT_THREAD(cache_ram_cache_bytes_stat, -(ENTRY_OVERHEAD + e->data->block_size())); - DDebug("ram_cache", "put %X %" PRIu64 " FREED", e->key.slice32(3), e->auxkey); + DDbg(dbg_ctl_ram_cache, "put %X %" PRIu64 " FREED", e->key.slice32(3), e->auxkey); e->data = nullptr; THREAD_FREE(e, ramCacheLRUEntryAllocator, this_thread()); objects--; @@ -169,7 +180,7 @@ RamCacheLRU::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool, uint64 uint16_t kk = seen[i]; seen[i] = k; if ((kk != k)) { - DDebug("ram_cache", "put %X %" PRIu64 " len %d UNSEEN", key->slice32(3), auxkey, len); + DDbg(dbg_ctl_ram_cache, "put %X %" PRIu64 " len %d UNSEEN", key->slice32(3), auxkey, len); return 0; } } @@ -204,7 +215,7 @@ RamCacheLRU::put(CryptoHash *key, IOBufferData *data, uint32_t len, bool, uint64 break; } } - DDebug("ram_cache", "put %X %" PRIu64 " INSERTED", key->slice32(3), auxkey); + DDbg(dbg_ctl_ram_cache, "put %X %" PRIu64 " INSERTED", key->slice32(3), auxkey); if (objects > nbuckets) { ++ibuckets; resize_hashtable();