org.opensearch.migrations.replay.util.ActiveContextMonitor Maven / Gradle / Ivy

Go to download
package org.opensearch.migrations.replay.util;

import java.time.Duration;
import java.util.ArrayList;
import java.util.Collections;
import java.util.Comparator;
import java.util.HashSet;
import java.util.Map;
import java.util.NoSuchElementException;
import java.util.Optional;
import java.util.Set;
import java.util.TreeMap;
import java.util.concurrent.atomic.AtomicReference;
import java.util.function.BiConsumer;
import java.util.function.Function;
import java.util.function.Predicate;
import java.util.function.Supplier;
import java.util.stream.Collectors;
import java.util.stream.IntStream;
import java.util.stream.Stream;

import org.opensearch.migrations.Utils;
import org.opensearch.migrations.tracing.ActiveContextTracker;
import org.opensearch.migrations.tracing.ActiveContextTrackerByActivityType;
import org.opensearch.migrations.tracing.IScopedInstrumentationAttributes;

import lombok.AllArgsConstructor;
import lombok.Getter;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.Logger;
import org.slf4j.event.Level;

@Slf4j
public class ActiveContextMonitor implements Runnable {

    static final String INDENT = "  ";

    private final BiConsumer> logger;
    private final ActiveContextTracker globalContextTracker;
    private final ActiveContextTrackerByActivityType perActivityContextTracker;
    private final OrderedWorkerTracker orderedRequestTracker;
    private final int totalItemsToOutputLimit;
    private final Function, String> formatWorkItem;

    private final Predicate logLevelIsEnabled;
    private final AtomicReference> ageToLevelEdgeMapRef;

    public ActiveContextMonitor(
        ActiveContextTracker globalContextTracker,
        ActiveContextTrackerByActivityType perActivityContextTracker,
        OrderedWorkerTracker orderedRequestTracker,
        int totalItemsToOutputLimit,
        Function, String> formatWorkItem,
        Logger logger
    ) {
        this(
            globalContextTracker,
            perActivityContextTracker,
            orderedRequestTracker,
            totalItemsToOutputLimit,
            formatWorkItem,
            (level, supplier) -> logger.atLevel(level).setMessage("{}").addArgument(supplier).log(),
            logger::isEnabledForLevel
        );
    }

    public ActiveContextMonitor(
        ActiveContextTracker globalContextTracker,
        ActiveContextTrackerByActivityType perActivityContextTracker,
        OrderedWorkerTracker orderedRequestTracker,
        int totalItemsToOutputLimit,
        Function, String> formatWorkItem,
        BiConsumer> logger,
        Predicate logLevelIsEnabled
    ) {
        this(
            globalContextTracker,
            perActivityContextTracker,
            orderedRequestTracker,
            totalItemsToOutputLimit,
            formatWorkItem,
            logger,
            logLevelIsEnabled,
            Map.of(
                Level.ERROR,
                Duration.ofSeconds(600),
                Level.WARN,
                Duration.ofSeconds(60),
                Level.INFO,
                Duration.ofSeconds(30),
                Level.DEBUG,
                Duration.ofSeconds(5),
                Level.TRACE,
                Duration.ofSeconds(2)
            )
        );
    }

    public ActiveContextMonitor(
        ActiveContextTracker globalContextTracker,
        ActiveContextTrackerByActivityType perActivityContextTracker,
        OrderedWorkerTracker orderedRequestTracker,
        int totalItemsToOutputLimit,
        Function, String> formatWorkItem,
        BiConsumer> logger,
        Predicate logLevelIsEnabled,
        Map levelShowsAgeOlderThanMap
    ) {

        this.globalContextTracker = globalContextTracker;
        this.perActivityContextTracker = perActivityContextTracker;
        this.orderedRequestTracker = orderedRequestTracker;
        this.totalItemsToOutputLimit = totalItemsToOutputLimit;
        this.logger = logger;
        this.formatWorkItem = formatWorkItem;
        this.logLevelIsEnabled = logLevelIsEnabled;
        ageToLevelEdgeMapRef = new AtomicReference<>();
        setAgeToLevelMap(levelShowsAgeOlderThanMap);
    }

    /**
     * Supply new level-age edge values and convert them into the internal data structure for this class to use.
     * @param levelShowsAgeOlderThanMap
     */
    public void setAgeToLevelMap(Map levelShowsAgeOlderThanMap) {
        ageToLevelEdgeMapRef.set(
            new TreeMap<>(
                levelShowsAgeOlderThanMap.entrySet()
                    .stream()
                    .collect(Collectors.toMap(Map.Entry::getValue, Map.Entry::getKey))
            )
        );
    }

    Duration getAge(long recordedNanoTime) {
        return Duration.ofNanos(System.nanoTime() - recordedNanoTime);
    }

    /**
     * Try to print out the most valuable details at the end, assuming that a user is tailing a file that's
     * constantly being appended, and therefore could be harder to home in on the start of a block.
     */
    public void logTopOpenActivities(boolean dedupCommonTraces) {
        logRequests().ifPresent(ll -> logger.accept(ll, () -> "\n"));
        logScopes(dedupCommonTraces);
    }

    public void logScopes(boolean dedupCommonTraces) {
        var scopesSeen = dedupCommonTraces ? new HashSet() : null;
        var activitiesDeferral = getTopActivities(scopesSeen);
        logTopActiveScopes(scopesSeen).ifPresent(ll -> logger.accept(ll, () -> "\n"));
        logTopActiveScopesByType(activitiesDeferral).ifPresent(ll -> logger.accept(ll, () -> "\n"));
    }

    private Optional logTopActiveScopesByType(Stream stream) {
        return stream.map(cad -> {
            if (cad.items.isEmpty()) {
                return Optional.empty();
            }
            final var sample = cad.items.get(0);
            logger.accept(
                getHigherLevel(Optional.of(sample.getLevel()), Optional.of(Level.INFO)).get(),
                () -> "Oldest of "
                    + cad.totalScopes
                    + " scopes for '"
                    + sample.getScope().getActivityName()
                    + "'"
                    + " that are past thresholds that are not otherwise reported below "
            );
            final var numItems = cad.items.size();
            IntStream.range(0, numItems)
                .mapToObj(i -> cad.items.get(numItems - i - 1))
                .forEach(
                    kvp -> logger.accept(
                        kvp.getLevel(),
                        () -> activityToString(kvp.getScope(), kvp.ancestorDepthBeforeRedundancy)
                    )
                );
            return (Optional) Optional.of(cad.items.get(0).getLevel());
        }).collect(Utils.foldLeft(Optional.empty(), ActiveContextMonitor::getHigherLevel));
    }

    private Stream getTopActivities(
        Set scopesSeenSoFar
    ) {
        var reverseOrderedList = perActivityContextTracker.getActiveScopeTypes()
            .map(
                c -> Map.<
                    Class,
                    Supplier>>entry(
                        c,
                        () -> perActivityContextTracker.getOldestActiveScopes(c)
                    )
            )
            .sorted(
                Comparator.comparingInt(
                    kvp -> -1 * kvp.getValue().get().findAny().map(ActiveContextMonitor::contextDepth).orElse(0)
                )
            )
            .map(
                kvp -> gatherActivities(
                    scopesSeenSoFar,
                    kvp.getValue().get(),
                    perActivityContextTracker.numScopesFor(kvp.getKey()),
                    this::getLogLevelForActiveContext
                )
            )
            .collect(Collectors.toCollection(ArrayList::new));
        Collections.reverse(reverseOrderedList);
        return reverseOrderedList.stream();
    }

    private static Optional getHigherLevel(Optional aOuter, Optional bOuter) {
        return aOuter.map(a -> bOuter.filter(b -> a.toInt() <= b.toInt()).orElse(a)).or(() -> bOuter);
    }

    public Optional logRequests() {
        var orderedItems = orderedRequestTracker.orderedSet;
        return logActiveItems(
            null,
            orderedItems.stream(),
            orderedItems.size(),
            " outstanding requests that are past thresholds",
            tkaf -> getLogLevelForActiveContext(tkaf.nanoTimeKey),
            this::activityToString
        );
    }

    private Optional logTopActiveScopes(Set scopesSeen) {
        return logActiveItems(
            scopesSeen,
            globalContextTracker.getActiveScopesByAge(),
            globalContextTracker.size(),
            " GLOBAL scopes that are past thresholds that are not otherwise reported below",
            this::getLogLevelForActiveContext,
            ctx -> activityToString(ctx, scanUntilAncestorSeen(scopesSeen, ctx, 0))
        );
    }

    @AllArgsConstructor
    @Getter
    private static class ScopePath {
        private final IScopedInstrumentationAttributes scope;
        private final int ancestorDepthBeforeRedundancy;
        private final Level level;
    }

    @AllArgsConstructor
    @Getter
    private static class ActivitiesAndDepthsForLogging {
        ArrayList items;
        double averageContextDepth;
        long totalScopes;
    }

    private ActivitiesAndDepthsForLogging gatherActivities(
        Set scopesSeenSoFar,
        Stream oldestActiveScopes,
        long numScopes,
        Function> getLevel
    ) {
        int depthSum = 0;
        var outList = new ArrayList();
        try {
            var activeScopeIterator = oldestActiveScopes.iterator();
            while ((outList.size() < totalItemsToOutputLimit) && activeScopeIterator.hasNext()) {
                final var activeScope = activeScopeIterator.next();
                Optional levelForElementOp = getLevel.apply(activeScope);
                if (levelForElementOp.isEmpty()) {
                    break;
                }
                var ancestorDepth = scanUntilAncestorSeen(scopesSeenSoFar, activeScope, 0);
                if (ancestorDepth != 0) {
                    outList.add(new ScopePath(activeScope, ancestorDepth, levelForElementOp.get()));
                    depthSum += contextDepth(activeScope);
                }
            }
        } catch (NoSuchElementException e) {
            if (outList.isEmpty()) {
                // work is asynchronously added/removed, so don't presume that other sets of work are also empty
                log.trace("No active work found, not outputting them to the active context logger");
            } // else, we're done
        }
        return new ActivitiesAndDepthsForLogging(outList, depthSum / (double) outList.size(), numScopes);
    }

    private static int scanUntilAncestorSeen(
        Set ctxSeenSoFar,
        IScopedInstrumentationAttributes ctx,
        int depth
    ) {
        // if we added an item, then recurse if the parent was non-null; otherwise return depth
        if (ctxSeenSoFar == null) {
            return -1;
        } else if (!ctxSeenSoFar.add(ctx)) {
            return depth;
        }
        ++depth;
        var p = ctx.getEnclosingScope();
        return p == null ? depth : scanUntilAncestorSeen(ctxSeenSoFar, p, depth);
    }

    private static int contextDepth(IScopedInstrumentationAttributes activeScope) {
        return contextDepth(activeScope, 0);
    }

    private static int contextDepth(IScopedInstrumentationAttributes activeScope, int count) {
        return activeScope == null ? count : contextDepth(activeScope.getEnclosingScope(), count + 1);
    }

    private String activityToString(OrderedWorkerTracker.TimeKeyAndFuture tkaf) {
        var timeStr = "age=" + getAge(tkaf.nanoTimeKey);
        return INDENT + timeStr + " " + formatWorkItem.apply(tkaf.future);
    }

    private String activityToString(IScopedInstrumentationAttributes context, int depthToInclude) {
        return activityToString(context, depthToInclude, INDENT);
    }

    private String activityToString(IScopedInstrumentationAttributes ctx, int depthToInclude, String indent) {
        if (ctx == null) {
            return "";
        }
        var idStr = depthToInclude < 0 ? null : "<<" + System.identityHashCode(ctx) + ">>";
        if (depthToInclude == 0) {
            return " parentRef=" + idStr + "...";
        }
        var timeStr = "age=" + getAge(ctx.getStartTimeNano()) + ", start=" + ctx.getStartTimeInstant();
        var attributesStr = ctx.getPopulatedSpanAttributes()
            .asMap()
            .entrySet()
            .stream()
            .map(kvp -> kvp.getKey() + ": " + kvp.getValue())
            .collect(Collectors.joining(", "));
        var parentStr = activityToString(ctx.getEnclosingScope(), depthToInclude - 1, indent + INDENT);
        return indent
            + timeStr
            + Optional.ofNullable(idStr).map(s -> " id=" + s).orElse("")
            + " "
            + ctx.getActivityName()
            + ": attribs={"
            + attributesStr
            + "}"
            + (!parentStr.isEmpty() && depthToInclude != 1 ? "\n" : "")
            + parentStr;
    }

    private Optional getLogLevelForActiveContext(IScopedInstrumentationAttributes activeContext) {
        return getLogLevelForActiveContext(activeContext.getStartTimeNano());
    }

    private Optional getLogLevelForActiveContext(long nanoTime) {
        var age = getAge(nanoTime);
        var ageToLevelEdgeMap = ageToLevelEdgeMapRef.get();
        var floorElement = ageToLevelEdgeMap.floorEntry(age);
        return Optional.ofNullable(floorElement).map(Map.Entry::getValue).filter(logLevelIsEnabled);
    }

    private  Optional logActiveItems(
        Set itemsSeenSoFar,
        Stream activeItemStream,
        long totalItems,
        String trailingGroupLabel,
        Function> getLevel,
        Function getActiveLoggingMessage
    ) {
        int numOutput = 0;
        Optional firstLevel = Optional.empty();
        try {
            var activeItemIterator = activeItemStream.iterator();
            while (activeItemIterator.hasNext() && (numOutput < totalItemsToOutputLimit)) {
                final var activeItem = activeItemIterator.next();
                var levelForElementOp = getLevel.apply(activeItem);
                if (levelForElementOp.isEmpty()) {
                    break;
                }
                if (Optional.ofNullable(itemsSeenSoFar).map(s -> s.contains(activeItem)).orElse(false)) {
                    continue;
                }
                if (firstLevel.isEmpty()) {
                    firstLevel = levelForElementOp;
                }
                if (numOutput++ == 0) {
                    logger.accept(
                        getHigherLevel(levelForElementOp, Optional.of(Level.INFO)).get(),
                        () -> "Oldest of " + totalItems + trailingGroupLabel
                    );
                }
                logger.accept(levelForElementOp.get(), () -> getActiveLoggingMessage.apply(activeItem));
            }
        } catch (NoSuchElementException e) {
            if (numOutput == 0) {
                // work is asynchronously added/removed, so don't presume that other sets of work are also empty
                log.trace("No active work found, not outputting them to the active context logger");
            } // else, we're done
        }
        return firstLevel;
    }

    @Override
    public void run() {
        logTopOpenActivities(true);
    }
}