Web Scripts executing slowly

[eagledelta1]

Hi, I am currently working on moving our alfresco server from a local Ubuntu VM to a RHEL5 VM at our datacenter.

So far everything has worked great, except for one script that execute when metadata is added to a document in a specific folder.

This script:

var descT = '';
var fieldA = ['Onum','PO'];

for (var j=0; j<fieldA.length ;j++) 
   {
      var curField = document.properties[("kb:"+ fieldA[j])];
      if(curField  !== undefined && curField  !== ''  && curField  !== null)
      {
         var query = 'PATH:"/app:company_home/st:sites/cm:Operations/cm:documentLibrary//*"'+ 'AND ASPECT:"kb:referencable" AND ';
         query+= '@kb\\:' + fieldA[j]+ ':\" ' + curField + ' \"';
         var searchRes = search.luceneSearch(query);

         for (var i=1; i<searchRes.length; i++)
         {
         if (searchRes[0].properties[("kb:"+ fieldA[j])] == searchRes[i].properties[("kb:"+ fieldA[j])] )
          { if(descT!==''){descT += ' and ';};
            descT += fieldA[j] + ':  ' + searchRes[i].properties[("kb:"+ fieldA[j])]+ '\r\n';}
         }
      }
   }


if(descT=='')
{
 document.removeAspect("kb:dupli");
 if(document.properties["kb:Otype"] == 'PO')
 {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("01. POs to Sort")); }
 
  if(document.properties["kb:Otype"] == 'Easy Order')
 {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("02. Easy Orders to Enter")); }
 
  if(document.properties["kb:Otype"] == 'Tradeshow')
 {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("04. TS Orders to Enter")); }
 
  if(document.properties["kb:Otype"] == 'Workshop')
 {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("03. WS Orders to Enter")); }
 
  if(document.properties["kb:Otype"] == 'N/A')
 {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("04. Other Orders to Enter")); }
}else
{
  if(document.properties["kb:DupIgn"] == true)
 {
     document.removeAspect("kb:dupli");
    if(document.properties["kb:Otype"] == 'PO')
    {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("01. POs to Sort")); }

     if(document.properties["kb:Otype"] == 'Easy Order')
    {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("02. Easy Orders to Enter")); }

     if(document.properties["kb:Otype"] == 'Tradeshow')
    {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("04. TS Orders to Enter")); }

     if(document.properties["kb:Otype"] == 'Workshop')
    {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("03. WS Orders to Enter")); }

     if(document.properties["kb:Otype"] == 'N/A')
    {  document.move(space.parent.childByNamePath("02. Orders to Enter").childByNamePath("04. Other Orders to Enter")); }
 }else
 {
  descT = '' + descT;
  document.properties["kb:DupRecord"] = descT;
  var newDesc = new Array(1);
  newDesc ["kb:DupRecord"] = descT;
  if(document.hasAspect("kb:dupli") == false)
 { document.addAspect("kb:dupli", newDesc);}
 }
}
  document.save();
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Checks for duplicates and also moves the document to the appropriate folder based off the data in the metadata.

The problem I'm having is that on the current live server it executes immediately, but on the test server it takes 10 seconds to run (I've verified this through debug logs).  Any idea what may be causing this?


Here is the log from the Test Server when the script is executed:

11:15:20,209 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Writing Transactional response: size=144647
11:15:20,209 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] Response status code: 200
11:15:20,209 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] Response encoding: Content-Type: application/x-shockwave-flash;charset=UTF-8

11:15:20,210 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Authentication reset: unauthenticated
11:15:20,210 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] Web Script org/alfresco/repository/thumbnail/thumbnail.get executed in 15.045ms
11:15:20,210 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] Processed script url (GET) /api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42/content/thumbnails/webpreview in 15.306ms
11:15:20,315 DEBUG [org.springframework.extensions.webscripts.connector.AuthenticatingConnector] Received 200 on first call to: /api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42/content/thumbnails/webpreview?c=force&noCacheToken=1343664920715
11:15:20,315 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController] Return code: 200
11:15:29,207 DEBUG [org.alfresco.repo.activities.feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController] EndPointProxyController preparing to proxy:
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController]  - endpointId: alfresco
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController]  - userId: admin
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController]  - connector: http://localhost:8080/alfresco/s - {cleartextUsername=admin, cleartextPassword=admin}
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController]  - method: POST
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController]  - url: /api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42/formprocessor
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] Executing (POST) http://localhost:8080/alfresco/s/api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42...
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient]  - InputStream supplied - will push…
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient]  - OutputStream supplied - will stream response…
11:15:36,865 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient]  - Full Proxy mode between servlet request and response…
11:15:36,866 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] Set content-type=application/json
11:15:36,866 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] POST entity content-length=117
11:15:36,867 DEBUG [org.springframework.extensions.webscripts.servlet.WebScriptServlet] Processing request (POST) http://localhost:8080/alfresco/s/api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42...
11:15:36,867 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] (Runtime=ServletRuntime, Container=Repository) Processing script url (POST) /api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42/formprocessor
11:15:36,867 DEBUG [org.springframework.extensions.webscripts.servlet.WebScriptServletRequest] Content Type: application/json
11:15:36,867 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] Agent: null
11:15:36,867 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] Invoking Web Script org/alfresco/repository/forms/form.post (format json, style: any, default: json)
11:15:36,867 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Current authentication: unauthenticated
11:15:36,867 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Authentication required: user
11:15:36,867 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Guest login requested: false
11:15:36,867 DEBUG [org.alfresco.repo.web.scripts.servlet.BasicHttpAuthenticatorFactory$BasicHttpAuthenticator] HTTP Authorization provided: false
11:15:36,867 DEBUG [org.alfresco.repo.web.scripts.servlet.BasicHttpAuthenticatorFactory$BasicHttpAuthenticator] URL ticket provided: true
11:15:36,867 DEBUG [org.alfresco.repo.web.scripts.servlet.BasicHttpAuthenticatorFactory$BasicHttpAuthenticator] Authenticating (URL argument) ticket TICKET_4c5e844c1ac9b09a77f1ae3b1142ae197ac641fc
11:15:36,872 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Authentication: authenticated as admin
11:15:36,872 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Begin retry transaction block: required,readwrite
11:15:36,872 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Creating Transactional Response for ReadWrite transaction; buffersize=4096
11:15:36,872 DEBUG [org.springframework.extensions.webscripts.DeclarativeWebScript] Executing script classpath*:alfresco/extension/templates/webscripts/org/alfresco/repository/forms/form.post.json.js
11:15:36,875 DEBUG [org.alfresco.repo.jscript.ScriptLogger] json form submission for item:
11:15:36,875 DEBUG [org.alfresco.repo.jscript.ScriptLogger]     kind = node
11:15:36,875 DEBUG [org.alfresco.repo.jscript.ScriptLogger]     id = workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42
11:15:36,877 DEBUG [org.alfresco.repo.forms.FormServiceImpl] Saving form for item '[node]workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42': org.alfresco.repo.forms.FormData@6da8e1ac (data={prop_kb_Otype=org.alfresco.repo.forms.FormData$FieldData@6a781b72 (name=prop_kb_Otype, value=PO, isFile=false), prop_kb_CheqNo=org.alfresco.repo.forms.FormData$FieldData@73520ff9 (name=prop_kb_CheqNo, value=, isFile=false), prop_kb_PO=org.alfresco.repo.forms.FormData$FieldData@1096df95 (name=prop_kb_PO, value=7984687461, isFile=false), prop_kb_Company=org.alfresco.repo.forms.FormData$FieldData@2130b7b5 (name=prop_kb_Company, value=Test, isFile=false), prop_kb_Zcode=org.alfresco.repo.forms.FormData$FieldData@56cdd19 (name=prop_kb_Zcode, value=68114, isFile=false)})
11:15:36,877 DEBUG [org.alfresco.repo.forms.processor.AbstractFormProcessor] Checking processor org.alfresco.repo.forms.processor.node.NodeFormProcessor@14c55ea (active=true, matchPattern=node) for applicability for item '[node]workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42', result = true
11:15:36,877 DEBUG [org.alfresco.repo.forms.processor.FormProcessorRegistry] Returning applicable processor: org.alfresco.repo.forms.processor.node.NodeFormProcessor@14c55ea (active=true, matchPattern=node)
11:15:36,877 DEBUG [org.alfresco.repo.forms.processor.FilterRegistry] Returning active filters: []
11:15:36,877 DEBUG [org.alfresco.repo.forms.processor.node.NodeFormProcessor] Persisting form for: workspace://SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42
11:15:36,878 DEBUG [org.alfresco.repo.forms.processor.node.NodeFormProcessor] Processing field org.alfresco.repo.forms.FormData$FieldData@6a781b72 (name=prop_kb_Otype, value=PO, isFile=false) for property persistence
11:15:36,878 DEBUG [org.alfresco.repo.forms.processor.node.NodeFormProcessor] Processing field org.alfresco.repo.forms.FormData$FieldData@73520ff9 (name=prop_kb_CheqNo, value=, isFile=false) for property persistence
11:15:36,878 DEBUG [org.alfresco.repo.forms.processor.node.NodeFormProcessor] Processing field org.alfresco.repo.forms.FormData$FieldData@1096df95 (name=prop_kb_PO, value=7984687461, isFile=false) for property persistence
11:15:36,878 DEBUG [org.alfresco.repo.forms.processor.node.NodeFormProcessor] Processing field org.alfresco.repo.forms.FormData$FieldData@2130b7b5 (name=prop_kb_Company, value=Test, isFile=false) for property persistence
11:15:36,878 DEBUG [org.alfresco.repo.forms.processor.node.NodeFormProcessor] Processing field org.alfresco.repo.forms.FormData$FieldData@56cdd19 (name=prop_kb_Zcode, value=68114, isFile=false) for property persistence
11:15:36,973 DEBUG [org.alfresco.repo.forms.processor.FilterRegistry] Returning active filters: []
11:15:36,973 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Time to execute script: 98.793ms
11:15:36,973 DEBUG [org.springframework.extensions.webscripts.AbstractWebScript] Executed script classpath*:alfresco/extension/templates/webscripts/org/alfresco/repository/forms/form.post.json.js in 98.907ms
11:15:36,974 DEBUG [org.springframework.extensions.webscripts.servlet.WebScriptServletResponse] Cache - set response header Cache-Control: no-cache
11:15:36,974 DEBUG [org.springframework.extensions.webscripts.servlet.WebScriptServletResponse] Cache - set response header Pragma: no-cache
11:15:36,974 DEBUG [org.springframework.extensions.webscripts.DeclarativeWebScript] Rendering response: content type=application/json, status=200
11:15:36,974 DEBUG [org.springframework.extensions.webscripts.DeclarativeWebScript] Rendering template 'org/alfresco/repository/forms/form.post.json'
11:15:36,976 DEBUG [org.springframework.extensions.webscripts.AbstractWebScript] Rendered template org/alfresco/repository/forms/form.post.json in 1.626ms
11:15:36,976 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] End retry transaction block: required,readwrite
11:15:36,984 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Imports resolved, adding resource '_root
11:15:37,003 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Time to execute script: 16.451ms
11:15:37,012 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Imports resolved, adding resource '_root
11:15:37,025 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Time to execute script: 11.76ms
11:15:37,034 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Imports resolved, adding resource '_root
11:15:47,041 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Time to execute script: 10001.479ms
11:15:47,048 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Imports resolved, adding resource '_root
11:15:47,065 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Time to execute script: 13.987ms
11:15:47,074 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Imports resolved, adding resource '_root
11:15:47,089 DEBUG [org.alfresco.repo.jscript.RhinoScriptProcessor] Time to execute script: 13.267ms
11:15:47,200 DEBUG [org.alfresco.repo.web.scripts.RepositoryContainer] Authentication reset: unauthenticated
11:15:47,200 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] Web Script org/alfresco/repository/forms/form.post executed in 10332.5ms
11:15:47,200 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] Processed script url (POST) /api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42/formprocessor in 10332.734ms
11:15:47,200 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] Response status code: 200
11:15:47,200 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] Response encoding: Content-Type: application/json;charset=UTF-8

11:15:47,200 DEBUG [org.springframework.extensions.webscripts.connector.AuthenticatingConnector] Received 200 on first call to: /api/node/workspace/SpacesStore/db9c77c5-739a-43b3-bdd2-d7be1347af42/formprocessor
11:15:47,201 DEBUG [org.springframework.extensions.webscripts.servlet.mvc.EndPointProxyController] Return code: 200
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Here are the specs for the two servers:

Live:
Ubuntu 10.04.4
4GB RAM
100GB VHD (92% used)
4 core CPU


Test (will be live when finished):
RHEL 5
8GB RAM
8 core CPU
300GB VHD

[eagledelta1]

Is there no one with any sort of answer, suggestion or even question?

[afaust]

Hello,

you should keep in mind that Lucene PATH queries, especially one for "..//*", can take a very long time depending on the state, content and I/O performance of the index. Until there is more information, I'd bet on this as my most-likely suspect, since you perform this type of search in a loop none the less.

I'd suggest adding some logging to your web script in order to measure what individual part of it executes slowly. So, you should at least put some simple log statements at the begin and end of your loop, and before / after you execute the search.

Regards
Axel

[mrogers]

It may also be worth you experimenting with removing that path statement - or do you have other sites containing kb:referenceable?

Another approach is to use 4.0 and SOLR which doesn't have the problems with paths.