Author: bpoussin Date: 2010-12-02 19:00:04 +0100 (Thu, 02 Dec 2010) New Revision: 553 Url: http://nuiton.org/repositories/revision/wikitty/553 Log: Evolution #1130: Add call time in proxy to trace long method execution - refactore some method to suppress return in middle of method Modified: trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyConfig.java trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyProxy.java Modified: trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyConfig.java =================================================================== --- trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyConfig.java 2010-12-02 15:44:03 UTC (rev 552) +++ trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyConfig.java 2010-12-02 18:00:04 UTC (rev 553) @@ -287,8 +287,17 @@ "wikitty.service.slave.master.xmpp.room", _("Room to use for synchronization with master," + " this room must have history activated"), - "test@conference.im.codelutin.com", String.class, false, false); + "test@conference.im.codelutin.com", String.class, false, false), + WIKITTY_PROXY_TIME_TO_LOG_INFO( + "wikitty.proxy.timeToLog.info", + _("maximum time before send log info with time consumed"), + "5000", Integer.class, false, false), + WIKITTY_PROXY_TIME_TO_LOG_WARN( + "wikitty.proxy.timeToLog.warn", + _("maximum time before send log warn with time consumed"), + "1000", Integer.class, false, false); + public String key; public String description; public String defaultValue; Modified: trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyProxy.java =================================================================== --- trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyProxy.java 2010-12-02 15:44:03 UTC (rev 552) +++ trunk/wikitty-api/src/main/java/org/nuiton/wikitty/WikittyProxy.java 2010-12-02 18:00:04 UTC (rev 553) @@ -43,6 +43,10 @@ import java.util.Map; import java.util.Map.Entry; import java.util.Set; +import org.apache.commons.lang.mutable.MutableLong; +import org.apache.commons.lang.time.DurationFormatUtils; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.nuiton.wikitty.entities.WikittyTreeNode; import org.nuiton.wikitty.search.operators.Element; @@ -62,6 +66,33 @@ */ public class WikittyProxy { + /** to use log facility, just put in your code: log.info(\"...\"); */ + static private Log log = LogFactory.getLog(WikittyProxy.class); + + static public class CallStat { + long callNumber = 0; + long callTime = 0; + + @Override + public String toString() { + String callTimeString = + DurationFormatUtils.formatDuration(callTime, "s'.'S"); + String avgTimeString = + DurationFormatUtils.formatDuration((callTime/ callNumber), "s'.'S"); + return String.format("total call %s, total time %s, avg time %s", + callNumber, callTimeString, avgTimeString); + } + + } + + /** time to trigger log time in info level */ + protected long timeToLogInfo = 1000; + /** time to trigger log time in warn level */ + protected long timeToLogWarn = 3000; + + /** for each method of all proxies, keep number of call */ + static protected Map<String, CallStat> callCount = new HashMap<String, CallStat>(); + /** Delegated wikitty service. */ protected WikittyServiceEnhanced wikittyService; @@ -76,9 +107,17 @@ * Empty constructor (uninitialized wikittyService). */ public WikittyProxy() { - } + public WikittyProxy(WikittyConfig config) { + if (config != null) { + timeToLogInfo = config.getOptionAsInt(WikittyConfig.WikittyOption. + WIKITTY_PROXY_TIME_TO_LOG_INFO.getKey()); + timeToLogWarn = config.getOptionAsInt(WikittyConfig.WikittyOption. + WIKITTY_PROXY_TIME_TO_LOG_WARN.getKey()); + } + } + /** * Constructor with wikittyService. * @@ -89,14 +128,57 @@ setWikittyService(wikittyService); } + public WikittyProxy(WikittyConfig config, WikittyService wikittyService) { + this(config); + setWikittyService(wikittyService); + } + + static public Map<String, CallStat> getCallCount() { + return callCount; + } + + protected void traceTime(long start, long stop, String methodName) { + long time = stop - start; + + // incremente le nombre d'appel pour cette methode + CallStat calls = callCount.get(methodName); + if (calls == null) { + // is not thread safe, but if we lose one or two call, is not importante + calls = new CallStat(); + callCount.put(methodName, calls); + } + calls.callNumber++; + calls.callTime += time; + + // affiche le temps de l'appel si necessaire + String timeString = DurationFormatUtils.formatDuration(time, "s'.'S"); + String msg = String.format("[%s] for method %s (%s)", + timeString, methodName, calls); + + if (time > timeToLogWarn && log.isWarnEnabled()) { + log.warn(msg); + } else if (time > timeToLogInfo && log.isInfoEnabled()) { + log.info(msg); + } else if (log.isDebugEnabled()) { + log.debug(msg); + } + + } + public String login(String login, String password) { + long start = System.currentTimeMillis(); String result = wikittyService.login(login, password); setSecurityToken(result); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "login"); return result; } public void logout() { + long start = System.currentTimeMillis(); wikittyService.logout(securityToken); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "logout"); } public String getSecurityToken() { @@ -124,22 +206,26 @@ * @return new instance of object wanted */ public <E extends BusinessEntity> E cast(BusinessEntity source, Class<E> target) { + long start = System.currentTimeMillis(); E result = WikittyUtil.newInstance( securityToken, wikittyService, target, ((BusinessEntityImpl)source).getWikitty()); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "cast"); return result; } public <E extends BusinessEntity> E store(E e) { Wikitty w = ((BusinessEntityImpl)e).getWikitty(); - WikittyEvent resp = wikittyService.store(securityToken, w); - // update object - resp.update(w); + w = store(w); return e; } public Wikitty store(Wikitty w) { + long start = System.currentTimeMillis(); WikittyEvent resp = wikittyService.store(securityToken, w); // update object resp.update(w); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "store"); return w; } @@ -152,6 +238,7 @@ * @return updated objects list */ public <E extends BusinessEntity> List<E> store(List<E> objets) { + long start = System.currentTimeMillis(); // prepare data to send to service List<Wikitty> wikitties = new ArrayList<Wikitty>(objets.size()); for (E e : objets) { @@ -166,6 +253,8 @@ for (Wikitty w : wikitties) { resp.update(w); } + long stop = System.currentTimeMillis(); + traceTime(start, stop, "store<list>"); return objets; } @@ -180,42 +269,45 @@ * @return wikitty entity with specified id or {@code null} if entity can't be found */ public <E extends BusinessEntity> E restore(Class<E> clazz, String id, boolean checkExtension) { - if (id == null) { - return null; - } - E result = null; - HashSet<String> extNames = null; try { - Wikitty wikitty = wikittyService.restore(securityToken, id); - if(wikitty == null) { - return null; + long start = System.currentTimeMillis(); + E result = null; + if (id != null) { + HashSet<String> extNames = null; + + Wikitty wikitty = wikittyService.restore(securityToken, id); + if (wikitty != null) { + if (checkExtension) { + extNames = new HashSet<String>(wikitty.getExtensionNames()); + } + result = WikittyUtil.newInstance( + securityToken, wikittyService, clazz, wikitty); + + if (checkExtension) { + // WikittyUtil.newInstance instanciate only BusinessEntityWikittyImpl + BusinessEntityImpl b = (BusinessEntityImpl) result; + Collection<WikittyExtension> BusinessEntityStaticExtensions = b.getStaticExtensions(); + for (WikittyExtension ext : BusinessEntityStaticExtensions) { + String extensionName = ext.getName(); + if (!extNames.contains(extensionName)) { + // extension wanted by BusinessEntity (clazz) + // is not in wikitty, then wikitty is not good type + // for business + result = null; + break; + } + } + } + } } - - if (checkExtension) { - extNames = new HashSet<String>(wikitty.getExtensionNames()); - } - result = WikittyUtil.newInstance( - securityToken, wikittyService, clazz, wikitty); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restore<Business>"); + return result; } catch (SecurityException eee) { throw eee; } catch (Exception eee) { throw new WikittyException("Can't restore wikitty", eee); } - if (checkExtension) { - // WikittyUtil.newInstance instanciate only BusinessEntityWikittyImpl - BusinessEntityImpl b = (BusinessEntityImpl)result; - Collection<WikittyExtension> BusinessEntityStaticExtensions = b.getStaticExtensions(); - for (WikittyExtension ext : BusinessEntityStaticExtensions) { - String extensionName = ext.getName(); - if (!extNames.contains(extensionName)) { - // extension wanted by BusinessEntity (clazz) - // is not in wikitty, then wikitty is not good type - // for business - return null; - } - } - } - return result; } /** @@ -225,12 +317,14 @@ * @return wikitty entity with specified id or {@code null} if entity can't be found */ public Wikitty restore(String id) { - if (id == null) { - return null; + long start = System.currentTimeMillis(); + Wikitty result = null; + if (id != null) { + result = wikittyService.restore(securityToken, id); } - - Wikitty wikitty = wikittyService.restore(securityToken, id); - return wikitty; + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restore"); + return result; } /** @@ -257,6 +351,7 @@ */ public <E extends BusinessEntity> List<E> restore( Class<E> clazz, List<String> id, boolean checkExtension) { + long start = System.currentTimeMillis(); List<Wikitty> wikitties = wikittyService.restore(securityToken, id); List<E> result = new ArrayList<E>(); @@ -276,12 +371,21 @@ // extension wanted by BusinessEntity (clazz) // is not in wikitty, then wikitty is not good type // for business - return null; + result = null; + break; } } + // le break au dessus permet de soritr d'une boucle + // met si result est null il faut sortir de la methode et donc + // sortir de la deuxieme boucle + if (result == null) { + break; + } } result.add(dto); } + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restore<list>"); return result; } @@ -291,11 +395,17 @@ } public void delete(String id) { + long start = System.currentTimeMillis(); wikittyService.delete(securityToken, id); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "delete"); } public void delete(Collection<String> ids) { + long start = System.currentTimeMillis(); wikittyService.delete(securityToken, ids); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "delete<list>"); } /** @@ -309,6 +419,7 @@ */ public <E extends BusinessEntityImpl> PagedResult<E> findAllByExample(E e, int firstIndex, int endIndex, String ... fieldFacet ) { + long start = System.currentTimeMillis(); Criteria criteria = Search.query(e.getWikitty()).criteria() .setFirstIndex(firstIndex).setEndIndex(endIndex) @@ -320,6 +431,8 @@ // restriction on extension PagedResult<E> result = (PagedResult<E>)pagedResult.cast( this, e.getClass(), true); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "findAllByExample<limit>"); return result; } @@ -330,6 +443,7 @@ * @return */ public <E extends BusinessEntityImpl> E findByExample(E e) { + long start = System.currentTimeMillis(); Criteria criteria = Search.query(e.getWikitty()).criteria(); Wikitty w = wikittyService.findByCriteria(securityToken, criteria); @@ -338,6 +452,8 @@ result = (E) WikittyUtil.newInstance( securityToken, wikittyService, e.getClass(), w); } + long stop = System.currentTimeMillis(); + traceTime(start, stop, "findByExample"); return result; } @@ -353,6 +469,7 @@ */ public <E extends BusinessEntity> PagedResult<E> findAllByCriteria( Class<E> clazz, Criteria criteria) { + long start = System.currentTimeMillis(); // newInstance only return BusinessEntityWikittyImpl BusinessEntityImpl sample = @@ -407,16 +524,22 @@ // on extension PagedResult<E> result = (PagedResult<E>)pagedResult.cast( this, sample.getClass(), true); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "findAllByCriteria<Business>"); return result; } public PagedResult<Wikitty> findAllByCriteria(Criteria criteria) { + long start = System.currentTimeMillis(); PagedResult<String> resultId = wikittyService.findAllByCriteria(securityToken, criteria); PagedResult<Wikitty> result = resultId.cast(securityToken, wikittyService); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "findAllByCriteria"); return result; } public <E extends BusinessEntity> E findByCriteria(Class<E> clazz, Criteria criteria) { + long start = System.currentTimeMillis(); BusinessEntityImpl sample = (BusinessEntityImpl)WikittyUtil.newInstance(clazz); @@ -430,16 +553,24 @@ Wikitty w = wikittyService.findByCriteria(securityToken, criteria); E result = WikittyUtil.newInstance( securityToken, wikittyService, clazz, w); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "findByCriteria<Business>"); return result; } public Wikitty findByCriteria(Criteria criteria) { + long start = System.currentTimeMillis(); Wikitty wikitty = wikittyService.findByCriteria(securityToken, criteria); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "findByCriteria"); return wikitty; } public WikittyTree restoreTree(String wikittyId) { + long start = System.currentTimeMillis(); WikittyTree result = wikittyService.restoreTree(securityToken, wikittyId); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restoreTree"); return result; } @@ -450,7 +581,10 @@ * @return {@true} if at least one node has been deleted */ public WikittyEvent deleteTree(String treeNodeId) { + long start = System.currentTimeMillis(); WikittyEvent result = wikittyService.deleteTree(securityToken,treeNodeId); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "deleteTree"); return result; } @@ -462,19 +596,19 @@ public <E extends BusinessEntity> Map.Entry<E, Integer> restoreNode( Class<E> clazz, String wikittyId, Criteria filter, boolean checkExtension) { + long start = System.currentTimeMillis(); + Map.Entry<E, Integer> result = null; + Map.Entry<WikittyTreeNode, Integer> node = wikittyService.restoreNode( securityToken, wikittyId, filter); - if(node == null) { - return null; + if (node != null) { + E bean = restore(clazz, wikittyId, checkExtension); + if (bean != null) { + result = new HashMap.SimpleEntry<E, Integer>(bean, node.getValue()); + } } - - E bean = restore(clazz, wikittyId, checkExtension); - if(bean == null) { - return null; - } - - Map.Entry<E, Integer> result = - new HashMap.SimpleEntry<E, Integer>(bean, node.getValue()); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restoreNode"); return result; } @@ -486,99 +620,114 @@ public <E extends BusinessEntity> Map<E, Integer> restoreChildren( Class<E> clazz, String wikittyId, Criteria filter, boolean checkExtension) { + long start = System.currentTimeMillis(); + + Map<E, Integer> convertedResult = null; Map<WikittyTreeNode, Integer> result = wikittyService.restoreChildren( securityToken, wikittyId, filter); - if(result == null) { - return null; - } - Map<E, Integer> convertedResult = new LinkedHashMap<E, Integer>(); - Set<Entry<WikittyTreeNode, Integer>> entries = result.entrySet(); - for (Entry<WikittyTreeNode, Integer> entry : entries) { + if(result != null) { + convertedResult = new LinkedHashMap<E, Integer>(); + Set<Entry<WikittyTreeNode, Integer>> entries = result.entrySet(); + for (Entry<WikittyTreeNode, Integer> entry : entries) { - WikittyTreeNode node = entry.getKey(); - - //TODO EC-20100420 was : String nodeId = node.getId(); - String nodeId = node.getWikittyId(); + WikittyTreeNode node = entry.getKey(); - E businessEntity = null; - HashSet<String> extNames = null; - try { - Wikitty wikitty = wikittyService.restore(securityToken, nodeId); - if(checkExtension) { - extNames = new HashSet<String>(wikitty.getExtensionNames()); + //TODO EC-20100420 was : String nodeId = node.getId(); + String nodeId = node.getWikittyId(); + + E businessEntity = null; + HashSet<String> extNames = null; + try { + Wikitty wikitty = wikittyService.restore(securityToken, nodeId); + if (checkExtension) { + extNames = new HashSet<String>(wikitty.getExtensionNames()); + } + businessEntity = WikittyUtil.newInstance( + securityToken, wikittyService, clazz, wikitty); + } catch (SecurityException eee) { + throw eee; + } catch (Exception eee) { + throw new WikittyException("Can't restore children", eee); } - businessEntity = WikittyUtil.newInstance( - securityToken, wikittyService, clazz, wikitty); - } catch (SecurityException eee) { - throw eee; - } catch (Exception eee) { - throw new WikittyException("Can't restore children", eee); - } - boolean goodType = true; - if(checkExtension) { - // WikittyUtil.newInstance instanciate only BusinessEntityWikittyImpl - BusinessEntityImpl businessEntityImpl = - (BusinessEntityImpl) businessEntity; - Collection<WikittyExtension> staticExtensions = - businessEntityImpl.getStaticExtensions(); + boolean goodType = true; + if (checkExtension) { + // WikittyUtil.newInstance instanciate only BusinessEntityWikittyImpl + BusinessEntityImpl businessEntityImpl = + (BusinessEntityImpl) businessEntity; + Collection<WikittyExtension> staticExtensions = + businessEntityImpl.getStaticExtensions(); - for (Iterator<WikittyExtension> iterator = - staticExtensions.iterator(); iterator.hasNext() && goodType;) { - WikittyExtension ext = iterator.next(); - if (!extNames.contains(ext.getName())) { - // extension wanted by BusinessEntity (clazz) - // is not in wikitty, then wikitty is not good type - // for business - goodType = false; + for (Iterator<WikittyExtension> iterator = + staticExtensions.iterator(); iterator.hasNext() && goodType;) { + WikittyExtension ext = iterator.next(); + if (!extNames.contains(ext.getName())) { + // extension wanted by BusinessEntity (clazz) + // is not in wikitty, then wikitty is not good type + // for business + goodType = false; + } } } - } - if(goodType) { - Integer nodeCount = entry.getValue(); - convertedResult.put(businessEntity, nodeCount); + if (goodType) { + Integer nodeCount = entry.getValue(); + convertedResult.put(businessEntity, nodeCount); + } } } + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restoreChildren"); return convertedResult; } public Wikitty restoreVersion(String wikittyId, String version) { + long start = System.currentTimeMillis(); Wikitty result = wikittyService.restoreVersion( securityToken, wikittyId, version); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restoreVersion"); return result; } public <E extends BusinessEntity> boolean hasType(Class<E> clazz, String wikittyId) { - E result = null; - HashSet<String> extNames = null; try { + long start = System.currentTimeMillis(); + + boolean result = true; + + E businessObject = null; + HashSet<String> extNames = null; Wikitty wikitty = wikittyService.restore(securityToken, wikittyId); if (wikitty == null) { - return false; + result = false; + } else { + extNames = new HashSet<String>(wikitty.getExtensionNames()); + businessObject = WikittyUtil.newInstance( + securityToken, wikittyService, clazz, wikitty); + // WikittyUtil.newInstance instanciate only BusinessEntityWikittyImpl + BusinessEntityImpl b = (BusinessEntityImpl) businessObject; + for (WikittyExtension ext : b.getStaticExtensions()) { + if (!extNames.contains(ext.getName())) { + // extension wanted by BusinessEntity (clazz) + // is not in wikitty, then wikitty is not good type + // for business + result = false; + break; + } + } } - extNames = new HashSet<String>(wikitty.getExtensionNames()); - result = WikittyUtil.newInstance( - securityToken, wikittyService, clazz, wikitty); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "hasType"); + return result; } catch (SecurityException eee) { throw eee; } catch (Exception eee) { throw new WikittyException( "Can't retrieve wikitty needed for hasType test", eee); } - // WikittyUtil.newInstance instanciate only BusinessEntityWikittyImpl - BusinessEntityImpl b = (BusinessEntityImpl)result; - for (WikittyExtension ext : b.getStaticExtensions()) { - if (!extNames.contains(ext.getName())) { - // extension wanted by BusinessEntity (clazz) - // is not in wikitty, then wikitty is not good type - // for business - return false; - } - } - return true; } /** @@ -588,8 +737,11 @@ * @return update response */ public WikittyEvent storeExtension(WikittyExtension ext) { + long start = System.currentTimeMillis(); WikittyEvent response = wikittyService.storeExtension(securityToken, ext); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "storeExtension"); return response; } @@ -600,8 +752,11 @@ * @return update response */ public WikittyEvent storeExtension(Collection<WikittyExtension> exts) { + long start = System.currentTimeMillis(); WikittyEvent response = wikittyService.storeExtension(securityToken, exts); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "storeExtension<list>"); return response; } @@ -612,7 +767,10 @@ * @return the corresponding object, exception if no such object found. */ public WikittyExtension restoreExtension(String extensionId) { + long start = System.currentTimeMillis(); WikittyExtension extension = wikittyService.restoreExtension(securityToken, extensionId); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restoreExtension"); return extension; } @@ -623,7 +781,10 @@ * @return the corresponding object, exception if no such object found. */ public WikittyExtension restoreExtensionLastVersion(String extensionName) { + long start = System.currentTimeMillis(); WikittyExtension extension = wikittyService.restoreExtensionLastVersion(securityToken, extensionName); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "restoreExtensionLastVersion"); return extension; } @@ -633,7 +794,10 @@ * @return extension id list */ public List<String> getAllExtensionIds() { + long start = System.currentTimeMillis(); List<String> result = wikittyService.getAllExtensionIds(securityToken); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "getAllExtensionIds"); return result; } @@ -645,7 +809,10 @@ * @return extensions */ public List<String> getAllExtensionsRequires(String extensionName) { + long start = System.currentTimeMillis(); List<String> result = wikittyService.getAllExtensionsRequires(securityToken, extensionName); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "getAllExtensionsRequires"); return result; } @@ -654,7 +821,10 @@ * This operation should be disabled in production environment. */ public WikittyEvent clear() { + long start = System.currentTimeMillis(); WikittyEvent result = wikittyService.clear(securityToken); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "clear"); return result; } @@ -665,7 +835,10 @@ * @return update response */ public void syncSearchEngine() { + long start = System.currentTimeMillis(); wikittyService.syncSearchEngine(securityToken); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "syncSearchEngine"); } /** @@ -674,7 +847,10 @@ * @return the wikitty encapsulated */ public Wikitty getWikitty(BusinessEntity entity){ + long start = System.currentTimeMillis(); Wikitty result = WikittyUtil.getWikitty(wikittyService, securityToken, entity); + long stop = System.currentTimeMillis(); + traceTime(start, stop, "getWikitty"); return result; }