Changeset 3975 for trunk/pfixcore/src

Timestamp:

01/12/09 16:22:06 (3 years ago)

Author:

mtld

Message:

perflogging with aspectj

Location:

trunk/pfixcore/src

Files:

• de/schlund/pfixcore/util/StateUtil.java (modified) (3 diffs)
• de/schlund/pfixcore/workflow/app/DefaultIWrapperState.java (modified) (8 diffs)
• de/schlund/pfixcore/workflow/app/IHandlerContainerImpl.java (modified) (4 diffs)
• de/schlund/pfixcore/workflow/app/IWrapperContainerImpl.java (modified) (3 diffs)
• de/schlund/pfixcore/workflow/context/RequestContextImpl.java (modified) (5 diffs)
• de/schlund/pfixxml/PfixServletRequestImpl.java (modified) (3 diffs)
• de/schlund/pfixxml/perflogging/CorePerfLoggingAspect.java (added)
• org/pustefixframework/http/AbstractPustefixRequestHandler.java (modified) (2 diffs)
• org/pustefixframework/http/AbstractPustefixXMLRequestHandler.java (modified) (7 diffs)

trunk/pfixcore/src/de/schlund/pfixcore/util/StateUtil.java

@@ -41 +41 @@
 import de.schlund.pfixxml.ResultDocument;
 import de.schlund.pfixxml.SPDocument;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 
 
@@ -65 +63 @@
     
     
-    @SuppressWarnings("deprecation")
     public static void renderContextResources(Context context, ResultDocument resdoc, StateConfig config) throws Exception {
         Map<String, ?> contextResources = config.getContextResources();
@@ -71 +68 @@
         for (String nodename : contextResources.keySet()) {
             Object cr = contextResources.get(nodename);
-            String classname = cr.getClass().getName();
-            Class<?> clazz = cr.getClass();
-            if(Enhancer.isEnhanced(clazz)) {
-                clazz = clazz.getSuperclass();
-                classname = clazz.getName();
-            }
-            if (LOG.isDebugEnabled()) {
-                LOG.debug("*** Auto appending status for " + classname + " at node " + nodename);
-            }
-            PerfEvent pe = new PerfEvent(PerfEventType.CONTEXTRESOURCE_INSERTSTATUS, classname);
-            pe.start();
-            if (cr instanceof de.schlund.pfixcore.workflow.ContextResource) {
-                LOG.debug("***** Resource implements ContextResource => calling insertStatus(...) of " + clazz.getName());
-                ((de.schlund.pfixcore.workflow.ContextResource) cr).insertStatus(resdoc, resdoc.createNode(nodename));
-            } else {
-                boolean found_annotation = false;
-                for (Method m : clazz.getMethods()) {
-                    if (m.isAnnotationPresent(InsertStatus.class)) {
-                        Class<?>[] params = m.getParameterTypes();
-                        Class<?>  rettype = m.getReturnType();
-                        if (params.length == 0 && rettype != null) {
-                            LOG.debug("***** Found @InsertStatus for Object:" + m.getName() + "() of " + clazz.getName());
-                            ResultDocument.addObject(resdoc.createNode(nodename), m.invoke(cr, new Object[] {}));
-                        } else if (params.length == 1 && params[0].isAssignableFrom(Element.class)) {
-                            LOG.debug("***** Found @InsertStatus for " + m.getName() + "(Element) of " + clazz.getName());
-                            m.invoke(cr, resdoc.createNode(nodename));
-                        } else if (params.length == 2 && params[0].isAssignableFrom(ResultDocument.class) && params[1].isAssignableFrom(Element.class)) {
-                            LOG.debug("***** Found @InsertStatus for " + m.getName() + "(ResultDocument, Element) of " + clazz.getName());
-                            m.invoke(cr, resdoc, resdoc.createNode(nodename));
-                        } else {
-                            throw new PustefixApplicationException("Exception when trying to call annotated method '@InsertStatus' " +
-                                    "of " + clazz.getName() + ": Need either a signature of either " + 
-                            "method(Element) or method(ResultDocument, Element)");
-                        }
-                        found_annotation = true;
-                        break;
+            renderContextResource(cr, resdoc, nodename);
+        }
+    }
+    
+    @SuppressWarnings("deprecation")
+    private static void renderContextResource(Object cr, ResultDocument resdoc, String nodename) throws Exception {
+        String classname = cr.getClass().getName();
+        Class<?> clazz = cr.getClass();
+        if(Enhancer.isEnhanced(clazz)) {
+            clazz = clazz.getSuperclass();
+            classname = clazz.getName();
+        }
+        if (LOG.isDebugEnabled()) {
+            LOG.debug("*** Auto appending status for " + classname + " at node " + nodename);
+        }
+        if (cr instanceof de.schlund.pfixcore.workflow.ContextResource) {
+            LOG.debug("***** Resource implements ContextResource => calling insertStatus(...) of " + clazz.getName());
+            ((de.schlund.pfixcore.workflow.ContextResource) cr).insertStatus(resdoc, resdoc.createNode(nodename));
+        } else {
+            boolean found_annotation = false;
+            for (Method m : clazz.getMethods()) {
+                if (m.isAnnotationPresent(InsertStatus.class)) {
+                    Class<?>[] params = m.getParameterTypes();
+                    Class<?>  rettype = m.getReturnType();
+                    if (params.length == 0 && rettype != null) {
+                        LOG.debug("***** Found @InsertStatus for Object:" + m.getName() + "() of " + clazz.getName());
+                        ResultDocument.addObject(resdoc.createNode(nodename), m.invoke(cr, new Object[] {}));
+                    } else if (params.length == 1 && params[0].isAssignableFrom(Element.class)) {
+                        LOG.debug("***** Found @InsertStatus for " + m.getName() + "(Element) of " + clazz.getName());
+                        m.invoke(cr, resdoc.createNode(nodename));
+                    } else if (params.length == 2 && params[0].isAssignableFrom(ResultDocument.class) && params[1].isAssignableFrom(Element.class)) {
+                        LOG.debug("***** Found @InsertStatus for " + m.getName() + "(ResultDocument, Element) of " + clazz.getName());
+                        m.invoke(cr, resdoc, resdoc.createNode(nodename));
+                    } else {
+                        throw new PustefixApplicationException("Exception when trying to call annotated method '@InsertStatus' " +
+                                "of " + clazz.getName() + ": Need either a signature of either " + 
+                        "method(Element) or method(ResultDocument, Element)");
                     }
-                }
-                if (!found_annotation) {
-                    LOG.debug("***** Serializing the complete resource " + clazz.getName());
-                    ResultDocument.addObject(resdoc.createNode(nodename), cr);
+                    found_annotation = true;
+                    break;
                 }
             }
-            pe.save();
+            if (!found_annotation) {
+                LOG.debug("***** Serializing the complete resource " + clazz.getName());
+                ResultDocument.addObject(resdoc.createNode(nodename), cr);
+            }
         }
     }

trunk/pfixcore/src/de/schlund/pfixcore/workflow/app/DefaultIWrapperState.java

@@ -22 +22 @@
 import java.util.Map;
 
-import org.pustefixframework.generated.CoreStatusCodes;
 import org.pustefixframework.config.contextxmlservice.IWrapperConfig;
 import org.pustefixframework.config.contextxmlservice.StateConfig;
+import org.pustefixframework.generated.CoreStatusCodes;
 
 import de.schlund.pfixcore.util.TokenManager;
@@ -36 +36 @@
 import de.schlund.pfixxml.ResultDocument;
 import de.schlund.pfixxml.XMLException;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 
 /**
@@ -89 +87 @@
         ResdocFinalizer rfinal = getResdocFinalizer(context);
         ResultDocument  resdoc = new ResultDocument();
-        PerfEvent       pe     = new PerfEvent(PerfEventType.PAGE_INITIWRAPPERS, context.getCurrentPageRequest().toString());
-
-        pe.start();
+      
         IWrapperContainer wrp_container =  getIHandlerContainer(context).createIWrapperContainerInstance(context, preq, resdoc);
-        pe.save();
 
         if (isSubmitTrigger(context, preq)) {
@@ -113 +108 @@
                         context.addPageMessage(CoreStatusCodes.FORM_TOKEN_INVALID, null, null);
                         if (errorPage.equals("")) {
-                            pe = new PerfEvent(PerfEventType.PAGE_RETRIEVECURRENTSTATUS, context.getCurrentPageRequest().toString());
-                            pe.start();
                             wrp_container.retrieveCurrentStatus(false);
-                            pe.save();
                             rfinal.onWorkError(wrp_container);
                             context.prohibitContinue();
@@ -131 +123 @@
                 if (stateConf != null && stateConf.requiresToken()) {
                     context.addPageMessage(CoreStatusCodes.FORM_TOKEN_MISSING, null, null);
-                    pe = new PerfEvent(PerfEventType.PAGE_RETRIEVECURRENTSTATUS, context.getCurrentPageRequest().toString());
-                    pe.start();
                     wrp_container.retrieveCurrentStatus(false);
-                    pe.save();
                     rfinal.onWorkError(wrp_container);
                     context.prohibitContinue();
@@ -142 +131 @@
 
             if (valid) {
-                pe = new PerfEvent(PerfEventType.PAGE_HANDLESUBMITTEDDATA, context.getCurrentPageRequest().toString());
-                pe.start();
                 wrp_container.handleSubmittedData();
-                pe.save();
 
                 if (wrp_container.errorHappened()) {
@@ -154 +140 @@
                     CAT.debug("    => No error happened during work... end of submit reached successfully.");
                     CAT.debug("    => retrieving current status.");
-                    pe = new PerfEvent(PerfEventType.PAGE_RETRIEVECURRENTSTATUS, context.getCurrentPageRequest().toString());
-                    pe.start();
                     wrp_container.retrieveCurrentStatus(false);
-                    pe.save();
 
                     rfinal.onSuccess(wrp_container);
@@ -165 +148 @@
             CAT.debug(">>> Retrieving current status...");
 
-            pe = new PerfEvent(PerfEventType.PAGE_RETRIEVECURRENTSTATUS, context.getCurrentPageRequest().toString());
-            pe.start();
             wrp_container.retrieveCurrentStatus(true);
-            pe.save();
             if (CAT.isDebugEnabled()) {
                 if (isDirectTrigger(context, preq)) {

trunk/pfixcore/src/de/schlund/pfixcore/workflow/app/IHandlerContainerImpl.java

@@ -31 +31 @@
 import de.schlund.pfixxml.PfixServletRequest;
 import de.schlund.pfixxml.ResultDocument;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 
 /**
@@ -102 +100 @@
         for (Iterator<IHandler> iter = handlers.iterator(); iter.hasNext(); ) {
             IHandler handler = iter.next();
-            PerfEvent pe = new PerfEvent(PerfEventType.IHANDLER_PREREQUISITESMET, handler.getClass().getName());
-            pe.start();
             boolean  test = handler.prerequisitesMet(context);
-            pe.save();
             
             if (!test) {
@@ -176 +171 @@
      */
     private boolean doIsActive(IHandler handler, Context ctx) throws Exception{
-        PerfEvent pe = new PerfEvent(PerfEventType.IHANDLER_ISACTIVE, handler.getClass().getName());
-        pe.start();
         boolean  test = handler.isActive(ctx);
-        pe.save();
         return test;
     }
@@ -193 +185 @@
      */
     private boolean doNeedsData(IHandler handler, Context ctx) throws Exception{
-        PerfEvent pe = new PerfEvent(PerfEventType.IHANDLER_NEEDSDATA, handler.getClass().getName());
-        pe.start();
         boolean  test = handler.needsData(ctx);
-        pe.save();
         return test;
     }

trunk/pfixcore/src/de/schlund/pfixcore/workflow/app/IWrapperContainerImpl.java

@@ -47 +47 @@
 import de.schlund.pfixxml.ResultDocument;
 import de.schlund.pfixxml.XMLException;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 import de.schlund.pfixxml.resources.FileResource;
 import de.schlund.pfixxml.resources.ResourceUtil;
@@ -66 +64 @@
     private Set<IWrapper>             allsubmit        = new TreeSet<IWrapper>();
     private Set<IWrapper>             allretrieve      = new TreeSet<IWrapper>();
-    private Context                   context          = null;
+    public Context                   context          = null;
     private ResultDocument            resdoc           = null;
     private RequestData               reqdata          = null;
@@ -235 +233 @@
                     wrapper.tryParamLogging();
                     if (!wrapper.errorHappened()) {
-                        PerfEvent pe = new PerfEvent(PerfEventType.IHANDLER_HANDLESUBMITTEDDATA, handler.getClass().getName());
-                        pe.start();
                         handler.handleSubmittedData(context, wrapper);
-                        pe.save();
                     }
                 }

trunk/pfixcore/src/de/schlund/pfixcore/workflow/context/RequestContextImpl.java

@@ -67 +67 @@
 import de.schlund.pfixxml.SPDocument;
 import de.schlund.pfixxml.Variant;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 import de.schlund.util.statuscodes.StatusCode;
 
@@ -842 +840 @@
         State state = getStateForPageRequest(page);
 
-        PerfEvent pe = new PerfEvent(PerfEventType.PAGE_NEEDSDATA, page.getName());
-        pe.start();
         boolean retval;
         try {
@@ -850 +846 @@
             throw new PustefixApplicationException("Exception while running needsData() for page " + page.getName(), e);
         }
-        pe.save();
 
         currentpagerequest = saved;
@@ -865 +860 @@
             State state = getStateForPageRequest(page);
 
-            PerfEvent pe = new PerfEvent(PerfEventType.PAGE_ISACCESSIBLE, page.getName());
-            pe.start();
             boolean retval;
             try {
@@ -873 +866 @@
                 throw new PustefixApplicationException("Got exception from state for page " + page.getName() + " while calling isAccessible()", e);
             }
-            pe.save();
 
             return retval;

trunk/pfixcore/src/de/schlund/pfixxml/PfixServletRequestImpl.java

@@ -39 +39 @@
 import de.schlund.pfixxml.multipart.MultipartHandler;
 import de.schlund.pfixxml.multipart.PartData;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 import de.schlund.pfixxml.serverutil.SessionHelper;
 import de.schlund.pfixxml.util.CookieUtils;
@@ -100 +98 @@
      */
     public PfixServletRequestImpl(HttpServletRequest req, Properties properties) {
-        PerfEvent pe = new PerfEvent(PerfEventType.PFIXSERVLETREQUEST_INIT);
-        pe.start();
-        
+    
         starttime   = System.currentTimeMillis();
         getRequestParams(req, properties);
@@ -113 +109 @@
         session     = req.getSession(false);
 
-        pe.setIdentfier(uri);
-        pe.save();
     }
 

trunk/pfixcore/src/org/pustefixframework/http/AbstractPustefixRequestHandler.java

@@ -54 +54 @@
 import de.schlund.pfixxml.exceptionprocessor.ExceptionConfig;
 import de.schlund.pfixxml.exceptionprocessor.ExceptionProcessor;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 import de.schlund.pfixxml.serverutil.SessionAdmin;
 import de.schlund.pfixxml.serverutil.SessionHelper;
@@ -416 +414 @@
         LOG.debug("*** >>> End of redirection management, handling request now.... <<< ***\n");
 
-        PerfEvent pe = new PerfEvent(PerfEventType.XMLSERVER_CALLPROCESS, req.getRequestURI());
-        pe.start();
         callProcess(preq, req, res);
-        pe.save();
     }
 

trunk/pfixcore/src/org/pustefixframework/http/AbstractPustefixXMLRequestHandler.java

@@ -63 +63 @@
 import de.schlund.pfixxml.perflogging.AdditionalTrailInfo;
 import de.schlund.pfixxml.perflogging.AdditionalTrailInfoFactory;
-import de.schlund.pfixxml.perflogging.PerfEvent;
-import de.schlund.pfixxml.perflogging.PerfEventType;
 import de.schlund.pfixxml.resources.FileResource;
 import de.schlund.pfixxml.resources.ResourceUtil;
@@ -389 +387 @@
         if (spdoc == null) {
             
-            // Performace tracking
-            PerfEvent pe = new PerfEvent(PerfEventType.XMLSERVER_GETDOM);
-            pe.start();
             currtime        = System.currentTimeMillis();
             
@@ -407 +402 @@
                 }
             }
-            
-            //Performance tracking
-            pe.setIdentfier(spdoc.getPagename());
-            pe.save();
             
             
@@ -541 +532 @@
         }
         
-        //Performance tracking
-        PerfEvent pe = new PerfEvent(PerfEventType.XMLSERVER_HANDLEDOCUMENT, spdoc.getPagename());
-        pe.start();
-        
         if (spdoc.docIsUpdateable()) {
             if (stylesheet.indexOf("::") > 0) {
@@ -570 +557 @@
             setCookies(spdoc,res);
         }
+        
+        boolean modified_or_no_etag = doHandleDocument(spdoc, stylesheet, paramhash, preq, res, session);
+
+        long handletime = System.currentTimeMillis() - currtime;
+        preq.getRequest().setAttribute(TRAFOTIME, handletime);
+        
+        Map<String, Object> addinfo = addtrailinfo.getData(preq);
+        
+        if (session != null && !spdoc.getTrailLogged()) {
+            StringBuffer logbuff = new StringBuffer();
+            logbuff.append(session.getAttribute(VISIT_ID) + "|");
+            logbuff.append(session.getId() + "|");
+            logbuff.append(preq.getRemoteAddr() + "|");
+            logbuff.append(preq.getServerName() + "|");
+            logbuff.append(stylesheet + "|");
+            logbuff.append(preq.getOriginalRequestURI());
+            if (preq.getQueryString() != null) {
+                logbuff.append("?" + preq.getQueryString());
+            }
+            String flow = (String) paramhash.get("pageflow");
+            if (flow != null) {
+                logbuff.append("|" + flow);
+            }
+            for (Iterator<String> keys = addinfo.keySet().iterator(); keys.hasNext(); ) {
+                logbuff.append("|" + addinfo.get(keys.next()));
+            }
+            LOGGER_TRAIL.warn(logbuff.toString());
+            spdoc.setTrailLogged();
+        }
+        
+        if (LOGGER.isInfoEnabled()) {
+            LOGGER.info(">>> Complete handleDocument(...) took " + handletime + "ms" + 
+                    " (needed xslt: " + modified_or_no_etag + ")");
+        }
+        
+        try {
+            if (modified_or_no_etag && 
+                    (spdoc.getResponseContentType() == null || spdoc.getResponseContentType().startsWith("text/html"))) {
+                OutputStream       out          = res.getOutputStream();
+                OutputStreamWriter writer       = new OutputStreamWriter(out, res.getCharacterEncoding());
+                writer.write("\n<!--");
+                for (Iterator<String> keys = addinfo.keySet().iterator(); keys.hasNext(); ) {
+                    String key = keys.next();
+                    writer.write(" " + key + ": " + addinfo.get(key));
+                }
+                writer.write(" -->");
+                writer.flush();
+            }
+        } catch (Exception e) {
+            // ignore
+        }
+    }
+
+    private boolean doHandleDocument(SPDocument spdoc, String stylesheet, TreeMap<String, Object> paramhash, 
+            PfixServletRequest preq, HttpServletResponse res, HttpSession session) throws PustefixCoreException {
         
         boolean modified_or_no_etag = true;
@@ -582 +624 @@
         }
         
-        PerfEvent pe_etag = new PerfEvent(PerfEventType.XMLSERVER_CREATEETAG, spdoc.getPagename());
-        pe_etag.start();
-        String etag_outgoing = MD5Utils.hex_md5(output.toString());
-        pe_etag.save();
+        String etag_outgoing = createETag(output.toString(), spdoc);
         res.setHeader("ETag", etag_outgoing);
-
+        
         if (getRendering(preq) == RENDERMODE.RENDER_NORMAL && etag_incoming != null && etag_incoming.equals(etag_outgoing)) {
             //it's important to reset the content type, because old Apache versions in conjunction
@@ -603 +642 @@
             }
         }
-
-        long handletime = System.currentTimeMillis() - currtime;
-        preq.getRequest().setAttribute(TRAFOTIME, handletime);
-        
-        Map<String, Object> addinfo = addtrailinfo.getData(preq);
-        
-        if (session != null && !spdoc.getTrailLogged()) {
-            StringBuffer logbuff = new StringBuffer();
-            logbuff.append(session.getAttribute(VISIT_ID) + "|");
-            logbuff.append(session.getId() + "|");
-            logbuff.append(preq.getRemoteAddr() + "|");
-            logbuff.append(preq.getServerName() + "|");
-            logbuff.append(stylesheet + "|");
-            logbuff.append(preq.getOriginalRequestURI());
-            if (preq.getQueryString() != null) {
-                logbuff.append("?" + preq.getQueryString());
-            }
-            String flow = (String) paramhash.get("pageflow");
-            if (flow != null) {
-                logbuff.append("|" + flow);
-            }
-            for (Iterator<String> keys = addinfo.keySet().iterator(); keys.hasNext(); ) {
-                logbuff.append("|" + addinfo.get(keys.next()));
-            }
-            LOGGER_TRAIL.warn(logbuff.toString());
-            spdoc.setTrailLogged();
-        }
-
-        pe.save();
-        
-        if (LOGGER.isInfoEnabled()) {
-            LOGGER.info(">>> Complete handleDocument(...) took " + handletime + "ms" + 
-                    " (needed xslt: " + modified_or_no_etag + ")");
-        }
-        
-        try {
-            if (modified_or_no_etag && 
-                    (spdoc.getResponseContentType() == null || spdoc.getResponseContentType().startsWith("text/html"))) {
-                OutputStream       out          = res.getOutputStream();
-                OutputStreamWriter writer       = new OutputStreamWriter(out, res.getCharacterEncoding());
-                writer.write("\n<!--");
-                for (Iterator<String> keys = addinfo.keySet().iterator(); keys.hasNext(); ) {
-                    String key = keys.next();
-                    writer.write(" " + key + ": " + addinfo.get(key));
-                }
-                writer.write(" -->");
-                writer.flush();
-            }
-        } catch (Exception e) {
-            // ignore
-        }
-    }
-
+        
+        return modified_or_no_etag;
+    }
+    
+    private String createETag(String output, SPDocument spdoc) {
+        String etag_outgoing = MD5Utils.hex_md5(output.toString());
+        return etag_outgoing;
+    }
     
     private void render(SPDocument spdoc, RENDERMODE rendering, HttpServletResponse res, TreeMap<String, Object> paramhash, String stylesheet, OutputStream output) throws RenderingException {