diff --git a/.github/workflows/lru-cache-example.yml b/.github/workflows/lru-cache-example.yml new file mode 100644 index 0000000..d9d0ae3 --- /dev/null +++ b/.github/workflows/lru-cache-example.yml @@ -0,0 +1,36 @@ +# This workflow will build a Java project with Maven, and cache/restore any dependencies to improve the workflow execution time +# For more information see: https://docs.github.com/en/actions/automating-builds-and-tests/building-and-testing-java-with-maven + +# This workflow uses actions that are not certified by GitHub. +# They are provided by a third-party and are governed by +# separate terms of service, privacy policy, and support +# documentation. + +name: Instrumented LRU Cache Example + +on: + push: + branches: [ "main" ] + pull_request: + branches: [ "main" ] + +jobs: + build: + + runs-on: ubuntu-latest + strategy: + matrix: + java_version: [ 21 ] + + steps: + - uses: actions/checkout@v4 + - name: Set up JDK ${{ matrix.java_version }} + uses: actions/setup-java@v4 + with: + java-version: ${{ matrix.java_version }} + distribution: 'temurin' + cache: maven + - name: Build with Maven + run: cd examples/lrucache && mvn -q compile exec:exec + + diff --git a/README.md b/README.md index f1e3dc0..359dfd7 100644 --- a/README.md +++ b/README.md @@ -46,6 +46,7 @@ To use free form tracing, check traceInstant. ### Examples +(In addition to the examples below, also see under root folder `examples/lrucache` for an example that generates interesting traces, inspired by a real-life investigation about the performance of an application's cache.) To instrument diff --git a/examples/lrucache/.gitignore b/examples/lrucache/.gitignore new file mode 100644 index 0000000..35ed677 --- /dev/null +++ b/examples/lrucache/.gitignore @@ -0,0 +1 @@ +traces/ \ No newline at end of file diff --git a/examples/lrucache/README.md b/examples/lrucache/README.md new file mode 100644 index 0000000..8d84c7d --- /dev/null +++ b/examples/lrucache/README.md @@ -0,0 +1,343 @@ +# LRU cache example + +This is inspired from a real-life scenario where nice traces were obtained :) + +The program is a toy LRU cache backing a data structure. Reader threads each access the data structure sequentially through the cache. When the cache contains an element, it's returned really quick, else there's a delay to simulate it being loaded from slower storage (e.g. disk). The size of the data struct and cache are configurable, as well as the number of reader thread and a few other parameters. + +## Real-life case + +This toy example was inspired by a real-life investigation, regarding a web-accessible application that had configurable caches, including a specific one whose performance came under scrutiny. + +The main symptoms were that some performance problems coincided with that cache being used intensively. It was also noticed that though the cache was used by multiple threads concurrently, that should have been completely independent in their execution, they seem to end-up synchronized, executing in lock-step, and finishing execution almost at the same time. + +That investigation produced some interesting traces, which we aim to approximately replicate with this example. + +### Real life investigation - some info about that cache: + +`type`: LRU (least recently used) - when the cache is full, the cache element that was the least recently used is evicted to make space for a new element to be inserted in its place. + +`configurable cache size`: The number of elements it can hold is configurable by the app's admins + +`Cache usage`: The cache is used in a peculiar way. Thought the cached data can be accessed randomly, it's often accessed sequentially, from first element to the last, in order. The app is multi-threaded and often multiple reader threads would be reading the data through the cache, in parallel. + +The app provides cache statistics, which seemed quite good (a high cache "hit" rate was reported) despite the. + +### Investigation goal + +The cache was configured to be slightly under-sized vs the data it was caching, which size (number of elements) was slowly but surely increasing. Given the good reported cache stats, was it an issue that it was a bit undersized (by ~15%)? Was the cache, as configured, potentially affecting performance? + +### Tracing to the rescue! + +The cache and reader thread code were instrumented. From the generated traces, it was possible to distinguish cache hits vs misses. Capturing traces for a few scenarios, some surprising details started to emerge + +## Build and run the example: + +### Configuration + +The example has several configurable parameters, that can be provided as CLI arguments or through maven config: + +- --cache-size: number of elements the cache can hold +- --data-size: number of elements contained in the structure to be cached +- --num-threads: number of reader threads that will read the structure through the cache +- --readers-startup-delay-ms: delay between starting reader threads +- --cache-miss-delay-ms: delay to use when a cache miss occurs, e.g. to simulate the data being read from a slower source (e.g. disk or network) +- --log-warmup: whether or not to include the cache warm-up loop in the generated traces +- --verbose: Whether to have verbose, detailed output on STDOUT + + +When run using maven, one can tweak the configuration by editing their values in local `pom.xml`, section `configuration` under `exec-maven-plugin`: + +```xml +[...] +--cache-size=95 +--data-size=100 +--num-threads=10 +--readers-startup-delay-ms=130 +--cache-miss-delay-ms=6 +--log-warmup=true +--verbose=false +``` + +### Running the example + +After having configured it as wanted in `pom.xml`: + +```bash +$ cd examples/lrucache +$ mvn -q compile exec:exec +``` + +The generated trace will be under sub-folder `traces/`. + +### Opening the generated trace in Trace Compass + +First, run `jsonify.py` on the generated trace. The first time, it's necessary to install a couple of Python dependencies - see near the top of `jsonify.py` for the "pip" command to run. + +```bash +$ cd examples/lrucache/traces +# "massage" the trace into valid json - +# feel free to give it a more descriptive name +# (second parameter): +../../../jsonify.py trace.log cache_trace.json +# If everything went well "cache_trace.json" can be +# opened in Trace Compass! +``` + +#### Trace Compass + +If you do not already have it, download the Trace Compass RCP and unzip it to a convenient place, then start it. + +Create a new tracing project, expand it. Select "traces" and right-click, select "open trace", navigate-to and select the newly generated cache trace. Then right-click on the new trace and hover "Select trace type". Confirm if there is a "Trace Event Format" entry. If so, select "Generic Trace Event Trace" under it, as the trace type. Else, we need to install support for this format: + +`Help` -> `Install New Software`, then search for "trace event". Under +category `Trace Types`, install: +`Trace Compass TraceEvent Parser (incubator)` + +With the correct trace type selected, double-click on the trace to open it. Under it, there should be an expendable "views" item, and under it two "Thread by Component" entries - expand the second one, and select "Flame Chart (new callback)" under it. + + +## Playing with the example + +With the mechanical aspect out of the way, here's some suggestions for interesting configurations to try, that should generate interesting traces, from which a deeper understanding of the LRU cache, as it's used in the example, can be gained. + +### 1) Warm-up and then 1 reader thread + +The warm-up populates the cache, hopefully making it ready for a "real" reader to use it. Compare the performance of 1 reader thread, when the cache is fully sized (100/100) vs slightly undersized (95/100): + +#### Traces to capture + +a) +```xml + +--cache-size=20 +--data-size=20 +--num-threads=1 +--readers-startup-delay-ms=0 +--cache-miss-delay-ms=6 +--log-warmup=true +--verbose=false +``` + +b) +```xml + +--cache-size=19 +--data-size=20 +--num-threads=1 +--readers-startup-delay-ms=0 +--cache-miss-delay-ms=6 +--log-warmup=true +--verbose=false +``` + +#### Sample results (STDOUT) + +a) Fully sized cache +``` +--- Cache Stats --- +Total Requests : 20 +Cache Hits : 20 (100.00%) +Cache Misses : 0 (0.00%) +Avg get() Time/Op: 0.469 ms +Total get() Time : 9 ms +------------------- +``` + +b) Slightly undersized cache +``` +--- Cache Stats --- +Total Requests : 20 +Cache Hits : 0 (0.00%) +Cache Misses : 20 (100.00%) +Avg get() Time/Op: 8.044 ms +Total get() Time : 160 ms +------------------- +``` + +#### Leads + +- How to explain the slightly undersized cache has `100%` miss rate? +- Performance has decreased by ~20x, probably because the cache never hits? + + +### 2) Warm-up then 5 reader threads started at once + +The warm-up populates the cache, hopefully making it ready for a "real" reader to use it. + +Compare the performance when the cache is fully sized (100/100) vs slightly undersized (95/100): + +#### Traces to capture + +a) +```xml + +--cache-size=20 +--data-size=20 +--num-threads=5 +--readers-startup-delay-ms=0 +--cache-miss-delay-ms=6 +--log-warmup=true +``` + +b) +```xml + +--cache-size=19 +--data-size=20 +--num-threads=5 +--readers-startup-delay-ms=0 +--cache-miss-delay-ms=6 +--log-warmup=true +--verbose=false +``` + +#### Sample results (STDOUT) + +a) Fully sized cache +``` +--- Cache Stats --- +Total Requests : 100 +Cache Hits : 100 (100.00%) +Cache Misses : 0 (0.00%) +Avg get() Time/Op: 0.581 ms +Total get() Time : 58 ms +------------------- +``` + +b) Slightly undersized cache +``` +--- Cache Stats --- +Total Requests : 100 +Cache Hits : 80 (80.00%) +Cache Misses : 20 (20.00%) +Avg get() Time/Op: 7.446 ms +Total get() Time : 744 ms +------------------- +``` + +#### Leads + +- How to explain the disproportional decrease in performance between the fully sized caches vs 95% sized results? It's a ~12x factor! + +### 3) Warm-up then 5 reader threads started with a delay + +The warm-up populates the cache, hopefully making it ready for a "real" reader to use it. + +Compare the performance when the cache is fully sized (100/100) vs slightly undersized (95/100): + +#### Traces to capture + +a) +```xml + +--cache-size=20 +--data-size=20 +--num-threads=5 +--readers-startup-delay-ms=25 +--cache-miss-delay-ms=6 +--log-warmup=true +``` + +b) +```xml + +--cache-size=19 +--data-size=20 +--num-threads=5 +--readers-startup-delay-ms=25 +--cache-miss-delay-ms=6 +--log-warmup=true +--verbose=false +``` + +#### Sample results (STDOUT) + +a) Fully sized cache +``` +--- Cache Stats --- +Total Requests : 100 +Cache Hits : 100 (100.00%) +Cache Misses : 0 (0.00%) +Avg get() Time/Op: 0.187 ms +Total get() Time : 18 ms +------------------- +``` + +b) Slightly undersized cache +``` +--- Cache Stats --- +Total Requests : 100 +Cache Hits : 80 (80.00%) +Cache Misses : 20 (20.00%) +Avg get() Time/Op: 5.026 ms +Total get() Time : 502 ms +------------------- +``` + +#### Leads + +- How to explain the disproportional decrease in performance between the fully sized caches vs 95% sized results? +- Looking at the captured traces, do reader thread executions overlap in both cases? Any unexpected effect of overlap when the cache is undersized (e.g. unintended thread synchronization or lockstep effect)? +- zooming-in, in a zone in the trace where two or more threads seem to execute in "lockstep", examine one particular iteration + - how many of the reader threads end-up having a cache miss? + - how does iteration execution time compare between the reader thread that has a cache miss vs those who have a "cache hit after waiting"? + - in such a situation, is there a meaningful performance gain in a reported cache miss vs hit? + +### 4) "At scale" run + +This run we will push the limits a bit to generate a nice, rather big trace. + +Compare the performance when the cache is fully sized (100/100) vs slightly undersized (95/100): + +#### Traces to capture + +a) +```xml + +--cache-size=100 +--data-size=100 +--num-threads=10 +--readers-startup-delay-ms=130 +--cache-miss-delay-ms=6 +--log-warmup=true +``` + +b) +```xml + +--cache-size=95 +--data-size=100 +--num-threads=10 +--readers-startup-delay-ms=130 +--cache-miss-delay-ms=6 +--log-warmup=true +--verbose=false +``` + +#### Sample results (STDOUT) + +a) Fully sized cache +``` +--- Cache Stats --- +Total Requests : 1000 +Cache Hits : 1000 (100.00%) +Cache Misses : 0 (0.00%) +Avg get() Time/Op: 0.083 ms +Total get() Time : 82 ms +------------------- +``` + +b) Slightly undersized cache +``` +--- Cache Stats --- +Total Requests : 1000 +Cache Hits : 806 (80.60%) +Cache Misses : 194 (19.40%) +Avg get() Time/Op: 3.985 ms +Total get() Time : 3985 ms +------------------- +``` + +#### Leads + +Nothing new, but look how nice the trace looks :) diff --git a/examples/lrucache/logging.properties b/examples/lrucache/logging.properties new file mode 100644 index 0000000..fc98566 --- /dev/null +++ b/examples/lrucache/logging.properties @@ -0,0 +1,41 @@ +# MIT License +# +# Copyright (c) 2024, 2025 Ericsson +# +# Permission is hereby granted, free of charge, to any person obtaining a copy +# of this software and associated documentation files (the "Software"), to deal +# in the Software without restriction, including without limitation the rights +# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +# copies of the Software, and to permit persons to whom the Software is +# furnished to do so, subject to the following conditions: +# +# The above copyright notice and this permission notice shall be included in all +# copies or substantial portions of the Software. +# +# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY#, +# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +# SOFTWARE. +# +# SPDX-License-Identifier: MIT + +# used in AsyncFileHandlerTest as well as SnapshotTest + +handlers=org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler + +.level = ALL + +java.util.logging.FileHandler.pattern = ./traces/trace.log +java.util.logging.SimpleFormatter.format = "%5$s%n" +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.maxSize = 1000 +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.queueDepth = 20 +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.flushRate = 250 +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.formatter = java.util.logging.SimpleFormatter +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.filter = org.eclipse.tracecompass.traceeventlogger.FailFilter +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.encoding = UTF-8 +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.errormanager = java.util.logging.ErrorManager +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.level = FINER + diff --git a/examples/lrucache/pom.xml b/examples/lrucache/pom.xml new file mode 100644 index 0000000..65b32eb --- /dev/null +++ b/examples/lrucache/pom.xml @@ -0,0 +1,72 @@ + + + + + 4.0.0 + + org.example + lrucachedemo + 1.0-SNAPSHOT + + + UTF-8 + 11 + 11 + + + + + org.eclipse.tracecompass + trace-event-logger + 0.5.0 + + + + + + + + maven-compiler-plugin + 3.11.0 + + 11 + + + + + + org.codehaus.mojo + exec-maven-plugin + 3.1.0 + + + + exec + + + + + java + + -Djava.util.logging.config.file=logging.properties + -cp + + org.eclipse.tracecompass.traceeventlogger.lrucachedemo.Main + + --cache-size=24 + --data-size=25 + --num-threads=4 + --readers-startup-delay-ms=30 + --cache-miss-delay-ms=6 + --log-warmup=true + --verbose=false + + + + + + + diff --git a/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/Config.java b/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/Config.java new file mode 100644 index 0000000..a1ef538 --- /dev/null +++ b/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/Config.java @@ -0,0 +1,119 @@ +/******************************************************************************* + * Copyright (c) 2025 Ericsson + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the “Software”), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * SPDX-License-Identifier: MIT + *******************************************************************************/ +package org.eclipse.tracecompass.traceeventlogger.lrucachedemo; + +/** + * Config class that parses CLI arguments and provides the + * parameters to run the simulation + */ +public class Config { + /** + * Number of elements the cache can contain + */ + public int cacheSize = 100; + /** + * Number of elements in the data to be cached + */ + public int dataSize = 100; + /** + * The delay in ms to be used when a data element is + * "loaded", to simulate it being accesses from a slower + * source, e.g. disk, network, or carrier pigeon + */ + public int cacheMissDelayMs = 5; + /** + * Number of reader threads, that each will be + * reading the data through the cache + */ + public int numThreads = 20; + /** + * The delay between reader threads start up + */ + public int readersStartupDelayMs = 50; + /** + * Whether or not to write to trace log, the cache warm-up phase, + * where each element of the data is read once to populate the + * cache + */ + public boolean logWarmup = false; + /** + * Whether or not to write detailed information on STDOUT + */ + public boolean verbose = false; + + private static Config instance; + + /** + * @return an instance of the static config object + */ + public static Config getInstance() { + return instance; + } + + /** + * @param args CLI arguments the simulator was called-with + * @return a static instance of the Config object that contains the + * simulation's parameters for this run, that reflects the + * CLI arguments provided, and when not, the default values + * to be used. + */ + @SuppressWarnings("nls") + public static Config fromArgs(String[] args) { + Config config = new Config(); + for (String arg : args) { + if (arg.startsWith("--cache-size=")) { + config.cacheSize = Integer.parseInt(arg.split("=")[1]); + } else if (arg.startsWith("--data-size=")) { + config.dataSize = Integer.parseInt(arg.split("=")[1]); + } else if (arg.startsWith("--num-threads=")) { + config.numThreads = Integer.parseInt(arg.split("=")[1]); + } else if (arg.startsWith("--cache-miss-delay-ms=")) { + config.cacheMissDelayMs = Integer.parseInt(arg.split("=")[1]); + } else if (arg.startsWith("--readers-startup-delay-ms=")) { + config.readersStartupDelayMs = Integer.parseInt(arg.split("=")[1]); + } else if (arg.startsWith("--log-warmup=")) { + config.logWarmup = Boolean.parseBoolean(arg.split("=")[1]); + } else if (arg.startsWith("--verbose=")) { + config.verbose = Boolean.parseBoolean(arg.split("=")[1]); + } + } + instance = config; + return instance; + } + + /** + * Prints the current configuration + */ + @SuppressWarnings("nls") + public static void printConfig() { + System.out.println("\n--- Run Configuration ---"); + System.out.printf("cacheSize : %d%n", instance.cacheSize); + System.out.printf("dataSize : %d%n", instance.dataSize); + System.out.printf("threads : %d%n", instance.numThreads); + System.out.printf("cacheMissDelay : %d ms%n", instance.cacheMissDelayMs); + System.out.printf("readersStartupDelay-ms: %d ms%n", instance.readersStartupDelayMs); + System.out.printf("log-warmup : %b%n", instance.logWarmup); + System.out.printf("verbose : %b%n", instance.verbose); + } +} \ No newline at end of file diff --git a/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/LoadingLRUCache.java b/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/LoadingLRUCache.java new file mode 100644 index 0000000..fb273cc --- /dev/null +++ b/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/LoadingLRUCache.java @@ -0,0 +1,272 @@ +/******************************************************************************* + * Copyright (c) 2025 Ericsson + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the “Software”), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * SPDX-License-Identifier: MIT + *******************************************************************************/ +package org.eclipse.tracecompass.traceeventlogger.lrucachedemo; + +import java.util.*; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.concurrent.atomic.AtomicLong; +import java.util.function.Function; +import java.util.logging.Level; +import java.util.logging.Logger; + +import org.eclipse.tracecompass.traceeventlogger.LogUtils; + +/** + * LoadingLRUCache - a toy loading cache with LRU (least recently used) eviction + * + * @param K the type of the cache key + * @param V the type of the cache value + */ +public class LoadingLRUCache { + private static Logger LOGGER = Logger.getAnonymousLogger(); + private static boolean verbose = false; + + /** + * @param verbose set verbose mode - more printouts to STDOUT if enabled + */ + public static void setVerbose(boolean verbose) { + LoadingLRUCache.verbose = verbose; + } + + private final int capacity; + private final Function loader; + + // the cache + private final Map cache = new ConcurrentHashMap<>(); + // granular lock to control access to each cache element + // note: we could rely on the ConcurrentHashMap locking, when + // updating the cache, but providing our own locking permits + // adding tracepoints to it :) + private final Map locks = new ConcurrentHashMap<>(); + // LRU tracking: keeps track of cache element access order + private final Map lruTracker = new LinkedHashMap<>(16, 0.75f, true); + + // cache statistics + private final AtomicInteger hits = new AtomicInteger(); + private final AtomicInteger hitsAfterWait = new AtomicInteger(); + private final AtomicInteger misses = new AtomicInteger(); + private final AtomicInteger requests = new AtomicInteger(); + private final AtomicInteger evictions = new AtomicInteger(); + private final AtomicLong totalTimeNanos = new AtomicLong(); + + /** + * @param capacity max number of elements the cache can hold + * @param loader call-back function the cache will use to fetch elements, + * is provided by the cache user code + */ + public LoadingLRUCache(int capacity, Function loader) { + this.capacity = capacity; + this.loader = loader; + } + + /** + * Get an element from the cache that corresponds to a certain key. If that + * element is not in the cache, the loader function provided in the constructor + * will be used to load it in the cache. + * + * @param key key of the element + * @return value of the element corresponding to key + */ + @SuppressWarnings("nls") + public V get(K key) { + long start = System.nanoTime(); + requests.incrementAndGet(); + V value = cache.get(key); + if (value != null) { + try (LogUtils.ScopeLog sl2 = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "CACHE:HIT!", "element", key.toString())) { + hits.incrementAndGet(); + updateLRU(key); + log("HIT - key: " + key); + totalTimeNanos.addAndGet(System.nanoTime() - start); + } + return value; + } + + try (LogUtils.ScopeLog sl3 = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "CACHE:GET()-SYNCHRONIZED-BLOCK", "element", key.toString())) { + // Per-key locking + synchronized (locks.computeIfAbsent(key, k -> new Object())) { + // Double-check after acquiring lock + value = cache.get(key); + if (value != null) { + try (LogUtils.ScopeLog sl4 = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "CACHE:HIT_AFTER_WAIT", "element", key.toString())) { + hits.incrementAndGet(); + hitsAfterWait.incrementAndGet(); + log("HIT - key: " + key.toString()); + totalTimeNanos.addAndGet(System.nanoTime() - start); + } + updateLRU(key); + return value; + } + try (LogUtils.ScopeLog sl5 = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "CACHE:MISS!", "element", key.toString())) { + // cache miss + misses.incrementAndGet(); + log("MISS - key: " + key.toString()); + // simulate loading value from slower source + value = loader.apply(key); + log("Loaded value from slow storage: " + value.toString()); + // add value to the cache, evicting old entries if necessary + try (LogUtils.ScopeLog sl6 = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "CACHE:INSERTION", "element", key.toString())) { + insert(key, value); + } + } + } + } + totalTimeNanos.addAndGet(System.nanoTime() - start); + return value; + } + + /** + * add key/value pair to the cache, evicting old entries if necessary + */ + @SuppressWarnings("nls") + private void insert(K key, V value) { + synchronized (lruTracker) { + evictLRU(); + // for comparison, an alternative eviction algorithm + // evictRandom(); + + cache.put(key, value); + updateLRU(key); + } + } + + /** + * Evict to make space for a new cache entry, if needed. + * Use the LRU strategy. + */ + @SuppressWarnings("nls") + private void evictLRU() { + Iterator it = lruTracker.keySet().iterator(); + K eldest; + while (lruTracker.size() >= capacity) { + eldest = it.next(); + try (LogUtils.ScopeLog sl = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "CACHE:EVICTION! (LRU)", "element", eldest.toString())) { + it.remove(); + cache.remove(eldest); + log("EVICTION - key: " + eldest.toString()); + evictions.incrementAndGet(); + } + } + } + + /** + * Alternate version of "evictLRU()". + * Evict to make space for a new cache entry, if needed. + * Pick a cache entry at random to evict. + */ + @SuppressWarnings("nls") + private void evictRandom() { + while (lruTracker.size() >= capacity) { + int randomElem = (int) (Math.random() * capacity); + + try (LogUtils.ScopeLog sl = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "CACHE:EVICTION! {Random}", "element", randomElem)) { + lruTracker.remove(randomElem); + cache.remove(randomElem); + log("EVICTION - key: " + randomElem); + } + } + } + + /** + * Insert/re-insert key in LRU map so it takes its place as the latest accessed + */ + private void updateLRU(K key) { + synchronized (lruTracker) { + lruTracker.put(key, Boolean.TRUE); + } + } + + @SuppressWarnings("nls") + private void log(String msg) { + if (verbose) { + System.out.printf("[%s] %s%n", Thread.currentThread().getName(), msg); + } + } + + /** + * Resets the cache's stats counters + */ + public void resetStats() { + hits.set(0); + misses.set(0); + requests.set(0); + evictions.set(0); + totalTimeNanos.set(0); + } + + /** + * Prints the cache's stats counters + */ + @SuppressWarnings("nls") + public void printStats() { + int h = hits.get(); + int hAfterW = hitsAfterWait.get(); + int adjustedHits = h - hAfterW; + int m = misses.get(); + int r = requests.get(); + int e = evictions.get(); + double avgTimeMs = totalTimeNanos.get() / 1_000_000.0 / r; + double tt = totalTimeNanos.get() / 1_000_000; + + System.out.println("\n--- Cache Stats ---"); + System.out.printf("Total Requests : %d%n", r); + System.out.printf("Cache Hits (total) : %d (%.2f%%)%n", h, 100.0 * h / r); + System.out.printf("Cache Misses : %d (%.2f%%)%n", m, 100.0 * m / r); + System.out.printf("Cache Evictions : %d (%.2f%%)%n", e, 100.0 * e / r); + System.out.printf("Avg get() Time/Op : %.3f ms%n", avgTimeMs); + System.out.printf("Total get() Time : %d ms\n", totalTimeNanos.get() / 1_000_000); + System.out.println("\n--- Counting any cache-hit-after-wait as a miss ---"); + System.out.printf("Cache Hits (after wait): %d / %d%n", hAfterW, h); + System.out.printf("Cache Hits (adjusted) : %d (%.2f%%)%n", adjustedHits, 100.0 * adjustedHits / r); + System.out.printf("Cache Misses (adjusted): %d (%.2f%%)%n", m + hAfterW, 100.0 * (m + hAfterW) / r); + System.out.println("-------------------\n"); + + try (LogUtils.ScopeLog sl = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "--- Cache Stats --- : see 'args'", + "Total Requests", r, + "Cache Hits (total)", h, + "Cache Misses", m, + "Cache Evictions", e, + "Avg get() Time/Op(ms)", avgTimeMs, + "Total get() Time(ms)", tt)) { + // do nothing + } + try (LogUtils.ScopeLog sl = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "--- Adjusted Cache Stats, counting any cache-hit-after-wait as a miss --- : see 'args'", + "Total Requests", r, + "Cache Hits (adjusted)", adjustedHits, + "Cache Misses (adjusted)", m + hAfterW)) { + // do nothing + } + } + +} diff --git a/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/Main.java b/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/Main.java new file mode 100644 index 0000000..08d95bd --- /dev/null +++ b/examples/lrucache/src/main/java/org/eclipse/tracecompass/traceeventlogger/lrucachedemo/Main.java @@ -0,0 +1,263 @@ +/******************************************************************************* + * Copyright (c) 2025 Ericsson + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the “Software”), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * SPDX-License-Identifier: MIT + *******************************************************************************/ +package org.eclipse.tracecompass.traceeventlogger.lrucachedemo; + +import java.util.ArrayList; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.List; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.Logger; + +import org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler; +import org.eclipse.tracecompass.traceeventlogger.LogUtils; + +/** + * Driver for the LoadingLRUCache simulation + */ +public class Main { + static Config config; + static String[] cacheableData; + static LoadingLRUCache cache; + private static Logger LOGGER = Logger.getAnonymousLogger(); + private static AsyncFileHandler aHandler = null; + + private final static AtomicInteger numParallelLoads = new AtomicInteger(); + + /** + * Main class + * + * @param args CLI arguments - see README + */ + @SuppressWarnings("nls") + public static void main(String[] args) { + config = Config.fromArgs(args); + initializeLogging(true); + try (LogUtils.ScopeLog sl = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "--- Configuration ---: see 'args'", + "cacheSize", config.cacheSize, + "dataSize", config.dataSize, + "numThreads", config.numThreads, + "cacheMissDelayMs", config.cacheMissDelayMs, + "readersStartupDelay", config.readersStartupDelayMs, + "logWarmup", config.logWarmup)) { + Config.printConfig(); + + // Initialize backing data + cacheableData = new String[config.dataSize]; + for (int i = 0; i < config.dataSize; i++) { + cacheableData[i] = "ELEMENT " + i; + } + + // Create cache with loading logic and simulated delay + cache = new LoadingLRUCache( + config.cacheSize, + key -> { + numParallelLoads.incrementAndGet(); + try (LogUtils.ScopeLog sl2 = new LogUtils.ScopeLog(LOGGER, Level.FINE, + "LOAD-FROM-SLOW-STORAGE", "element", key)) { + simulateLoadDelay(); + } + numParallelLoads.decrementAndGet(); + return cacheableData[key]; + }); + cache.setVerbose(config.verbose); + + // Warm-up thread: populate the cache before starting the readers + enableLogging(config.logWarmup); + try (LogUtils.ScopeLog sl3 = new LogUtils.ScopeLog(LOGGER, Level.FINE, "WARMUP")) { + Thread warmUpThread = new Thread(new SequentialReader(0), "Warm-up Thread"); + warmUpThread.start(); + + try { + // Wait for the warm-up to complete + warmUpThread.join(); + if (config.verbose) { + System.out.println("Cache warmed up."); + } + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + + // small delay between warm-up and reader threads + try { + Thread.sleep(10); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + } + + + + // warm-up not part of cache stats + cache.resetStats(); + enableLogging(true); + + // Start reader threads + List readers = new ArrayList<>(); + for (int i = 1; i <= config.numThreads; i++) { + String threadName = String.format("Reader-%03d", i); + Thread t = new Thread(new SequentialReader(i), threadName); + readers.add(t); + t.start(); + simulateDelayBetweenReaders(); + } + + // Wait for all threads to finish + for (Thread t : readers) { + try { + t.join(); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + } + + cache.printStats(); + enableLogging(false); + } + System.exit(0); + } + + private static void simulateDelayBetweenReaders() { + try { + Thread.sleep(config.readersStartupDelayMs); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + } + + /** + * Reader thread, that exercises the cache. This reader accesses + * the data structure sequentially, through the cache - i.e. always + * from the first to the last element. This may seem weird, and it + * has big implications regarding the cache configuration, but it + * does correspond to a real-life case we encountered, and want to + * simulate here. + */ + static class SequentialReader implements Runnable { + private final int id; + + public SequentialReader(int id) { + this.id = id; + } + + @SuppressWarnings("nls") + @Override + public void run() { + try (LogUtils.ScopeLog sl = new LogUtils.ScopeLog(LOGGER, Level.FINE, + Thread.currentThread().getName())) { + for (int i = 0; i < config.dataSize; i++) { + @SuppressWarnings("nls") + String iter = String.format("ITERATION-%04d", i); + try (LogUtils.ScopeLog sl2 = new LogUtils.ScopeLog(LOGGER, + Level.FINE, iter)) { + String value = cache.get(i); + // simulate some processing + doSomeWork(value); + } + } + if (config.verbose) { + System.out.printf("Reader thread %d is done\n", this.id); + } + } + } + + /** + * Simulate doing some with the data from he cache + * + * @param value + */ + private void doSomeWork(String value) { + try { + Thread.sleep(1); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + } + } + + private static void simulateLoadDelay() { + try { + Thread.sleep(config.cacheMissDelayMs); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + } + + /** + * Alternate version of simulateLoadDelay(), that adds an + * exponential factor to the load delay, based on the number + * of concurrent load operations running concurrently. This + * simulates the load operation being costly in resources, + * such that running multiples in parallel results in making + * them take more time. + * + * The exponential factor used is exaggerated on purpose, to + * obtain interesting traces more easily. + */ + @SuppressWarnings("nls") + private static void simulateLoadDelayExponential() { + int parallelLoads = numParallelLoads.get(); + double exponentialFactor = 0.5; + double baseDelay = (double)config.cacheMissDelayMs; + double exponent = 1.0 + (exponentialFactor * (parallelLoads - 1.0)); + + double delay = Math.pow(baseDelay, exponent); + System.out.println("simulateLoadDelayExponential() - parallelLoads: " + + parallelLoads +", exponent: " + exponent + ", delay: " + delay); + try { + Thread.sleep((int)delay); + + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + } + + @SuppressWarnings("nls") + private static void initializeLogging(boolean enable) { + boolean found = false; + for (Handler handler : Logger.getLogger("").getHandlers()) { + if (handler instanceof AsyncFileHandler) { + if (config.verbose) { + System.out.println("AsyncFileHandler found: " + handler.toString()); + } + aHandler = (AsyncFileHandler) handler; + found = true; + } + } + if (!found) { + System.out.println("Error: Could not find AsyncFileHandler - Exiting"); + System.exit(1); + } + enableLogging(enable); + } + + /** + * @param e boolean : whether to enable logging or not + */ + public static void enableLogging(boolean e) { + aHandler.setEnabled(e); + } + +} diff --git a/examples/lrucache/traces/_trace_generated_here b/examples/lrucache/traces/_trace_generated_here new file mode 100644 index 0000000..bfa0048 --- /dev/null +++ b/examples/lrucache/traces/_trace_generated_here @@ -0,0 +1,11 @@ +Process traces like so: +$ ../../../jsonify.py trace.log cache_trace.json + +Then open "cache_trace.json" in Trace Compass. Select trace type: +"Trace Event Format" -> "Generic Trace Event Trace" + +If this trace type is not available, you may need to install support +for it: +Help -> Install New Software, then search for "trace event". Under +category "Trace Types", install: +"Trace Compass TraceEvent Parser (incubator)"