GC Pause Annotator

BraveTracingGarbageCollectionConfig.java

package com.dealer.metrics.aspects.tracing.config;

import com.dealer.metrics.aspects.tracing.gc.GcEventStore;
import com.dealer.metrics.aspects.tracing.gc.GcMonitor;
import com.dealer.metrics.aspects.tracing.gc.GcEventTracingAspect;
import org.aspectj.lang.Aspects;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Import;

import java.util.concurrent.TimeUnit;

@Configuration
public class BraveTracingGarbageCollectionConfig {

    @Bean
    public GcEventTracingAspect serverResponseGcAnnotationsAspect() {
        return Aspects.aspectOf(GcEventTracingAspect.class);
    }

    @Bean
    public GcEventStore gcEventStore() {
        // record up to 5 minutes of GC activity
        return new GcEventStore(5, TimeUnit.MINUTES);
    }

    @Bean
    public GcMonitor gcMonitor(GcEventStore eventStore) {
        return new GcMonitor(eventStore);
    }

}

GcEventStore.java

package com.dealer.metrics.aspects.tracing.gc;

import com.google.common.collect.Range;
import com.google.common.collect.RangeSet;
import com.google.common.collect.TreeRangeSet;
import com.sun.management.GarbageCollectionNotificationInfo;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.util.ArrayList;
import java.util.Collections;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.ReadWriteLock;
import java.util.concurrent.locks.ReentrantReadWriteLock;


/**
 * This class keeps track of a range of discrete events by start and stop times.
 * <p>
 * It can answer the question "Between this start and stop time, are there any events that were tracked?"
 * <p>
 * One useful application of this is to keep a record of GC intervals, and at the end of a test run
 * the test agent can check to see if there were any GC events that may be tainting its timings and
 * discard or flag the test result as being "tainted"
 */
public class GcEventStore {
    private static final Logger log = LoggerFactory.getLogger(GcEventStore.class);
    private final RangeSet<Long> timeStore;
    // store information about the GC event, indexed by the start time
    private final Map<Long, GarbageCollectionNotificationInfo> gcReasonStore;

    // make it easy to short-circuit the whole thing by knowing the last time one was recorded
    private long latestEventTimestamp = 0;

    private final TimeUnit durationUnit;
    private final long maxAge;
    private final ScheduledExecutorService ses;

    private final ReadWriteLock readWriteLock = new ReentrantReadWriteLock();

    /**
     * Create a RangeStore that will keep track of events that are within this time range.
     * <p>
     * Periodically, events older than the maxAge will be purged.
     *
     * @param maxAge
     * @param durationUnit
     */
    public GcEventStore(final long maxAge, final TimeUnit durationUnit) {
        this.durationUnit = durationUnit;
        this.maxAge = maxAge;
        timeStore = TreeRangeSet.create();

        ses = Executors.newScheduledThreadPool(1);
        ses.scheduleWithFixedDelay(new Runnable() {
            public void run() {
                purgeTimeStore(maxAge, durationUnit);
            }
        }, maxAge, maxAge, durationUnit);
        gcReasonStore = new HashMap<>();
    }

    public void storeEvent(long startTimeMs, long endTimeMs, GarbageCollectionNotificationInfo description) {
        try {
            readWriteLock.writeLock().lock();
            timeStore.add(Range.closed(startTimeMs, endTimeMs));
            if (endTimeMs > latestEventTimestamp) {
                latestEventTimestamp = endTimeMs;
            }
            gcReasonStore.put(startTimeMs, description);
        } finally {
            readWriteLock.writeLock().unlock();
        }
    }

    // purge the time store of events older than maxAge from the current time
    protected void purgeTimeStore(long maxAge, TimeUnit durationUnit) {
        purgeBefore(System.currentTimeMillis() - durationUnit.toMillis(maxAge));
    }

    // split out for easier unit testing
    protected void purgeBefore(long start) {
        log.debug("purging since {}. Before purge there are {} items", start, timeStore.asRanges().size());
        try {
            readWriteLock.writeLock().lock();
            Range<Long> removalRange = Range.lessThan(start);
            // clear out events from the map of descriptions
            Set<Range<Long>> events = eventsBetween(0, start).asRanges();
            for (Range<Long> event : events) {
                gcReasonStore.remove(event.lowerEndpoint());
            }
            timeStore.remove(removalRange);
        }
        finally {
            readWriteLock.writeLock().unlock();
        }
        log.debug("After purge there are {} items", timeStore.asRanges().size());
    }

    public boolean anyEventsBetween(long startTime, long endTime) {
        try {
            readWriteLock.readLock().lock();
            return (latestEventTimestamp > startTime || endTime > latestEventTimestamp && !(timeStore.subRangeSet(Range.closed(startTime, endTime))).isEmpty());
        } finally {
            readWriteLock.readLock().unlock();
        }
    }

    public boolean anyEventsSince(long startTime) {
        try {
            readWriteLock.readLock().lock();
            return (latestEventTimestamp > startTime);
        } finally {
            readWriteLock.readLock().unlock();
        }

    }

    public RangeSet eventsBetween(long startTime, long endTime) {
        try {
            readWriteLock.readLock().lock();
            return timeStore.subRangeSet(Range.closed(startTime, endTime));
        } finally {
            readWriteLock.readLock().unlock();
        }
    }

    public List<Event> eventsSince(long startTime) {
        try {
            long endTime = System.currentTimeMillis();
            readWriteLock.readLock().lock();
            if (anyEventsBetween(startTime, endTime)) {
                Set<Range<Long>> ranges = timeStore.subRangeSet(Range.closed(startTime, endTime)).asRanges();
                List<Event> events = new ArrayList<>(ranges.size());
                for (Range<Long> range : ranges) {
                    events.add(new Event(range.lowerEndpoint(), range.upperEndpoint(), gcReasonStore.get(range.lowerEndpoint())));
                }
                return events;
            }
            else {
                return Collections.EMPTY_LIST;
            }
        } finally {
            readWriteLock.readLock().unlock();
        }
    }

    public static class Event {
        private long startTime;
        private long endTime;
        private GarbageCollectionNotificationInfo gcNotificationInfo;


        public Event(long startTime, long endTime, GarbageCollectionNotificationInfo gcNotificationInfo) {
            this.startTime = startTime;
            this.endTime = endTime;
            this.gcNotificationInfo = gcNotificationInfo;
        }

        public long getStartTime() {
            return startTime;
        }

        public long getEndTime() {
            return endTime;
        }

        public GarbageCollectionNotificationInfo gcNotificationInfo() {
            return gcNotificationInfo;
        }
    }

    /**
     * Purge the store and stop the running of the periodic purging task
     */
    public void shutdown() {
        ses.shutdown();
        gcReasonStore.clear();
        timeStore.clear();
    }

}

GcEventTracingAspect.java

package com.dealer.metrics.aspects.tracing.gc;

import com.github.kristofa.brave.ServerClientAndLocalSpanState;
import com.github.kristofa.brave.ServerTracer;
import com.sun.management.GarbageCollectionNotificationInfo;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;

import java.util.List;

@Aspect
public class GcEventTracingAspect {
    private static final Logger log = LoggerFactory.getLogger(GcEventTracingAspect.class);

    @Autowired
    protected GcEventStore gcEventStore;

    @Autowired
    protected ServerClientAndLocalSpanState braveSpanState;

    @Autowired
    protected ServerTracer serverTracer;

    @Pointcut("execution(* com.github.kristofa.brave.ServerTracer.setServerSend())")
    public void serverTracerServerSend() {
    }

    // submit a few annotations before the request gets sent out including GC information
    @Before("serverTracerServerSend()")
    public void addGcResponseAnnotationsToResponse() {
        // exit quickly if the dependencies aren't available
        if (braveSpanState == null || gcEventStore == null || serverTracer == null) {
            log.debug("The GcEventTracingAspect wasn't properly initialized");
            return;
        }
        try {
            if (braveSpanState.getCurrentServerSpan() != null && braveSpanState.getCurrentServerSpan().getSpan() != null) {
                // start timestamp - brave uses micros because zipkin uses micros
                long startTime = braveSpanState.getCurrentServerSpan().getSpan().getTimestamp() / 1000;

                if (gcEventStore.anyEventsSince(startTime)) {
                    serverTracer.submitBinaryAnnotation("gc.happened", "true");
                    List<GcEventStore.Event> events = gcEventStore.eventsSince(startTime);
                    if (events.size() > 0) {
                        serverTracer.submitBinaryAnnotation("gc.count", events.size());
                        for (GcEventStore.Event event : events) {
                            String startInfo = "GC - Unknown type and cause";
                            String endInfo = "GC End - Unknown type and cause";
                            if (event.gcNotificationInfo() != null) {
                                startInfo = generateStartGcInfo(event.gcNotificationInfo());
                                endInfo = generateEndGcInfo(event.gcNotificationInfo());
                            }

                            serverTracer.submitAnnotation(startInfo, event.getStartTime() * 1000);
                            serverTracer.submitAnnotation(endInfo, event.getEndTime() * 1000);
                            serverTracer.submitBinaryAnnotation("gc.duration.ms", (int) (event.getEndTime() - event.getStartTime()));
                        }
                    }
                }
            }
        }catch(Exception e) {
            log.error("Unable to add the gc information to the request annotations", e);
        }
    }

    private String generateStartGcInfo(GarbageCollectionNotificationInfo garbageCollectionNotificationInfo) {
        return "GC - " + garbageCollectionNotificationInfo.getGcName() + " : " + garbageCollectionNotificationInfo.getGcCause();
    }

    private String generateEndGcInfo(GarbageCollectionNotificationInfo garbageCollectionNotificationInfo) {
        return "GC - " + garbageCollectionNotificationInfo.getGcName() + " : " + garbageCollectionNotificationInfo.getGcCause()
                + " : " + garbageCollectionNotificationInfo.getGcAction() +
                " - took " + garbageCollectionNotificationInfo.getGcInfo().getDuration() + " ms ";
    }


}

GcMonitor.java

package com.dealer.metrics.aspects.tracing.gc;

import com.sun.management.GarbageCollectionNotificationInfo;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import javax.management.Notification;
import javax.management.NotificationEmitter;
import javax.management.NotificationListener;
import javax.management.openmbean.CompositeData;
import java.lang.management.GarbageCollectorMXBean;
import java.lang.management.ManagementFactory;

public class GcMonitor {
    private static final Logger log = LoggerFactory.getLogger(GcMonitor.class);
    final GcEventStore eventStore;

    // start time of JVM - (the time stamps given by the GC notification are all relative to the start time of the JVM)
    private long jvmStartTimeMillis;

    public GcMonitor(final GcEventStore eventStore) {
        this.eventStore = eventStore;
        jvmStartTimeMillis = ManagementFactory.getRuntimeMXBean().getStartTime();
        for (GarbageCollectorMXBean garbageCollectorMXBean : ManagementFactory.getGarbageCollectorMXBeans()) {
            NotificationEmitter emitter = (NotificationEmitter) garbageCollectorMXBean;
            emitter.addNotificationListener(listener, null, null);
        }
    }

    // anonymous listener for GC events that stores any timings into the event handler
    NotificationListener listener = new NotificationListener() {
        @Override
        public void handleNotification(Notification notification, Object handback) {
            if (notification.getType().equals(GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION)) {
                GarbageCollectionNotificationInfo info = GarbageCollectionNotificationInfo.from((CompositeData) notification.getUserData());
                eventStore.storeEvent(jvmStartTimeMillis + info.getGcInfo().getStartTime(), jvmStartTimeMillis + info.getGcInfo().getEndTime(), info);
                log.trace("gc happened. I stored info about it.");
            }
        }
    };



}