src/com/facebook/buck/debug/ThreadTrace.java - buck - Git at Google

 /*
  * Copyright 2012-present Facebook, Inc.
  *
  * Licensed 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
  *
  *     http://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 com.facebook.buck.debug;

 import com.google.common.base.Joiner;
 import com.google.common.base.Strings;
 import com.google.common.collect.Lists;
 import com.google.common.collect.Maps;
 import com.google.common.eventbus.EventBus;
 import com.google.common.eventbus.Subscribe;

 import java.io.PrintStream;
 import java.util.LinkedList;
 import java.util.List;
 import java.util.Map;
 import java.util.concurrent.atomic.AtomicLong;

 /**
  * Tracer for debugging slow points in code. Based on Google Closure's goog.debug.Tracer.
  */
 final class ThreadTrace {

   static ThreadLocal<ThreadTrace> threadTracer = new ThreadLocal<ThreadTrace>() {
     @Override
     protected ThreadTrace initialValue() {
       return new ThreadTrace();
     }
   };

   private static final int MAX_TRACE_SIZE = 1000;

   private static AtomicLong idGenerator = new AtomicLong();

   private long defaultThreshold;

   /** Events in order. */
   private List<TraceEvent> events = Lists.newArrayList();

   /** Outstanding events that haven't ended yet. */
   private Map<Long, TraceEvent> outstandingEvents = Maps.newHashMap();

   private long startTime;

   private EventBus getEventBus() {
     if (eventBus == null) {
       setEventBus(new EventBus());
     }
     return eventBus;
   }

   private EventBus eventBus = null;

   private void setEventBus(EventBus eventBus) {
     this.eventBus = eventBus;
     this.eventBus.register(this);
   }

   /**
    * Initializes and resets the current trace
    *
    * @param defaultThreshold The default threshold below which the tracer output will be suppressed.
    *     Can be overridden on a per-Tracer basis.
    *
    */
   static void initCurrentTrace(long defaultThreshold) {
     threadTracer.get().reset(defaultThreshold);
   }

   /**
    * Initializes and resets the current trace
    *
    * @param defaultThreshold The default threshold below which the tracer output will be suppressed.
    *     Can be overridden on a per-Tracer basis.
    *
    * @param eventBus The EventBus which TraceEvents are published to.
    */
   static void initCurrentTrace(long defaultThreshold, EventBus eventBus) {
     initCurrentTrace(defaultThreshold);
     threadTracer.get().setEventBus(eventBus);
   }

   /**
    * Clears the current trace.
    */
   static void clearCurrentTrace() {
     threadTracer.get().reset(0);
   }

   static void clearAndPrintCurrentTrace(PrintStream stream) {
     String trace = threadTracer.get().getFormattedTrace();
     if (!Strings.isNullOrEmpty(trace)) {
       stream.println("Thread trace:\n" + Tracer.getFormattedThreadTrace());
     }
     clearCurrentTrace();
   }

   /**
    * Resets the trace.
    *
    * @param defaultThreshold The default threshold below which the tracer output will be suppressed.
    *     Can be overridden on a per-Tracer basis.
    */
   @SuppressWarnings("PMD.UnusedPrivateMethod")
   private void reset(long defaultThreshold) {
     this.defaultThreshold = defaultThreshold;

     this.events.clear();
     this.outstandingEvents.clear();
     this.startTime = System.currentTimeMillis();
   }

   /**
    * Starts a tracer
    *
    * @param comment a comment used to identify the tracer. Does not need to be unique.
    * @param type type used to identify the tracer. If a Trace is given a type (the first argument
    *     to the constructor) and multiple Traces are done on that type then a "TOTAL line will be
    *     produced showing the total number of traces and the sum of the time
    *     ("TOTAL Database 2 (37 ms)" in our example). These traces should be mutually
    *     exclusive or else the sum won't make sense (the time will be double counted if the second
    *     starts before the first ends).
    * @return The identifier for the tracer that should be passed to the the stopTracer method.
    */
   long startTracer(String comment, String type) {
     TraceEvent event = TraceEvents.started(idGenerator.incrementAndGet(), comment, type, -1);
     outstandingEvents.put(event.getId(), event); // Avoid traceStarted/stopTracer race.
     getEventBus().post(event);
     return event.getId();
   }

   @Subscribe
   public void traceStarted(TraceStart event) {
     outstandingEvents.put(event.getId(), event);
     int outstandingEventCount = outstandingEvents.size();
     if (events.size() + outstandingEventCount > MAX_TRACE_SIZE) {
       System.err.println("Giant thread trace. Clearing to avoid memory leak.");

       // This is the more likely case. This usually means that we
       // either forgot to clear the trace or else we are performing a
       // very large number of events
       if (events.size() > MAX_TRACE_SIZE / 2) {
         this.events.clear();
       }

       // This is less likely and probably indicates that a lot of traces
       // aren't being closed. We want to avoid unnecessarily clearing
       // this though in case the events do eventually finish.
       if (outstandingEventCount > MAX_TRACE_SIZE / 2) {
         this.outstandingEvents.clear();
       }
     }
     events.add(event);
   }

   /**
    * Stops a tracer
    *
    * @param id The id of the tracer that is ending.
    * @param silenceThresholdParam Threshold below which the tracer is silenced.
    * @return The elapsed time for the tracer or -1 if the tracer identifier was not recognized.
    */
   @SuppressWarnings("PMD.PrematureDeclaration")
   long stopTracer(long id, Long silenceThresholdParam) {

     long now = System.currentTimeMillis();
     long silenceThreshold;
     if (silenceThresholdParam == null) {
       silenceThreshold = defaultThreshold;
     } else {
       silenceThreshold = silenceThresholdParam;
     }

     TraceEvent startEvent = outstandingEvents.get(id);
     if (startEvent == null) {
       return -1;
     }
     outstandingEvents.remove(id);

     long elapsed = now - startEvent.getEventTime();
     if (elapsed < silenceThreshold) {
       int count = events.size();
       for (int i = count - 1; i >= 0; i--) {
         TraceEvent nextEvent = this.events.get(i);
         if (nextEvent == startEvent) {
           events.remove(i);
           break;
         }
       }

     } else {
       getEventBus().post(TraceEvents.stopped(idGenerator.incrementAndGet(), startEvent.getComment(),
           startEvent.getType(), startEvent.getEventTime()));
     }
     return elapsed;
   }

   @Subscribe
   public void traceStopped(TraceStop event) {
     events.add(event);
   }

   /**
    * Adds a comment to the trace. Makes it possible to see when a specific event
    * happened in relation to the traces.
    *
    * @param comment A comment that is inserted into the trace.
    * @param type    Type used to identify the tracer. If a comment is given a type and multiple
    *                comments are done on that type then a "TOTAL line will be produced showing the
    *                total number of comments of that type.
    */
   void addComment(String comment, String type) {
     getEventBus().post(TraceEvents.comment(idGenerator.incrementAndGet(), comment, type, -1));
   }

   @Subscribe
   public void traceComment(TraceComment event) {
     events.add(event);
   }

   /**
    * Returns a formatted string for the current trace
    *
    * @return a formatted string that shows the timings of the current trace
    */
   String getFormattedTrace() {
     return this.toString();
   }

   /**
    * Returns a formatted string that describes the thread trace.
    *
    * @return {string} A formatted string.
    */
   @Override
   public String toString() {
     StringBuilder sb = new StringBuilder();
     long etime = -1;

     long now = System.currentTimeMillis();
     LinkedList<String> indent = Lists.newLinkedList();
     for (int i = 0; i < events.size(); i++) {
       TraceEvent e = events.get(i);
       if (e instanceof TraceStop) {
         indent.removeFirst();
       }
       sb.append(" ");
       sb.append(e.toTraceString(startTime, etime, join(indent)));
       sb.append(" ");
       etime = e.getEventTime();
       sb.append("\n");
       if (e instanceof TraceStart) {
         indent.add("|  ");
       }
     }

     if (!outstandingEvents.isEmpty()) {
       sb.append(" Unstopped timers:\n");
       for (TraceEvent startEvent : outstandingEvents.values()) {
         sb.append("  ");
         sb.append(startEvent);
         sb.append(" (");
         sb.append(now - startEvent.getEventTime());
         sb.append(" ms, started at ");
         sb.append(TraceEvent.formatTime(startEvent.getEventTime()));
         sb.append("\n");
       }
     }
     return sb.toString();
   }

   private String join(List<String> indents) {
     return Joiner.on("").join(indents);
   }

 }
	/*
	* Copyright 2012-present Facebook, Inc.
	*
	* Licensed 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
	*
	* http://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 com.facebook.buck.debug;

	import com.google.common.base.Joiner;
	import com.google.common.base.Strings;
	import com.google.common.collect.Lists;
	import com.google.common.collect.Maps;
	import com.google.common.eventbus.EventBus;
	import com.google.common.eventbus.Subscribe;

	import java.io.PrintStream;
	import java.util.LinkedList;
	import java.util.List;
	import java.util.Map;
	import java.util.concurrent.atomic.AtomicLong;

	/**
	* Tracer for debugging slow points in code. Based on Google Closure's goog.debug.Tracer.
	*/
	final class ThreadTrace {

	static ThreadLocal<ThreadTrace> threadTracer = new ThreadLocal<ThreadTrace>() {
	@Override
	protected ThreadTrace initialValue() {
	return new ThreadTrace();
	}
	};

	private static final int MAX_TRACE_SIZE = 1000;

	private static AtomicLong idGenerator = new AtomicLong();

	private long defaultThreshold;

	/** Events in order. */
	private List<TraceEvent> events = Lists.newArrayList();

	/** Outstanding events that haven't ended yet. */
	private Map<Long, TraceEvent> outstandingEvents = Maps.newHashMap();

	private long startTime;

	private EventBus getEventBus() {
	if (eventBus == null) {
	setEventBus(new EventBus());
	}
	return eventBus;
	}

	private EventBus eventBus = null;

	private void setEventBus(EventBus eventBus) {
	this.eventBus = eventBus;
	this.eventBus.register(this);
	}

	/**
	* Initializes and resets the current trace
	*
	* @param defaultThreshold The default threshold below which the tracer output will be suppressed.
	* Can be overridden on a per-Tracer basis.
	*
	*/
	static void initCurrentTrace(long defaultThreshold) {
	threadTracer.get().reset(defaultThreshold);
	}

	/**
	* Initializes and resets the current trace
	*
	* @param defaultThreshold The default threshold below which the tracer output will be suppressed.
	* Can be overridden on a per-Tracer basis.
	*
	* @param eventBus The EventBus which TraceEvents are published to.
	*/
	static void initCurrentTrace(long defaultThreshold, EventBus eventBus) {
	initCurrentTrace(defaultThreshold);
	threadTracer.get().setEventBus(eventBus);
	}

	/**
	* Clears the current trace.
	*/
	static void clearCurrentTrace() {
	threadTracer.get().reset(0);
	}

	static void clearAndPrintCurrentTrace(PrintStream stream) {
	String trace = threadTracer.get().getFormattedTrace();
	if (!Strings.isNullOrEmpty(trace)) {
	stream.println("Thread trace:\n" + Tracer.getFormattedThreadTrace());
	}
	clearCurrentTrace();
	}

	/**
	* Resets the trace.
	*
	* @param defaultThreshold The default threshold below which the tracer output will be suppressed.
	* Can be overridden on a per-Tracer basis.
	*/
	@SuppressWarnings("PMD.UnusedPrivateMethod")
	private void reset(long defaultThreshold) {
	this.defaultThreshold = defaultThreshold;

	this.events.clear();
	this.outstandingEvents.clear();
	this.startTime = System.currentTimeMillis();
	}

	/**
	* Starts a tracer
	*
	* @param comment a comment used to identify the tracer. Does not need to be unique.
	* @param type type used to identify the tracer. If a Trace is given a type (the first argument
	* to the constructor) and multiple Traces are done on that type then a "TOTAL line will be
	* produced showing the total number of traces and the sum of the time
	* ("TOTAL Database 2 (37 ms)" in our example). These traces should be mutually
	* exclusive or else the sum won't make sense (the time will be double counted if the second
	* starts before the first ends).
	* @return The identifier for the tracer that should be passed to the the stopTracer method.
	*/
	long startTracer(String comment, String type) {
	TraceEvent event = TraceEvents.started(idGenerator.incrementAndGet(), comment, type, -1);
	outstandingEvents.put(event.getId(), event); // Avoid traceStarted/stopTracer race.
	getEventBus().post(event);
	return event.getId();
	}

	@Subscribe
	public void traceStarted(TraceStart event) {
	outstandingEvents.put(event.getId(), event);
	int outstandingEventCount = outstandingEvents.size();
	if (events.size() + outstandingEventCount > MAX_TRACE_SIZE) {
	System.err.println("Giant thread trace. Clearing to avoid memory leak.");

	// This is the more likely case. This usually means that we
	// either forgot to clear the trace or else we are performing a
	// very large number of events
	if (events.size() > MAX_TRACE_SIZE / 2) {
	this.events.clear();
	}

	// This is less likely and probably indicates that a lot of traces
	// aren't being closed. We want to avoid unnecessarily clearing
	// this though in case the events do eventually finish.
	if (outstandingEventCount > MAX_TRACE_SIZE / 2) {
	this.outstandingEvents.clear();
	}
	}
	events.add(event);
	}

	/**
	* Stops a tracer
	*
	* @param id The id of the tracer that is ending.
	* @param silenceThresholdParam Threshold below which the tracer is silenced.
	* @return The elapsed time for the tracer or -1 if the tracer identifier was not recognized.
	*/
	@SuppressWarnings("PMD.PrematureDeclaration")
	long stopTracer(long id, Long silenceThresholdParam) {

	long now = System.currentTimeMillis();
	long silenceThreshold;
	if (silenceThresholdParam == null) {
	silenceThreshold = defaultThreshold;
	} else {
	silenceThreshold = silenceThresholdParam;
	}

	TraceEvent startEvent = outstandingEvents.get(id);
	if (startEvent == null) {
	return -1;
	}
	outstandingEvents.remove(id);

	long elapsed = now - startEvent.getEventTime();
	if (elapsed < silenceThreshold) {
	int count = events.size();
	for (int i = count - 1; i >= 0; i--) {
	TraceEvent nextEvent = this.events.get(i);
	if (nextEvent == startEvent) {
	events.remove(i);
	break;
	}
	}

	} else {
	getEventBus().post(TraceEvents.stopped(idGenerator.incrementAndGet(), startEvent.getComment(),
	startEvent.getType(), startEvent.getEventTime()));
	}
	return elapsed;
	}

	@Subscribe
	public void traceStopped(TraceStop event) {
	events.add(event);
	}

	/**
	* Adds a comment to the trace. Makes it possible to see when a specific event
	* happened in relation to the traces.
	*
	* @param comment A comment that is inserted into the trace.
	* @param type Type used to identify the tracer. If a comment is given a type and multiple
	* comments are done on that type then a "TOTAL line will be produced showing the
	* total number of comments of that type.
	*/
	void addComment(String comment, String type) {
	getEventBus().post(TraceEvents.comment(idGenerator.incrementAndGet(), comment, type, -1));
	}

	@Subscribe
	public void traceComment(TraceComment event) {
	events.add(event);
	}

	/**
	* Returns a formatted string for the current trace
	*
	* @return a formatted string that shows the timings of the current trace
	*/
	String getFormattedTrace() {
	return this.toString();
	}

	/**
	* Returns a formatted string that describes the thread trace.
	*
	* @return {string} A formatted string.
	*/
	@Override
	public String toString() {
	StringBuilder sb = new StringBuilder();
	long etime = -1;

	long now = System.currentTimeMillis();
	LinkedList<String> indent = Lists.newLinkedList();
	for (int i = 0; i < events.size(); i++) {
	TraceEvent e = events.get(i);
	if (e instanceof TraceStop) {
	indent.removeFirst();
	}
	sb.append(" ");
	sb.append(e.toTraceString(startTime, etime, join(indent)));
	sb.append(" ");
	etime = e.getEventTime();
	sb.append("\n");
	if (e instanceof TraceStart) {
	indent.add("\| ");
	}
	}

	if (!outstandingEvents.isEmpty()) {
	sb.append(" Unstopped timers:\n");
	for (TraceEvent startEvent : outstandingEvents.values()) {
	sb.append(" ");
	sb.append(startEvent);
	sb.append(" (");
	sb.append(now - startEvent.getEventTime());
	sb.append(" ms, started at ");
	sb.append(TraceEvent.formatTime(startEvent.getEventTime()));
	sb.append("\n");
	}
	}
	return sb.toString();
	}

	private String join(List<String> indents) {
	return Joiner.on("").join(indents);
	}

	}