details: https://code.openbravo.com/erp/devel/pi/rev/ea7a25da9285 changeset: 32385:ea7a25da9285 user: Mark <markmm82 <at> gmail.com> date: Wed Jun 21 16:23:42 2017 -0400 summary: 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. details: https://code.openbravo.com/erp/devel/pi/rev/b3da3000ba8d changeset: 32386:b3da3000ba8d user: Alvaro Ferraz <alvaro.ferraz <at> openbravo.com> date: Fri Jun 23 11:25:32 2017 +0200 summary: Related to issue 35384: Code review improvements diffstat: src/org/openbravo/costing/CostAdjustmentProcess.java | 8 +- src/org/openbravo/costing/CostingAlgorithm.java | 114 ++++++++-------- src/org/openbravo/costing/CostingBackground.java | 51 +++++++- src/org/openbravo/costing/CostingMigrationProcess.java | 102 +++++++++++++- 4 files changed, 203 insertions(+), 72 deletions(-) diffs (truncated from 506 to 300 lines): diff -r 252dd00489e8 -r b3da3000ba8d src/org/openbravo/costing/CostAdjustmentProcess.java --- a/src/org/openbravo/costing/CostAdjustmentProcess.java Fri Jun 30 15:19:43 2017 +0000 +++ b/src/org/openbravo/costing/CostAdjustmentProcess.java Fri Jun 23 11:25:32 2017 +0200 @@ -339,14 +339,14 @@ 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: {}", + costAdjustment.getDocumentNo()); 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; } diff -r 252dd00489e8 -r b3da3000ba8d src/org/openbravo/costing/CostingAlgorithm.java --- a/src/org/openbravo/costing/CostingAlgorithm.java Fri Jun 30 15:19:43 2017 +0000 +++ b/src/org/openbravo/costing/CostingAlgorithm.java Fri Jun 23 11:25:32 2017 +0200 @@ -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."); } } diff -r 252dd00489e8 -r b3da3000ba8d src/org/openbravo/costing/CostingBackground.java --- a/src/org/openbravo/costing/CostingBackground.java Fri Jun 30 15:19:43 2017 +0000 +++ b/src/org/openbravo/costing/CostingBackground.java Fri Jun 23 11:25:32 2017 +0200 @@ -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,6 +110,13 @@ int batch = 0; int counter = 0; int counterBatch; + int pendingTrxs = 0; + long elapsedTime = 0; + if (log4j.isDebugEnabled()) { + pendingTrxs = getTransactionsBatchCount(orgsWithRule); + log4j.debug("Pending transactions: " + pendingTrxs); + } + trxs = getTransactionsBatch(orgsWithRule); while (!trxs.isEmpty()) { long t1 = System.currentTimeMillis(); @@ -134,9 +141,21 @@ + ". Took: " + (t4 - t3) + " ms."); } trxs = getTransactionsBatch(orgsWithRule); - long t2 = System.currentTimeMillis(); - log4j.debug("Processing batch: " + batch + " (" + counterBatch + " transactions) took: " - + (t2 - t1) + " ms."); + + if (log4j.isDebugEnabled()) { + long t2 = System.currentTimeMillis(); + log4j.debug("Processing batch: " + batch + " (" + counterBatch + " transactions) took: " + + (t2 - t1) + " ms."); + pendingTrxs -= counterBatch; + int pendingBatches = (pendingTrxs % BATCH_SIZE == 0) ? (pendingTrxs / BATCH_SIZE) + : (pendingTrxs / BATCH_SIZE) + 1; + elapsedTime += t2 - t1; + long avgTimePerBatch = elapsedTime / batch / 1000; + log4j.debug("Pending transactions: " + pendingTrxs); + log4j.debug("Average time per batch: " + avgTimePerBatch + + " seconds. Estimated time to finish: " + (avgTimePerBatch * pendingBatches) + + " seconds."); + } } logger.logln(OBMessageUtils.messageBD("Success")); @@ -217,6 +236,30 @@ 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); + return ((Long) trxQry.uniqueResult()).intValue(); + } + private void initializeMtransCostDateAcct() throws Exception { boolean transactionCostDateacctInitialized = false; Client client = OBDal.getInstance().get(Client.class, "0"); diff -r 252dd00489e8 -r b3da3000ba8d src/org/openbravo/costing/CostingMigrationProcess.java --- a/src/org/openbravo/costing/CostingMigrationProcess.java Fri Jun 30 15:19:43 2017 +0000 +++ b/src/org/openbravo/costing/CostingMigrationProcess.java Fri Jun 23 11:25:32 2017 +0200 @@ -101,6 +101,9 @@ @Override public void execute(ProcessBundle bundle) throws Exception { + long start = System.currentTimeMillis(); + log4j.debug("Starting CostingMigrationProcess at: " + new Date()); + logger = bundle.getLogger(); OBError msg = new OBError(); conn = bundle.getConnection(); @@ -120,13 +123,20 @@ .registerSQLFunction("now", new StandardSQLFunction("now", new DateType())); if (!isMigrationFirstPhaseCompleted()) { + long t1 = System.currentTimeMillis(); + log4j.debug("Starting CostingMigrationProcess first phase at: " + new Date()); doChecks(); updateLegacyCosts(); createRules(); createMigrationFirstPhaseCompletedPreference(); + long t2 = System.currentTimeMillis(); + log4j.debug("Ending CostingMigrationProcess first phase at: " + new Date() + ". Duration: " + + (t2 - t1) + " ms."); } else { + long t1 = System.currentTimeMillis(); + log4j.debug("Starting CostingMigrationProcess second phase at: " + new Date()); checkAllInventoriesAreProcessed(); for (CostingRule rule : getRules()) { rule.setValidated(true); @@ -136,9 +146,13 @@ updateReportRoles(); CostingStatus.getInstance().setMigrated(); deleteMigrationFirstPhaseCompletedPreference(); + long t2 = System.currentTimeMillis(); + log4j.debug("Ending CostingMigrationProcess second phase at: " + new Date() + + ". Duration: " + (t2 - t1) + " ms."); } + } - } catch (final OBException e) { + catch (final OBException e) { OBDal.getInstance().rollbackAndClose(); String resultMsg = OBMessageUtils.parseTranslation(e.getMessage()); logger.log(resultMsg); @@ -147,8 +161,9 @@ msg.setTitle(OBMessageUtils.messageBD("Error")); msg.setMessage(resultMsg); bundle.setResult(msg); + } - } catch (final Exception e) { + catch (final Exception e) { OBDal.getInstance().rollbackAndClose(); String message = DbUtility.getUnderlyingSQLException(e).getMessage(); logger.log(message); @@ -157,15 +172,22 @@ msg.setTitle(OBMessageUtils.messageBD("Error")); msg.setMessage(message); bundle.setResult(msg); + } - } finally { + finally { OBContext.restorePreviousMode(); } + bundle.setResult(msg); ------------------------------------------------------------------------------ Check out the vibrant tech community on one of the world's most engaging tech sites, Slashdot.org! http://sdm.link/slashdot _______________________________________________ Openbravo-commits mailing list Openbravo-commits@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/openbravo-commits
