com.adobe.xfa.ut.trace.TraceHandler Maven / Gradle / Ivy
Go to download
Show more of this group Show more artifacts with this name
Show all versions of aem-sdk-api Show documentation
Show all versions of aem-sdk-api Show documentation
The Adobe Experience Manager SDK
The newest version!
/*
* ADOBE CONFIDENTIAL
*
* Copyright 2005 Adobe Systems Incorporated All Rights Reserved.
*
* NOTICE: All information contained herein is, and remains the property of
* Adobe Systems Incorporated and its suppliers, if any. The intellectual and
* technical concepts contained herein are proprietary to Adobe Systems
* Incorporated and its suppliers and may be covered by U.S. and Foreign
* Patents, patents in process, and are protected by trade secret or copyright
* law. Dissemination of this information or reproduction of this material
* is strictly forbidden unless prior written permission is obtained from
* Adobe Systems Incorporated.
*/
package com.adobe.xfa.ut.trace;
import java.io.BufferedReader;
import java.io.BufferedWriter;
import java.io.FileNotFoundException;
import java.io.FileReader;
import java.io.FileWriter;
import java.io.IOException;
import java.util.HashMap;
import java.util.Formatter;
import java.util.Locale;
import java.util.Map;
import java.util.StringTokenizer;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLongArray;
import com.adobe.xfa.ut.FindBugsSuppress;
import com.adobe.xfa.ut.MsgFormatPos;
import com.adobe.xfa.ut.ResourceLoader;
import com.adobe.xfa.ut.StringUtils;
/**
* This trace handler class manages Trace areas for a given thread and
* outputs trace messages to standard out.
* If an application uses tracing it should create one instance of this class for
* each thread.
*
* example:
*
* Trace dataTrace = new Trace("data", ResId.DataTraceHelp);
* Trace stringTrace = new Trace("string" ResId.StringTraceHelp);
* main(...)
* {
* TraceHandler traceHandler = new TraceHandler();
*
* TraceHandler.registerTraceHandler(traceHandler);
*
* // three ways to activate
* traceHandler.activate("data", 2);
* traceHandler.activate("data:2 eval:3 signature:1");
* stringTrace.activate(3);
*
* ...
* traceHandler.trace(dataTrace, 2, 27, "data msg"); // issue message
* ...
* dataTrace.trace(2, 33, "string msg"); // issue message
* ...
* }
*
*
*
* @exclude from published api -- Mike Tardif, May 2006.
*/
public final class TraceHandler {
/**
* @exclude from published api.
*/
public enum TimingType {
XFAPA_MERGE_TIMING, // Merge for PA (includes validate call; includes XFAPA_MERGE_CALC_TIMING)
XFAPA_LAYOUT_TIMING, // Layout for PA (includes XFAPA_LAYOUT_CALC_TIMING)
XFAPA_RENDER_TIMING, // Render for PA
XFAPA_MERGE_CALC_TIMING, // Calculation during merge as run from PA
XFAPA_LAYOUT_CALC_TIMING, // Calculation during layout as run from PA
XFAPA_LAYOUT_FONTSERVICE_TIMING,// Font processing during layout
XMLFORM_INIT_TIMING, // XMLFormAgent initialization
XMLFORM_INIT_BATCH_TIMING, // XMLFormAgent batch initialization
XMLFORM_RENDER_TIMING, // XMLFormAgent render time
XMLFORM_IMPORT_TIMING, // XMLFormAgent importPackets/reloadPackets
XMLFORM_POSTPROCESS_TIMING, // XMLFormAgent postprocessing
CORETECH_INIT_TIMING, // CoreTech & AXTE initialization
XFA_MERGE_ONLY_TIMING, // Merge algorithm proper (not including scripts)
XFA_LAYOUT_ONLY_TIMING, // Layout algorithm proper (not including scripts)
XFA_SCRIPTS_ONLY_TIMING, // Cumulative time for all scripts
UT_TESTCASE, // Used inside tests to time the entire test
APP_TOTALTIME, // Used to time total running time of the app.
XFA_OPEN_TIMING, // Used time how long it take for a document to open in Acrobat/Reader
USER1_TIMING, // Not used -- useful for temporary experiments
USER2_TIMING,
};
// Static member variable for global timing.
private static volatile boolean gbTimingTraceEnabled;
private final static AtomicLongArray mTimingData = new AtomicLongArray(TimingType.values().length);
// These settings are set in the synchronized parseTraceControlFile method.
private static volatile BufferedWriter gScriptLog;
private static BufferedWriter gTimingLog;
private static boolean gbTimingLogNonZeroOnly;
private static final AtomicInteger mnThreadIdPool = new AtomicInteger();
private static final ThreadLocal mTraceHandlerTLS = new ThreadLocal() {
protected TraceHandler initialValue() {
return new TraceHandler(mnThreadIdPool.getAndIncrement());
}
};
private final int mnThreadId; // A unique thread id - has nothing to do with Java thread id
private int mnLastCheckState; // to improve lookups, store the last trace area's state
private String msLastCheckName = ""; // to improve lookups, store the last trace area's name
private int mnMaxTraceNameLen; // to improve output format, store the largest trace area's name
private final Map mTraceLevels = new HashMap(); // name, level - list of trace areas
private final Map mTraces = new HashMap(); // name, trace - map of trace areas
private Formatter mFormatter;
private Object mUserData = null; // user data for mAmendMsgCallback
private AmendMsgCallback mAmendMsgCallback = null; // callback that returns a string to append to the trace message
public static void timingTraceEnabled(boolean bEnabled) {
gbTimingTraceEnabled = bEnabled;
}
public static boolean timingTraceEnabled() {
return gbTimingTraceEnabled;
}
public static boolean scriptLoggingEnabled() {
return gScriptLog != null;
}
/** @exclude from published api. */
public interface AmendMsgCallback {
public String amendMessage(int nID, Object userData);
}
public static void setAmendMsgCallback(AmendMsgCallback callback, Object userData) {
TraceHandler traceHandler = getTraceHandler();
if (traceHandler != null) {
traceHandler.mAmendMsgCallback = callback;
traceHandler.mUserData = userData;
}
}
// Reset all timing counters to zero.
public static void resetTiming() {
for (int i = 0; i < mTimingData.length(); i++)
mTimingData.set(i, 0);
}
// Static function to reset selected types timing information to zero
public static void resetTiming(TimingType eType) {
mTimingData.set(eType.ordinal(), 0);
}
// Static function to activate timing tracing (possibly in the absence of tracing, eg in the plugin).
// Can be called more than once, in order to re-read the contents of the file specified by XTG_TRACE_CONTROL.
public static void initializeTiming() {
resetTiming();
parseTraceControlFile();
}
// If initializeTiming has been called and XTG_TRACE_CONTROL was set, reportScriptInfo will write
// script information to the log file specified.
public synchronized static void reportScriptInfo(String sMsg) {
// re-read the settings from the control file, in case they've changed.
parseTraceControlFile();
if (gScriptLog == null)
return; // not activated by initializeTiming()
try {
gScriptLog.write(sMsg);
gScriptLog.write('\n');
}
catch (IOException ex) {
}
}
private static void outputTime(String prefix, TimingType eType) throws IOException {
final long milliseconds = getTimerMilliseconds(eType);
if (milliseconds == 0 && gbTimingLogNonZeroOnly)
return;
gTimingLog.write(prefix);
gTimingLog.write(Long.toString(milliseconds));
gTimingLog.write('\n');
}
public synchronized static void reportTimingResults(boolean bClearStoppedTimers) {
// re-read the settings from the control file, in case they've changed.
parseTraceControlFile();
if (gTimingLog == null)
return; // not activated by initializeTiming()
try {
gTimingLog.write("Timing results (ms):\n");
outputTime("XFAPA_MERGE_TIMING: ", TimingType.XFAPA_MERGE_TIMING);
outputTime("XFAPA_LAYOUT_TIMING: ", TimingType.XFAPA_LAYOUT_TIMING);
outputTime("XFAPA_RENDER_TIMING: ", TimingType.XFAPA_RENDER_TIMING);
outputTime("XFAPA_MERGE_CALC_TIMING: ", TimingType.XFAPA_MERGE_CALC_TIMING);
outputTime("XFAPA_LAYOUT_CALC_TIMING: ", TimingType.XFAPA_LAYOUT_CALC_TIMING);
outputTime("XFA_MERGE_ONLY_TIMING: ", TimingType.XFA_MERGE_ONLY_TIMING);
outputTime("XFA_LAYOUT_ONLY_TIMING: ", TimingType.XFA_LAYOUT_ONLY_TIMING);
outputTime("XFA_SCRIPTS_ONLY_TIMING: ", TimingType.XFA_SCRIPTS_ONLY_TIMING);
outputTime("XFA_OPEN_TIMING: ", TimingType.XFA_OPEN_TIMING);
gTimingLog.write("Timing results complete.\n\n");
gTimingLog.flush();
if (bClearStoppedTimers)
resetTiming();
}
catch (IOException ex) {
}
}
// Static function to retrieve one entry's timing information.
public static long getTimerMilliseconds(TimingType eType) {
return mTimingData.get(eType.ordinal()) / 1000000;
}
// Used by TraceTimer.stopTimer() to increment timing data
static void addTimerNanos(TraceHandler.TimingType eType, long nanos) {
mTimingData.addAndGet(eType.ordinal(), nanos);
}
/**
* Constructor
* @param nThreadId the thread id of the current thread
*/
public TraceHandler(int nThreadId) {
mnLastCheckState = 0;
mnThreadId = nThreadId;
mnMaxTraceNameLen = 0;
}
/**
* Get the TraceHandler for the current thread.
* @return the TraceHandler assigned to the current thread.
*/
public static TraceHandler getTraceHandler() {
return mTraceHandlerTLS.get();
}
/**
* Registers the trace handler for the current thread.
*/
public static void registerTraceHandler(TraceHandler traceHandler) {
if (traceHandler != null) {
mTraceHandlerTLS.set(traceHandler);
}
}
/**
* Unregisters a trace handler for the current thread.
*/
public static void unregisterTraceHandler() {
mTraceHandlerTLS.set(null);
}
/**
* Activates a trace section
* @param trace a globally defined Trace object
* @param nLevel the detail level of the messages allowed,
* higher the level greater the detail
*/
public void activate(Trace trace, int nLevel) {
if (trace == null)
return;
activate(trace.getName(), nLevel);
}
/**
* Activates a trace section
* @param sName the name of a globally defined Trace object
* @param nLevel the detail level of the messages allowed
* higher the level greater the detail
*/
public void activate(String sName, int nLevel) {
if (sName.equals("timing")) {
timingTraceEnabled(nLevel > 0);
resetTiming();
}
// populate the last check info
msLastCheckName = sName;
mnLastCheckState = 0;
// search for the trace section in the lookup map
if (!mTraceLevels.containsKey(msLastCheckName)) {
// Check for any late comers (Traces that were added
// after this TraceHandler was registered) by copying
// any trace sections from the global trace store that
// we don't already have.
final GlobalTraceStore globalTraceStore = GlobalTraceStore.getStore();
globalTraceStore.ensureTraceExists(msLastCheckName);
for (Trace t: globalTraceStore.getTraceSections())
addTrace(t);
}
// update the trace level
mTraceLevels.put(msLastCheckName, nLevel);
mnLastCheckState = nLevel;
// get the Trace object
final Trace trace = mTraces.get(msLastCheckName);
// set that tracing is on on some thread for some section
GlobalTraceStore.getStore().enable();
// tell the Trace object that it has been activated by a thread
// (if the object is null, it's an unknown trace area)
if (trace != null)
trace.enable();
}
/**
* Activates one or more trace sections
* @param sNamesAndLevels the whitespace-separated list of trace names
* and the associated detail level. For example: "eval:2 signature:1".
* This is the same format as a command line argument, so the argument
* following the -trace argument (by convention) can be passed to
* this method.
*/
public void activate(String sNamesAndLevels) {
final StringTokenizer tokenizer = new StringTokenizer(sNamesAndLevels);
while (tokenizer.hasMoreTokens()) {
final String token = tokenizer.nextToken();
final int colon = token.indexOf(':');
String sName;
int nLevel = 0;
if (colon == -1) {
sName = token.trim();
}
else {
sName = token.substring(0, colon).trim();
final String sLevel = token.substring(colon + 1);
try {
nLevel = Integer.parseInt(sLevel);
}
catch (NumberFormatException ex) {
}
}
activate(sName, nLevel);
}
}
/**
* Deactivates a trace section
* @param sName the name of a globally defined Trace object
*/
public void deactivate(String sName) {
// populate the last check info
msLastCheckName = sName;
mnLastCheckState = 0;
// search for the trace section in the lookup map
if (mTraceLevels.containsKey(sName)) {
// update the trace level
mTraceLevels.put(sName, 0);
}
}
/**
* Finds the available trace sections
* @param bIncludeHelp if true, include the description for the trace areas
* @return a newline-delimited list of available trace
* areas (and their descriptions) for this thread.
*/
String dumpAvailable(boolean bIncludeHelp) {
final StringBuilder sRetValue = new StringBuilder();
for (Trace trace: mTraces.values()) {
if (sRetValue.length() > 0)
sRetValue.append('\n');
if (bIncludeHelp)
sRetValue.append('\t');
sRetValue.append(trace.getName());
if (bIncludeHelp) {
sRetValue.append(" - ");
sRetValue.append(trace.getHelpId());
}
}
return sRetValue.toString();
}
/**
* Check if a trace section is enabled for this thread
* @param sName the name of a globally defined Trace object
* @param nLevel the desired trace level
* @return true if this trace section is enabled for this thread, else false
*/
boolean isActive(String sName, int nLevel) {
// if it wasn't the last checked trace section
if (!msLastCheckName.equals(sName)) {
msLastCheckName = sName;
Integer value = mTraceLevels.get(msLastCheckName);
mnLastCheckState = value == null ? 0 : value.intValue();
}
// check if it was activated
if (mnLastCheckState == 0 || mnLastCheckState < nLevel)
return false;
return true;
}
/**
* Issues a trace message.
* @param oTrace a globally defined jfTrace object
* @param nLevel the detail level of the message, higher the level greater the detail
* @param nId the message Id.
* @param sMsg the message text.
*/
void trace(Trace oTrace, int nLevel, int nId, String sMsg) {
// isEnabled calls isActive().
if (oTrace != null && oTrace.isEnabled(nLevel)) {
printTrace(oTrace.getName(), nId, sMsg); // print the trace message
}
}
/**
* Issues a trace message.
* @param sName the name of a globally defined Trace object
* @param nLevel the detail level of the message, higher the level greater the detail
* @param nId the message Id.
* @param sMsg the message text.
*/
void trace(String sName, int nLevel, int nId, String sMsg) {
if (isActive(sName, nLevel))
printTrace(sName, nId, sMsg); // print the trace message
}
/**
* Issues a trace message.
* @param sName the name of a globally defined jfTrace object
* @param nLevel the detail level of the message, 1 for high level information, 3 for detailed information.
* @param oMsg the message for the trace.
*/
void trace(String sName, int nLevel, MsgFormatPos oMsg) {
if (isActive(sName, nLevel))
printTrace(sName, oMsg.resId(), oMsg.toString()); // print the trace message
}
/**
* Issues a trace message.
* @param oTrace a globally defined Trace object
* @param nLevel the detail level of the message, higher the level greater the detail
* @param oMsg the message for the trace.
*/
void trace(Trace oTrace, int nLevel, MsgFormatPos oMsg) {
// isEnabled calls isActive().
if (oTrace != null && oTrace.isEnabled(nLevel)) {
printTrace(oTrace.getName(), oMsg.resId(), oMsg.toString()); // print the trace message
}
}
/**
* Get the thread ID of this TraceHandler
* @return thread ID
*/
public int getThreadId() {
return mnThreadId;
}
/** helper function to populate the trace areas
*/
private void addTrace(Trace trace) {
// update mnMaxTraceNameLen
if (trace.getName().length() > mnMaxTraceNameLen)
mnMaxTraceNameLen = trace.getName().length();
// add a trace area
mTraceLevels.put(trace.getName(), 0);
mTraces.put(trace.getName(), trace);
}
private String amendMsg(int nAmendId) {
if (mAmendMsgCallback != null)
return mAmendMsgCallback.amendMessage(nAmendId, mUserData);
else
return "";
}
private void printTrace(String sName, int nId, String sMsg) {
if (mFormatter == null)
mFormatter = new Formatter(System.out, Locale.US);
// Javaport: a format such as "%-*s" where the "*" indicates that the width comes
// from a parameter, isn't supported by the Formatter, so we have to insert it in the
// format string directly.
mFormatter.format("%-" + mnMaxTraceNameLen + "s trace: mid=%-3u tid=%-3u msg: %s\n",
mnMaxTraceNameLen,
sName,
nId,
mnThreadId,
sMsg);
int nAmendId = nId; // default Id
String sAmendId = amendMsg(nAmendId);
if (!StringUtils.isEmpty(sAmendId)) {
mFormatter.format(" trace: mid=%-3u tid=%-3u msg: %s\n",
nAmendId,
mnThreadId,
sAmendId);
}
}
// Static function to activate timing tracing (possibly in the absence of tracing, eg in the plugin).
// Can be called more than once, in order to re-read the contents of the file specified by XTG_TRACE_CONTROL.
@FindBugsSuppress(code="DE")
private synchronized static void parseTraceControlFile() {
// Javaport: modified to avoid using deprecated System's getenv() method.
// Used Java properties instead. See com.adobe.xfa.environment.properties file.
String sTraceControlFileName = ResourceLoader.loadProperty("xtg.trace.control.file");
if (sTraceControlFileName.length() == 0)
return;
gbTimingTraceEnabled = true;
// Reset any entries that will be parsed from the file.
if (gTimingLog != null) {
try { gTimingLog.close(); } catch (IOException ex) {}
gTimingLog = null;
}
if (gScriptLog != null) {
try { gScriptLog.close(); } catch (IOException ex) {}
gScriptLog = null;
}
gbTimingLogNonZeroOnly = false;
try {
final BufferedReader reader = new BufferedReader(new FileReader(sTraceControlFileName));
try {
while (true) {
String line;
try {
line = reader.readLine();
}
catch (IOException ex) {
break;
}
if (line == null)
break;
int index;
if ((index = line.indexOf("timinglog=")) != -1) {
final String timingLog = line.substring(index + "timinglog=".length());
if (gTimingLog == null) {
try {
gTimingLog = new BufferedWriter(new FileWriter(timingLog, true)); // append
}
catch (IOException ex) {
}
}
}
else if ((index = line.indexOf("nonZeroOnly=")) != -1) {
final String timingLogNonZeroOnly = line.substring(index + "nonZeroOnly=".length());
gbTimingLogNonZeroOnly = Integer.parseInt(timingLogNonZeroOnly) == 1;
}
else if ((index = line.indexOf("scriptlog=")) != -1) {
final String scriptLog = line.substring(index + "scriptlog=".length());
if (gScriptLog == null) {
try {
gScriptLog = new BufferedWriter(new FileWriter(scriptLog, true)); // append
}
catch (IOException ex) {
}
}
}
}
}
finally {
try { reader.close(); }
catch (IOException ex) {}
}
}
catch (FileNotFoundException ex) {
}
}
public boolean isTimerActive(TimingType eType) {
return mTimingData.get(eType.ordinal()) != 0;
}
}