1. opensymphony
  2. xwork

Commits

tm_jee  committed f1bfbb7

WW-727
- profiling in ww2
- added profiling to followings:-
1] creation of DefaultActionProxy
2] creation of DefaultActionInvocation
3] execution of DefaultActionProxy
4] invocation of PreResultListeners
5] invocation of interceptors
- This is added cause there's some post in WW forum suggesting that the creation of little objects like ActionProxy and ActionInvocation in each request is causing performance problem and its better if WW does caching of them. With this profiling it should clear things up.
- added also test cases for profiling classes and a convenient callback class.

git-svn-id: http://svn.opensymphony.com/svn/xwork/trunk@1161e221344d-f017-0410-9bd5-d282ab1896d7

  • Participants
  • Parent commits 9d17c3a
  • Branches master

Comments (0)

Files changed (6)

File src/java/com/opensymphony/xwork2/DefaultActionInvocation.java

View file
 import com.opensymphony.xwork2.config.entities.ResultConfig;
 import com.opensymphony.xwork2.interceptor.PreResultListener;
 import com.opensymphony.xwork2.util.ValueStack;
-import com.opensymphony.xwork2.util.ValueStack;
 import com.opensymphony.xwork2.util.ValueStackFactory;
 import com.opensymphony.xwork2.util.XWorkContinuationConfig;
 import com.opensymphony.xwork2.util.profiling.UtilTimerStack;
  * The Default ActionInvocation implementation
  *
  * @author Rainer Hermanns
- * @version $Revision$
+ * @author tmjee
+ * 
+ * @version $Date$ $Id$
+ * 
  * @see com.opensymphony.xwork2.DefaultActionProxy
  */
 public class DefaultActionInvocation implements ActionInvocation {
     
-    public static ContinuationHandler continuationHandler;
+	private static final long serialVersionUID = -585293628862447329L;
+
+	public static ContinuationHandler continuationHandler;
 
     static {
         if (ObjectFactory.getContinuationPackage() != null) {
         this(proxy, extraContext, true);
     }
 
-    protected DefaultActionInvocation(ActionProxy proxy, Map extraContext, boolean pushAction) throws Exception {
-        this.proxy = proxy;
-        this.extraContext = extraContext;
-        this.pushAction = pushAction;
-        init();
+    protected DefaultActionInvocation(final ActionProxy proxy, final Map extraContext, final boolean pushAction) throws Exception {
+    	UtilTimerStack.profile("create DefaultActionInvocation: ", 
+    			new UtilTimerStack.ProfilingBlock<Object>() {
+					public Object doProfiling() throws Exception {
+						DefaultActionInvocation.this.proxy = proxy;
+				        DefaultActionInvocation.this.extraContext = extraContext;
+				        DefaultActionInvocation.this.pushAction = pushAction;
+				        init();
+						return null;
+					}
+    			});
     }
 
     public Object getAction() {
      * @throws ConfigurationException If no result can be found with the returned code
      */
     public String invoke() throws Exception {
-        if (executed) {
-            throw new IllegalStateException("Action has already executed");
-        }
-
-        if (interceptors.hasNext()) {
-            InterceptorMapping interceptor = (InterceptorMapping) interceptors.next();
-            resultCode = interceptor.getInterceptor().intercept(this);
-        } else {
-            resultCode = invokeActionOnly();
-        }
-
-        // this is needed because the result will be executed, then control will return to the Interceptor, which will
-        // return above and flow through again
-        if (!executed) {
-            if (preResultListeners != null) {
-                for (Iterator iterator = preResultListeners.iterator();
-                     iterator.hasNext();) {
-                    PreResultListener listener = (PreResultListener) iterator.next();
-                    listener.beforeResult(this, resultCode);
-                }
-            }
-
-            // now execute the result, if we're supposed to
-            if (proxy.getExecuteResult()) {
-                executeResult();
-            }
-
-            executed = true;
-        }
-
-        return resultCode;
+    	String profileKey = "invoke: ";
+    	try {
+    		UtilTimerStack.push(profileKey);
+    		
+    		if (executed) {
+    			throw new IllegalStateException("Action has already executed");
+    		}
+
+    		if (interceptors.hasNext()) {
+    			final InterceptorMapping interceptor = (InterceptorMapping) interceptors.next();
+    			return UtilTimerStack.profile("interceptor: "+interceptor.getName(), 
+    					new UtilTimerStack.ProfilingBlock<String>() {
+							public String doProfiling() throws Exception {
+				    			resultCode = interceptor.getInterceptor().intercept(DefaultActionInvocation.this);
+								return resultCode;
+							}
+    			});
+    		} else {
+    			resultCode = invokeActionOnly();
+    		}
+
+    		// this is needed because the result will be executed, then control will return to the Interceptor, which will
+    		// return above and flow through again
+    		if (!executed) {
+    			if (preResultListeners != null) {
+    				for (Iterator iterator = preResultListeners.iterator();
+    					iterator.hasNext();) {
+    					PreResultListener listener = (PreResultListener) iterator.next();
+    					
+    					String _profileKey="preResultListener: ";
+    					try {
+    						UtilTimerStack.push(_profileKey);
+    						listener.beforeResult(this, resultCode);
+    					}
+    					finally {
+    						UtilTimerStack.pop(_profileKey);
+    					}
+    				}
+    			}
+
+    			// now execute the result, if we're supposed to
+    			if (proxy.getExecuteResult()) {
+    				executeResult();
+    			}
+
+    			executed = true;
+    		}
+
+    		return resultCode;
+    	}
+    	finally {
+    		UtilTimerStack.pop(profileKey);
+    	}
     }
 
     public String invokeActionOnly() throws Exception {
-        return invokeAction(getAction(), proxy.getConfig());
+    	return invokeAction(getAction(), proxy.getConfig());
     }
 
     protected void createAction(Map contextMap) {

File src/java/com/opensymphony/xwork2/DefaultActionProxy.java

View file
 import com.opensymphony.xwork2.util.TextUtils;
 import com.opensymphony.xwork2.config.Configuration;
 import com.opensymphony.xwork2.config.ConfigurationException;
-import com.opensymphony.xwork2.config.RuntimeConfiguration;
 import com.opensymphony.xwork2.config.entities.ActionConfig;
 import com.opensymphony.xwork2.util.LocalizedTextUtil;
+import com.opensymphony.xwork2.util.profiling.UtilTimerStack;
+
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
 
  *
  * @author Rainer Hermanns
  * @author Revised by <a href="mailto:hu_pengfei@yahoo.com.cn">Henry Hu</a>
- * @version $Revision$
+ * @author tmjee
+ * 
+ * @version $Date$ $Id$
  * @since 2005-8-6
  */
 public class DefaultActionProxy implements ActionProxy, Serializable {
-    private static final Log LOG = LogFactory.getLog(DefaultActionProxy.class);
+	
+	private static final long serialVersionUID = 3293074152487468527L;
+
+	private static final Log LOG = LogFactory.getLog(DefaultActionProxy.class);
 
     protected Configuration configuration;
     protected ActionConfig config;
      * (like a RMIActionProxy).
      */
     protected DefaultActionProxy(Configuration cfg, String namespace, String actionName, Map extraContext, boolean executeResult, boolean cleanupContext) throws Exception {
-        this.cleanupContext = cleanupContext;
-        if (LOG.isDebugEnabled()) {
-            LOG.debug("Creating an DefaultActionProxy for namespace " + namespace + " and action name " + actionName);
-        }
-
-        this.configuration = cfg;
-        this.actionName = actionName;
-        this.namespace = namespace;
-        this.executeResult = executeResult;
-        this.extraContext = extraContext;
-
-        config = configuration.getRuntimeConfiguration().getActionConfig(namespace, actionName);
-
-        if (config == null) {
-            String message;
-
-            if ((namespace != null) && (namespace.trim().length() > 0)) {
-                message = LocalizedTextUtil.findDefaultText(XWorkMessages.MISSING_PACKAGE_ACTION_EXCEPTION, Locale.getDefault(), new String[]{
+    	String profileKey = "create DefaultActionProxy: ";
+    	try {
+    		UtilTimerStack.push(profileKey);
+    		
+    		this.cleanupContext = cleanupContext;
+    		if (LOG.isDebugEnabled()) {
+    			LOG.debug("Creating an DefaultActionProxy for namespace " + namespace + " and action name " + actionName);
+    		}
+
+    		this.configuration = cfg;
+    		this.actionName = actionName;
+    		this.namespace = namespace;
+    		this.executeResult = executeResult;
+    		this.extraContext = extraContext;
+
+    		config = configuration.getRuntimeConfiguration().getActionConfig(namespace, actionName);
+
+    		if (config == null) {
+    			String message;
+
+    			if ((namespace != null) && (namespace.trim().length() > 0)) {
+    				message = LocalizedTextUtil.findDefaultText(XWorkMessages.MISSING_PACKAGE_ACTION_EXCEPTION, Locale.getDefault(), new String[]{
                         namespace, actionName
-                });
-            } else {
-                message = LocalizedTextUtil.findDefaultText(XWorkMessages.MISSING_ACTION_EXCEPTION, Locale.getDefault(), new String[]{
+    				});
+    			} else {
+    				message = LocalizedTextUtil.findDefaultText(XWorkMessages.MISSING_ACTION_EXCEPTION, Locale.getDefault(), new String[]{
                         actionName
-                });
-            }
-
-            throw new ConfigurationException(message);
-        }
-
-        prepare();
+    				});
+    			}
+    			throw new ConfigurationException(message);
+    		}	
+
+    		prepare();
+    	}
+    	finally {
+    		UtilTimerStack.pop(profileKey);
+    	}
     }
 
     public Object getAction() {
 
         String retCode = null;
 
+        String profileKey = "execute: ";
         try {
+        	UtilTimerStack.push(profileKey);
+        	
             retCode = invocation.invoke();
         } finally {
             if (cleanupContext) {
                 ActionContext.setContext(nestedContext);
             }
+            UtilTimerStack.pop(profileKey);
         }
 
         return retCode;

File src/java/com/opensymphony/xwork2/util/profiling/ProfilingTimerBean.java

View file
  *
  * @author <a href="mailto:mike@atlassian.com">Mike Cannon-Brookes</a>
  * @author <a href="mailto:scott@atlassian.com">Scott Farquhar</a>
+ * 
+ * @version $Date$ $Id$
  */
-public class ProfilingTimerBean implements java.io.Serializable
-{
-    List children = new ArrayList();
+public class ProfilingTimerBean implements java.io.Serializable {
+	
+	private static final long serialVersionUID = -6180672043920208784L;
+	
+	List<ProfilingTimerBean> children = new ArrayList<ProfilingTimerBean>();
     ProfilingTimerBean parent = null;
 
     String resource;

File src/java/com/opensymphony/xwork2/util/profiling/UtilTimerStack.java

View file
  * <p>
  * Usage:
  * <pre>
- * String logMessage = "Log message";
- * UtilTimerStack.push(logMessage);
- * try
- * {
- *   //do some code
- * }
- * finally
- * {
- *   UtilTimerStack.pop(logMessage); //this needs to be the same text as above
- * }
+ *    String logMessage = "Log message";
+ *    UtilTimerStack.push(logMessage);
+ *    try {
+ *      // do some code
+ *    }
+ *    finally {
+ *      UtilTimerStack.pop(logMessage); //this needs to be the same text as above
+ *    }
  * </pre>
+ * 
+ * or 
+ * 
+ * <pre>
+ *   String result = UtilTimerStack.profile("purchaseItem: ", 
+ *       new UtilTimerStack.ProfilingBlock<String>() {
+ *            public String doProfiling() {
+ *               // do some code
+ *               return "Ok";
+ *            }
+ *       });
+ * </pre>
+ * 
+ * @version $Date$ $Id$
  */
 public class UtilTimerStack
 {
 
     // A reference to the current ProfilingTimerBean
-    private static ThreadLocal current = new ThreadLocal();
+    protected static ThreadLocal<ProfilingTimerBean> current = new ThreadLocal<ProfilingTimerBean>();
 
     /**
      * System property that controls whether this timer should be used or not.  Set to "true" activates
      */
     public static final String ACTIVATE_PROPERTY = "xwork.profile.activate";
 
-    public static final String MIN_TIME = "atlassian.profile.mintime";
+    /**
+     * System property that controls the min time, that if exceeded will cause a log (at INFO level) to be
+     * created.
+     */
+    public static final String MIN_TIME = "xwork.profile.mintime";
     
     private static final Log log = LogFactory.getLog(UtilTimerStack.class);
 
+    /**
+     * Create and start a performance profiling with the <code>name</code> given. Deal with 
+     * profile hierarchy automatically, so caller don't have to be concern about it.
+     * 
+     * @param name profile name
+     */
     public static void push(String name)
     {
         if (!isActive())
         current.set(newTimer);
     }
 
+    /**
+     * End a preformance profiling with the <code>name</code> given. Deal with
+     * profile hierarchy automatically, so caller don't have to be concern about it.
+     * 
+     * @param name profile name
+     */
     public static void pop(String name)
     {
         if (!isActive())
 
     }
 
+    /**
+     * Do a log (at INFO level) of the time taken for this particular profiling.
+     * 
+     * @param currentTimer profiling timer bean
+     */
     private static void printTimes(ProfilingTimerBean currentTimer)
     {
         log.info(currentTimer.getPrintable(getMinTime()));
     }
 
+    /**
+     * Get the min time for this profiling, it searches for a System property
+     * 'xwork.profile.mintime' and default to 0.
+     * 
+     * @return long
+     */
     private static long getMinTime()
     {
         try
         }
     }
 
+    /**
+     * Determine if profiling is being activated, by searching for a system property
+     * 'xwork.profile.activate', default to false (profiling is off).
+     * 
+     * @return
+     */
     public static boolean isActive()
     {
         return System.getProperty(ACTIVATE_PROPERTY) != null;
     }
 
+    /**
+     * Turn profiling on or off.
+     * 
+     * @param active
+     */
     public static void setActive(boolean active)
     {
         if (active)
             System.setProperty(ACTIVATE_PROPERTY, "true");
         else
-            System.setProperty(ACTIVATE_PROPERTY, null);
+        	System.clearProperty(ACTIVATE_PROPERTY);
     }
 
+
+    /**
+     * A convenience method that allows <code>block</code> of code subjected to profiling to be executed 
+     * and avoid the need of coding boiler code that does pushing (UtilTimeBean.push(...)) and 
+     * poping (UtilTimerBean.pop(...)) in a try ... finally ... block.
+     * 
+     * <p/>
+     * 
+     * Example of usage:
+     * <pre>
+     * 	 // we need a returning result
+     *   String result = UtilTimerStack.profile("purchaseItem: ", 
+     *       new UtilTimerStack.ProfilingBlock<String>() {
+     *            public String doProfiling() {
+     *               getMyService().purchaseItem(....)
+     *               return "Ok";
+     *            }
+     *       });
+     * </pre>
+     * or
+     * <pre>
+     *   // we don't need a returning result
+     *   UtilTimerStack.profile("purchaseItem: ", 
+     *       new UtilTimerStack.ProfilingBlock<String>() {
+     *            public String doProfiling() {
+     *               getMyService().purchaseItem(....)
+     *               return null;
+     *            }
+     *       });
+     * </pre>
+     * 
+     * @param <T> any return value if there's one.
+     * @param name profile name
+     * @param block code block subjected to profiling
+     * @return T
+     * @throws Exception
+     */
+    public static <T> T profile(String name, ProfilingBlock<T> block) throws Exception {
+    	UtilTimerStack.push(name);
+    	try {
+    		return block.doProfiling();
+    	}
+    	finally {
+    		UtilTimerStack.pop(name);
+    	}
+    }
+    
+    /**
+     * A callback interface where code subjected to profile is to be executed. This eliminates the need
+     * of coding boiler code that does pushing (UtilTimerBean.push(...)) and poping (UtilTimerBean.pop(...))
+     * in a try ... finally ... block.
+     * 
+     * @version $Date$ $Id$
+     * 
+     * @param <T>
+     */
+    public static interface ProfilingBlock<T> {
+    	
+    	/**
+    	 * Method that execute the code subjected to profiling.
+    	 * 
+    	 * @return
+    	 * @throws Exception
+    	 */
+    	T doProfiling() throws Exception;
+    }
 }

File src/test/com/opensymphony/xwork2/util/profiling/ProfilingTimerBeanTest.java

View file
+/*
+ * Copyright (c) 2002-2006 by OpenSymphony
+ * All rights reserved.
+ */
+package com.opensymphony.xwork2.util.profiling;
+
+import junit.framework.TestCase;
+
+/**
+ * 
+ * @author tm_jee
+ * @version $Date$ $Id$
+ */
+public class ProfilingTimerBeanTest extends TestCase {
+	
+	public void testAddChild() throws Exception {
+		ProfilingTimerBean bean0 = new ProfilingTimerBean("bean0");
+		ProfilingTimerBean bean1 = new ProfilingTimerBean("bean1");
+		ProfilingTimerBean bean2 = new ProfilingTimerBean("bean2");
+		ProfilingTimerBean bean3 = new ProfilingTimerBean("bean3");
+		ProfilingTimerBean bean4 = new ProfilingTimerBean("bean4");
+		ProfilingTimerBean bean5 = new ProfilingTimerBean("bean5");
+		ProfilingTimerBean bean6 = new ProfilingTimerBean("bean6");
+		ProfilingTimerBean bean7 = new ProfilingTimerBean("bean7");
+		ProfilingTimerBean bean8 = new ProfilingTimerBean("bean8");
+		
+		/*  bean0
+		 *    + bean1
+		 *       + bean2
+		 *    + bean3
+		 *       + bean4
+		 *         + bean5
+		 *           + bean6
+		 *       +bean7
+		 *    + bean8
+		 */
+		
+		bean0.addChild(bean1);
+		bean0.addChild(bean3);
+		bean0.addChild(bean8);
+		
+		bean1.addChild(bean2);
+		
+		bean3.addChild(bean4);
+		bean3.addChild(bean7);
+		
+		bean4.addChild(bean5);
+		
+		bean5.addChild(bean6);
+		
+		
+		// bean0
+		assertNull(bean0.getParent());
+		assertEquals(bean0.children.size(), 3);
+		assertTrue(bean0.children.contains(bean1));
+		assertTrue(bean0.children.contains(bean3));
+		assertTrue(bean0.children.contains(bean8));
+		
+		// bean1
+		assertEquals(bean1.getParent(), bean0);
+		assertEquals(bean1.children.size(), 1);
+		assertTrue(bean1.children.contains(bean2));
+		
+		// bean2
+		assertEquals(bean2.getParent(), bean1);
+		assertEquals(bean2.children.size(), 0);
+		
+		// bean3
+		assertEquals(bean3.getParent(), bean0);
+		assertEquals(bean3.children.size(), 2);
+		assertTrue(bean3.children.contains(bean4));
+		assertTrue(bean3.children.contains(bean7));
+		
+		// bean4
+		assertEquals(bean4.getParent(), bean3);
+		assertEquals(bean4.children.size(), 1);
+		assertTrue(bean4.children.contains(bean5));
+		
+		// bean5
+		assertEquals(bean5.getParent(), bean4);
+		assertEquals(bean5.children.size(), 1);
+		assertTrue(bean5.children.contains(bean6));
+		
+		// bean6
+		assertEquals(bean6.getParent(), bean5);
+		assertEquals(bean6.children.size(), 0);
+		
+		// bean7
+		assertEquals(bean7.getParent(), bean3);
+		assertEquals(bean7.children.size(), 0);
+		
+		// bean8
+		assertEquals(bean8.getParent(), bean0);
+		assertEquals(bean8.children.size(), 0);
+	}
+	
+	public void testTime() throws Exception {
+		ProfilingTimerBean bean0 = new ProfilingTimerBean("bean0");
+		bean0.setStartTime();
+		Thread.sleep(1050);
+		bean0.setEndTime();
+		assertTrue(bean0.totalTime >= 1000);
+	}
+	
+	public void testPrint() throws Exception {
+		ProfilingTimerBean bean0 = new ProfilingTimerBean("bean0");
+		bean0.setStartTime();
+		Thread.sleep(1050);
+		bean0.setEndTime();
+		assertEquals(bean0.getPrintable(2000), "");
+		assertTrue(bean0.getPrintable(500).length() > 0);
+	}
+}

File src/test/com/opensymphony/xwork2/util/profiling/UtilTimerStackTest.java

View file
+/*
+ * Copyright (c) 2002-2006 by OpenSymphony
+ * All rights reserved.
+ */
+package com.opensymphony.xwork2.util.profiling;
+
+import junit.framework.TestCase;
+
+/**
+ * 
+ * @author tmjee
+ * @version $Date$ $Id$
+ */
+public class UtilTimerStackTest extends TestCase {
+
+	protected String activateProp;
+	protected String minTimeProp;
+	
+	
+	public void testActivateInactivate() throws Exception {
+		UtilTimerStack.setActive(true);
+		assertTrue(UtilTimerStack.isActive());
+		UtilTimerStack.setActive(false);
+		assertFalse(UtilTimerStack.isActive());
+	}
+	
+	
+	public void testPushPop() throws Exception {
+		UtilTimerStack.push("p1");
+		Thread.sleep(1050);
+		ProfilingTimerBean bean = UtilTimerStack.current.get();
+		assertTrue(bean.startTime > 0);
+		UtilTimerStack.pop("p1");
+		assertTrue(bean.totalTime > 1000);
+	}
+	
+	
+	
+	
+	public void testProfileCallback() throws Exception {
+		
+			MockProfilingBlock<String> block = new MockProfilingBlock<String>() {
+				public String performProfiling() throws Exception {
+					Thread.sleep(1050);
+					return "OK";
+				}
+			};
+			String result = UtilTimerStack.profile("p1", block);
+			assertEquals(result, "OK");
+			assertNotNull(block.getProfilingTimerBean());
+			assertTrue(block.getProfilingTimerBean().totalTime >= 1000);
+		
+	}
+	
+	
+	public void testProfileCallbackThrowsException() throws Exception {
+		try {
+			UtilTimerStack.profile("p1", 
+					new UtilTimerStack.ProfilingBlock<String>() {
+						public String doProfiling() throws Exception {
+							throw new RuntimeException("test");
+						}
+					});
+			fail("exception should have been thrown");
+		}
+		catch(Exception e) {
+			assertTrue(true);
+		}
+	}
+	
+	
+	@Override
+	protected void setUp() throws Exception {
+		super.setUp();
+		
+		activateProp = System.getProperty(UtilTimerStack.ACTIVATE_PROPERTY);
+		minTimeProp = System.getProperty(UtilTimerStack.MIN_TIME);
+		
+		System.setProperty(UtilTimerStack.ACTIVATE_PROPERTY, "true");
+		System.setProperty(UtilTimerStack.MIN_TIME, "0");
+	}
+	
+	
+	@Override
+	protected void tearDown() throws Exception {
+		
+		if (activateProp != null) {
+			System.setProperty(UtilTimerStack.ACTIVATE_PROPERTY, activateProp);
+		}
+		else {
+			System.clearProperty(UtilTimerStack.ACTIVATE_PROPERTY);
+		}
+		if (minTimeProp != null) {
+			System.setProperty(UtilTimerStack.MIN_TIME, minTimeProp);
+		}
+		else {
+			System.clearProperty(UtilTimerStack.ACTIVATE_PROPERTY);
+		}
+		
+		
+		activateProp = null;
+		minTimeProp = null;
+		
+		super.tearDown();
+	}
+	
+	
+	
+	public abstract class MockProfilingBlock<T> implements UtilTimerStack.ProfilingBlock<T> {
+		
+		private ProfilingTimerBean bean;
+		
+		public T doProfiling() throws Exception {
+			bean = UtilTimerStack.current.get();
+			return performProfiling();
+		}
+		
+		public ProfilingTimerBean getProfilingTimerBean() {
+			return bean;
+		}
+		
+		public abstract T performProfiling() throws Exception;
+	}
+}
+
+