diff options
Diffstat (limited to 'site/trunk/site-publish/documentation-2x/logging-tracing-and-timing.html')
| -rw-r--r-- | site/trunk/site-publish/documentation-2x/logging-tracing-and-timing.html | 266 |
1 files changed, 266 insertions, 0 deletions
diff --git a/site/trunk/site-publish/documentation-2x/logging-tracing-and-timing.html b/site/trunk/site-publish/documentation-2x/logging-tracing-and-timing.html new file mode 100644 index 0000000000..2f555cf79e --- /dev/null +++ b/site/trunk/site-publish/documentation-2x/logging-tracing-and-timing.html @@ -0,0 +1,266 @@ + + + + + + +<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd"> +<HTML> + <HEAD> + <META name="description" content="Apache Tuscany"> + <META name="keywords" content="apache, apache tuscany, tuscany, service, services, fabric, soa, service oriented architecture, sca, service component architecture, das, sdo, csa, ruby, opensource"> + + <LINK type="text/css" rel="stylesheet" href="http://tuscany.apache.org/stylesheets/default.css"> + <LINK rel="SHORTCUT ICON" href="https://cwiki.apache.org/confluence/display/TUSCANYxDOCx2x/$images/favicon.ico"> + <TITLE>Logging, Tracing and Timing : Apache Tuscany</TITLE> + <META http-equiv="Content-Type" content="text/html;charset=UTF-8"></HEAD> + + <STYLE> + .spacetree * ul { + padding-left:0px; + margin-left: 0px; + } + .spacetree * li { + margin-left: 5px; + padding-left:5px; + } + </STYLE> + + <BODY onload="init()"> + <!-- topNav --> + <TABLE border="0" cellpadding="2" cellspacing="0" width="100%"> + <TR class="topBar"> + <TD align="left" valign="middle" class="topBarDiv" align="left" nowrap=""> + <A href="https://cwiki.apache.org/geronimo"> Home</A> > <A href="index.html" title="Apache Tuscany Docs 2.x">Apache Tuscany Docs 2.x</A> > <A href="index.html" title="Index">Index</A> > <A href="development-guides.html" title="Development Guides">Development Guides</A> > <A href="" title="Logging, Tracing and Timing">Logging, Tracing and Timing</A> + </TD> + <TD align="right" valign="middle" nowrap=""> + <FORM name="search" action="http://www.google.com/search" method="get"> + <INPUT type="hidden" name="ie" value="UTF-8"> + <INPUT type="hidden" name="oe" value="UTF-8"> + <INPUT type="hidden" name="domains" value=""> + <INPUT type="hidden" name="sitesearch" value=""> + <INPUT type="text" name="q" maxlength="255" value=""> + <INPUT type="submit" name="btnG" value="Google Search"> + </FORM> + </TD> + </TR> + </TABLE> + + + <TABLE border="0" cellpadding="2" cellspacing="0" width="100%"> + <TR class="topBar"> + <TD align="left" valign="middle" class="topBarDiv" nowrap="true" width="100%"> + <A href="index.html" title="Apache Tuscany Docs 2.x">Apache Tuscany Docs 2.x</A> > <A href="index.html" title="Index">Index</A> > <A href="development-guides.html" title="Development Guides">Development Guides</A> > <A href="" title="Logging, Tracing and Timing">Logging, Tracing and Timing</A> + </TD> + + <TD align="right" valign="middle" class="topBarDiv" align="left" nowrap="true"> + <A href="http://tuscany.apache.org/">Tuscany Home</A> | <A href="http://mail-archives.apache.org/mod_mbox/tuscany-user">User List</A> | <A href="http://mail-archives.apache.org/mod_mbox/tuscany-dev">Dev List</A> | <A href="http://issues.apache.org/jira/browse/Tuscany">Issue Tracker</A> + </TD> + </TR> + </TABLE> + + <TABLE border="0" cellpadding="0" width="100%" bgcolor="#FFFFFF"> + <TR> + <TD valign="top" align="left" width="22%" bgcolor="#F9F9F9" class="noprint"> + <DIV class="tabletitle">Table of Contents</DIV> + <DIV class="spacetree"> + + + </DIV> + </TD> + <TD align="left" valign="top" width="78%"> + <!-- pageContent --> + <DIV id="PageContent"> + <DIV class="pageheader" style="padding: 6px 0px 0px 0px;"> + <!-- We'll enable this once we figure out how to access (and save) the logo resource --> + <!--img src="http://geronimo.apache.org/images/confluence_logo.gif" style="float: left; margin: 4px 4px 4px 10px;" border="0"--> + <DIV style="margin: 0px 10px 0px 10px" class="smalltext">Apache Tuscany Docs 2.x</DIV> + <DIV style="margin: 0px 10px 8px 10px" class="pagetitle">Logging, Tracing and Timing</DIV> + + <DIV class="greynavbar" align="right" style="padding: 2px 10px; margin: 0px;"> +<!-- --> + <A href="https://cwiki.apache.org/confluence/pages/editpage.action?pageId=20645145"> + <IMG src="http://geronimo.apache.org/images/icons/notep_16.gif" height="16" width="16" border="0" align="absmiddle" title="Edit Page"></A> + <A href="https://cwiki.apache.org/confluence/pages/editpage.action?pageId=20645145">Edit Page</A> + + <A href="https://cwiki.apache.org/confluence/pages/listpages.action?key=TUSCANYxDOCx2x"> + <IMG src="http://geronimo.apache.org/images/icons/browse_space.gif" height="16" width="16" border="0" align="absmiddle" title="Browse Space"></A> + <A href="https://cwiki.apache.org/confluence/pages/listpages.action?key=TUSCANYxDOCx2x">Browse Space</A> + + <A href="https://cwiki.apache.org/confluence/pages/createpage.action?spaceKey=TUSCANYxDOCx2x&fromPageId=20645145"> + <IMG src="http://geronimo.apache.org/images/icons/add_page_16.gif" height="16" width="16" border="0" align="absmiddle" title="Add Page"></A> + <A href="https://cwiki.apache.org/confluence/pages/createpage.action?spaceKey=TUSCANYxDOCx2x&fromPageId=20645145">Add Page</A> + + <A href="https://cwiki.apache.org/confluence/pages/createblogpost.action?spaceKey=TUSCANYxDOCx2x&fromPageId=20645145"> + <IMG src="http://geronimo.apache.org/images/icons/add_blogentry_16.gif" height="16" width="16" border="0" align="absmiddle" title="Add News"></A> + <A href="https://cwiki.apache.org/confluence/pages/createblogpost.action?spaceKey=TUSCANYxDOCx2x&fromPageId=20645145">Add News</A> +<!-- --> + </DIV> + </DIV> + + <DIV class="pagecontent"> + <DIV class="wiki-content"> + <H1><A name="Logging%2CTracingandTiming-TuscanyLogging%2CTracing%2CTimingInformationinTuscany2.X"></A>Tuscany Logging, Tracing, Timing Information in Tuscany 2.X</H1> + +<P>This page describes the logging, tracing, and timing features of Tuscany. These features can be used to debug problems with the Tuscany runtime, understand code flow, and provide timing metrics for competitive analysis or performance claims.</P> + +<H2><A name="Logging%2CTracingandTiming-JavaLoggingversusAspectOrientedProgramming%28AOP%29Approach"></A>Java Logging versus Aspect Oriented Programming (AOP) Approach</H2> + +<P>There are two types of logging embeded in the Tuscany runtime: explicit and implicit. The explicit logging is implemented by the Java 2 SE core logging facilities such as java.util.logging.Logger. This is the logging that many Java programmers are familiar with, and the logging requires calls to the Logger programming interface. Throughout the Tuscany code base you see calls to this facility such as this call in Tuscany org.apache.tuscany.sca.node.launcher.NodeLauncher.</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Java Logging in Tuscany</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java"> logger.info(<SPAN class="code-quote">"Apache Tuscany SCA Node is starting..."</SPAN>); +</PRE> +</DIV></DIV> +<P>Calls to this facility by default go to the standard output of the program. This is the typical result that one sees in the console:</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Java Logging Output</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java">INFO: Apache Tuscany SCA Node is starting... +</PRE> +</DIV></DIV> +<P>The Java SE core logging works well as a general purpose logger and gives a general idea of the important phases in the Tuscany runtime. However, one drawback is that this logging system only publishes predetermined messages created by the developers. If you wish to change the logging points, you must change the Tuscany source code, build, and run again with your private code base.</P> + +<P>Another logging and tracing facility is available in Tuscany that gives the user a bit of flexibility in what gets logged and requires no source code modifications to run. This is an Aspect Oriented Programming (AOP) approach that runs via a Java agent at runtime. Just like a debugger can start and stop and inspect a Tuscany Java program, so too can an AOP agent inspect and report on a Tuscany Java program. Tuscany employs the AspectJ implementation, and its runtime agent is contained in the aspectjweaver.jar file. The AOP agent is specified from a command line option or runtime options:</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Java AOP Agent</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java">java -javaagent:<SPAN class="code-quote">"<path to aspectjweaver.jar>"</SPAN> calculator.CalculatorClient +</PRE> +</DIV></DIV> +<P>The AOP logging and tracing agent can be run with any Tuscany program. No additional calls or log statements need be added to the Tuscany code. The results of running a timing for example, look like this:</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Tuscany AOP Output</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java">Running org.apache.tuscany.sca.aspectj.TracingTestCase +Timing Around timedSection jp=call(void java.util.logging.Logger.info(<SPAN class="code-object">String</SPAN>)) +Oct 21, 2008 9:26:36 AM org.apache.tuscany.sca.aspectj.TracingTestCase info_aroundBody0 +Timing Around timedSection Roundtrip is 32ms <SPAN class="code-keyword">for</SPAN> jp.getSignature=void java.util.logging.Logger.info(<SPAN class="code-object">String</SPAN>) +</PRE> +</DIV></DIV> +<P>Full documentation on AspectJ is available at the <A href="http://www.eclipse.org/aspectj/doc/released" class="external-link" rel="nofollow">AspectJ web site</A>. Tuscany provides example usage in the module tracing-aspectj in the build tree and the released code.</P> + +<H2><A name="Logging%2CTracingandTiming-BriefApectOrientedProgrammingIntroduction"></A>Brief Apect Oriented Programming Introduction</H2> + +<P>In order to understand the aspect oriented approach to logging in Tuscany, one must understand a few basic concepts.</P> + +<P>A <EM>join point</EM> is well defined point in the program flow. An example join point is the entry to a Java method. Another is after an exception is thrown. These join points contain useful information when running a program such as the argument list, the call stack, and the signature of the point that is executing.</P> + +<P>A <EM>point cut</EM> is a subset of all the program join points. For instance, a point cut might be only the join points from exceptions thrown by the Tuscany runtime. Or only the set of calls to a Tuscany API org.apache.tuscany.sca.node.launcher.NodeLauncher.</P> + +<P><EM>Advice</EM> is the code that is run when a point cut is reached. For instance, your advice might want to print out all the arguments when entering a given method. Or your advice might show the call stack of an exception and print the original cause of the exception.</P> + +<P>Finally, an <EM>aspect</EM> is a module that bundles up a particular set of point cuts and advice. Here is an example aspect that is marked with Java 5 annotations. The name of the aspect is <EM>LoggingAspect</EM>, there is a point cut defined at Tuscany calls to org.apache.tuscany.sca.* classes (but not inside of Aspect classes), and when the point cut is run, the advice for this point cut prints out the join point signature.</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Example Aspect</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java">@Aspect +<SPAN class="code-keyword">public</SPAN> class LoggingAspect { + @Pointcut(<SPAN class="code-quote">"call(* org.apache.tuscany.sca..*(..)) && (!within(org.apache.tuscany.sca.aspectj.*Aspect))"</SPAN>) + <SPAN class="code-keyword">public</SPAN> void anyMethodCall() { + } + + @Before(<SPAN class="code-quote">"anyMethodCall()"</SPAN>) + <SPAN class="code-keyword">public</SPAN> void before(JoinPoint jp) { + <SPAN class="code-object">System</SPAN>.out.println(<SPAN class="code-quote">"Logging Before anyMethodCall jp.getSignature="</SPAN> + jp.getSignature()); + } +} +</PRE> +</DIV></DIV> +<P>Full explanation of these concepts are in the AspectJ documents. The purpose here is to provide enough information to allow a user to run or modify the Tuscany aspects to one's liking.</P> + +<H2><A name="Logging%2CTracingandTiming-LoggingandTracinginTuscany"></A>Logging and Tracing in Tuscany</H2> + +<P>Following the approach of AspectJ, Tuscany provides two concrete aspects for logging and tracing. org.apache.tuscany.sca.aspectj.LoggingAspect provides logging for methods, constructors, and static initializers in Tuscany. org.apache.tuscany.sca.aspectj.SimpleTracingAspect provide tracing into user methods, constructors, and static initializers. Both provide detailed information when an Exception or Throwable is thrown by the Tuscany runtime or user SCA program.</P> + +<P>Both LoggingAspect and SimpleTracingAspect are run by naming the AspectJ runtime agent aspectjweaver.jar at launch. This is shown in the command line example above, and an example is provided in launcher.bat in the tracing-aspectj module, and a further example is provded by running the command "ant runtraced" on the calculator sample in a binary distribution.</P> + +<P>The runtime configuration file aop.xml has references to these aspects. Uncomment one or both of these in aop.xml to run with this logging enabled. Following is an example logging run with the verbose weaver option specified. Note the verbose output of class names, build times, etc. The logging statements too are quite verbose stating the name of the join point, the point cut, and various signatures and arguments.</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Example Logging in Tuscany</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java">[INFO] Configured Artifact: org.aspectj:aspectjweaver:1.6.1:jar +[INFO] Copying aspectjweaver-1.6.1.jar to E:\t\java\sca\modules\tracing-aspectj\target\dependency\aspectjweaver-1.6.1.jar +[AppClassLoader@92e78c] info AspectJ Weaver Version 1.6.1 built on Thursday Jul 3, 2008 at 18:35:41 GMT +[AppClassLoader@92e78c] info register classloader sun.misc.Launcher$AppClassLoader@92e78c +[AppClassLoader@92e78c] info using configuration /E:/t/java/sca/modules/tracing-aspectj/target/classes/META-INF/aop.xml +[AppClassLoader@92e78c] info register aspect org.apache.tuscany.sca.aspectj.LoggingAspect +[AppClassLoader@92e78c] info define aspect org.apache.tuscany.sca.aspectj.UserTimingAspect + +------------------------------------------------------- + T E S T S +------------------------------------------------------- +Logging Before anyMethodCall jp.getSignature=SCANodeFactory org.apache.tuscany.sca.node.SCANodeFactory.newInstance() +Logging Before anyConstructor jp.getSignature=org.apache.tuscany.sca.extensibility.ServiceDiscovery() +Logging Before anyConstructor jp.getSignature=org.apache.tuscany.sca.extensibility.ServiceDiscovery.1(ServiceDiscovery, <SPAN class="code-object">Class</SPAN>) +Logging Before anyConstructor jp.getArgs=[org.apache.tuscany.sca.extensibility.ServiceDiscovery@ceb6dd, + class org.apache.tuscany.sca.node.SCANodeFactory] +Logging Before anyMethodCall jp.getSignature=ServiceDiscoverer org.apache.tuscany.sca.extensibility.ServiceDiscovery.getServiceDiscoverer() +Logging Before anyConstructor jp.getSignature=org.apache.tuscany.sca.extensibility.ContextClassLoaderServiceDiscoverer() +Logging AfterReturning anyMethodCall jp=call(ServiceDiscoverer org.apache.tuscany.sca.extensibility.ServiceDiscovery.getServiceDiscoverer()), + result=org.apache.tuscany.sca.extensibility.ContextClassLoaderServiceDiscoverer@17574b9 +Logging Before anyMethodCall jp.getSignature=Set org.apache.tuscany.sca.extensibility.ServiceDiscoverer.discover(<SPAN class="code-object">String</SPAN>, <SPAN class="code-object">boolean</SPAN>) +Logging Before anyMethodCall jp.getArgs=[org.apache.tuscany.sca.node.SCANodeFactory, <SPAN class="code-keyword">true</SPAN>] +</PRE> +</DIV></DIV> +<P>These aspects provide static point cuts and advice. That is, the various methods, constructors, and exception points are constrained by the source code of the aspects. You can change these items via editing LoggingAspect or SimpleTracingAspect and rerunning the application.</P> + +<H2><A name="Logging%2CTracingandTiming-Timing"></A>Timing</H2> + +<P>Timing of various calls is also available via the AOP logging and tracing facility in Tuscany. The apsect UserTimingAspect is provided to time certain point cuts. As shown above, this AOP timing feature can be used for timing metrics for competitive analysis of performance gauges. The output of the timing is shown here, as a Logger.info method is called and timed.</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Tuscany AOP Timing Output</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java">Running org.apache.tuscany.sca.aspectj.TracingTestCase +Timing Around timedSection jp=call(void java.util.logging.Logger.info(<SPAN class="code-object">String</SPAN>)) +Oct 21, 2008 9:26:36 AM org.apache.tuscany.sca.aspectj.TracingTestCase info_aroundBody0 +Timing Around timedSection Roundtrip is 32ms <SPAN class="code-keyword">for</SPAN> jp.getSignature=void java.util.logging.Logger.info(<SPAN class="code-object">String</SPAN>) +</PRE> +</DIV></DIV> +<P>Unlike LoggingAspect and SimpleTracingAspect, the pointcut for UserTimingAspect is settable at runtime via the aop.xml runtime configuration file. Look for the UserTimingAspect name, and note the expression in the pointcut element. You may change the name of expression to any valid AspectJ pointcut expression. Here calls to any Logger.info methods, regardless of arguments or return types are logged. For instance you may change this to "call( * calculator.CalculatorServiceImpl.multiply(..))" to time calls in your SCA application.</P> +<DIV class="code panel" style="border-style: solid;border-width: 1px;"><DIV class="codeHeader panelHeader" style="border-bottom-width: 1px;border-bottom-style: solid;"><B>Dynamic PointCut for UserTimingAspect</B></DIV><DIV class="codeContent panelContent"> +<PRE class="code-java"> <concrete-aspect name=<SPAN class="code-quote">"org.apache.tuscany.sca.aspectj.UserTimingAspect"</SPAN> + <SPAN class="code-keyword">extends</SPAN>=<SPAN class="code-quote">"org.apache.tuscany.sca.aspectj.TimingAspect"</SPAN> + precedence=<SPAN class="code-quote">"org.apache.tuscany.sca.aspectj.UserTimingAspect, *"</SPAN>> + <pointcut name=<SPAN class="code-quote">"timedCall"</SPAN> + expression=<SPAN class="code-quote">"call(* java.util.logging.Logger.info(..))"</SPAN>/> + </concrete-aspect> +</PRE> +</DIV></DIV> + +<H2><A name="Logging%2CTracingandTiming-LoggingandTracinginAlternateContainers"></A>Logging and Tracing in Alternate Containers</H2> + +<P>So far this article discussed logging and tracing for Tuscany applications. Often Tuscany applications are run standalone in a Java 2 SE environment. You can also turn on logging and tracing in various application servers that support Tuscany SCA applications.</P> + +<H3><A name="Logging%2CTracingandTiming-ApacheTomcatExample"></A>Apache Tomcat Example</H3> + +<P>Show Apache Tomcat J2EE application server plus Tuscany bundled SCA application.</P> + +<H3><A name="Logging%2CTracingandTiming-WebSphereExample"></A>WebSphere Example</H3> + +<P>Show WebSphere 7.0.0.1 plus SOA Feature Pack based on Tuscany output.</P> + </DIV> + + </DIV> + </DIV> + </TD> + </TR> + </TABLE> + + <!-- footer --> + <TABLE border="0" cellpadding="2" cellspacing="0" width="100%"> + <TR> + <TD align="left" valign="middle" class="footer"> + + <IMG src="http://static.delicious.com/img/delicious.small.gif" height="10" width="10" alt="Delicious"> + <A href="http://delicious.com/save" onclick="window.open('http://delicious.com/save?v=5&noui&jump=close&url='+encodeURIComponent(location.href)+'&title='+encodeURIComponent(document.title),'delicious','toolbar=no,width=550,height=550'); return false;">Bookmark this on Delicious</A> + + <IMG src="http://digg.com/img/badges/16x16-digg-guy.gif" width="16" height="16" alt="Digg!"> + <A href="" onclick="window.open('http://digg.com/submit?url='+encodeURIComponent(location.href)+'&title='+encodeURIComponent(document.title)+'&topic=programming');">Digg this</A> + <!-- Slicker, but no text + <script type="text/javascript"> + digg_skin = 'icon'; + digg_window = 'new'; + digg_title = 'Apache Geronimo v2.2 Documentation : Logging, Tracing and Timing'; + digg_topic = 'programming'; + </script> + <script src="http://digg.com/tools/diggthis.js" type="text/javascript"></script> + --> + + </TD> + <TD align="right" valign="middle" class="footer"> + <A href="http://cwiki.apache.org/GMOxPMGT/geronimo-privacy-policy.html">Privacy Policy</A> - + Copyright © 2003-2010, The Apache Software Foundation, Licensed under <A href="http://www.apache.org/licenses/LICENSE-2.0">ASL 2.0.</A> + </TD> + </TR> + </TABLE> + + </BODY> +</HTML>
\ No newline at end of file |