Tutorial Log

From Plex-XML

Jump to: navigation, search

Tutorial workflow: Plex-XML tutorial main page → Preparing your environment → Extract the tutorial from CVS → Restore the tutorial DB → Tutorial Plex → Tutorial Eclipse → Tutorial application user guide → Tutorial debug → Tutorial Log → Help text Wiki


Analyze the execution and performance log

While your application runs in debug mode it will provide some XML and log files which can be very helpful if you are in doubt about the XML that is generated or in doubt about the performance of your application.

tutorial.log

Based on the settings and requests from the previous section of this tutorial (Investigate the XML that is generated...) you should be able to find the "tutorial.log" file in the 'logs' directory of your Tomcat.

Assuming you have a performance problem in your 'Employee Update' function you should execute that function, open the "tutorial.log" file and search for 'EmployeeUD'. The log file shows in detail all execution steps of your function and some debug infos from the control servlet.


Demonstrated on the example below you can see sorted by time stamp:

  • 14:41:59,913 The servlet gets the web request and provides you with some debug infos about the request.
  • 14:41:59,914 The request name and the session locale that is used for translations in your XSLT files.
  • 14:41:59,920 The main Plex-XML for this web request is started.
  • 14:41:59,920 - 14:41:59,951 Other Plex functions are called. You are able to see the start and end time stamps of these functions.
  • 14:41:59,953 The Plex function is finished, the control servlet has the XML result and could start the XSLT transformation
  • 14:41:59,954 XSLT transformation is started.
  • 14:41:59,960 XSLT Transformation is done and the response is send to the user.


The 2 step XSLT transformation (we have learned about it in the step before) takes in this example only 6ms. Which we thing is a good value even for larger applications. Also interesting to see is the 'on the fly' translation and format handling from 14:41:59,938 to 14:41:59,951. It is cached after the first call and doesn't take much time compared to the benefit you get from it.

The total execution time of this web request on the server side was 47ms. For a detailed performance breakdown on the client side you could use 'Firebug'. Be aware that you can get a mixture of different requests if there is is more then one request at the time.

If you need additional debug messages form your functions you can easily attach them by calling the "PATTY/Log Performance Java" API in your Plex function.

Sometimes you can see time stamps that differ up to 16ms without any explainable reason like on 14:41:59,942-14:41:59,947. In our experience there are some system actions or timer handling problems that have influence on this log. But if you call a function more then once you can see that these delays not always on the same step of your function.


Example

tomcat/logs/tutorial.log
14:41:59,913 - 14:41:59,960 in total 47ms 

2007-10-23 14:41:59,913 INFO  [de.bodow.web.ControlServlet] START a Webrequest 
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] checking FileUpload
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] end checking FileUpload
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] --------- START REQUEST HEADERS -----------
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] host=127.0.0.1:8080
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] user-agent=Mozilla/5.0 
                              (Windows; U; Windows NT 6.0; de; rv:1.8.1.8) Gecko/20071008 Firefox/2.0.0.8
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] accept=text/xml,application/xml,application/xhtml
                              +xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] accept-language=en,de;q=0.7,en-us;q=0.3
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] accept-encoding=gzip,deflate
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] accept-charset=ISO-8859-1,utf-8;q=0.7,*;q=0.7
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] keep-alive=300
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] connection=keep-alive
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] referer=http://127.0.0.1:8080/tutorial/aServlet
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] cookie=rememberme=false; userid=demo;
                              JSESSIONID=7CC6C6FFAA9867FCF9423654870CDF38; 
                              dbx-pagemeta=grabit:0-|1-|2-|3+|4+|5-|6-|7-&advancedstuff:0-; dbx-postmeta=grabit:0+|1-|2-|3-|4-|5-&
                              advancedstuff:0-|1-|2-; __utma=96992031.1780481183.1143456676.1193080841.1193086373.524; 
                              __utmz=96992031.1178878319.391.1.utmccn=(direct)|utmcsr=(direct)|utmcmd=(none)
2007-10-23 14:41:59,913 DEBUG [de.bodow.web.ControlServlet] --------- END REQUEST PARAMETERS -------------
2007-10-23 14:41:59,914 INFO  [de.bodow.web.ControlServlet]  Webrequest name is EmployeeUD
2007-10-23 14:41:59,914 DEBUG [de.bodow.web.ControlServlet] session.locale='en'
2007-10-23 14:41:59,920 INFO  [plexperformance] Employee.XML_Intern.Dictionary.U- START
2007-10-23 14:41:59,920 INFO  [plexperformance] Session.BusinessExtraFunctions.ValidateSession- START
2007-10-23 14:41:59,920 INFO  [plexperformance] Session.BusinessExtraFunctions.GetSessionData- START
2007-10-23 14:41:59,921 INFO  [plexperformance] Session.BusinessExtraFunctions.GetSessionData- END
2007-10-23 14:41:59,921 INFO  [plexperformance] SystemParameter.BusinessExtraFunctions.GetSystemParameterClient- START
2007-10-23 14:41:59,921 INFO  [plexperformance] SystemParameter.BusinessExtraFunctions.GetSystemParameterClient- END
2007-10-23 14:41:59,921 INFO  [plexperformance] Session.BusinessExtraFunctions.SetSessionData- START
2007-10-23 14:41:59,922 INFO  [plexperformance] SystemParameter.BusinessExtraFunctions.GetSystemParameterClient- START
2007-10-23 14:41:59,922 INFO  [plexperformance] SystemParameter.BusinessExtraFunctions.GetSystemParameterClient- END
2007-10-23 14:41:59,922 INFO  [plexperformance] Session.BusinessExtraFunctions.SetSessionData- END
2007-10-23 14:41:59,922 INFO  [plexperformance] Session.BusinessExtraFunctions.ValidateSession- END
2007-10-23 14:41:59,922 INFO  [plexperformance] Function.BusinessExtraFunctions.CheckAndCreateRegistrationCache- START
2007-10-23 14:41:59,923 INFO  [plexperformance] Function.BusinessExtraFunctions.CheckAndCreateRegistrationCache- END
2007-10-23 14:41:59,923 INFO  [plexperformance] Function_Format.BusinessExtraFunctions.CheckFunctionFormat- START
2007-10-23 14:41:59,923 INFO  [plexperformance] Function_Format.BusinessExtraFunctions.CheckFunctionFormat- END
2007-10-23 14:41:59,938 INFO  [plexperformance] Format_FieldDetail.BusinessExtraFunctions.GetFunctionDetails- START
2007-10-23 14:41:59,939 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,939 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,939 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,940 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,940 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,940 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,940 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,941 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,941 INFO  [plexperformance] Format_FieldDetail.BusinessExtraFunctions.GetFunctionDetails- END
2007-10-23 14:41:59,941 INFO  [plexperformance] Function_FormatTranslation.BusinessExtraFunctions.GetFormatTranslationSF- START
2007-10-23 14:41:59,941 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,941 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,941 INFO  [plexperformance] Function_FormatTranslation.BusinessExtraFunctions.GetFormatTranslationSF- END
2007-10-23 14:41:59,941 INFO  [plexperformance] Function_FormatTranslation.BusinessExtraFunctions.GetFormatTranslationSF- START
2007-10-23 14:41:59,942 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,942 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,942 INFO  [plexperformance] Function_FormatTranslation.BusinessExtraFunctions.GetFormatTranslationSF- END
2007-10-23 14:41:59,942 INFO  [plexperformance] Function_FormatTranslation.BusinessExtraFunctions.GetFormatTranslationSF- START
2007-10-23 14:41:59,942 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,947 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,947 INFO  [plexperformance] Function_FormatTranslation.BusinessExtraFunctions.GetFormatTranslationSF- END
2007-10-23 14:41:59,948 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- START
2007-10-23 14:41:59,948 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- END
2007-10-23 14:41:59,948 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- START
2007-10-23 14:41:59,948 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- END
2007-10-23 14:41:59,949 INFO  [plexperformance] Field_Value.BusinessExtraFunctions.GetFieldValues- START
2007-10-23 14:41:59,949 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,949 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,949 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,949 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,950 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- START
2007-10-23 14:41:59,950 INFO  [plexperformance] BusinessExtraFunctions.GetTranslation- END
2007-10-23 14:41:59,950 INFO  [plexperformance] Field_Value.BusinessExtraFunctions.GetFieldValues- END
2007-10-23 14:41:59,950 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- START
2007-10-23 14:41:59,950 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- END
2007-10-23 14:41:59,950 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- START
2007-10-23 14:41:59,951 INFO  [plexperformance] Field_Attributes.BusinessExtraFunctions.GetFieldAttributes- END
2007-10-23 14:41:59,951 INFO  [plexperformance] Employee.XML_Intern.Dictionary.U- END
2007-10-23 14:41:59,953 DEBUG [de.bodow.web.ControlServlet] session.locale='en'
2007-10-23 14:41:59,954 DEBUG [de.bodow.web.ControlServlet] using style de.bodow.web.DefaultStyle
                              [type=DEFAULT,mime=text/html,isdefault=true,name=/WEB-INF/resources/ajax_html/aaBaseDoc.xsl
2007-10-23 14:41:59,960 INFO  [de.bodow.web.ControlServlet]  before delete Nodes EmployeeUD
2007-10-23 14:41:59,960 INFO  [de.bodow.web.ControlServlet]  END Webrequest EmployeeUD
2007-10-23 14:41:59,960 WARN  [de.bodow.web.filters.CharsetFilter] request-Encoding-2=UTF-8
Retrieved from "http://wiki.plex-xml.com/index.php/Tutorial_Log"
Personal tools