May 2008 - logback-dev - mailman3.qos.ch

svn commit: r1691 - logback/trunk/logback-site/src/site/pages/manual
by noreply.ceki＠qos.ch 06 May '08

06 May '08

Author: ceki Date: Tue May 6 22:23:57 2008 New Revision: 1691 Modified: logback/trunk/logback-site/src/site/pages/manual/profilers.html Log: - ongoing work Modified: logback/trunk/logback-site/src/site/pages/manual/profilers.html ============================================================================== --- logback/trunk/logback-site/src/site/pages/manual/profilers.html (original) +++ logback/trunk/logback-site/src/site/pages/manual/profilers.html Tue May 6 22:23:57 2008 @@ -2,13 +2,13 @@ <html xmlns="http://www.w3.org/1999/xhtml"> <head> <meta http-equiv="content-type" content="text/html; charset=iso-8859-1" /> -<title>Chapter 5: Layouts</title> +<title>Chapter 8: Profilers</title> <link rel="stylesheet" type="text/css" media="screen" href="../css/site.css" /> <link rel="stylesheet" type="text/css" media="print" href="../css/print.css" /> </head> <body> - <script> + <script> prefix='../'; </script> <script src="../templates/header.js"></script> @@ -21,7 +21,7 @@ <div id="content"> <h1>Chapter 8: Profilers</h1> - + <div class="quote"> <p>We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil. @@ -31,7 +31,7 @@ <script src="../templates/creative.js"></script> <script src="../templates/setup.js"></script> - + <h2>What is a profiler?</h2> <p>According to wikipedia, <a @@ -43,30 +43,67 @@ optimize for speed or memory usage. </p> - <p>A logback profiler help the developer gather performance data - by managing one or more stopwatches driven by statements inserted - in the source code. An example, should make the point clearer. + <p>A logback profiler will help the developer to gather + performance data. Essentially, a profiler consists of one or more + stopwatches. Stopwatches are driven (started/stopped) by + statements in the source code. An example, should make the point + clearer. </p> - <p class="source"> - doSomethingBasic() { - Profiler profiler = new Profiler("BASIC"); - - profiler.start("Subtask_1"); - doSubtaskOne(); - - profiler.start("Subtask_1"); - for (int i = 0; i < 5; i++) { - doSubtaskTwo(i); - } - profiler.start("Other"); - doOther(); - profiler.stop().print();</p> + <h2>Basic example</h2> + + <em>Example 8.1: Using the profiler (<a + href="../xref/chapter8/ProfilerUsageExample.html"> + logback-examples/src/main/java/chapter8/ProfilerUsageExample.java</a>)</em> + + <p class="source">package chapter8; + +import ch.qos.logback.classic.stopwatch.Profiler; + +public class ProfilerUsageExample { + + 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(); + <b>profiler.stop().print();</b> + } + ... cut </p> + + <p>Running the above example will output the following output.</p> <p class="source">+ Profiler [BASIC] -|-- elapsed time [Subtask_1] 9.987 milliseconds. -|-- elapsed time [Subtask_1] 47.263 milliseconds. -|-- elapsed time [Other] 2.790 milliseconds. -|-- Total elapsed time [BASIC] 60.092 milliseconds. -</p> -</div> \ No newline at end of file +|-- 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 subtask which itself has subtasks that need + to be timed. </p> + +</div> +

1 0

svn commit: r1690 - logback/trunk/logback-examples/src/main/java/chapter8
by noreply.ceki＠qos.ch 06 May '08

06 May '08

Author: ceki Date: Tue May 6 22:23:31 2008 New Revision: 1690 Added: logback/trunk/logback-examples/src/main/java/chapter8/ logback/trunk/logback-examples/src/main/java/chapter8/NestedProfilerExample.java logback/trunk/logback-examples/src/main/java/chapter8/ProfilerUsageExample.java Log: - adding profiler examples Added: logback/trunk/logback-examples/src/main/java/chapter8/NestedProfilerExample.java ============================================================================== --- (empty file) +++ logback/trunk/logback-examples/src/main/java/chapter8/NestedProfilerExample.java Tue May 6 22:23:31 2008 @@ -0,0 +1,46 @@ +package chapter8; + +import ch.qos.logback.classic.stopwatch.Profiler; + +public class NestedProfilerExample { + + public static void main(String[] args) { + Profiler profiler = new Profiler("BASIC"); + profiler.start("A"); + doA(); + + profiler.start("B"); + for (int i = 0; i < 5; i++) { + doB(i); + } + profiler.start("Other"); + doOther(); + profiler.stop().print(); + } + + public void subTask() { + + } + + + static void doA() { + delay(10); + } + + static void doB(int millis) { + delay(millis); + } + + static void doOther() { + delay(10); + } + + + static void delay(int millis) { + try { + Thread.sleep(millis); + } catch (InterruptedException e) { + } + } + +} Added: logback/trunk/logback-examples/src/main/java/chapter8/ProfilerUsageExample.java ============================================================================== --- (empty file) +++ logback/trunk/logback-examples/src/main/java/chapter8/ProfilerUsageExample.java Tue May 6 22:23:31 2008 @@ -0,0 +1,40 @@ +package chapter8; + +import ch.qos.logback.classic.stopwatch.Profiler; + +public class ProfilerUsageExample { + + public static void main(String[] args) { + Profiler profiler = new Profiler("BASIC"); + profiler.start("A"); + doA(); + + profiler.start("B"); + for (int i = 0; i < 5; i++) { + doB(i); + } + profiler.start("Other"); + doOther(); + profiler.stop().print(); + } + + static void doA() { + delay(10); + } + + static void doB(int millis) { + delay(millis); + } + + static void doOther() { + delay(10); + } + + + static void delay(int millis) { + try { + Thread.sleep(millis); + } catch (InterruptedException e) { + } + } +}

1 0

svn commit: r1689 - in logback/trunk: logback-classic/src/main/java/ch/qos/logback/classic/stopwatch logback-classic/src/test/java/ch/qos/logback/classic/stopwatch logback-site/src/site/pages/manual
by noreply.ceki＠qos.ch 05 May '08

05 May '08

Author: ceki Date: Mon May 5 22:32:25 2008 New Revision: 1689 Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/ProfilerRegistry.java logback/trunk/logback-site/src/site/pages/manual/profilers.html Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Profiler.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java logback/trunk/logback-site/src/site/pages/manual/contextSelector.html logback/trunk/logback-site/src/site/pages/manual/index_menu.js Log: - created a new chapter on profilers - ProfilerRegistry instance are intended to help developers track profilers Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Profiler.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Profiler.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Profiler.java Mon May 5 22:32:25 2008 @@ -18,7 +18,7 @@ public class Profiler { - final static int MIN_SW_NAME_LENGTH = 10; + final static int MIN_SW_NAME_LENGTH = 12; final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 6; final String name; @@ -27,11 +27,21 @@ List<StopWatch> stopwatchList = new ArrayList<StopWatch>(); List<Object> childList = new ArrayList<Object>(); + ProfilerRegistry profilerRegistry; + public Profiler(String name) { this.name = name; this.globalStopWatch = new StopWatch(name); } + public ProfilerRegistry getProfilerRegistry() { + return profilerRegistry; + } + + public void setProfilerRegistry(ProfilerRegistry profilerRegistry) { + this.profilerRegistry = profilerRegistry; + } + public void start(String name) { stopLastStopWatch(); StopWatch childSW = new StopWatch(name); @@ -41,6 +51,7 @@ public Profiler startNested(String name) { Profiler nestedProfiler = new Profiler(name); + nestedProfiler.setProfilerRegistry(profilerRegistry); childList.add(nestedProfiler); return nestedProfiler; } Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/ProfilerRegistry.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/ProfilerRegistry.java Mon May 5 22:32:25 2008 @@ -0,0 +1,37 @@ +/** + * Logback: the generic, reliable, fast and flexible logging framework. + * + * Copyright (C) 1999-2008, QOS.ch + * + * This library is free software, you can redistribute it and/or modify it under + * the terms of the GNU Lesser General Public License as published by the Free + * Software Foundation. + */ + +package ch.qos.logback.classic.stopwatch; + +import java.util.HashMap; +import java.util.Map; + +/** + * A miniminalistic registry of profilers. + * + * @author Ceki + */ +public class ProfilerRegistry { + + + Map<String, Profiler> profilerMap = new HashMap<String, Profiler>(); + + public void put(String name, Profiler profiler) { + profilerMap.put(name, profiler); + } + + public Profiler get(String name) { + return profilerMap.get(name); + } + + public void clear() { + profilerMap.clear(); + } +} Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java Mon May 5 22:32:25 2008 @@ -34,6 +34,23 @@ } @Test + 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(); + } + + @Test public void testNestedProfiling() { Profiler profiler = new Profiler("BAS"); @@ -58,12 +75,12 @@ public void doSubtask(Profiler nested) { nested.start("n1"); doX(1); - + nested.start("n2"); doX(5); nested.stop(); } - + void doY(int millis) { delay(millis); } Modified: logback/trunk/logback-site/src/site/pages/manual/contextSelector.html ============================================================================== --- logback/trunk/logback-site/src/site/pages/manual/contextSelector.html (original) +++ logback/trunk/logback-site/src/site/pages/manual/contextSelector.html Mon May 5 22:32:25 2008 @@ -20,7 +20,7 @@ </div> <div id="content"> - <h2>Chapter 8: Context Selectors</h2> + <h2>Chapter 9: Context Selectors</h2> <div class="quote"> <p><em>It is not knowledge, but the act of learning, not Modified: logback/trunk/logback-site/src/site/pages/manual/index_menu.js ============================================================================== --- logback/trunk/logback-site/src/site/pages/manual/index_menu.js (original) +++ logback/trunk/logback-site/src/site/pages/manual/index_menu.js Mon May 5 22:32:25 2008 @@ -7,5 +7,6 @@ document.write('<p class="menu"><a href="layouts.html"><b>Ch5: Layouts</b></a>'); document.write('<p class="menu"><a href="filters.html"><b>Ch6: Filter chains</b></a>'); document.write('<p class="menu"><a href="mdc.html"><b>Ch7: Mapped Diagnostic Contexts</b></a>'); -document.write('<p class="menu"><a href="contextSelector.html"><b>Ch8: Context Selectors</b></a>'); +document.write('<p class="menu"><a href="profilers.html"><b>Ch8: Profilers</b></a>'); +document.write('<p class="menu"><a href="contextSelector.html"><b>Ch9: Context Selectors</b></a>'); Added: logback/trunk/logback-site/src/site/pages/manual/profilers.html ============================================================================== --- (empty file) +++ logback/trunk/logback-site/src/site/pages/manual/profilers.html Mon May 5 22:32:25 2008 @@ -0,0 +1,72 @@ +<!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>Chapter 5: Layouts</title> +<link rel="stylesheet" type="text/css" media="screen" href="../css/site.css" /> +<link rel="stylesheet" type="text/css" media="print" href="../css/print.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="index_menu.js"></script> +</div> +<div id="content"> + + <h1>Chapter 8: Profilers</h1> + + <div class="quote"> + <p>We should forget about small efficiencies, say about 97% of + the time: premature optimization is the root of all evil. + </p> + <p>— Donald Knuth, JON POSTEL, Structured Programming with + go to Statements</p> </div> + + <script src="../templates/creative.js"></script> + <script src="../templates/setup.js"></script> + + <h2>What is a profiler?</h2> + + <p>According to wikipedia, <a + href="http://en.wikipedia.org/wiki/Profiler_%28computer_science%29">profiling</a> + is 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>A logback profiler help the developer gather performance data + by managing one or more stopwatches driven by statements inserted + in the source code. An example, should make the point clearer. + </p> + + <p class="source"> + doSomethingBasic() { + Profiler profiler = new Profiler("BASIC"); + + profiler.start("Subtask_1"); + doSubtaskOne(); + + profiler.start("Subtask_1"); + for (int i = 0; i < 5; i++) { + doSubtaskTwo(i); + } + profiler.start("Other"); + doOther(); + profiler.stop().print();</p> + + <p class="source">+ Profiler [BASIC] +|-- elapsed time [Subtask_1] 9.987 milliseconds. +|-- elapsed time [Subtask_1] 47.263 milliseconds. +|-- elapsed time [Other] 2.790 milliseconds. +|-- Total elapsed time [BASIC] 60.092 milliseconds. +</p> +</div> \ No newline at end of file

1 0

svn commit: r1688 - logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util
by noreply.ceki＠qos.ch 05 May '08

05 May '08

Author: ceki Date: Mon May 5 18:52:05 2008 New Revision: 1688 Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java Log: - refactoring StatusPrinter Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java Mon May 5 18:52:05 2008 @@ -16,6 +16,7 @@ import java.util.Iterator; import ch.qos.logback.core.Context; +import ch.qos.logback.core.Layout; import ch.qos.logback.core.status.Status; import ch.qos.logback.core.status.StatusManager; @@ -45,16 +46,29 @@ } public static void print(StatusManager sm) { + StringBuilder sb = buildStr(sm); + ps.println(sb.toString()); + } + + public static StringBuilder buildStr(StatusManager sm) { + StringBuilder sb = new StringBuilder(); synchronized (sm) { Iterator it = sm.iterator(); while (it.hasNext()) { Status s = (Status) it.next(); - print("", s); + buildStr(sb, "", s); } + return sb; } } - private static void print(String indentation, Status s) { + private static void appendThrowable(StringBuilder sb, Throwable t) { + StackTraceElement[] steArray = t.getStackTrace(); + for (StackTraceElement ste : steArray) { + sb.append(ste.toString()).append(Layout.LINE_SEP); + } + } + private static void buildStr(StringBuilder sb, String indentation, Status s) { String prefix; if(s.hasChildren()) { prefix = indentation + "+ "; @@ -65,21 +79,19 @@ if(simpleDateFormat != null) { Date date = new Date(s.getDate()); String dateStr = simpleDateFormat.format(date); - ps.print(dateStr); - ps.print(" "); + sb.append(dateStr).append(" "); } - ps.println(prefix+s); + sb.append(prefix+s).append(Layout.LINE_SEP); if (s.getThrowable() != null) { - s.getThrowable().printStackTrace(ps); + appendThrowable(sb, s.getThrowable()); } if(s.hasChildren()) { Iterator<Status> ite = s.iterator(); while(ite.hasNext()) { Status child = ite.next(); - print(indentation+" ", child); + buildStr(sb, indentation+" ", child); } - } }

1 0

Joran Configurator
by Hu, Julia 05 May '08

05 May '08

Hi, I have created customized TurboFilter to support filtering the logs by FI, and expecting it supports dynamic configuration. Once I use JoranConfigurator to reload context, noticed that TurboFilter's decide() method has been called twice, obviously, log context caches previous TurboFilter. What's best way to support dynamic configuration for TurboFilter? It seems normal filter works fine for dynamic reconfiguration, but we kind of prefer fast fail feature for TurboFilter. Thanks! Julia

2 2

svn commit: r1687 - logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet
by noreply.ceki＠qos.ch 05 May '08

05 May '08

Author: ceki Date: Mon May 5 17:55:10 2008 New Revision: 1687 Modified: logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeHttpServletResponse.java logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletInputStream.java logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletOutputStream.java Log: - refactoring TeeFilter and co Modified: logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeHttpServletResponse.java ============================================================================== --- logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeHttpServletResponse.java (original) +++ logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeHttpServletResponse.java Mon May 5 17:55:10 2008 @@ -11,7 +11,7 @@ public class TeeHttpServletResponse extends HttpServletResponseWrapper { TeeServletOutputStream teeServletOutputStream; - PrintWriter writer; + PrintWriter teeWriter; public TeeHttpServletResponse(HttpServletResponse httpServletResponse) { super(httpServletResponse); @@ -27,17 +27,17 @@ @Override public PrintWriter getWriter() throws IOException { - if (this.writer == null) { - this.writer = new PrintWriter(new OutputStreamWriter(getOutputStream()), + if (this.teeWriter == null) { + this.teeWriter = new PrintWriter(new OutputStreamWriter(getOutputStream()), true); } - return this.writer; + return this.teeWriter; } @Override public void flushBuffer() { - if (this.writer != null) { - this.writer.flush(); + if (this.teeWriter != null) { + this.teeWriter.flush(); } } @@ -45,15 +45,15 @@ // teeServletOutputStream can be null if the getOutputStream method is never // called. if (teeServletOutputStream != null) { - return teeServletOutputStream.getOutputBuffer(); + return teeServletOutputStream.getOutputStreamAsByteArray(); } else { return null; } } void finish() throws IOException { - if (this.writer != null) { - this.writer.close(); + if (this.teeWriter != null) { + this.teeWriter.close(); } if (this.teeServletOutputStream != null) { this.teeServletOutputStream.close(); Modified: logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletInputStream.java ============================================================================== --- logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletInputStream.java (original) +++ logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletInputStream.java Mon May 5 17:55:10 2008 @@ -1,7 +1,6 @@ package ch.qos.logback.access.servlet; import java.io.ByteArrayInputStream; -import java.io.ByteArrayOutputStream; import java.io.IOException; import java.io.InputStream; @@ -30,12 +29,9 @@ if (len < 0) { in = originalSIS; } else { - ByteArrayOutputStream baos = new ByteArrayOutputStream(); inputBuffer = new byte[len]; - int n = 0; - while ((n = originalSIS.read(inputBuffer, 0, len)) != -1) { - baos.write(inputBuffer, 0, n); - } + int n = originalSIS.read(inputBuffer, 0, len); + assert n == len; this.in = new ByteArrayInputStream(inputBuffer); originalSIS.close(); } Modified: logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletOutputStream.java ============================================================================== --- logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletOutputStream.java (original) +++ logback/trunk/logback-access/src/main/java/ch/qos/logback/access/servlet/TeeServletOutputStream.java Mon May 5 17:55:10 2008 @@ -9,24 +9,24 @@ public class TeeServletOutputStream extends ServletOutputStream { final ServletOutputStream underlyingStream; - final ByteArrayOutputStream baos; + final ByteArrayOutputStream baosCopy; TeeServletOutputStream(ServletResponse httpServletResponse) throws IOException { // System.out.println("TeeServletOutputStream.constructor() called"); this.underlyingStream = httpServletResponse.getOutputStream(); - baos = new ByteArrayOutputStream(); + baosCopy = new ByteArrayOutputStream(); } - byte[] getOutputBuffer() { - return baos.toByteArray(); + byte[] getOutputStreamAsByteArray() { + return baosCopy.toByteArray(); } @Override public void write(int val) throws IOException { if (underlyingStream != null) { underlyingStream.write(val); - baos.write(val); + baosCopy.write(val); } } @@ -49,31 +49,27 @@ // called"); // System.out.println(new String(byteArray, offset, length)); underlyingStream.write(byteArray, offset, length); - baos.write(byteArray, offset, length); + baosCopy.write(byteArray, offset, length); } + @Override public void close() throws IOException { // System.out.println("CLOSE TeeServletOutputStream.close() called"); // If the servlet accessing the stream is using a writer instead of - // an OutputStream, it will probably call os.close() begore calling - // writer.close. Thus, the undelying output stream will be called + // an OutputStream, it will probably call os.close() before calling + // writer.close. Thus, the underlying output stream will be called // before the data sent to the writer could be flushed. } - public void finish() throws IOException { - flush(); - underlyingStream.close(); - baos.close(); - } + @Override public void flush() throws IOException { if (underlyingStream == null) { return; } // System.out.println("FLUSH TeeServletOutputStream.flush() called"); underlyingStream.flush(); - baos.flush(); + baosCopy.flush(); } - }

1 0

svn commit: r1686 - logback/trunk/logback-site/src/site/pages
by noreply.ceki＠qos.ch 04 May '08

04 May '08

Author: ceki Date: Sun May 4 20:21:47 2008 New Revision: 1686 Modified: logback/trunk/logback-site/src/site/pages/news.html Log: - added blurb about bug fix in LoggerContext.shutdownAndReset() Modified: logback/trunk/logback-site/src/site/pages/news.html ============================================================================== --- logback/trunk/logback-site/src/site/pages/news.html (original) +++ logback/trunk/logback-site/src/site/pages/news.html Sun May 4 20:21:47 2008 @@ -42,6 +42,14 @@ the layout of a <code>SyslogAppender</code>. The code now actively prevents this. Documenation has been updated to reflect the change. </p> + + <p>The TurboFilterChain in a LoggerContext is <a + href="http://svn.qos.ch/viewvc?view=rev&revision=1678">now + cleared</a> when the shutdownAndReset method is called. This problem + was reported on May 1st, 2008, by Julia Hu on the logback + developpers list. + </p> + <hr width="80%" align="center" />

1 0

svn commit: r1685 - logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch
by noreply.ceki＠qos.ch 04 May '08

04 May '08

Author: ceki Date: Sun May 4 20:20:11 2008 New Revision: 1685 Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/DurationUnit.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Profiler.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/StopWatch.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Util.java Log: renaming folder Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/DurationUnit.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/DurationUnit.java Sun May 4 20:20:11 2008 @@ -0,0 +1,5 @@ +package ch.qos.logback.classic.stopwatch; + +public enum DurationUnit { + NANOSECOND, MICROSECOND, MILLISSECOND, SECOND; +} \ No newline at end of file Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Profiler.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Profiler.java Sun May 4 20:20:11 2008 @@ -0,0 +1,137 @@ +package ch.qos.logback.classic.stopwatch; + +import java.util.ArrayList; +import java.util.List; + +import ch.qos.logback.core.Layout; +import ch.qos.logback.core.pattern.SpacePadder; + +// + Profiler [BAS] +// |-- elapsed time [doX] 0 milliseconds. +// |-- elapsed time [doYYYYY] 56 milliseconds. +// |--+ Profiler Y +// |-- elapsed time [doZ] 21 milliseconds. +// |-- elapsed time [doZ] 21 milliseconds. +// |-- Total elapsed time [Y] 78 milliseconds. +// |-- elapsed time [doZ] 21 milliseconds. +// |-- Total elapsed time [BAS] 78 milliseconds. + +public class Profiler { + + final static int MIN_SW_NAME_LENGTH = 10; + final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 6; + + final String name; + final StopWatch globalStopWatch; + + List<StopWatch> stopwatchList = new ArrayList<StopWatch>(); + List<Object> childList = new ArrayList<Object>(); + + public Profiler(String name) { + this.name = name; + this.globalStopWatch = new StopWatch(name); + } + + public void start(String name) { + stopLastStopWatch(); + StopWatch childSW = new StopWatch(name); + stopwatchList.add(childSW); + childList.add(childSW); + } + + public Profiler startNested(String name) { + Profiler nestedProfiler = new Profiler(name); + childList.add(nestedProfiler); + return nestedProfiler; + } + + StopWatch getLastStopWatch() { + if (stopwatchList.size() > 0) { + return stopwatchList.get(stopwatchList.size() - 1); + } else { + return null; + } + } + + void stopLastStopWatch() { + StopWatch last = getLastStopWatch(); + if (last != null) { + last.stop(); + } + } + + void stopNestedProfilers() { + for (Object child : childList) { + if (child instanceof Profiler) + ((Profiler) child).stop(); + } + } + + public Profiler stop() { + stopLastStopWatch(); + stopNestedProfilers(); + globalStopWatch.stop(); + return this; + } + + public void print() { + DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch); + String r = buildString(du, "+", ""); + System.out.println(r); + } + + private String buildString(DurationUnit du, String prefix, String indentation) { + StringBuffer buf = new StringBuffer(); + + + buf.append(prefix); + buf.append(" Profiler ["); + buf.append(name); + buf.append("]"); + buf.append(Layout.LINE_SEP); + for (Object child : childList) { + if(child instanceof StopWatch) { + buildStringForChildStopWatch(buf, indentation, (StopWatch) child, du); + } else if(child instanceof Profiler) { + Profiler profiler = (Profiler) child; + profiler.stop(); + String subString = profiler.buildString(du, "|--+", indentation + " "); + buf.append(subString); + } + } + buildStringForGlobalStopWatch(buf, indentation, globalStopWatch, du); + return buf.toString(); + } + + private static void buildStringForChildStopWatch(StringBuffer buf, + String indentation, StopWatch sw, DurationUnit du) { + + buf.append(indentation); + buf.append("|--"); + buf.append(" elapsed time "); + SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH); + buf.append(" "); + String timeStr = Util.durationInDunrationUnitsAsStr(sw.getResultInNanos(), + du); + SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH); + buf.append(" "); + Util.appendDurationUnitAsStr(buf, du); + buf.append(Layout.LINE_SEP); + } + + private static void buildStringForGlobalStopWatch(StringBuffer buf, + String indentation, StopWatch sw, DurationUnit du) { + buf.append(indentation); + buf.append("|--"); + buf.append(" Total elapsed time "); + SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH); + buf.append(" "); + String timeStr = Util.durationInDunrationUnitsAsStr(sw.getResultInNanos(), + du); + SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH); + buf.append(" "); + Util.appendDurationUnitAsStr(buf, du); + buf.append(Layout.LINE_SEP); + } + +} Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/StopWatch.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/StopWatch.java Sun May 4 20:20:11 2008 @@ -0,0 +1,68 @@ +package ch.qos.logback.classic.stopwatch; + + +public class StopWatch { + + + enum Status { + STARTED, STOPPED; + } + + final String name; + final long startTime; + long stopTime; + Status status; + + public StopWatch(String name) { + this.name = name; + this.startTime = System.nanoTime(); + this.status = Status.STARTED; + } + + public String getName() { + return name; + } + + public StopWatch stop() { + if(status == Status.STOPPED) { + return this; + } + return stop(System.nanoTime()); + } + + public StopWatch stop(long stopTime) { + this.status = Status.STOPPED; + this.stopTime = stopTime; + return this; + } + + @Override + public String toString() { + StringBuffer buf = new StringBuffer(); + buf.append("StopWatch ["); + buf.append(name); + buf.append("] "); + + switch (status) { + case STARTED: + buf.append("STARTED"); + break; + case STOPPED: + buf.append("elapsed time: "); + buf.append(Util.durationInDunrationUnitsAsStr(getResultInNanos(), DurationUnit.MICROSECOND)); + break; + default: + new IllegalStateException("Status " + status + " is not expected"); + } + return buf.toString(); + } + + public final long getResultInNanos() { + if (status == Status.STARTED) { + return 0; + } else { + return stopTime - startTime; + } + } + +} Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Util.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopwatch/Util.java Sun May 4 20:20:11 2008 @@ -0,0 +1,83 @@ +package ch.qos.logback.classic.stopwatch; + +import java.text.DecimalFormat; + +class Util { + + static final long NANOS_IN_ONE_MICROSECOND = 1000; + static final long NANOS_IN_ONE_MILLISECOND = NANOS_IN_ONE_MICROSECOND * 1000; + static final long NANOS_IN_ONE_SECOND =NANOS_IN_ONE_MILLISECOND * 1000; + private static final DecimalFormat DECIMAL_FORMAT = new DecimalFormat("0.000"); + + static DurationUnit selectDurationUnitForDisplay(StopWatch sw) { + return selectDurationUnitForDisplay(sw.getResultInNanos()); + } + + static DurationUnit selectDurationUnitForDisplay(long durationInNanos) { + if (durationInNanos < 10*NANOS_IN_ONE_MICROSECOND) { + return DurationUnit.NANOSECOND; + } else if (durationInNanos < 10*NANOS_IN_ONE_MILLISECOND) { + return DurationUnit.MICROSECOND; + } else if (durationInNanos < 10*NANOS_IN_ONE_SECOND) { + return DurationUnit.MILLISSECOND; + } else { + return DurationUnit.SECOND; + } + } + + static public double convertToMicros(long nanos) { + return (double) nanos / NANOS_IN_ONE_MICROSECOND; + } + + static public double convertToMillis(long nanos) { + return (double) nanos / NANOS_IN_ONE_MILLISECOND; + } + + static public double convertToSeconds(long nanos) { + return ((double) nanos / NANOS_IN_ONE_SECOND); + } + + static String durationInDunrationUnitsAsStr(StringBuffer buf, StopWatch sw) { + DurationUnit du = selectDurationUnitForDisplay(sw); + return durationInDunrationUnitsAsStr(sw.getResultInNanos(), du); + } + + static String durationInDunrationUnitsAsStr(long nanos, DurationUnit durationUnit) { + StringBuffer buf = new StringBuffer(); + switch (durationUnit) { + case NANOSECOND: + buf.append(nanos); + break; + case MICROSECOND: + double micros = convertToMicros(nanos); + buf.append(DECIMAL_FORMAT.format(micros)); + break; + case MILLISSECOND: + double millis = convertToMillis(nanos); + buf.append(DECIMAL_FORMAT.format(millis)); + break; + case SECOND: + double seconds = convertToSeconds(nanos); + buf.append(DECIMAL_FORMAT.format(seconds)); + break; + } + return buf.toString(); + } + + static void appendDurationUnitAsStr(StringBuffer buf, DurationUnit durationUnit) { + switch (durationUnit) { + case NANOSECOND: + buf.append("nanoseconds."); + break; + case MICROSECOND: + buf.append("microseconds."); + break; + case MILLISSECOND: + buf.append("milliseconds."); + break; + case SECOND: + buf.append(" seconds."); + break; + } + } +}

1 0

svn commit: r1684 - logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch
by noreply.ceki＠qos.ch 04 May '08

04 May '08

Author: ceki Date: Sun May 4 20:19:26 2008 New Revision: 1684 Removed: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/ Log: renaming folder

1 0

svn commit: r1683 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch
by noreply.ceki＠qos.ch 04 May '08

04 May '08

Author: ceki Date: Sun May 4 20:17:08 2008 New Revision: 1683 Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/StopWatchTest.java Log: - ongoing work on StopWatch and poor man's profiler functionality Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/ProfilerTest.java Sun May 4 20:17:08 2008 @@ -1,21 +1,14 @@ package ch.qos.logback.classic.stopwatch; - +import org.junit.Ignore; import org.junit.Test; import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import ch.qos.logback.core.BasicStatusManager; -import ch.qos.logback.core.status.ErrorStatus; -import ch.qos.logback.core.status.InfoStatus; -import ch.qos.logback.core.status.Status; -import ch.qos.logback.core.status.StatusManager; -import ch.qos.logback.core.util.StatusPrinter; - public class ProfilerTest { Logger logger = LoggerFactory.getLogger(ProfilerTest.class); - + @Test public void smoke() { Profiler profiler = new Profiler("SMOKE"); @@ -23,56 +16,62 @@ profiler.stop(); } + @Ignore @Test - public void X() { - StatusManager sm = new BasicStatusManager(); - Status g = new InfoStatus("global", this); - Status g1 = new InfoStatus("g1", this); - Status g2 = new InfoStatus("g2", this); - Status g11 = new InfoStatus("g11", this); - Status g12 = new InfoStatus("g11", this); - Status g21 = new InfoStatus("g21", this); - - - g.add(g1); - g.add(g2); - - g1.add(g11); - g1.add(g12); - g2.add(g21); - - sm.add(g); - StatusPrinter.print(sm); - + public void testBasicProfiling() { + Profiler profiler = new Profiler("BAS"); + + profiler.start("doX"); + doX(1); + + profiler.start("doYYYYY"); + for (int i = 0; i < 5; i++) { + doY(i); + } + profiler.start("doZ"); + doZ(2); + profiler.stop().print(); } + @Test - public void testBasicProfiling() { + public void testNestedProfiling() { Profiler profiler = new Profiler("BAS"); - + profiler.start("doX"); doX(1); - + profiler.start("doYYYYY"); - for(int i = 0; i < 5; i++) { + for (int i = 0; i < 5; i++) { doY(i); } + Profiler nested = profiler.startNested("subtask"); + doSubtask(nested); profiler.start("doZ"); doZ(2); - profiler.stop(); + profiler.stop().print(); } - + void doX(int millis) { delay(millis); } + + public void doSubtask(Profiler nested) { + nested.start("n1"); + doX(1); + + nested.start("n2"); + doX(5); + nested.stop(); + } void doY(int millis) { - delay(millis); + delay(millis); } - + void doZ(int millis) { - delay(millis); + delay(millis); } - + void delay(int millis) { try { Thread.sleep(millis); Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/StopWatchTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/StopWatchTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/stopwatch/StopWatchTest.java Sun May 4 20:17:08 2008 @@ -16,46 +16,13 @@ super.tearDown(); } - public void testBasic() throws InterruptedException { - StopWatch sw = new StopWatch("testBasic"); - - { - long d = sw.startTime+10; - String s = sw.stop(d).toString(); - assertTrue(s.endsWith("10 nanoseconds.")); - } - - { - long d = sw.startTime+9*Util.NANOS_IN_ONE_MICROSECOND; - String s = sw.stop(d).toString(); - assertTrue(s.endsWith("9000 nanoseconds.")); - } - - { - long d = sw.startTime+11*Util.NANOS_IN_ONE_MICROSECOND; - String s = sw.stop(d).toString(); - assertTrue(s.endsWith("11 microseconds.")); - } - { - long d = sw.startTime+9*Util.NANOS_IN_ONE_MILLISECOND; - String s = sw.stop(d).toString(); - assertTrue(s.endsWith("9000 microseconds.")); - } - { - long d = sw.startTime+3*Util.NANOS_IN_ONE_SECOND; - String s = sw.stop(d).toString(); - System.out.println(s); - assertTrue(s.endsWith("3.000 seconds.")); - } - } - public void testSelectDurationUnitForDisplay() throws InterruptedException { assertEquals(DurationUnit.NANOSECOND, Util.selectDurationUnitForDisplay(10)); assertEquals(DurationUnit.NANOSECOND, Util.selectDurationUnitForDisplay(9*Util.NANOS_IN_ONE_MICROSECOND)); assertEquals(DurationUnit.MICROSECOND, Util.selectDurationUnitForDisplay(11*Util.NANOS_IN_ONE_MICROSECOND)); assertEquals(DurationUnit.MICROSECOND, Util.selectDurationUnitForDisplay(9*Util.NANOS_IN_ONE_MILLISECOND)); assertEquals(DurationUnit.MILLISSECOND, Util.selectDurationUnitForDisplay(11*Util.NANOS_IN_ONE_MILLISECOND)); - assertEquals(DurationUnit.SECOND, Util.selectDurationUnitForDisplay(3*Util.NANOS_IN_ONE_SECOND)); + assertEquals(DurationUnit.SECOND, Util.selectDurationUnitForDisplay(11*Util.NANOS_IN_ONE_SECOND)); } }

1 0