Fixes issue 35384: Add logs on costing background and costing migration process
authorMark <markmm82@gmail.com>
Wed, 21 Jun 2017 16:23:42 -0400
changeset 32385 ea7a25da9285
parent 32384 252dd00489e8
child 32386 b3da3000ba8d
Fixes issue 35384: Add logs on costing background and costing migration process

To analyze performance problems and make a better diagnosis was needed to have a
way to identify the time required to execute each process.

To take this feature included into the Costing Background Process and Costing Migration
Process, some logs were added in the most critical parts of the code to log relevant
information of the processing status like:
- How many transactions have been processed.
- How many transactions are pending to process.
- Estimated time to finish the execution based on current numbers.
- What part of the process is being executed at the moment.
src/org/openbravo/costing/CostAdjustmentProcess.java
src/org/openbravo/costing/CostingAlgorithm.java
src/org/openbravo/costing/CostingBackground.java
src/org/openbravo/costing/CostingMigrationProcess.java
--- a/src/org/openbravo/costing/CostAdjustmentProcess.java	Fri Jun 30 15:19:43 2017 +0000
+++ b/src/org/openbravo/costing/CostAdjustmentProcess.java	Wed Jun 21 16:23:42 2017 -0400
@@ -340,13 +340,13 @@
   public static JSONObject doProcessCostAdjustment(CostAdjustment costAdjustment)
       throws OBException {
     String docNo = costAdjustment.getDocumentNo();
-    log.debug("Starts process cost adjustment: {}", docNo);
+    log.debug("Starting doProcessCostAdjustment() for cost adjustment: {}", docNo);
     long t1 = System.currentTimeMillis();
     CostAdjustmentProcess cap = WeldUtils
         .getInstanceFromStaticBeanManager(CostAdjustmentProcess.class);
     JSONObject message = cap.processCostAdjustment(costAdjustment);
-    log.debug("Ends process cost adjustment: {}, took {} ms.", docNo,
-        (System.currentTimeMillis() - t1));
+    long t2 = System.currentTimeMillis();
+    log.debug("Ending doProcessCostAdjustment() took: {} ms.", (t2 - t1));
     return message;
   }
 
--- a/src/org/openbravo/costing/CostingAlgorithm.java	Fri Jun 30 15:19:43 2017 +0000
+++ b/src/org/openbravo/costing/CostingAlgorithm.java	Wed Jun 21 16:23:42 2017 -0400
@@ -94,60 +94,66 @@
    *           when the transaction type is unknown.
    */
   public BigDecimal getTransactionCost() throws OBException {
-    log4j.debug("Get transactions cost.");
-    if (transaction.getMovementQuantity().compareTo(BigDecimal.ZERO) == 0
-        && getZeroMovementQtyCost() != null) {
-      return getZeroMovementQtyCost();
-    }
-    switch (trxType) {
-    case Shipment:
-      return getShipmentCost();
-    case ShipmentReturn:
-      return getShipmentReturnCost();
-    case ShipmentVoid:
-      return getShipmentVoidCost();
-    case ShipmentNegative:
-      return getShipmentNegativeCost();
-    case Receipt:
-      return getReceiptCost();
-    case ReceiptReturn:
-      return getReceiptReturnCost();
-    case ReceiptVoid:
-      return getReceiptVoidCost();
-    case ReceiptNegative:
-      return getReceiptNegativeCost();
-    case InventoryDecrease:
-      return getInventoryDecreaseCost();
-    case InventoryIncrease:
-      return getInventoryIncreaseCost();
-    case InventoryOpening:
-      return getInventoryOpeningCost();
-    case InventoryClosing:
-      return getInventoryClosingCost();
-    case IntMovementFrom:
-      return getIntMovementFromCost();
-    case IntMovementTo:
-      return getIntMovementToCost();
-    case InternalCons:
-      return getInternalConsCost();
-    case InternalConsNegative:
-      return getInternalConsNegativeCost();
-    case InternalConsVoid:
-      return getInternalConsVoidCost();
-    case BOMPart:
-      return getBOMPartCost();
-    case BOMProduct:
-      return getBOMProductCost();
-    case ManufacturingConsumed:
-      // Manufacturing transactions are not fully implemented.
-      return getManufacturingConsumedCost();
-    case ManufacturingProduced:
-      // Manufacturing transactions are not fully implemented.
-      return getManufacturingProducedCost();
-    case Unknown:
-      throw new OBException("@UnknownTrxType@: " + transaction.getIdentifier());
-    default:
-      throw new OBException("@UnknownTrxType@: " + transaction.getIdentifier());
+    log4j.debug("Starting getTransactionCost() for transaction: " + transaction.getIdentifier());
+    long t1 = System.currentTimeMillis();
+    try {
+      if (transaction.getMovementQuantity().compareTo(BigDecimal.ZERO) == 0
+          && getZeroMovementQtyCost() != null) {
+        return getZeroMovementQtyCost();
+      }
+      switch (trxType) {
+      case Shipment:
+        return getShipmentCost();
+      case ShipmentReturn:
+        return getShipmentReturnCost();
+      case ShipmentVoid:
+        return getShipmentVoidCost();
+      case ShipmentNegative:
+        return getShipmentNegativeCost();
+      case Receipt:
+        return getReceiptCost();
+      case ReceiptReturn:
+        return getReceiptReturnCost();
+      case ReceiptVoid:
+        return getReceiptVoidCost();
+      case ReceiptNegative:
+        return getReceiptNegativeCost();
+      case InventoryDecrease:
+        return getInventoryDecreaseCost();
+      case InventoryIncrease:
+        return getInventoryIncreaseCost();
+      case InventoryOpening:
+        return getInventoryOpeningCost();
+      case InventoryClosing:
+        return getInventoryClosingCost();
+      case IntMovementFrom:
+        return getIntMovementFromCost();
+      case IntMovementTo:
+        return getIntMovementToCost();
+      case InternalCons:
+        return getInternalConsCost();
+      case InternalConsNegative:
+        return getInternalConsNegativeCost();
+      case InternalConsVoid:
+        return getInternalConsVoidCost();
+      case BOMPart:
+        return getBOMPartCost();
+      case BOMProduct:
+        return getBOMProductCost();
+      case ManufacturingConsumed:
+        // Manufacturing transactions are not fully implemented.
+        return getManufacturingConsumedCost();
+      case ManufacturingProduced:
+        // Manufacturing transactions are not fully implemented.
+        return getManufacturingProducedCost();
+      case Unknown:
+        throw new OBException("@UnknownTrxType@: " + transaction.getIdentifier());
+      default:
+        throw new OBException("@UnknownTrxType@: " + transaction.getIdentifier());
+      }
+    } finally {
+      long t2 = System.currentTimeMillis();
+      log4j.debug("Ending getTransactionCost() took: " + (t2 - t1) + " ms.");
     }
   }
 
--- a/src/org/openbravo/costing/CostingBackground.java	Fri Jun 30 15:19:43 2017 +0000
+++ b/src/org/openbravo/costing/CostingBackground.java	Wed Jun 21 16:23:42 2017 -0400
@@ -11,7 +11,7 @@
  * under the License.
  * The Original Code is Openbravo ERP.
  * The Initial Developer of the Original Code is Openbravo SLU
- * All portions are Copyright (C) 2012-2016 Openbravo SLU
+ * All portions are Copyright (C) 2012-2017 Openbravo SLU
  * All Rights Reserved.
  * Contributor(s):  ______________________________________.
  *************************************************************************
@@ -110,11 +110,23 @@
       int batch = 0;
       int counter = 0;
       int counterBatch;
+      long elapsedTime = 0;
+      long avgTimePerBatch = 0;
+      int pendingTrxs = 0;
+      int pendingBatches = 0;
+      if (log4j.isDebugEnabled()) {
+        pendingTrxs = getTransactionsBatchCount(orgsWithRule);
+        log4j.debug("Pending transactions: " + pendingTrxs);
+        pendingBatches = (pendingTrxs % BATCH_SIZE == 0) ? (pendingTrxs / BATCH_SIZE)
+            : (pendingTrxs / BATCH_SIZE) + 1;
+        log4j.debug("Pending batches: " + pendingBatches);
+      }
       trxs = getTransactionsBatch(orgsWithRule);
       while (!trxs.isEmpty()) {
         long t1 = System.currentTimeMillis();
         batch++;
         counterBatch = 0;
+        pendingBatches--;
         for (String trxId : trxs) {
           if (killProcess) {
             throw new OBException("Process killed");
@@ -135,8 +147,17 @@
         }
         trxs = getTransactionsBatch(orgsWithRule);
         long t2 = System.currentTimeMillis();
+
         log4j.debug("Processing batch: " + batch + " (" + counterBatch + " transactions) took: "
             + (t2 - t1) + " ms.");
+
+        if (log4j.isDebugEnabled()) {
+          pendingTrxs -= counterBatch;
+          log4j.debug("Pending transactions: " + pendingTrxs);
+          elapsedTime += t2 - t1;
+          avgTimePerBatch = elapsedTime / batch;
+          log4j.debug("Estimated time to finish: " + (avgTimePerBatch * pendingBatches) + " ms.");
+        }
       }
 
       logger.logln(OBMessageUtils.messageBD("Success"));
@@ -217,6 +238,31 @@
     return trxQry.list();
   }
 
+  private int getTransactionsBatchCount(List<String> orgsWithRule) {
+    StringBuffer where = new StringBuffer();
+    where.append(" select count(trx." + MaterialTransaction.PROPERTY_ID + ") ");
+    where.append(" from " + MaterialTransaction.ENTITY_NAME + " as trx");
+    where.append(" join trx." + MaterialTransaction.PROPERTY_PRODUCT + " as p");
+    where.append("\n , " + org.openbravo.model.ad.domain.List.ENTITY_NAME + " as trxtype");
+    where.append("\n where trx." + MaterialTransaction.PROPERTY_ISPROCESSED + " = false");
+    where.append("   and trx." + MaterialTransaction.PROPERTY_COSTINGSTATUS + " <> 'S'");
+    where.append("   and p." + Product.PROPERTY_PRODUCTTYPE + " = 'I'");
+    where.append("   and p." + Product.PROPERTY_STOCKED + " = true");
+    where.append("   and trxtype." + CostAdjustmentUtils.propADListReference + ".id = :refid");
+    where.append("   and trxtype." + CostAdjustmentUtils.propADListValue + " = trx."
+        + MaterialTransaction.PROPERTY_MOVEMENTTYPE);
+    where.append("   and trx." + MaterialTransaction.PROPERTY_TRANSACTIONPROCESSDATE + " <= :now");
+    where.append("   and trx." + MaterialTransaction.PROPERTY_ORGANIZATION + ".id in (:orgs)");
+    Query trxQry = OBDal.getInstance().getSession().createQuery(where.toString());
+
+    trxQry.setParameter("refid", CostAdjustmentUtils.MovementTypeRefID);
+    trxQry.setParameter("now", new Date());
+    trxQry.setParameterList("orgs", orgsWithRule);
+    trxQry.setMaxResults(1);
+    Long trxCount = (Long) trxQry.uniqueResult();
+    return trxCount.intValue();
+  }
+
   private void initializeMtransCostDateAcct() throws Exception {
     boolean transactionCostDateacctInitialized = false;
     Client client = OBDal.getInstance().get(Client.class, "0");
--- a/src/org/openbravo/costing/CostingMigrationProcess.java	Fri Jun 30 15:19:43 2017 +0000
+++ b/src/org/openbravo/costing/CostingMigrationProcess.java	Wed Jun 21 16:23:42 2017 -0400
@@ -102,6 +102,10 @@
   @Override
   public void execute(ProcessBundle bundle) throws Exception {
     logger = bundle.getLogger();
+    long start = System.currentTimeMillis();
+    long startPhase = 0;
+    long endPhase = 0;
+    log4j.debug("Starting CostingMigrationProcess at: " + new Date());
     OBError msg = new OBError();
     conn = bundle.getConnection();
     msg.setType("Success");
@@ -120,13 +124,20 @@
           .registerSQLFunction("now", new StandardSQLFunction("now", new DateType()));
 
       if (!isMigrationFirstPhaseCompleted()) {
+        startPhase = System.currentTimeMillis();
+        log4j.debug("Starting CostingMigrationProcess first phase at: " + new Date());
         doChecks();
         updateLegacyCosts();
         createRules();
         createMigrationFirstPhaseCompletedPreference();
+        endPhase = System.currentTimeMillis();
+        log4j.debug("Ending CostingMigrationProcess first phase at: " + new Date() + ". Duration: "
+            + (endPhase - startPhase) + " ms.");
       }
 
       else {
+        startPhase = System.currentTimeMillis();
+        log4j.debug("Starting CostingMigrationProcess second phase at: " + new Date());
         checkAllInventoriesAreProcessed();
         for (CostingRule rule : getRules()) {
           rule.setValidated(true);
@@ -136,6 +147,9 @@
         updateReportRoles();
         CostingStatus.getInstance().setMigrated();
         deleteMigrationFirstPhaseCompletedPreference();
+        endPhase = System.currentTimeMillis();
+        log4j.debug("Ending CostingMigrationProcess second phase at: " + new Date()
+            + ". Duration: " + (endPhase - startPhase) + " ms.");
       }
 
     } catch (final OBException e) {
@@ -161,11 +175,15 @@
     } finally {
       OBContext.restorePreviousMode();
     }
-
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending CostingMigrationProcess at: " + new Date() + ". Duration: " + (end - start)
+        + " ms.");
     bundle.setResult(msg);
   }
 
   private void doChecks() {
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting doChecks() at: " + new Date());
     // Check all transactions have a legacy cost available.
     AlertRule legacyCostAvailableAlert = getLegacyCostAvailableAlert();
     if (legacyCostAvailableAlert == null) {
@@ -365,11 +383,13 @@
       throw new OBException("@InconsistenciesInStock@");
     }
 
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending doChecks() at: " + new Date() + ". Duration: " + (end - start) + " ms.");
   }
 
   private void updateLegacyCosts() {
-    log4j.debug("UpdateLegacyCosts");
-
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting updateLegacyCosts() at: " + new Date());
     resetTransactionCosts();
     fixLegacyCostingCurrency();
 
@@ -408,9 +428,15 @@
     updateWithZeroCostRemainingTrx();
     insertTrxCosts();
     insertStandardCosts();
+
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending updateLegacyCosts() at: " + new Date() + ". Duration: " + (end - start)
+        + " ms.");
   }
 
   private void resetTransactionCosts() {
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting resetTransactionCosts() at: " + new Date());
     TriggerHandler.getInstance().disable();
     try {
       // Reset costs in m_transaction_cost
@@ -434,9 +460,14 @@
     } finally {
       TriggerHandler.getInstance().enable();
     }
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending resetTransactionCosts() at: " + new Date() + ". Duration: " + (end - start)
+        + " ms.");
   }
 
   private void fixLegacyCostingCurrency() {
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting fixLegacyCostingCurrency() at: " + new Date());
     TriggerHandler.getInstance().disable();
     try {
       // Fix legacy costing currency
@@ -457,9 +488,14 @@
     } finally {
       TriggerHandler.getInstance().enable();
     }
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending fixLegacyCostingCurrency() at: " + new Date() + ". Duration: "
+        + (end - start) + " ms.");
   }
 
   private void createRules() throws Exception {
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting createRules() at: " + new Date());
     // Delete manually created rules.
     Query delQry = OBDal.getInstance().getSession()
         .createQuery("delete from " + CostingRule.ENTITY_NAME);
@@ -479,7 +515,8 @@
         calculateCosts(org);
       }
     }
-
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending createRules() at: " + new Date() + ". Duration: " + (end - start) + " ms.");
   }
 
   private void processRule(CostingRule rule) {
@@ -669,6 +706,9 @@
   }
 
   private ScrollableResults getLegacyCostScroll(String clientId, Set<String> naturalTree) {
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting getLegacyCostScroll() at: " + new Date());
+
     StringBuffer where = new StringBuffer();
     where.append(" as c");
     where.append(" where c." + Costing.PROPERTY_CLIENT + ".id = :client");
@@ -693,11 +733,16 @@
     costingQry.setNamedParameter("client", clientId);
     costingQry.setNamedParameter("orgs", naturalTree);
     costingQry.setFetchSize(1000);
+
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending getLegacyCostScroll() at: " + new Date() + ". Duration: " + (end - start)
+        + " ms.");
     return costingQry.scroll(ScrollMode.FORWARD_ONLY);
   }
 
   private void updateTrxLegacyCosts(Costing _cost, int standardPrecision, Set<String> naturalTree) {
-    log4j.debug("****** UpdateTrxLegacyCosts");
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting updateTrxLegacyCosts() at: " + new Date());
     Costing cost = OBDal.getInstance().get(Costing.class, _cost.getId());
 
     StringBuffer where = new StringBuffer();
@@ -757,7 +802,9 @@
       trxs.close();
     }
 
-    log4j.debug("****** UpdateTrxLegacyCosts updated:" + i);
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending updateTrxLegacyCosts() at: " + new Date() + ". Duration: " + (end - start)
+        + " ms. Updated: " + i + " transactions.");
   }
 
   /**
@@ -767,7 +814,8 @@
    * with zero cost.
    */
   private void updateWithZeroCostRemainingTrx() {
-    log4j.debug("****** updateWithCeroRemainingTrx");
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting updateWithZeroCostRemainingTrx() at: " + new Date());
     int n = 0;
     TriggerHandler.getInstance().disable();
     try {
@@ -802,7 +850,9 @@
     } finally {
       TriggerHandler.getInstance().enable();
     }
-    log4j.debug("****** updateWithCeroRemainingTrx updated:" + n);
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending updateWithZeroCostRemainingTrx() at: " + new Date() + ". Duration: "
+        + (end - start) + " ms. Updated: " + n + " transactions.");
   }
 
   private void insertAlertRecipients(AlertRule alertRule) {
@@ -843,9 +893,12 @@
   }
 
   private void insertTrxCosts() {
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting insertTrxCosts() at: " + new Date());
     TriggerHandler.getInstance().disable();
+    long countTrx = 0;
     try {
-      long countTrx = Long.valueOf(CostingUtilsData.countTrxCosts(conn)).longValue();
+      countTrx = Long.valueOf(CostingUtilsData.countTrxCosts(conn)).longValue();
       long iters = (countTrx % maxTrx == 0) ? (countTrx / maxTrx) : (countTrx / maxTrx) + 1;
       String pgLimit = null, oraLimit = null;
       if (StringUtils.equalsIgnoreCase(conn.getRDBMS(), "ORACLE")) {
@@ -861,13 +914,19 @@
     } catch (Exception e) {
       log4j.error(e.getMessage());
     } finally {
+      long end = System.currentTimeMillis();
+      log4j.debug("Ending insertTrxCosts() at: " + new Date() + ". Duration: " + (end - start)
+          + " ms. Inserted: " + countTrx + " transactions.");
       TriggerHandler.getInstance().enable();
     }
   }
 
   private void insertStandardCosts() {
+    long start = System.currentTimeMillis();
+    log4j.debug("Starting insertStandardCosts() at: " + new Date());
     // Insert STANDARD cost for products with costtype = 'ST'.
     TriggerHandler.getInstance().disable();
+    int insertedTrx = 0;
     try {
       StringBuffer insert = new StringBuffer();
       insert.append(" insert into " + Costing.ENTITY_NAME);
@@ -931,13 +990,16 @@
       queryInsert.setString("startingDate", startingDate);
       queryInsert.setString("limitDate", startingDate);
       queryInsert.setString("limitDate2", startingDate);
-      queryInsert.executeUpdate();
+      insertedTrx = queryInsert.executeUpdate();
 
       OBDal.getInstance().flush();
       OBDal.getInstance().getSession().clear();
     } finally {
       TriggerHandler.getInstance().enable();
     }
+    long end = System.currentTimeMillis();
+    log4j.debug("Ending insertStandardCosts() at: " + new Date() + ". Duration: " + (end - start)
+        + " ms. Inserted: " + insertedTrx + " transactions.");
   }
 
   private CostingRule createCostingRule(Organization org) {