0043367: Performance issues when using attributes and having many instances with the same description

Openbravo Issue Tracking System - Retail Modules

View Issue Details

Project

Category

View Status

Date Submitted

Last Update

0043367

Retail Modules

Web POS

public

2020-02-28 11:19

2020-03-16 12:52

Reporter

gorkaion

Assigned To

rqueralta

Priority

high

Severity

major

Reproducibility

always

Status

closed

Resolution

fixed

Platform

OS Version

Product Version

Target Version

Fixed in Version

RR20Q2

Merge Request Status

Review Assigned To

jorge-garcia

OBNetwork customer

Support ticket

Regression level

Regression date

Regression introduced in release

Regression introduced by commit

Triggers an Emergency Pack

Summary

0043367: Performance issues when using attributes and having many instances with the same description

Description

On a environment using instance attributes (for example with expiration date)

In case you have many attribute set instances with the same description the OrderLoader is very slow.

Steps To Reproduce

Define some products using instance attributes. Generate attribute set instances with the same description. For example using an attribute set with expiration date and assigning the same date in several receipts.

As it is an instance attribute it generates many records in the m_attributesetinstance with the same description.

Create a Sales Order using one of the products using that instance and check the timings of the OrderLoader.

2020-02-27 08:14:07,459 [Import Entry - 5] DEBUG org.openbravo.retail.posterminal.OrderLoader - Order with docno: XXXXX saved correctly. Initial flush: 2; Generate bobs:2617; Save bobs:0; First flush:0; Process Payments:17969 Final flush: 1473
2020-02-27 08:14:07,459 [Import Entry - 5] DEBUG org.openbravo.retail.posterminal.OrderLoader - Order total time: 24944
2020-02-27 08:14:09,057 [Import Entry - 5] DEBUG org.openbravo.mobile.core.process.DataSynchronizationProcess - Total process org.openbravo.retail.posterminal.OrderLoader time: 26564

Enabling debug mode on OBDal most of the time is in flushed (23s out of 26s)

2020-02-27 08:13:42,507 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 11 entities and 86 collections took: 6
2020-02-27 08:13:42,516 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 18 entities and 241 collections took: 1
2020-02-27 08:13:46,238 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31988 entities and 832092 collections took: 1093
2020-02-27 08:13:48,017 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31988 entities and 832092 collections took: 1777
2020-02-27 08:13:49,002 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31990 entities and 832105 collections took: 980
2020-02-27 08:13:50,131 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31991 entities and 832113 collections took: 1122
2020-02-27 08:13:51,791 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31991 entities and 832113 collections took: 1659
2020-02-27 08:13:53,318 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31991 entities and 832113 collections took: 1524
2020-02-27 08:13:54,236 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31992 entities and 832136 collections took: 909
2020-02-27 08:13:55,135 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 31993 entities and 832139 collections took: 895
2020-02-27 08:13:56,787 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32001 entities and 832163 collections took: 1638
2020-02-27 08:13:57,799 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32002 entities and 832173 collections took: 997
2020-02-27 08:13:59,354 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32002 entities and 832186 collections took: 1549
2020-02-27 08:14:01,056 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32004 entities and 832202 collections took: 1690
2020-02-27 08:14:02,667 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32007 entities and 832299 collections took: 1600
2020-02-27 08:14:03,543 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32008 entities and 832299 collections took: 872
2020-02-27 08:14:05,011 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32008 entities and 832299 collections took: 1466
2020-02-27 08:14:05,983 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32015 entities and 832317 collections took: 958
2020-02-27 08:14:07,459 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32015 entities and 832317 collections took: 1471
2020-02-27 08:14:09,025 [Import Entry - 5] DEBUG org.openbravo.dal.service.OBDal - Flush of 32015 entities and 832317 collections took: 1565

Proposed Solution

The flush times degrades when it loads 30k entities and 830k in memory and they are never cleared.

Fix should review:
- Why it is required to load so many objects in Hibernate cache
- Execute a clearSession after the flush to free the cache.

Reviewing the log we have find out that the issue is in org.openbravo.retail.posterminal.utility.AttributesUtils class.

This class is searching attributesetinstances by description. Loading all found instances in memory by using .list(). In reality we just need to know if there are 0, 1 or more than 1. And we will only use the 1st result.
Consider:
- setting a limit to get just 2 attribute set instances.
- changing the select clause to return just the IDs instead of full objects.

Later something similar is done searching for stock if there are more than 1 attribute set instance.In this case we only use the 1st one.
Consider:
- setting a limit to retrieve just 1 value.
- changing the select clause to get the attributesetinstance id instead of the full storagedetail object.

Check if it is possible to return a proxy object instead of the full baseobobject.

In customer instance just setting the proposed limits the time executing the orderloader has decreased to less than 1 second.

Additional Information