[slf4j-dev] svn commit: r1075 - in slf4j/trunk: . slf4j-api/src/main/java/org/slf4j/impl slf4j-ext slf4j-ext/src/main/java/org/slf4j/profiler slf4j-ext/src/test/java/org/slf4j/profiler slf4j-site/src/site/pages
ceki at slf4j.org
ceki at slf4j.org
Wed Jul 23 22:34:12 CEST 2008
Author: ceki
Date: Wed Jul 23 22:34:11 2008
New Revision: 1075
Added:
slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/TimeInstrumentStatus.java
slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/ProfilerDemo.java
slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/RandomIntegerArrayGenerator.java
slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/SortAndPruneComposites.java
slf4j/trunk/slf4j-site/src/site/pages/extensions.html
Modified:
slf4j/trunk/pom.xml
slf4j/trunk/slf4j-api/src/main/java/org/slf4j/impl/StaticLoggerBinder.java
slf4j/trunk/slf4j-ext/pom.xml
slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Profiler.java
slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/StopWatch.java
slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Util.java
slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/ProfilerTest.java
slf4j/trunk/slf4j-site/src/site/pages/docs.html
Log:
- minor refactoring of the SLF4J profiler API
- documentation (of SLF4J profilers)
This is still ongoing work
Modified: slf4j/trunk/pom.xml
==============================================================================
--- slf4j/trunk/pom.xml (original)
+++ slf4j/trunk/pom.xml Wed Jul 23 22:34:11 2008
@@ -254,12 +254,22 @@
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-jxr-plugin</artifactId>
+ <reportSets>
+ <reportSet>
+ <reports>
+ <report>jxr</report>
+ <report>test-jxr</report>
+ </reports>
+ </reportSet>
+ </reportSets>
<configuration>
<aggregate>true</aggregate>
<javadocDir>target/site/api/</javadocDir>
<linkJavadoc>true</linkJavadoc>
</configuration>
</plugin>
+
+
</plugins>
</reporting>
Modified: slf4j/trunk/slf4j-api/src/main/java/org/slf4j/impl/StaticLoggerBinder.java
==============================================================================
--- slf4j/trunk/slf4j-api/src/main/java/org/slf4j/impl/StaticLoggerBinder.java (original)
+++ slf4j/trunk/slf4j-api/src/main/java/org/slf4j/impl/StaticLoggerBinder.java Wed Jul 23 22:34:11 2008
@@ -44,7 +44,7 @@
public static final StaticLoggerBinder SINGLETON = new StaticLoggerBinder();
private StaticLoggerBinder() {
- throw new UnsupportedOperationException("This code should never make it into the jar");
+ throw new UnsupportedOperationException("This code should have never made it into the jar");
}
public ILoggerFactory getLoggerFactory() {
Modified: slf4j/trunk/slf4j-ext/pom.xml
==============================================================================
--- slf4j/trunk/slf4j-ext/pom.xml (original)
+++ slf4j/trunk/slf4j-ext/pom.xml Wed Jul 23 22:34:11 2008
@@ -80,13 +80,7 @@
<reporting>
<plugins>
- <plugin>
- <groupId>org.codehaus.mojo</groupId>
- <artifactId>clirr-maven-plugin</artifactId>
- <configuration>
- <comparisonVersion>1.5.0</comparisonVersion>
- </configuration>
- </plugin>
+
</plugins>
</reporting>
Modified: slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Profiler.java
==============================================================================
--- slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Profiler.java (original)
+++ slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Profiler.java Wed Jul 23 22:34:11 2008
@@ -41,27 +41,12 @@
// |-- elapsed time [doZ] 21 milliseconds.
// |-- Total elapsed time [BAS] 78 milliseconds.
-// + Profiler [TOP]
-// |--+ Profiler [IIII]
-// |-- elapsed time [A] 0.006 milliseconds.
-// |-- elapsed time [B] 75.777 milliseconds.
-// |-- elapsed time [VVVVVV] 161.589 milliseconds.
-// |-- Total elapsed time [IIII] 240.580 milliseconds.
-// |--+ Profiler [RRRRRRRRR]
-// |-- elapsed time [R0] 9.390 milliseconds.
-// |-- elapsed time [R1] 6.555 milliseconds.
-// |-- elapsed time [R2] 5.995 milliseconds.
-// |-- elapsed time [R3] 115.502 milliseconds.
-// |-- elapsed time [R4] 0.064 milliseconds.
-// |-- Total elapsed time [R] 138.340 milliseconds.
-// |--+ Profiler [S]
-// |-- Total elapsed time [S0] 3.091 milliseconds.
-// |--+ Profiler [P]
-// |-- elapsed time [P0] 87.550 milliseconds.
-// |-- Total elapsed time [P] 87.559 milliseconds.
-// |-- Total elapsed time [TOP] 467.548 milliseconds.
-
-public class Profiler {
+/**
+ * A poor man's profiler to measure the time elapsed performing
+ * some lengthy task.
+ *
+ */
+public class Profiler implements TimeInstrument {
final static String PROFILER_MARKER_NAME = "PROFILER";
@@ -71,10 +56,12 @@
final String name;
final StopWatch globalStopWatch;
- List<StopWatch> stopwatchList = new ArrayList<StopWatch>();
- List<Object> childList = new ArrayList<Object>();
+ //List<StopWatch> stopwatchList = new ArrayList<StopWatch>();
+ List<TimeInstrument> childTimeInstrumentList = new ArrayList<TimeInstrument>();
+ // optional field
ProfilerRegistry profilerRegistry;
+//optional field
Logger logger;
public Profiler(String name) {
@@ -90,7 +77,7 @@
return profilerRegistry;
}
- public void setProfilerRegistry(ProfilerRegistry profilerRegistry) {
+ public void registerWith(ProfilerRegistry profilerRegistry) {
if (profilerRegistry == null) {
return;
}
@@ -106,97 +93,144 @@
this.logger = logger;
}
+ /**
+ * Starts a child stop watch and stops any previously started time instruments.
+ */
public void start(String name) {
- stopLastStopWatch();
+ stopLastTimeInstrument();
StopWatch childSW = new StopWatch(name);
- stopwatchList.add(childSW);
- childList.add(childSW);
+ childTimeInstrumentList.add(childSW);
}
public Profiler startNested(String name) {
+ stopLastTimeInstrument();
Profiler nestedProfiler = new Profiler(name);
- nestedProfiler.setProfilerRegistry(profilerRegistry);
+ nestedProfiler.registerWith(profilerRegistry);
nestedProfiler.setLogger(logger);
- childList.add(nestedProfiler);
+ childTimeInstrumentList.add(nestedProfiler);
return nestedProfiler;
}
- StopWatch getLastStopWatch() {
- if (stopwatchList.size() > 0) {
- return stopwatchList.get(stopwatchList.size() - 1);
+ TimeInstrument getLastTimeInstrument() {
+ if (childTimeInstrumentList.size() > 0) {
+ return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1);
} else {
return null;
}
}
- void stopLastStopWatch() {
- StopWatch last = getLastStopWatch();
+ void stopLastTimeInstrument() {
+ TimeInstrument last = getLastTimeInstrument();
if (last != null) {
last.stop();
}
}
- void stopNestedProfilers() {
- for (Object child : childList) {
- if (child instanceof Profiler)
- ((Profiler) child).stop();
- }
- }
+// void stopNestedProfilers() {
+// for (Object child : childTimeInstrumentList) {
+// if (child instanceof Profiler)
+// ((Profiler) child).stop();
+// }
+// }
- public Profiler stop() {
- stopLastStopWatch();
- stopNestedProfilers();
+ public long elapsedTime() {
+ return globalStopWatch.elapsedTime();
+ }
+
+ public TimeInstrument stop() {
+ stopLastTimeInstrument();
globalStopWatch.stop();
return this;
}
+ public TimeInstrumentStatus getStatus() {
+ return globalStopWatch.status;
+ }
+
+ /**
+ * This mehtod is used in tests.
+ */
+ void sanityCheck() throws IllegalStateException {
+ if(getStatus() != TimeInstrumentStatus.STOPPED) {
+ throw new IllegalStateException("time instrument ["+getName()+" is not stopped");
+ }
+
+ long totalElapsed = globalStopWatch.elapsedTime();
+ long childTotal = 0;
+
+ for(TimeInstrument ti: childTimeInstrumentList) {
+ childTotal += ti.elapsedTime();
+ if(ti.getStatus() != TimeInstrumentStatus.STOPPED) {
+ throw new IllegalStateException("time instrument ["+ti.getName()+" is not stopped");
+ }
+ if(ti instanceof Profiler) {
+ Profiler nestedProfiler = (Profiler) ti;
+ nestedProfiler.sanityCheck();
+ }
+ }
+ if(totalElapsed < childTotal) {
+ throw new IllegalStateException("children have a higher accumulated elapsed time");
+ }
+ }
+
+ static String TOP_PROFILER_FIRST_PREFIX = "+";
+ static String NESTED_PROFILER_FIRST_PREFIX = "|---+";
+ static String TOTAL_ELAPSED = " Total ";
+ static String SUBTOTAL_ELAPSED = " Subtotal ";
+ static String ELAPSED_TIME = " elapsed time ";
+
+
public void print() {
+ System.out.println(toString());
+ }
+
+ @Override
+ public String toString() {
DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
- String r = buildString(du, "+", "");
- System.out.println(r);
+ return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
}
-
+
public void log() {
Marker profilerMarker = MarkerFactory.getMarker(PROFILER_MARKER_NAME);
if (logger.isDebugEnabled(profilerMarker)) {
DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
- String r = buildString(du, "+", "");
- logger.debug(profilerMarker, r);
+ String r = buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
+ logger.debug(profilerMarker, SpacePadder.LINE_SEP+r);
}
}
-
- private String buildString(DurationUnit du, String prefix, String indentation) {
+
+ private String buildProfilerString(DurationUnit du, String firstPrefix, String label, String indentation) {
StringBuffer buf = new StringBuffer();
- buf.append(prefix);
+ buf.append(firstPrefix);
buf.append(" Profiler [");
buf.append(name);
buf.append("]");
buf.append(SpacePadder.LINE_SEP);
- for (Object child : childList) {
+ for (TimeInstrument child : childTimeInstrumentList) {
if (child instanceof StopWatch) {
- buildStringForChildStopWatch(buf, indentation, (StopWatch) child, du);
+ buildStopWatchString(buf, du, ELAPSED_TIME, indentation, (StopWatch) child);
} else if (child instanceof Profiler) {
Profiler profiler = (Profiler) child;
- profiler.stop();
String subString = profiler
- .buildString(du, "|--+", indentation + " ");
+ .buildProfilerString(du, NESTED_PROFILER_FIRST_PREFIX, SUBTOTAL_ELAPSED, indentation + " ");
buf.append(subString);
+ buildStopWatchString(buf, du, ELAPSED_TIME, indentation, profiler.globalStopWatch);
}
}
- buildStringForGlobalStopWatch(buf, indentation, globalStopWatch, du);
+ buildStopWatchString(buf, du, label, indentation, globalStopWatch);
return buf.toString();
}
- private static void buildStringForChildStopWatch(StringBuffer buf,
- String indentation, StopWatch sw, DurationUnit du) {
+ private static void buildStopWatchString(StringBuffer buf, DurationUnit du,
+ String prefix, String indentation, StopWatch sw) {
buf.append(indentation);
buf.append("|--");
- buf.append(" elapsed time ");
+ buf.append(prefix);
SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH);
buf.append(" ");
- String timeStr = Util.durationInDunrationUnitsAsStr(sw.getResultInNanos(),
+ String timeStr = Util.durationInDunrationUnitsAsStr(sw.elapsedTime(),
du);
SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH);
buf.append(" ");
@@ -204,14 +238,15 @@
buf.append(SpacePadder.LINE_SEP);
}
- private static void buildStringForGlobalStopWatch(StringBuffer buf,
+ static void XXXbuildStringForGlobalStopWatch(StringBuffer buf,
String indentation, StopWatch sw, DurationUnit du) {
buf.append(indentation);
buf.append("|--");
- buf.append(" Total elapsed time ");
+ //buf.append(prefix);
+ //buf.append(" Total elapsed time ");
SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH);
buf.append(" ");
- String timeStr = Util.durationInDunrationUnitsAsStr(sw.getResultInNanos(),
+ String timeStr = Util.durationInDunrationUnitsAsStr(sw.elapsedTime(),
du);
SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH);
buf.append(" ");
Modified: slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/StopWatch.java
==============================================================================
--- slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/StopWatch.java (original)
+++ slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/StopWatch.java Wed Jul 23 22:34:11 2008
@@ -25,37 +25,36 @@
package org.slf4j.profiler;
-public class StopWatch {
+public class StopWatch implements TimeInstrument {
+ private String name;
+ private long startTime;
+ private long stopTime;
+ TimeInstrumentStatus status;
- enum Status {
- STARTED, STOPPED;
+ public StopWatch(String name) {
+ start(name);
}
-
- final String name;
- final long startTime;
- long stopTime;
- Status status;
- public StopWatch(String name) {
+ public void start(String name) {
this.name = name;
- this.startTime = System.nanoTime();
- this.status = Status.STARTED;
+ startTime = System.nanoTime();
+ status = TimeInstrumentStatus.STARTED;
}
-
+
public String getName() {
return name;
}
- public StopWatch stop() {
- if(status == Status.STOPPED) {
+ public TimeInstrument stop() {
+ if(status == TimeInstrumentStatus.STOPPED) {
return this;
}
return stop(System.nanoTime());
}
public StopWatch stop(long stopTime) {
- this.status = Status.STOPPED;
+ this.status = TimeInstrumentStatus.STOPPED;
this.stopTime = stopTime;
return this;
}
@@ -73,7 +72,7 @@
break;
case STOPPED:
buf.append("elapsed time: ");
- buf.append(Util.durationInDunrationUnitsAsStr(getResultInNanos(), DurationUnit.MICROSECOND));
+ buf.append(Util.durationInDunrationUnitsAsStr(elapsedTime(), DurationUnit.MICROSECOND));
break;
default:
new IllegalStateException("Status " + status + " is not expected");
@@ -81,12 +80,20 @@
return buf.toString();
}
- public final long getResultInNanos() {
- if (status == Status.STARTED) {
+ public final long elapsedTime() {
+ if (status == TimeInstrumentStatus.STARTED) {
return 0;
} else {
return stopTime - startTime;
}
}
+ public TimeInstrumentStatus getStatus() {
+ return status;
+ }
+
+ public void print() {
+ System.out.println(toString());
+ }
+
}
Added: slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/TimeInstrumentStatus.java
==============================================================================
--- (empty file)
+++ slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/TimeInstrumentStatus.java Wed Jul 23 22:34:11 2008
@@ -0,0 +1,35 @@
+/*
+ * Copyright (c) 2004-2008 QOS.ch
+ * All rights reserved.
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining
+ * a copy of this software and associated documentation files (the
+ * "Software"), to deal in the Software without restriction, including
+ * without limitation the rights to use, copy, modify, merge, publish,
+ * distribute, sublicense, and/or sell copies of the Software, and to
+ * permit persons to whom the Software is furnished to do so, subject to
+ * the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be
+ * included in all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
+ * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+ * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
+ * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
+ * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
+ * OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
+ * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+ */
+
+
+
+/**
+ * A StopWatch can be in two states: STARTED or STOPPED.
+ */
+
+package org.slf4j.profiler;
+
+enum TimeInstrumentStatus {
+ STARTED, STOPPED;
+}
\ No newline at end of file
Modified: slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Util.java
==============================================================================
--- slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Util.java (original)
+++ slf4j/trunk/slf4j-ext/src/main/java/org/slf4j/profiler/Util.java Wed Jul 23 22:34:11 2008
@@ -34,7 +34,7 @@
private static final DecimalFormat DECIMAL_FORMAT = new DecimalFormat("0.000");
static DurationUnit selectDurationUnitForDisplay(StopWatch sw) {
- return selectDurationUnitForDisplay(sw.getResultInNanos());
+ return selectDurationUnitForDisplay(sw.elapsedTime());
}
static DurationUnit selectDurationUnitForDisplay(long durationInNanos) {
@@ -63,7 +63,7 @@
static String durationInDunrationUnitsAsStr(StringBuffer buf, StopWatch sw) {
DurationUnit du = selectDurationUnitForDisplay(sw);
- return durationInDunrationUnitsAsStr(sw.getResultInNanos(), du);
+ return durationInDunrationUnitsAsStr(sw.elapsedTime(), du);
}
static String durationInDunrationUnitsAsStr(long nanos, DurationUnit durationUnit) {
Added: slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/ProfilerDemo.java
==============================================================================
--- (empty file)
+++ slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/ProfilerDemo.java Wed Jul 23 22:34:11 2008
@@ -0,0 +1,50 @@
+package org.slf4j.profiler;
+
+
+
+/**
+ *
+ * This demo illustrates usage of SLF4J profilers.
+ *
+ * <p>
+ * We have been given the task of generating a large number, say N,
+ * of random integers. We need to transform that array into a smaller array
+ * containing only prime numbers. The new array has to be sorted.
+ *
+ * <p>
+ * While tackling this problem, we would like to measure the
+ * time spent in each subtask.
+ *
+ * <p>
+ * A typical output for this demo would be:
+ <pre>
+ + Profiler [DEMO]
+|-- elapsed time [RANDOM] 0.089 seconds.
+|---+ Profiler [SORT_AND_PRUNE]
+ |-- elapsed time [SORT] 0.221 seconds.
+ |-- elapsed time [PRUNE_COMPOSITES] 11.567 seconds.
+ |-- Subtotal [SORT_AND_PRUNE] 11.788 seconds.
+|-- elapsed time [SORT_AND_PRUNE] 11.788 seconds.
+|-- Total [DEMO] 11.877 seconds.
+</pre>
+ *
+ * @author Ceki Gulcu
+ */
+public class ProfilerDemo {
+
+ public static void main(String[] args) {
+ Profiler profiler = new Profiler("DEMO");
+ ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
+ profiler.registerWith(profilerRegistry);
+
+ profiler.start("RANDOM");
+ RandomIntegerArrayGenerator riag = new RandomIntegerArrayGenerator();
+ int n = 100*1000;
+ int[] randomArray = riag.generate(n);
+
+ profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);
+ SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
+ pruner.sortAndPruneComposites();
+ profiler.stop().print();
+ }
+}
Modified: slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/ProfilerTest.java
==============================================================================
--- slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/ProfilerTest.java (original)
+++ slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/ProfilerTest.java Wed Jul 23 22:34:11 2008
@@ -26,18 +26,26 @@
import junit.framework.TestCase;
-
import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
+import org.slf4j.LoggerFactory;
-public class ProfilerTest extends TestCase{
+public class ProfilerTest extends TestCase {
Logger logger = LoggerFactory.getLogger(ProfilerTest.class);
- public void smoke() {
+ public void setUp() throws Exception {
+ super.setUp();
+ }
+ public void testSmoke() {
Profiler profiler = new Profiler("SMOKE");
- System.out.println("Hello");
profiler.stop();
+ StopWatch gSW = profiler.globalStopWatch;
+
+ // verify
+ profiler.sanityCheck();
+ assertEquals(TimeInstrumentStatus.STOPPED, gSW.status);
+ assertEquals(0, profiler.childTimeInstrumentList.size());
+ assertNull(profiler.getLastTimeInstrument());
}
public void testBasicProfiling() {
@@ -46,35 +54,35 @@
profiler.start("doX");
doX(1);
- profiler.start("doYYYYY");
- for (int i = 0; i < 5; i++) {
- doY(i);
- }
+ profiler.start("doY");
+ doY(10);
+
profiler.start("doZ");
doZ(2);
- profiler.stop().print();
- }
-
- public void X() {
- Profiler profiler = new Profiler("BASIC");
-
-
- profiler.start("Subtask_1");
- doX(1);
-
- profiler.start("Subtask_1");
- for (int i = 0; i < 5; i++) {
- doX(i);
- }
- profiler.start("doOther");
- doX(2);
- profiler.stop().print();
- }
-
-
+ profiler.stop();
+
+ // verify
+ profiler.sanityCheck();
+ StopWatch gSW = profiler.globalStopWatch;
+ assertEquals(TimeInstrumentStatus.STOPPED, gSW.status);
+ assertEquals(3, profiler.childTimeInstrumentList.size());
+ assertNotNull(profiler.getLastTimeInstrument());
+ assertEquals("doZ", profiler.getLastTimeInstrument().getName());
+ }
+
+ // + Profiler [BAS]
+ // |-- elapsed time [doX] 1.272 milliseconds.
+ // |-- elapsed time [doYYYYY] 25.398 milliseconds.
+ // |--+ Profiler [subtask]
+ // |-- elapsed time [n1] 1.434 milliseconds.
+ // |-- elapsed time [n2] 5.855 milliseconds.
+ // |-- Total elapsed time [subtask] 7.321 milliseconds.
+ // |-- elapsed time [doZ] 3.211 milliseconds.
+ // |-- Total elapsed time [BAS] 30.317 milliseconds.
public void testNestedProfiling() {
+
Profiler profiler = new Profiler("BAS");
-
+ profiler.setLogger(logger);
profiler.start("doX");
doX(1);
@@ -86,10 +94,26 @@
doSubtask(nested);
profiler.start("doZ");
doZ(2);
- profiler.stop().print();
+ profiler.stop();
+
+ // verify
+ profiler.sanityCheck();
+ StopWatch gSW = profiler.globalStopWatch;
+ assertEquals(TimeInstrumentStatus.STOPPED, gSW.status);
+ //assertEquals(3, profiler.stopwatchList.size());
+ assertEquals(4, profiler.childTimeInstrumentList.size());
+ assertNotNull(profiler.getLastTimeInstrument());
+ assertEquals("doZ", profiler.getLastTimeInstrument().getName());
+
}
- void doX(int millis) {
+ private void doX(int millis) {
+ delay(millis);
+ }
+ private void doY(int millis) {
+ delay(millis);
+ }
+ private void doZ(int millis) {
delay(millis);
}
@@ -102,13 +126,6 @@
nested.stop();
}
- void doY(int millis) {
- delay(millis);
- }
-
- void doZ(int millis) {
- delay(millis);
- }
void delay(int millis) {
try {
Added: slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/RandomIntegerArrayGenerator.java
==============================================================================
--- (empty file)
+++ slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/RandomIntegerArrayGenerator.java Wed Jul 23 22:34:11 2008
@@ -0,0 +1,16 @@
+package org.slf4j.profiler;
+
+import java.util.Random;
+
+public class RandomIntegerArrayGenerator {
+ Random rand = new Random(11);
+
+ int[] generate(int size) {
+ int[] result = new int[size];
+ for(int i = 0; i < size; i++) {
+ int r = rand.nextInt();
+ result[i] = r;
+ }
+ return result;
+ }
+}
Added: slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/SortAndPruneComposites.java
==============================================================================
--- (empty file)
+++ slf4j/trunk/slf4j-ext/src/test/java/org/slf4j/profiler/SortAndPruneComposites.java Wed Jul 23 22:34:11 2008
@@ -0,0 +1,69 @@
+package org.slf4j.profiler;
+
+import java.util.ArrayList;
+import java.util.Arrays;
+
+public class SortAndPruneComposites {
+
+ static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
+
+ final int[] originalArray;
+ final int originalArrrayLength;
+
+ public SortAndPruneComposites(int[] randomArray) {
+ this.originalArray = randomArray;
+ this.originalArrrayLength = randomArray.length;
+
+ }
+
+ public int[] sortAndPruneComposites() {
+
+ ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
+ Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);
+ sortProfiler.start("SORT");
+ int[] sortedArray = sort();
+ sortProfiler.start("PRUNE_COMPOSITES");
+ int result[] = pruneComposites(sortedArray);
+
+ return result;
+ }
+
+ private int[] sort() {
+ int[] sortedArray = new int[originalArrrayLength];
+ System.arraycopy(originalArray, 0, sortedArray, 0, originalArrrayLength);
+ Arrays.sort(sortedArray);
+ return sortedArray;
+ }
+
+ int[] pruneComposites(int[] sortedArray) {
+ ArrayList<Integer> primesArray = new ArrayList<Integer>();
+ for(int i = 0; i < originalArrrayLength; i++) {
+ int n = sortedArray[i];
+ if(isPrime(n)) {
+ primesArray.add(n);
+ }
+ }
+ int resultSize = primesArray.size();
+ int[] result = new int[resultSize];
+
+ for(int i = 0; i < resultSize; i++) {
+ result[i] = primesArray.get(i);
+ }
+ return result;
+ }
+
+ public boolean isPrime(int n) {
+ if(n < 2) {
+ return false;
+ }
+ if(n%2 == 0) {
+ return false;
+ }
+ for(int i = 3; i*i <=n; i += 2) {
+ if(n%i ==0) {
+ return false;
+ }
+ }
+ return true;
+ }
+}
Modified: slf4j/trunk/slf4j-site/src/site/pages/docs.html
==============================================================================
--- slf4j/trunk/slf4j-site/src/site/pages/docs.html (original)
+++ slf4j/trunk/slf4j-site/src/site/pages/docs.html Wed Jul 23 22:34:11 2008
@@ -29,9 +29,14 @@
<li><a href="faq.html">FAQ</a></li>
<li><a href="legacy.html">Bridging legacy APIs</a></li>
<li><a href="migrator.html">SLF4J migrator</a></li>
+ <li><a href="extensions.html">SLF4J extensions</a></li>
+
<li><a href="log4j-over-slf4j.html">log4j-over-slf4j</a></li>
<li><a href="api/index.html">javadocs</a></li>
- <li><a href="xref/index.html">sources</a></li>
+ <li>
+ <a href="xref/index.html">sources</a>,
+ <a href="xref-test/index.html">test sources</a>
+ </li>
</ul>
<h2>Articles</h2>
Added: slf4j/trunk/slf4j-site/src/site/pages/extensions.html
==============================================================================
--- (empty file)
+++ slf4j/trunk/slf4j-site/src/site/pages/extensions.html Wed Jul 23 22:34:11 2008
@@ -0,0 +1,120 @@
+<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/2000/REC-xhtml1-20000126/DTD/xhtml1-transitional.dtd">
+<html xmlns="http://www.w3.org/1999/xhtml">
+<head>
+<meta http-equiv="content-type" content="text/html; charset=iso-8859-1" />
+<title>SLF4J extensions</title>
+
+<link rel="stylesheet" type="text/css" media="screen" href="css/site.css" />
+</head>
+<body>
+ <script>
+prefix='';
+</script>
+
+<script src="templates/header.js"></script>
+<div id="left">
+ <script src="templates/left.js"></script>
+</div>
+<div id="right">
+ <script src="templates/right.js"></script>
+</div>
+<div id="content">
+
+ <h1>SLF4J extensions</h1>
+
+ <p>SLF4J extensions are packaged within <em>slf4j-ext.jar</em>
+ which ships with SLF4J.</p>
+
+ <h2>Profilers</h2>
+
+ <h2>What is a profiler?</h2>
+
+ <p>According to wikipedia, <a
+ href="http://en.wikipedia.org/wiki/Profiler_%28computer_science%29">profiling</a>
+ is the investigation of a program's behavior using information
+ gathered as the program runs, i.e. it is a form of dynamic program
+ analysis, as opposed to static code analysis. The usual goal of
+ performance analysis is to determine which parts of a program to
+ optimize for speed or memory usage.
+ </p>
+
+ <p>SLF4J profilers, a.k.a. poor man's profilers, will help the
+ developer gather performance data. Essentially, a profiler
+ consists of one or more stopwatches. Stopwatches are driven
+ (started/stopped) by statements in the <em>source code</em>. An
+ example, should make the point clearer.
+ </p>
+
+ <h2>Basic example</h2>
+
+
+ <em>Example: Using the profiler </em>
+
+ <p class="source">
+
+import ch.qos.logback.classic.stopwatch.Profiler;
+
+public class BasicUsageExample {
+
+ public static void main(String[] args) {
+ <b>Profiler profiler = new Profiler("BASIC");</b>
+ <b>profiler.start("A");</b>
+ doA();
+
+ <b>profiler.start("B");</b>
+ for (int i = 0; i < 5; i++) {
+ doSubtaskTwo(i);
+ }
+ <b>profiler.start("doOther");</b>
+ doOther();
+ System.out.println(<b>profiler.stop().toString()</b>);
+ }
+ ... cut </p>
+
+ <p>Running the above example will output the following output.</p>
+
+ <p class="source">+ Profiler [BASIC]
+|-- elapsed time [A] 0.288 milliseconds.
+|-- elapsed time [B] 24.717 milliseconds.
+|-- elapsed time [Other] 22.085 milliseconds.
+|-- Total elapsed time [BASIC] 50.691 milliseconds.</p>
+
+
+ <p>Instantiating a profiler starts a global stopwatch. Each call to
+ the start() method starts a new and named stopwatch. In addition to
+ sarting a named stopwatch, the start() method also causes the
+ previous stopwatch to stop. Thus, the call to
+ <code>profiler.start("A")</code> starts a stopwatch named "A". The
+ subsequent call to <code>profiler.start("B")</code> starts
+ stopwatch "B" and simultanously stops the stopwatch named
+ "A". Invoking the <code>stop()</code> on a profiler method stops
+ the last stopwatch as well as the global stopwatch which was
+ started when the profiler was instantiated.
+ </p>
+
+
+ <h2>Profiler nesting</h2>
+
+ <p>Profilers can also be nested. By nesting profilers, it is
+ possible to measure a task which itself has subtasks that need to
+ be timed and measured.
+ </p>
+
+ <p>Starting a nested profiler will stop any previously started
+ stopwatch or nested profiler associated with the parent profiler.
+ </p>
+
+ <p>Often times, the subtask is implemented by a different class as
+ the class hosting the parent profiler. Using the
+ <code>ProfilerRegistry</code> is a convinient way of passing a
+ nested profiler to an object outside the current object.
+ </p>
+
+ <em>Example: <a
+ href="xref-test/org/slf4j/profiler/ProfilerDemo.html">ProfilerDemo</a>
+
+</div>
+</body>
+</html>
+
+
More information about the slf4j-dev
mailing list