0029905: Performance improvements in OrderLoader and Mobile.Core

diff --git a/src/org/openbravo/mobile/core/process/DataSynchronizationProcess.java b/src/org/openbravo/mobile/core/process/DataSynchronizationProcess.java
--- a/src/org/openbravo/mobile/core/process/DataSynchronizationProcess.java
+++ b/src/org/openbravo/mobile/core/process/DataSynchronizationProcess.java
@@ -165,6 +165,7 @@
   public JSONObject saveRecord(JSONArray jsonarray, boolean shouldFailWithError)
       throws JSONException {
     boolean error = false;
+    boolean obContextChanged = false;
     List<String> errorIds = new ArrayList<String>();
 
     OBContext cnx = OBContext.getOBContext();
@@ -185,6 +186,7 @@
         String orgId = jsonRecord.has("organization") ? jsonRecord.getString("organization")
             : currentOrg;
         if (!currentUser.equals(userId) || !currentOrg.equals(orgId)) {
+          obContextChanged = true;
           OBContext.setOBContext(userId, currentRole, OBContext.getOBContext().getCurrentClient()
               .getId(), orgId);
         }
@@ -234,6 +236,7 @@
               setImportEntryError(t);
             }
           } else {
+            // setImportEntryError is called in handleError
             handleError(t, this.getEntity(), result, jsonRecord);
           }
 
@@ -264,8 +267,10 @@
 
     } finally {
       OBContext.restorePreviousMode();
-      OBContext.setOBContext(originalUser, originalRole, OBContext.getOBContext()
-          .getCurrentClient().getId(), originalOrg);
+      if (obContextChanged) {
+        OBContext.setOBContext(originalUser, originalRole, OBContext.getOBContext()
+            .getCurrentClient().getId(), originalOrg);
+      }
       setImportEntryId(null);
     }
     JSONObject jsonResponse = new JSONObject();
diff --git a/src/org/openbravo/mobile/core/process/JSONProcessSimple.java b/src/org/openbravo/mobile/core/process/JSONProcessSimple.java
--- a/src/org/openbravo/mobile/core/process/JSONProcessSimple.java
+++ b/src/org/openbravo/mobile/core/process/JSONProcessSimple.java
@@ -37,15 +37,17 @@
         JSONObject response = new JSONObject(s);
         JSONObject contextInfo = getContextInformation();
         response.put("contextInfo", contextInfo);
-        OBContext.setAdminMode(false);
-        try {
-          final Map<String, Object> parameters = MobileCoreKernelUtils.getParameterMap(
-              RequestContext.getServletContext(), RequestContext.get().getRequest());
-          mobileStaticResourceComponent.setParameters(parameters);
-          response.put("sourceVersion",
-              mobileStaticResourceComponent.getGeneratedJavascriptFilename());
-        } finally {
-          OBContext.restorePreviousMode();
+        if (!(this instanceof DataSynchronizationImportProcess)) {
+          OBContext.setAdminMode(false);
+          try {
+            final Map<String, Object> parameters = MobileCoreKernelUtils.getParameterMap(
+                RequestContext.getServletContext(), RequestContext.get().getRequest());
+            mobileStaticResourceComponent.setParameters(parameters);
+            response.put("sourceVersion",
+                mobileStaticResourceComponent.getGeneratedJavascriptFilename());
+          } finally {
+            OBContext.restorePreviousMode();
+          }
         }
         String responseStr = response.toString();
         w.write(responseStr.substring(1, responseStr.length() - 1));

OrderLoader timing is only the order loader saveRecord itself, the Order timing includes OBContext handling

Before perforamance improvements:
Timings for orderLoader cnt: 100 avg millis: 180
Timings for Order cnt: 100 avg millis: 229
Timings for orderLoader cnt: 200 avg millis: 176
Timings for Order cnt: 200 avg millis: 224
Timings for orderLoader cnt: 300 avg millis: 175
Timings for Order cnt: 300 avg millis: 220

Single bin improvement:
Timings for orderLoader cnt: 100 avg millis: 164
Timings for Order cnt: 100 avg millis: 214
Timings for orderLoader cnt: 200 avg millis: 150
Timings for Order cnt: 200 avg millis: 199
Timings for orderLoader cnt: 300 avg millis: 146
Timings for Order cnt: 300 avg millis: 195

Adding using global stock update call statement
Timings for orderLoader cnt: 100 avg millis: 152
Timings for Order cnt: 100 avg millis: 204
Timings for orderLoader cnt: 200 avg millis: 148
Timings for Order cnt: 200 avg millis: 199
Timings for orderLoader cnt: 300 avg millis: 144
Timings for Order cnt: 300 avg millis: 194

Do all log.debug between if, Adding mobile core, don't reset obcontext
Timings for orderLoader cnt: 100 avg millis: 140
Timings for Order cnt: 100 avg millis: 174
Timings for orderLoader cnt: 200 avg millis: 146
Timings for Order cnt: 200 avg millis: 179
Timings for orderLoader cnt: 300 avg millis: 144
Timings for Order cnt: 300 avg millis: 179

After finance changes:
Timings for orderLoader cnt: 100 avg millis: 145
Timings for Order cnt: 100 avg millis: 184
Timings for orderLoader cnt: 200 avg millis: 134
Timings for Order cnt: 200 avg millis: 171
Timings for orderLoader cnt: 300 avg millis: 130
Timings for Order cnt: 300 avg millis: 165

diff --git a/src/org/openbravo/retail/posterminal/OrderLoader.java b/src/org/openbravo/retail/posterminal/OrderLoader.java
--- a/src/org/openbravo/retail/posterminal/OrderLoader.java
+++ b/src/org/openbravo/retail/posterminal/OrderLoader.java
@@ -49,7 +49,6 @@
 import org.openbravo.dal.service.OBDal;
 import org.openbravo.dal.service.OBQuery;
 import org.openbravo.erpCommon.ad_forms.AcctServer;
-import org.openbravo.erpCommon.utility.OBError;
 import org.openbravo.erpCommon.utility.OBMessageUtils;
 import org.openbravo.erpCommon.utility.SequenceIdData;
 import org.openbravo.erpCommon.utility.Utility;
@@ -89,9 +88,9 @@
 import org.openbravo.model.materialmgmt.transaction.MaterialTransaction;
 import org.openbravo.model.materialmgmt.transaction.ShipmentInOut;
 import org.openbravo.model.materialmgmt.transaction.ShipmentInOutLine;
-import org.openbravo.scheduling.ProcessBundle;
 import org.openbravo.service.db.CallStoredProcedure;
 import org.openbravo.service.db.DalConnectionProvider;
+import org.openbravo.service.importprocess.ImportEntryManager;
 import org.openbravo.service.json.JsonConstants;
 import org.openbravo.service.json.JsonToDataConverter;
 
@@ -278,16 +277,24 @@
         t3 = System.currentTimeMillis();
 
         if (createShipment) {
-          // Stock manipulation
-          handleStock(shipment);
-          // Send email
+          org.openbravo.database.ConnectionProvider cp = new DalConnectionProvider(false);
+          CallableStatement updateStockStatement = cp.getConnection().prepareCall(
+              "{call M_UPDATE_INVENTORY (?,?,?,?,?,?,?,?,?,?,?,?,?)}");
+          try {
+            // Stock manipulation
+            handleStock(shipment, updateStockStatement);
+          } finally {
+            updateStockStatement.close();
+          }
         }
 
         long t4 = System.currentTimeMillis();
 
-        log.debug("Creation of bobs. Order: " + (t112 - t111) + "; Orderlines: " + (t113 - t112)
-            + "; Shipment: " + (t115 - t113) + "; Invoice: " + (t116 - t115) + "; Approvals"
-            + (t11 - t116) + "; stock" + (t4 - t3));
+        if (log.isDebugEnabled()) {
+          log.debug("Creation of bobs. Order: " + (t112 - t111) + "; Orderlines: " + (t113 - t112)
+              + "; Shipment: " + (t115 - t113) + "; Invoice: " + (t116 - t115) + "; Approvals"
+              + (t11 - t116) + "; stock" + (t4 - t3));
+        }
 
         // do the docnumbers at the end
         OBContext.setAdminMode();
@@ -329,11 +336,15 @@
       long t5 = System.currentTimeMillis();
       OBDal.getInstance().flush();
 
-      log.info("Order with docno: " + order.getDocumentNo() + " (uuid: " + order.getId()
-          + ") saved correctly. Initial flush: " + (t1 - t0) + "; Generate bobs:" + (t11 - t1)
-          + "; Save bobs:" + (t2 - t11) + "; First flush:" + (t3 - t2) + "; Second flush: "
-          + (t4 - t3) + "; Process Payments:" + (t5 - t4) + " Final flush: "
-          + (System.currentTimeMillis() - t5));
+      if (log.isDebugEnabled()) {
+        log.debug("Order with docno: " + order.getDocumentNo() + " (uuid: " + order.getId()
+            + ") saved correctly. Initial flush: " + (t1 - t0) + "; Generate bobs:" + (t11 - t1)
+            + "; Save bobs:" + (t2 - t11) + "; First flush:" + (t3 - t2) + "; Second flush: "
+            + (t4 - t3) + "; Process Payments:" + (t5 - t4) + " Final flush: "
+            + (System.currentTimeMillis() - t5));
+      }
+      ImportEntryManager.getInstance()
+          .reportStats("orderLoader", (System.currentTimeMillis() - t0));
 
       return successMessage(jsonorder);
     } finally {
@@ -833,20 +844,37 @@
   protected void createShipmentLines(ShipmentInOut shipment, Order order, JSONObject jsonorder,
       JSONArray orderlines, ArrayList<OrderLine> lineReferences) throws JSONException {
     int lineNo = 0;
+    Locator foundSingleBin = null;
     Entity shplineentity = ModelProvider.getInstance().getEntity(ShipmentInOutLine.class);
+
+    final OBCriteria<Locator> locators = OBDal.getInstance().createCriteria(Locator.class);
+    locators.add(Restrictions.eq(Locator.PROPERTY_ACTIVE, true));
+    locators.add(Restrictions.eq(Locator.PROPERTY_WAREHOUSE, shipment.getWarehouse()));
+    // note the count causes a query but the good thing is that it doesn't cause loading
+    // additional bin locations if there are too many
+    if (locators.count() == 1) {
+      foundSingleBin = (Locator) locators.uniqueResult();
+    }
+
     for (int i = 0; i < orderlines.length(); i++) {
       String hqlWhereClause;
 
       OrderLine orderLine = lineReferences.get(i);
       BigDecimal pendingQty = orderLine.getOrderedQuantity().abs();
       boolean negativeLine = orderLine.getOrderedQuantity().compareTo(BigDecimal.ZERO) < 0;
+      boolean useSingleBin = foundSingleBin != null && orderLine.getAttributeSetValue() == null
+          && orderLine.getProduct().getAttributeSet() == null
+          && orderLine.getWarehouseRule() == null;
 
       AttributeSetInstance oldAttributeSetValues = null;
       if (negativeLine) {
         lineNo += 10;
         addShipemntline(shipment, shplineentity, orderlines.getJSONObject(i), orderLine, jsonorder,
             lineNo, pendingQty.negate(), getBinForReturns(jsonorder.getString("posTerminal")), null);
-
+      } else if (useSingleBin) {
+        lineNo += 10;
+        addShipemntline(shipment, shplineentity, orderlines.getJSONObject(i), orderLine, jsonorder,
+            lineNo, pendingQty, foundSingleBin, null);
       } else {
         HashMap<String, ShipmentInOutLine> usedBins = new HashMap<String, ShipmentInOutLine>();
         if (pendingQty.compareTo(BigDecimal.ZERO) > 0) {
@@ -1156,7 +1184,7 @@
     }
   }
 
-  protected void handleStock(ShipmentInOut shipment) {
+  protected void handleStock(ShipmentInOut shipment, CallableStatement updateStockStatement) {
     for (ShipmentInOutLine line : shipment.getMaterialMgmtShipmentInOutLineList()) {
       if (line.getProduct().getProductType().equals("I") && line.getProduct().isStocked()) {
         // Stock is changed only for stocked products of type "Item"
@@ -1173,19 +1201,15 @@
         transaction.setGoodsShipmentLine(line);
         transaction.setAttributeSetValue(line.getAttributeSetValue());
 
-        updateInventory(transaction);
+        updateInventory(transaction, updateStockStatement);
 
         OBDal.getInstance().save(transaction);
       }
     }
   }
 
-  protected void updateInventory(MaterialTransaction transaction) {
+  protected void updateInventory(MaterialTransaction transaction, CallableStatement cs) {
     try {
-      org.openbravo.database.ConnectionProvider cp = new DalConnectionProvider(false);
-      CallableStatement cs = cp.getConnection().prepareCall(
-          "{call M_UPDATE_INVENTORY (?,?,?,?,?,?,?,?,?,?,?,?,?)}");
-
       // client
       cs.setString(1, OBContext.getOBContext().getCurrentClient().getId());
       // org
@@ -1218,7 +1242,6 @@
           .multiply(NEGATIVE_ONE) : null);
 
       cs.execute();
-      cs.close();
     } catch (Exception e) {
       System.out.println("Error calling to M_UPDATE_INVENTORY");
       throw new OBException(e.getMessage());
@@ -1567,31 +1590,13 @@
 
       long t3 = System.currentTimeMillis();
       // Process Payment
-
+      FIN_PaymentProcess.doProcessPayment(finPayment, "D", true, null, null);
       VariablesSecureApp vars = RequestContext.get().getVariablesSecureApp();
-      ProcessBundle pb = new ProcessBundle("6255BE488882480599C81284B70CD9B3", vars)
-          .init(new DalConnectionProvider(false));
-      HashMap<String, Object> parameters = new HashMap<String, Object>();
-      parameters.put("action", "D");
-      parameters.put("Fin_Payment_ID", finPayment.getId());
-      parameters.put("isPOSOrder", "Y");
-      pb.setParams(parameters);
-      // the payment that has been created is processed
-      // the transaction is created
-      FIN_PaymentProcess process = new FIN_PaymentProcess();
-      process.execute(pb);
-      OBError result = (OBError) pb.getResult();
-      if (result.getType().equalsIgnoreCase("Error")) {
-        throw new OBException(result.getMessage());
-      }
       vars.setSessionValue("POSOrder", "Y");
 
       // retrieve the transactions of this payment and set the cashupId to those transactions
-      final OBCriteria<FIN_FinaccTransaction> transactionsCriteria = OBDal.getInstance()
-          .createCriteria(FIN_FinaccTransaction.class);
-      transactionsCriteria.add(Restrictions.eq(FIN_FinaccTransaction.PROPERTY_FINPAYMENT,
-          finPayment));
-      final List<FIN_FinaccTransaction> transactions = transactionsCriteria.list();
+      final List<FIN_FinaccTransaction> transactions = finPayment.getFINFinaccTransactionList();
+      OBDal.getInstance().refresh(finPayment);
       final String cashupId = jsonorder.getString("obposAppCashup");
       final OBPOSAppCashup cashup = OBDal.getInstance().get(OBPOSAppCashup.class, cashupId);
       if (transactions.size() == 0) {
@@ -1601,9 +1606,10 @@
         transaction.setObposAppCashup(cashup);
       }
 
-      log.debug("Payment. Create entities: " + (t2 - t1) + "; Save payment: " + (t3 - t2)
-          + "; Process payment: " + (System.currentTimeMillis() - t3));
-
+      if (log.isDebugEnabled()) {
+        log.debug("Payment. Create entities: " + (t2 - t1) + "; Save payment: " + (t3 - t2)
+            + "; Process payment: " + (System.currentTimeMillis() - t3));
+      }
     } finally {
       OBContext.restorePreviousMode();
     }
@@ -1668,17 +1674,25 @@
       }
       String oldKey = key;
       if (entity.hasProperty(key)) {
-        log.debug("Found property: " + key + " in entity " + entity.getName());
+        if (log.isDebugEnabled()) {
+          log.debug("Found property: " + key + " in entity " + entity.getName());
+        }
       } else {
         key = getEquivalentKey(key);
         if (key == null) {
-          log.debug("Did not find property: " + oldKey);
+          if (log.isDebugEnabled()) {
+            log.debug("Did not find property: " + oldKey);
+          }
           continue;
         } else {
           if (entity.hasProperty(key)) {
-            log.debug("Found equivalent key: " + key);
+            if (log.isDebugEnabled()) {
+              log.debug("Found equivalent key: " + key);
+            }
           } else {
-            log.debug("Did not find property: " + oldKey);
+            if (log.isDebugEnabled()) {
+              log.debug("Did not find property: " + oldKey);
+            }
             continue;
           }
         }
@@ -1779,18 +1793,22 @@
     String processId = SequenceIdData.getUUID();
     OBContext.setAdminMode();
     try {
-      log.debug("Parameters : '" + processId + "', '" + recordID + "', " + quantity + ", '"
-          + productId + "', null, '" + warehouseId + "', null, '" + orgId + "', '"
-          + attributesetinstanceId + "', '" + OBContext.getOBContext().getUser().getId() + "', '"
-          + clientId + "', '" + warehouseRuleId + "', '" + uomId
-          + "', null, null, null, null, null, '" + reservationId + "', 'N'");
+      if (log.isDebugEnabled()) {
+        log.debug("Parameters : '" + processId + "', '" + recordID + "', " + quantity + ", '"
+            + productId + "', null, '" + warehouseId + "', null, '" + orgId + "', '"
+            + attributesetinstanceId + "', '" + OBContext.getOBContext().getUser().getId() + "', '"
+            + clientId + "', '" + warehouseRuleId + "', '" + uomId
+            + "', null, null, null, null, null, '" + reservationId + "', 'N'");
+      }
       long initGetStockProcedureCall = System.currentTimeMillis();
       StockUtils.getStock(processId, recordID, quantity, productId, null, warehouseId, null, orgId,
           attributesetinstanceId, OBContext.getOBContext().getUser().getId(), clientId,
           warehouseRuleId, uomId, null, null, null, null, null, reservationId, "N");
       long elapsedGetStockProcedureCall = (System.currentTimeMillis() - initGetStockProcedureCall);
-      log.debug("Partial time to execute callGetStock Procedure Call() : "
-          + elapsedGetStockProcedureCall);
+      if (log.isDebugEnabled()) {
+        log.debug("Partial time to execute callGetStock Procedure Call() : "
+            + elapsedGetStockProcedureCall);
+      }
       return processId;
     } catch (Exception ex) {
       throw new OBException("Error in OrderLoader when getting stock for product " + productId