| /******************************************************************************* |
| * Copyright (c) 2005, 2006 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 scopeStack; |
| protected Map 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(); |
| if (scopeToAccumPerfDataMap == null) |
| scopeToAccumPerfDataMap = new TreeMap(); |
| |
| // 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(); |
| if (scopeToAccumPerfDataMap == null) |
| scopeToAccumPerfDataMap = new TreeMap(); |
| |
| // Do our calculations |
| AccumPerfScope then = (AccumPerfScope) 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 = (AccumPerfData) 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$ |
| Iterator iter = scopeToAccumPerfDataMap.values().iterator(); |
| while (iter.hasNext()) { |
| AccumPerfData d = (AccumPerfData) iter.next(); |
| 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; |
| } |
| } |