LoggingUtils.java

package cloud.literallya.util;

import java.util.Map;
import java.util.function.IntSupplier;
import java.util.function.LongSupplier;
import java.util.function.Supplier;
import java.util.logging.Logger;
import java.util.stream.Collectors;
import java.util.stream.IntStream;

import com.google.common.collect.Maps;

public class LoggingUtils{

  private LoggingUtils(){
  }

  public static Logger makePackageLogger(){
    String classPath[] = new Exception().getStackTrace()[1].getClassName().split("\\.");
    String pkg = IntStream.range(0, classPath.length - 1)
      .mapToObj(i -> classPath[i])
      .collect(Collectors.joining("."));
    return Logger.getLogger(pkg);
  }

  public static LogTimer logTimer(){
    return new LogTimerImpl();
  }

  /**
   * A timer utility similar in to {@link LoggingUtils#logTimer()} except it accumulates timing information
   * <br>
   * This can used to time sub-sections of an operation which occurs in a loop and print aggregate statistics
   */
  public static MultiTimer multiTimer(){
    return new MultiTimerImpl();
  }

  /**
   * A timer utility that is designed to aid in timing operations and logging the output.
   * <br>
   * The methods return suppliers to minimize impact on execution time when unused.
   * <br>
   * 
   * @see Logger
   */
  public static interface LogTimer{
    public void reset();

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment
     */
    public Supplier<String> endSegment(String verb);

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment
     */
    public Supplier<String> endSegment(Supplier<String> verb);

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     */
    public Supplier<String> endSegment(long ct, String verb);

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     */
    public Supplier<String> endSegment(long ct, Supplier<String> verb);

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     */
    public default Supplier<String> endSegment(int ct, String verb){
      return endSegment((long) ct, verb);
    }

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     */
    public default Supplier<String> endSegment(int ct, Supplier<String> verb){
      return endSegment((long) ct, verb);
    }

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     * <br>
     * the supplier is only called if the supplier is called, so this may be a relatively expensive operation which will only be
     * incurred if logging is enabled
     */
    public Supplier<String> endSegment(LongSupplier s, String verb);

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     * <br>
     * the supplier is only called if the supplier is called, so this may be a relatively expensive operation which will only be
     * incurred if logging is enabled
     */
    public Supplier<String> endSegment(LongSupplier s, Supplier<String> verb);

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     * <br>
     * the supplier is only called if the supplier is called, so this may be a relatively expensive operation which will only be
     * incurred if logging is enabled
     */
    public default Supplier<String> endSegment(IntSupplier s, String verb){
      return endSegment(() -> (long) s.getAsInt(), verb);
    }

    /**
     * ends the segment and returns a supplier that will print a message with the given name and elapsed time sine the last
     * segment and per-op statistics
     * <br>
     * the supplier is only called if the supplier is called, so this may be a relatively expensive operation which will only be
     * incurred if logging is enabled
     */
    public default Supplier<String> endSegment(IntSupplier s, Supplier<String> verb){
      return endSegment(() -> (long) s.getAsInt(), verb);
    }
  }

  private static class LogTimerImpl implements LogTimer{
    private long start = System.nanoTime();

    @Override
    public void reset(){
      start = System.nanoTime();
    }

    @Override
    public Supplier<String> endSegment(String verb){
      long end = System.nanoTime();
      long diff = end - start;
      start = end;

      return () -> String.format("%.3fms to %s", diff / 1_000_000.0, verb);
    }

    @Override
    public Supplier<String> endSegment(Supplier<String> verb){
      return () -> endSegment(verb.get()).get();
    }

    @Override
    public Supplier<String> endSegment(LongSupplier s, String verb){
      long end = System.nanoTime();
      long diff = end - start;
      start = end;

      return () -> {
        long ct = s.getAsLong();
        return String.format(
          "%d %s in %.2fms -> %.3fµsec/op",
          ct, verb, diff / 1_000_000.0,
          (diff / 1000) / (double) ct);
      };
    }

    @Override
    public Supplier<String> endSegment(LongSupplier s, Supplier<String> verb){
      return () -> endSegment(s, verb.get()).get();
    }

    @Override
    public Supplier<String> endSegment(long ct, String verb){
      long end = System.nanoTime();
      long diff = end - start;
      start = end;

      return () -> String.format(
        "%d %s in %.2fms -> %.5fµsec/op",
        ct, verb, diff / 1_000_000.0,
        diff / (double) (ct * 1000));
    }

    @Override
    public Supplier<String> endSegment(long ct, Supplier<String> verb){
      return () -> endSegment(ct, verb.get()).get();
    }

  }

  /*
   * Multi-timing
   */

  public static interface MultiTimer{
    /**
     * Sets the start timer. this should be called before the start of the critical segment so the statistics gathered will
     * always be specific to the code being timed
     */
    public void start();

    /**
     * End a segment and collect statistics in the bucket denoted by the verb
     */
    public void endSegment(String verb);

    /**
     * End a segment for some number of objects and collect statistics in the bucket denoted by the verb
     */
    public void endSegment(long ct, String verb);

    /**
     * End a segment for some number of objects and collect statistics in the bucket denoted by the verb
     */
    public default void endSegment(int ct, String verb){
      endSegment((long) ct, verb);
    }

    /**
     * returns a supplier that summarizes all the collected statistics, one 'verb' per line in the order that they were first
     * seen in
     */
    public Supplier<String> statsPrinter();

    /**
     * Returns true if nothing has been logged on this timer
     */
    public boolean isEmpty();

  }

  private static class Segment{
    private long time = 0;
    private long count = 0;
    private long calls = 0;

    private void add(long t, long ct){
      calls++;
      count += ct;
      time += t;
    }
  }

  private static class MultiTimerImpl implements MultiTimer{
    private Map<String, Segment> segments = Maps.newLinkedHashMap();

    private long start;

    {
      start();
    }

    @Override
    public void start(){
      start = System.nanoTime();
    }

    @Override
    public void endSegment(long ct, String verb){
      long end = System.nanoTime();
      segments.computeIfAbsent(verb, v -> new Segment()).add(end - start, ct);
      start = end;
    }

    @Override
    public void endSegment(String verb){
      endSegment(0, verb);
    }

    @Override
    public Supplier<String> statsPrinter(){
      return () -> {
        String totalString = String.format("\n %.2fms Total",
          segments.values().stream().mapToLong(s -> s.time).sum() / 1_000_000.0);
        return segments.entrySet().stream()
          .map(e -> {
            String verb = e.getKey();
            Segment seg = e.getValue();

            if(0 == seg.count)
              return String.format("%.3fms to %s %d times ->"
                + " %.3fµsec/op",
                seg.time / 1_000_000.0, verb, seg.calls,
                seg.time / (double) (seg.calls * 1000));
            return String.format(
              "%d %s over %d calls"
                + " in %.2fms ->"
                + " %.3fµsec/op"
                + " and %.3fµsec/call",
              seg.count, verb, seg.calls,
              seg.time / 1_000_000.0,
              seg.time / (double) (seg.count * 1000),
              seg.time / (double) (seg.calls * 1000));
          }).collect(Collectors.joining("\n", "\n", totalString));
      };
    }

    @Override
    public boolean isEmpty(){
      return segments.isEmpty();
    }
  }

  /*
   * Recursive timing
   */

  public static interface RecursiveTimer{
    /**
     * Sets the start timer. this should be called before the start of the critical segment so the statistics gathered will
     * always be specific to the code being timed
     */
    public void start();

    /**
     * Tells the timer that we are recursing to the next level, will build a new segment and when stats are printed all segments
     * will have recursive calls discounted
     */
    public void recurse();

    /**
     * Tells the timer that we are going back up the stack
     */
    public void pop();

    /**
     * End a segment and collect statistics in the bucket denoted by the verb
     */
    public void endSegment(String verb);

    /**
     * End a segment for some number of objects and collect statistics in the bucket denoted by the verb
     */
    public void endSegment(long ct, String verb);

    /**
     * End a segment for some number of objects and collect statistics in the bucket denoted by the verb
     */
    public default void endSegment(int ct, String verb){
      endSegment((long) ct, verb);
    }

    /**
     * returns a supplier that summarizes all the collected statistics, one 'verb' per line in the order that they were first
     * seen in
     */
    public Supplier<String> statsPrinter();
  }

}