This is an automated email from the ASF dual-hosted git repository. kturner pushed a commit to branch 2.1 in repository https://gitbox.apache.org/repos/asf/accumulo.git
The following commit(s) were added to refs/heads/2.1 by this push: new e981057599 adds detailed trace logging for block caches (#4872) e981057599 is described below commit e981057599647085069083453f519a817806827d Author: Keith Turner <ktur...@apache.org> AuthorDate: Fri Sep 13 13:47:43 2024 -0400 adds detailed trace logging for block caches (#4872) Adds detailed trace logging for the accumulo block caches that can be used for scans. With the following log4j config ``` logger.cache.name = org.apache.accumulo.cache logger.cache.level = trace ``` can see output like the following with these changes when running a few scans. ``` 2024-09-10T23:08:47,821 [accumulo.cache] TRACE: INDEX loader:299585732 getDependencies() returned [hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rf!RootData] 2024-09-10T23:08:47,828 [accumulo.cache] TRACE: INDEX loader:299585732 load(201326592,{hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rf!RootData=65}) returned 113 bytes in 823μs 2024-09-10T23:08:47,828 [accumulo.cache] TRACE: INDEX getBlock(hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rfMRFile.index, loader:299585732) returned 113 bytes in 6924μs 2024-09-10T23:08:47,829 [accumulo.cache] TRACE: DATA getBlock(hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rfR16, loader:1259534108) returned 101125 bytes in 865μs 2024-09-10T23:09:00,692 [accumulo.cache] TRACE: DATA getBlock(hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rfR16, loader:161430432) returned 101125 bytes in 5μs 2024-09-10T23:09:01,579 [accumulo.cache] TRACE: DATA getBlock(hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rfR16, loader:1386294126) returned 101125 bytes in 8μs 2024-09-10T23:09:02,323 [accumulo.cache] TRACE: DATA getBlock(hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rfR16, loader:740950152) returned 101125 bytes in 9μs 2024-09-10T23:09:03,011 [accumulo.cache] TRACE: DATA getBlock(hdfs://localhost:8020/accumulo/tables/1/default_tablet/A000003t.rfR16, loader:1766289486) returned 101125 bytes in 9μs ``` --- .../file/blockfile/impl/ScanCacheProvider.java | 19 +-- .../accumulo/core/logging/LoggingBlockCache.java | 131 +++++++++++++++++++++ .../accumulo/core/summary/SummaryReader.java | 6 +- src/build/ci/find-unapproved-chars.sh | 2 +- 4 files changed, 149 insertions(+), 9 deletions(-) diff --git a/core/src/main/java/org/apache/accumulo/core/file/blockfile/impl/ScanCacheProvider.java b/core/src/main/java/org/apache/accumulo/core/file/blockfile/impl/ScanCacheProvider.java index f82f534cf5..78b8600b37 100644 --- a/core/src/main/java/org/apache/accumulo/core/file/blockfile/impl/ScanCacheProvider.java +++ b/core/src/main/java/org/apache/accumulo/core/file/blockfile/impl/ScanCacheProvider.java @@ -20,7 +20,9 @@ package org.apache.accumulo.core.file.blockfile.impl; import org.apache.accumulo.core.conf.AccumuloConfiguration; import org.apache.accumulo.core.conf.Property; +import org.apache.accumulo.core.logging.LoggingBlockCache; import org.apache.accumulo.core.spi.cache.BlockCache; +import org.apache.accumulo.core.spi.cache.CacheType; import org.apache.accumulo.core.spi.scan.ScanDispatch; public class ScanCacheProvider implements CacheProvider { @@ -30,19 +32,23 @@ public class ScanCacheProvider implements CacheProvider { public ScanCacheProvider(AccumuloConfiguration tableConfig, ScanDispatch dispatch, BlockCache indexCache, BlockCache dataCache) { + + var loggingIndexCache = LoggingBlockCache.wrap(CacheType.INDEX, indexCache); + var loggingDataCache = LoggingBlockCache.wrap(CacheType.DATA, dataCache); + switch (dispatch.getIndexCacheUsage()) { case ENABLED: - this.indexCache = indexCache; + this.indexCache = loggingIndexCache; break; case DISABLED: this.indexCache = null; break; case OPPORTUNISTIC: - this.indexCache = new OpportunisticBlockCache(indexCache); + this.indexCache = new OpportunisticBlockCache(loggingIndexCache); break; case TABLE: this.indexCache = - tableConfig.getBoolean(Property.TABLE_INDEXCACHE_ENABLED) ? indexCache : null; + tableConfig.getBoolean(Property.TABLE_INDEXCACHE_ENABLED) ? loggingIndexCache : null; break; default: throw new IllegalStateException(); @@ -50,22 +56,21 @@ public class ScanCacheProvider implements CacheProvider { switch (dispatch.getDataCacheUsage()) { case ENABLED: - this.dataCache = dataCache; + this.dataCache = loggingDataCache; break; case DISABLED: this.dataCache = null; break; case OPPORTUNISTIC: - this.dataCache = new OpportunisticBlockCache(dataCache); + this.dataCache = new OpportunisticBlockCache(loggingDataCache); break; case TABLE: this.dataCache = - tableConfig.getBoolean(Property.TABLE_BLOCKCACHE_ENABLED) ? dataCache : null; + tableConfig.getBoolean(Property.TABLE_BLOCKCACHE_ENABLED) ? loggingDataCache : null; break; default: throw new IllegalStateException(); } - } @Override diff --git a/core/src/main/java/org/apache/accumulo/core/logging/LoggingBlockCache.java b/core/src/main/java/org/apache/accumulo/core/logging/LoggingBlockCache.java new file mode 100644 index 0000000000..d1239493ce --- /dev/null +++ b/core/src/main/java/org/apache/accumulo/core/logging/LoggingBlockCache.java @@ -0,0 +1,131 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.accumulo.core.logging; + +import java.util.Map; +import java.util.concurrent.TimeUnit; + +import org.apache.accumulo.core.spi.cache.BlockCache; +import org.apache.accumulo.core.spi.cache.CacheEntry; +import org.apache.accumulo.core.spi.cache.CacheType; +import org.apache.accumulo.core.util.Timer; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import com.google.common.collect.Maps; + +/** + * Provides trace level logging of block cache activity. + */ +public class LoggingBlockCache implements BlockCache { + + private final BlockCache blockCache; + private static final Logger log = LoggerFactory.getLogger(Logging.PREFIX + "cache"); + private final CacheType type; + + private LoggingBlockCache(CacheType type, BlockCache blockCache) { + this.type = type; + this.blockCache = blockCache; + } + + private static String toString(CacheEntry ce) { + return ce == null ? null : ce.getBuffer().length + " bytes"; + } + + @Override + public CacheEntry cacheBlock(String blockName, byte[] buf) { + var timer = Timer.startNew(); + var ce = blockCache.cacheBlock(blockName, buf); + var elapsed = timer.elapsed(TimeUnit.MICROSECONDS); + log.trace("{} cacheBlock({},{} bytes) returned {} in {}μs", type, blockName, buf.length, + toString(ce), elapsed); + return ce; + } + + @Override + public CacheEntry getBlock(String blockName) { + var timer = Timer.startNew(); + var ce = blockCache.getBlock(blockName); + var elapsed = timer.elapsed(TimeUnit.MICROSECONDS); + log.trace("{} getBlock({}) returned {} in {}μs", type, blockName, toString(ce), elapsed); + return ce; + + } + + private final class LoggingLoader implements Loader { + private final Loader loader; + + private LoggingLoader(Loader loader) { + this.loader = loader; + } + + @Override + public Map<String,Loader> getDependencies() { + var deps = loader.getDependencies(); + log.trace("{} loader:{} getDependencies() returned {}", type, loader.hashCode(), + deps.keySet()); + return Maps.transformValues(deps, secondLoader -> new LoggingLoader(secondLoader)); + } + + @Override + public byte[] load(int maxSize, Map<String,byte[]> dependencies) { + var timer = Timer.startNew(); + byte[] data = loader.load(maxSize, dependencies); + var elapsed = timer.elapsed(TimeUnit.MICROSECONDS); + Map<String,Integer> logDeps = + Maps.transformValues(dependencies, bytes -> bytes == null ? null : bytes.length); + log.trace("{} loader:{} load({},{}) returned {} in {}μs", type, loader.hashCode(), maxSize, + logDeps, data == null ? null : data.length + " bytes", elapsed); + return data; + } + } + + @Override + public CacheEntry getBlock(String blockName, Loader loader) { + var timer = Timer.startNew(); + var ce = blockCache.getBlock(blockName, new LoggingLoader(loader)); + var elapsed = timer.elapsed(TimeUnit.MICROSECONDS); + log.trace("{} getBlock({}, loader:{}) returned {} in {}μs", type, blockName, loader.hashCode(), + toString(ce), elapsed); + return ce; + } + + @Override + public long getMaxHeapSize() { + return blockCache.getMaxHeapSize(); + } + + @Override + public long getMaxSize() { + return blockCache.getMaxSize(); + } + + @Override + public Stats getStats() { + return blockCache.getStats(); + } + + public static BlockCache wrap(CacheType type, BlockCache blockCache) { + if (blockCache != null && log.isTraceEnabled() && !(blockCache instanceof LoggingBlockCache)) { + return new LoggingBlockCache(type, blockCache); + } else { + return blockCache; + } + } +} diff --git a/core/src/main/java/org/apache/accumulo/core/summary/SummaryReader.java b/core/src/main/java/org/apache/accumulo/core/summary/SummaryReader.java index 3a645c21dd..cce1044e65 100644 --- a/core/src/main/java/org/apache/accumulo/core/summary/SummaryReader.java +++ b/core/src/main/java/org/apache/accumulo/core/summary/SummaryReader.java @@ -37,8 +37,10 @@ import org.apache.accumulo.core.file.blockfile.impl.CachableBlockFile; import org.apache.accumulo.core.file.blockfile.impl.CachableBlockFile.CachableBuilder; import org.apache.accumulo.core.file.rfile.RFile.Reader; import org.apache.accumulo.core.file.rfile.bcfile.MetaBlockDoesNotExist; +import org.apache.accumulo.core.logging.LoggingBlockCache; import org.apache.accumulo.core.spi.cache.BlockCache; import org.apache.accumulo.core.spi.cache.CacheEntry; +import org.apache.accumulo.core.spi.cache.CacheType; import org.apache.accumulo.core.spi.crypto.CryptoService; import org.apache.accumulo.core.summary.Gatherer.RowRange; import org.apache.hadoop.conf.Configuration; @@ -191,7 +193,9 @@ public class SummaryReader { try { // the reason BCFile is used instead of RFile is to avoid reading in the RFile meta block when // only summary data is wanted. - CompositeCache compositeCache = new CompositeCache(summaryCache, indexCache); + CompositeCache compositeCache = + new CompositeCache(LoggingBlockCache.wrap(CacheType.SUMMARY, summaryCache), + LoggingBlockCache.wrap(CacheType.INDEX, indexCache)); CachableBuilder cb = new CachableBuilder().fsPath(fs, file).conf(conf).fileLen(fileLenCache) .cacheProvider(new BasicCacheProvider(compositeCache, null)).cryptoService(cryptoService); bcReader = new CachableBlockFile.Reader(cb); diff --git a/src/build/ci/find-unapproved-chars.sh b/src/build/ci/find-unapproved-chars.sh index 5f7c7b0efa..bb017badcb 100755 --- a/src/build/ci/find-unapproved-chars.sh +++ b/src/build/ci/find-unapproved-chars.sh @@ -22,7 +22,7 @@ # unintentionally, or maliciously, add any new non-ASCII characters unless they # are preapproved on the ALLOWED list or in known binary or resource files NUM_EXPECTED=0 -ALLOWED='©èö🐈三四五六八九十' +ALLOWED='©èö🐈三四五六八九十μ' function findallnonascii() { # -P for perl matching, -o for only showing the match for counting occurrences not lines