Author: seb Date: Fri Jan 19 18:33:53 2007 New Revision: 1257 Modified: logback/trunk/logback-site/src/site/xdocTemplates/demo.xml Log: Updates on the demo doc Modified: logback/trunk/logback-site/src/site/xdocTemplates/demo.xml ============================================================================== --- logback/trunk/logback-site/src/site/xdocTemplates/demo.xml (original) +++ logback/trunk/logback-site/src/site/xdocTemplates/demo.xml Fri Jan 19 18:33:53 2007 @@ -17,9 +17,9 @@ </p> <p> - First, please download the logback demo. You will need a + First, please download the logback demo. You will need to install a <a href="http://subversion.tigris.org/">Subversion</a> client - and issue the following command: + and issue the following command in a command/terminal window: </p> <div class="source"><pre>svn co http://svn.qos.ch/repos/logback-demo logback-demo</pre></div> @@ -34,14 +34,14 @@ </p> <p> - Using Maven, let's run the demo for the first time. From the <em>logback-demo</em> - directory, issue the following command: + Using Maven, let's package the files and run the demo for the first time. + From the <em>logback-demo</em> directory, issue the following command: </p> -<div class="source"><pre>mvn jetty:run</pre></div> +<div class="source"><pre>mvn package jetty:run</pre></div> <p> - Then, visit <em>http://localhost:8080/</em> to view the main page of the logback demo. + Then, visit <em>http://localhost:8080/logback-demo/</em> to view the main page of the logback demo. </p> <p>image main page</p> @@ -50,17 +50,18 @@ For now, logback uses two components: one <code>ConsoleAppender</code> and one <code>RollingFileAppender</code>. The <code>RollingFileAppender</code> sends logging events to a file called <em>logFile.log</em> and will rollover -the active file every minute. The old file will be renamed and compressed using the <em>zip</em> -format. The <code>ConsoleAppender</code> will output the logging requests to the console, +the active file every minute. The old file will be renamed and compressed to <em>zip</em> +file. The <code>ConsoleAppender</code> will output the logging requests to the console, and shorten the logger names to gain some space in the console window, without making the names unreadable. You can study the configuration file that is used by editing the file called <em>logback.xml</em>, located in the <em>src/main/resources/</em> directory -of the demo. +of the demo. You might want to keep this file in an editor window, since we will +modify its content several times thoughout the demo. </p> <p> Let's now visit the <em>ViewStatii</em> page, via the navigation menu on the left hand -of the screen. This page contains the content of the <code>Status</code> objects that were +of the navigator window. This page contains the content of the <code>Status</code> objects that were created until now. <code>Status</code> objects are a part of logback's powerful internal reporting framework. They allow you to see what is going on in logback, and check that a configuration file has been parsed correctly, or that a rollover has occured as @@ -72,19 +73,23 @@ <p> Visiting the <em>View logs</em> page does not impress much at the moment. Let us uncomment the two parts of the config file that are below the <em>Part I: Cyclic buffer</em> comment. +A <code>CyclicBuffer</code> is a class that keeps track of logging events and holds these +objects for immediate or differed display. Now reload the web-app by exiting the previous command with <em>CTRL-C</em> and issuing it -again: <em>mvn jetty:run</em>. +again: <em>mvn package jetty:run</em>. </p> <p> Now, the <em>View logs</em> page looks prettier. By virtue of the <code>CyclicBufferAppender</code>, this page can fetch the last events and present them through a servlet. We see that each 3 seconds -a line is added to the logs. +a line is added to the logs. The formatting of this page is made with +a <code>HTMLLayout</code>. This component creates a nice readable table containing the logging +events, based on a pattern that describes the information one wants to see in the table. </p> <p> Having the logs that we see on the web page cluttered with scheduled messages -is not very comfortable. To get rid of these logs once we've verified that they +is not very comfortable. To get rid of these logs, now that we've verified that they work, we can add an <code>EvaluatorFilter</code> to the Appender. Uncomment the parts named <em>PART II: Cyclic buffer with Evaluator</em>. You may then comment or delete the first Basic Cyclic buffer elements. @@ -105,8 +110,15 @@ </filter></pre></div> <p> -The expression element contains a familiar java statement. It uses a few variables -that are made available by logback before the filter evaluates the expression. +The expression element contains a familiar java statement. This expression +checks that the name of the logger contains the String <em>LoggingTask</em>, but +also that the message accompagnying the log contains <em>Howdydy-diddly-ho</em>. +Moreover, in order to be sure that the <em>Howdydy-diddly-ho</em> task actually +works, we add to the expression a last statement that allows logs to be processed +for the first 20 seconds after the application launch. +The variables used in this statement (<code>logger</code>, <code>message</code> and +<code>event</code>) are made available by logback before the filter +evaluates the expression. The <em>OnMatch</em> element allows the user to choose the filter's behaviour once the expression was evaluated to true. A similar <em>OnMismatch</em> element exists. </p> @@ -119,7 +131,8 @@ <p> Logback ships with a special category of filters: <code>TurboFilter</code> objects are ultra-fast, context-wide filters. They reveals themselves very useful to -test MDC values, for examples. Let's uncomment the part named +test MDC values, for examples and to add context-wide conditions to allow or deny +logging events. Let's uncomment the part named <em>PART III: TurboFilter: MDC value</em> in the <em>logback.xml</em> file. </p> <p> @@ -129,16 +142,79 @@ associated with a MDC value of <em>sebastien</em> bound to the <em>username</em> key. </p> <p> -To view the consequences of such a <code>TurboFilter</code>, try to log in the -application using the username <em>sebastien</em>, perform some tasks, log out -and log in again using another username. The <em>View logs</em> page should -clearly mark the difference between the logs that were generated when the first -and second user were logged in. +To view the consequences of such a <code>TurboFilter</code>, we are going to +stop all logging activity, except for a specific user. To achieve that, the simplest +way is to set the root logger's level to <code>OFF</code>. Modify the <em>level</em> +element, nested inside the <em>root</em> element of <em>logback.xml</em>. Its <em>value</em> +attribute should be <em>OFF</em> instead of <em>DEBUG</em>. Next, restart the server +as we've done previously. </p> +<p> +Once on the demo main webpage again, perform a few actions (i.e. calculate +a few prime numbers) and watch the <em>View logs</em> page. The table should be +empty. +</p> + +<p> +Now log in the application using the username <em>sebastien</em> and perform a few +prime calculations again. The <em>View logs</em> page now shows the logs that were +generated by the calculation classes. Moreover, each log is associated with the name +of the user who provoked the logging event. Please log off before continuing the +demo, using the <em>logout</em> button on the left. +</p> + +<p> +Parametrized logging is a feature that will be a great asset for any performance-critical +system. Usually, a logging request is issued like this: +</p> + +<div class="source"><pre>logger.debug("Hello, my name is" + username + ", I am " + age + " years old.");</pre></div> + +<p> +By issuing this line, the cost of constructing the String cannot be saved when the +log request is not processed. For example, using the <code>debug()</code> method +when, as we've just done, the root level is any value higher that <em>DEBUG</em> will +result in a loss of time because all calls to the <code>debug()</code> method will +be eventually dropped. +</p> + +<p> +Logback offers the following method: +</p> + +<div class="source"><pre>logger.debug("Hello, my name is {}, I am {} years old", username, age);</pre></div> + +<p> +As you can see, the variables are not inserted in the message yet. Both the message +and the values will be saved and used later, if the logging event is processed. +</p> + +<p> +Let us now run a test to see what kind of gain can we expect from this different +message formatting approach. First, go to the <em>Prime number</em> page and +run a few calculations. Check the time it takes to compute the results. To +see a clearer difference between the two formatting methods, you might want to +try the two big integers that are listed below the prime number textbox. +</p> <p> -Part IV? Parametrized logging: modify source? +Now let us edit the <code>NumberCruncherImpl</code> class, to switch the log methods. +You will find this class in the <em>src/main/java/ch/qos/logback/demo/prime/</em> +directory. On line 54 and 55, just umcomment the parametrized logging line and +and comment out the other line. Restart the server with <em>mvn package jetty:run</em> +and re-run the calculations you tried beforehand. +</p> + +<p> +The durations should be obviously different. Remember that we had turned off all +logging in the previous step of this demo. With the initial formatting method, +we were constructing the logging message (<em>"Trying "+i+" as a factor."</em>) +a huge amount of time, actually each time a factor was tried for these big numbers. +With the paramatrized logging, the construction of the message was postponed and, since +logging was turned off, not processed. We see here that the cost of the <b>non-</b>logging +was taken down to a very small figure, dividing the total cost of the calculation +by a non-negligeable factor. </p> <p> @@ -245,22 +321,76 @@ </p> <p> -Part VIII: JMX for access and classic +Logback publishes several components via JMX. This allows you to see +the status of certain objects, and change several configuration parameters. </p> +<p> +To see logback access' components, visit the following page: +</p> +<div class="source"><pre>http://localhost:8082/</pre></div> +<p> +The domain <em>ch.qos.logback.access.jetty</em> contains an entry +that allows you to see the <em>RequestLogImpl</em> component. This component +is used to plug logback in Jetty's internal achitecture. Clicking on +it reveals the status of several parameters, such as the started status, and +two methods are available to start and stop the <em>RequestLogImpl</em>. +</p> +<p> +To see the influence of the available operations, place the terminal window +and your web browser such that you can see them both. Stop the <em>RequestLogImlp</em> +and reload a few times the main page of the demo. Nothing should be displayed. If you start +the <em>RequestLogImpl</em> again, the requests will be shown in the terminal +window. +</p> +<p> +These is more to discover with logback and JMX. In the <em>logback.xml</em> file, +placed in the <em>src/main/resources</em> directory, uncomment the <code>JMXConfigurator</code> +element. Once done, restart the server. +</p> +<p> +By refreshing the loaded previously JMX page, you should see a new component, +under the domain <em>ch.qos.logback.classic</em>. It is the <code>JMXConfigurator</code>. +Clicking on it reveals its content. Its possibilities are listed below: +</p> +<ul> + <p> + Reload the configuration using the same file that was + previously used. + </p> + <p> + Reload the configuration using a file whose path is passed as + a parameter. + </p> + <p> + Reload the configuration using a file whose URL is passed as a + parameter. + </p> + <p>Get the level of a logger</p> + <p>Change the level setting of a specified logger.</p> + <p>Change a list of all declared loggers.</p> + <p>Change the level setting of a specified logger.</p> +</ul> +<p> + In the last case, you must specify the name of the logger you + wish to alter, and its new level. +</p> +<p> +Let us test the configurator. If you try to use the <em>Prime Number</em> page and +look at the <em>View logs</em> page after, you should see two types of logs. When the +calculation checks if a number is a factor, a <em>DEBUG</em> log is displayed. When +the calculation has found a factor, a <em>INFO</em> log is displayed. If you set the level +of the <em>ch.qos.logback.demo.prime</em> logger to <em>INFO</em>, and run a prime calculation +again, you should not see the <em>DEBUG</em> level logs anymore. +</p> - - - - - - </body> +</body> </document> \ No newline at end of file