path: root/bundles/org.eclipse.osgi/core/framework/org/eclipse/osgi/internal/profile/DefaultProfileLogger.java

/*******************************************************************************
 * Copyright (c) 2005, 2010 IBM Corporation and others.
 * All rights reserved. This program and the accompanying materials
 * are made available under the terms of the Eclipse Public License v1.0
 * which accompanies this distribution, and is available at
 * http://www.eclipse.org/legal/epl-v10.html
 * 
 * Contributors:
 *     IBM Corporation - initial API and implementation
 *******************************************************************************/

package org.eclipse.osgi.internal.profile;

import java.io.*;
import java.util.*;
import org.eclipse.osgi.framework.debug.FrameworkDebugOptions;
import org.eclipse.osgi.framework.internal.core.FrameworkProperties;

public class DefaultProfileLogger implements ProfileLogger {
	protected static final String DEFAULTPROFILE_PROP = "osgi.defaultprofile."; //$NON-NLS-1$
	protected static final String PROP_FILENAME = DEFAULTPROFILE_PROP + "logfilename"; //$NON-NLS-1$
	protected static final String PROP_LOGSYNCHRONOUSLY = DEFAULTPROFILE_PROP + "logsynchronously"; //$NON-NLS-1$
	protected static final String PROP_BUFFERSIZE = DEFAULTPROFILE_PROP + "buffersize"; //$NON-NLS-1$

	protected static final String DEFAULTPROFILE_OPTION = "org.eclipse.osgi/defaultprofile/"; //$NON-NLS-1$
	protected static final String OPTION_FILENAME = DEFAULTPROFILE_OPTION + "logfilename"; //$NON-NLS-1$
	protected static final String OPTION_LOGSYNCHRONOUSLY = DEFAULTPROFILE_OPTION + "logsynchronously"; //$NON-NLS-1$
	protected static final String OPTION_BUFFERSIZE = DEFAULTPROFILE_OPTION + "buffersize"; //$NON-NLS-1$

	protected boolean logSynchronously = false;
	protected long startTime = 0;
	protected static final int DEFAULT_BUFFER_SIZE = 256;

	protected TimeEntry[] timeLogEntries = null;
	protected int timeEntriesIndex = 0;
	protected StringBuffer timelog = null;

	protected long launchTime = -1;
	protected int bufferSize = DEFAULT_BUFFER_SIZE;
	protected String logFileName = null;
	protected File logFile = null;
	private StringBuffer entryReport = new StringBuffer(120);
	private StringBuffer padsb = new StringBuffer(16); // to prevent creating this over and over
	protected int indent;
	protected int timePaddingLength;
	protected Stack<AccumPerfScope> scopeStack;
	protected Map<String, AccumPerfData> scopeToAccumPerfDataMap;

	public DefaultProfileLogger() {
		initProps();

		int size = getBufferSize();
		timeLogEntries = new TimeEntry[size];
		timelog = new StringBuffer(4096);
		for (int i = 0; i < size; i++) {
			timeLogEntries[i] = timeEntryFactory();
		}
		timeEntriesIndex = 0;

		launchTime = getLaunchTime();
		if (launchTime == -1) {
			startTime = getMainStartTime();
		} else {
			startTime = launchTime;
		}

		long freq = getTimerFrequency();
		for (timePaddingLength = 3; freq > 9; timePaddingLength++) {
			freq /= 10;
		}

		logInitMessages();
	}

	protected void logInitMessages() {
		int index = 0;
		if (launchTime != -1L) {
			logTime(Profile.FLAG_NONE, "DefaultProfileLogger.init()", "launch time initialized", null); //$NON-NLS-1$//$NON-NLS-2$
			timeLogEntries[index++].time = launchTime;
		}

		logTime(Profile.FLAG_NONE, "DefaultProfileLogger.init()", "start time initialized", null); //$NON-NLS-1$//$NON-NLS-2$
		timeLogEntries[index++].time = getMainStartTime();
	}

	protected long getLaunchTime() {
		String launchTimeString = FrameworkProperties.getProperty("launch.startMillis"); //$NON-NLS-1$
		if (launchTimeString != null) {
			return Long.parseLong(launchTimeString);
		}
		return -1L;
	}

	protected long getMainStartTime() {
		String timeString = FrameworkProperties.getProperty("eclipse.startTime"); //$NON-NLS-1$
		if (timeString != null)
			return Long.parseLong(timeString);

		return System.currentTimeMillis();
	}

	public void initProps() {
		String prop;
		FrameworkDebugOptions dbgOptions = null;
		// if osgi.debug is not available, don't force DebugOptions
		//  to init as this variable may be set later on where 
		//  DebugOptions will succeed.
		if (FrameworkProperties.getProperty("osgi.debug") != null) { //$NON-NLS-1$
			dbgOptions = FrameworkDebugOptions.getDefault();
			if (dbgOptions != null) {
				logFileName = dbgOptions.getOption(OPTION_FILENAME);
				logSynchronously = dbgOptions.getBooleanOption(OPTION_LOGSYNCHRONOUSLY, false);
				int size = dbgOptions.getIntegerOption(OPTION_BUFFERSIZE, 0);
				if (size > 0)
					bufferSize = size;
			}
		}

		if ((prop = FrameworkProperties.getProperty(PROP_FILENAME)) != null) {
			logFileName = prop;
			if (dbgOptions != null)
				dbgOptions.setOption(OPTION_FILENAME, logFileName);
		}
		if ((prop = FrameworkProperties.getProperty(PROP_LOGSYNCHRONOUSLY)) != null) {
			logSynchronously = Boolean.valueOf(prop).booleanValue();
			if (dbgOptions != null)
				dbgOptions.setOption(OPTION_LOGSYNCHRONOUSLY, new Boolean(logSynchronously).toString());
		}
		if ((prop = FrameworkProperties.getProperty(PROP_BUFFERSIZE)) != null) {
			try {
				int value = Integer.parseInt(prop);
				if (value > 0) {
					bufferSize = value;
					if (dbgOptions != null)
						dbgOptions.setOption(OPTION_BUFFERSIZE, Integer.toString(bufferSize));
				}
			} catch (NumberFormatException e) {
				// do nothing
			}
		}
	}

	public synchronized void logTime(int flag, String id, String msg, String description) {
		if (timeEntriesIndex == timeLogEntries.length) {
			makeLog();
			logTime(Profile.FLAG_NONE, "Profile.logTime()", "log entries rolled", null); //$NON-NLS-1$ //$NON-NLS-2$
		}

		TimeEntry entry = timeLogEntries[timeEntriesIndex++];
		entry.time = getTime();
		entry.id = id;
		entry.msg = msg;
		entry.flag = flag;
		entry.description = description;

		if (logSynchronously) {
			System.out.print(getProfileLog().substring(2));
		}
	}

	public synchronized String getProfileLog() {
		String log;
		log = getProfileLogReport();
		writeToProfileLogFile(log);
		return log;
	}

	public synchronized void accumLogEnter(String scope) {
		// Initialize our data structures
		if (scopeStack == null)
			scopeStack = new Stack<AccumPerfScope>();
		if (scopeToAccumPerfDataMap == null)
			scopeToAccumPerfDataMap = new TreeMap<String, AccumPerfData>();

		// We want getTime() to evaluate as late as possible
		scopeStack.push(new AccumPerfScope(scope, getTime()));
	}

	public synchronized void accumLogExit(String scope) {
		// What time is it?
		long exit = getTime();

		// Initialize our data structures
		if (scopeStack == null)
			scopeStack = new Stack<AccumPerfScope>();
		if (scopeToAccumPerfDataMap == null)
			scopeToAccumPerfDataMap = new TreeMap<String, AccumPerfData>();

		// Do our calculations
		AccumPerfScope then = scopeStack.pop();
		if (then == null)
			System.err.println("ACCUM PERF ERROR: Scope stack empty: " + scope); //$NON-NLS-1$
		else {
			if (!then.scope.equals(scope))
				System.err.println("ACCUM PERF ERROR: Scope mismatch: then='" + then.scope + "', now='" + scope + "'"); //$NON-NLS-1$//$NON-NLS-2$//$NON-NLS-3$

			AccumPerfData now = scopeToAccumPerfDataMap.get(scope);
			if (now == null) {
				now = new AccumPerfData(scope);
				scopeToAccumPerfDataMap.put(scope, now);
			}

			now.time += exit - then.enter;
			now.enters++;
		}
	}

	protected long getTime() {
		return System.currentTimeMillis();
	}

	protected long getTimerFrequency() {
		return 1000L; // millisecond
	}

	protected TimeEntry findCompareEntry(int index, String id, int flag) {
		if (index > 0)
			index--;
		int prev = index;
		if (flag != Profile.FLAG_ENTER) {
			while (index >= 0) {
				TimeEntry entry = timeLogEntries[index];
				if (entry.id.equals(id)) {
					switch (flag) {
						case Profile.FLAG_NONE :
							return entry;
						case Profile.FLAG_EXIT :
							if (entry.flag == Profile.FLAG_ENTER)
								return entry;
							break;
					}
				}
				index--;
			}
		}
		return timeLogEntries[prev];
	}

	protected String entryReport(TimeEntry entry, TimeEntry compareWith) {
		// indent level:
		entryReport.setLength(0);
		if (entry.flag == Profile.FLAG_ENTER)
			indent++;
		long zeroTime = getRelativeTime(getStartTime());

		entryReport.append('-');
		long entryTime = getRelativeTime(entry.time);
		long diff = entryTime - zeroTime;
		entryReport.append(pad(Long.toString(diff), timePaddingLength));
		entryReport.append(" :"); //$NON-NLS-1$
		diff = entry.time - compareWith.time;
		entryReport.append(pad(Long.toString(diff), timePaddingLength));
		entryReport.append(pad("", indent * 2)); // indent before displaying the entry.id //$NON-NLS-1$

		if (entry.flag == Profile.FLAG_ENTER)
			entryReport.append(" >> "); //$NON-NLS-1$
		else if (entry.flag == Profile.FLAG_EXIT)
			entryReport.append(" << "); //$NON-NLS-1$
		else if (entry.flag == Profile.FLAG_NONE)
			entryReport.append(" -- "); //$NON-NLS-1$

		entryReport.append(entry.id);
		entryReport.append(" > "); //$NON-NLS-1$
		entryReport.append(entry.msg);
		if (entry.description != null) {
			entryReport.append(" :: "); //$NON-NLS-1$
			entryReport.append(entry.description);
		}
		entryReport.append("\r\n"); //$NON-NLS-1$

		if (entry.flag == Profile.FLAG_EXIT)
			indent -= 1;
		return entryReport.toString();
	}

	protected String accumEntryReport(AccumPerfData d) {
		return ("     " + d.scope + ":enters=" + d.enters + ";time=" + d.time + ";\r\n"); //$NON-NLS-1$//$NON-NLS-2$//$NON-NLS-3$//$NON-NLS-4$
	}

	protected void makeLog() {
		indent = 0;
		timelog.append("\r\n"); //$NON-NLS-1$
		for (int i = 0; i < timeEntriesIndex; i++) {
			TimeEntry entry = timeLogEntries[i];
			TimeEntry cmpEntry = findCompareEntry(i, entry.id, entry.flag);
			timelog.append(entryReport(entry, cmpEntry));
		}
		timeEntriesIndex = 0;

		if (scopeToAccumPerfDataMap == null || scopeToAccumPerfDataMap.isEmpty())
			return; // No data; nothing to do
		timelog.append("\r\n"); //$NON-NLS-1$
		timelog.append("Cumulative Log:\r\n"); //$NON-NLS-1$
		for (AccumPerfData d : scopeToAccumPerfDataMap.values()) {
			timelog.append(accumEntryReport(d));
		}
		scopeToAccumPerfDataMap.clear();
	}

	protected String pad(String str, int size) {
		padsb.setLength(0);
		int len = str.length();
		int count = size - len;
		for (int i = 0; i < count; i++)
			padsb.append(' ');
		padsb.append(str);
		return padsb.toString();
	}

	protected String getProfileLogReport() {
		if (timelog == null)
			return ""; //$NON-NLS-1$
		makeLog();
		String log = timelog.toString();
		timelog.setLength(0);
		return log;
	}

	protected void writeToProfileLogFile(String log) {
		File profileLog = getProfileLogFile();
		if (profileLog == null)
			return;
		FileWriter fw = null;
		try {
			fw = new FileWriter(profileLog.getAbsolutePath(), true);
			fw.write(log);
		} catch (IOException e) {
			e.printStackTrace();
		} finally {
			if (fw != null)
				try {
					fw.close();
				} catch (IOException e) {
					// do nothing
				}
		}
	}

	protected File getProfileLogFile() {
		if (logFile == null)
			if ((logFileName != null) && (logFileName.length() > 0))
				logFile = new File(logFileName);
		return logFile;
	}

	protected long getStartTime() {
		return startTime;
	}

	protected long getRelativeTime(long absoluteTime) {
		return absoluteTime;
	}

	protected int getBufferSize() {
		if (bufferSize < 2)
			return DEFAULT_BUFFER_SIZE;
		return bufferSize;
	}

	protected TimeEntry timeEntryFactory() {
		return new TimeEntry();
	}

	protected class TimeEntry {
		public long time;
		public String id;
		public String msg;
		public String description;
		public int flag;
	}

	protected static class AccumPerfData {
		public AccumPerfData(String scope) {
			this.scope = scope;
		}

		public String scope;
		public long time;
		public long enters;
	}

	protected static class AccumPerfScope {
		public AccumPerfScope(String scope, long enter) {
			this.scope = scope;
			this.enter = enter;
		}

		public String scope;
		public long enter;
	}
}