metadata import in 2.27 much slower than in 2.26

I am getting really large import time discrepancies between 2.26 and 2.27.

I stand up a blank DHIS2 locally with postgres 9.5. Import one very small file (attribute definition used in org units, and one level 1 and one level 2 org units). That takes under one second in both.

Then I try to import a hierarchy that starts at level 3 and has 14458 org units. This is the call i make on both versions of DHIS2 to import is:

curl -u ‘admin:district’ -H ‘Content-Type:application/xml’ -X POST ‘http://localhost:8080/api/26/metadata?atomicMode=NONE&importStrategy=CREATE’ --data-binary @import.xml

2.26 takes under 30 seconds. 2.27 takes over 15 minutes. Is this normal? I know it’s not a small hierarchy, but more than 30 fold increase between versions seems a bit much.

I’ve tried multiple times each, and get consistent results.

This is the log from 2.26:

  • INFO 2017-08-24 15:53:10,602 (admin) Import:Start (DefaultMetadataImportService.java [http-bio-8080-exec-7])

  • INFO 2017-08-24 15:53:10,788 (admin) Import:Preheat[REFERENCE] took 0.18 seconds (DefaultPreheatService.java [http-bio-8080-exec-7])

  • INFO 2017-08-24 15:53:11,178 (admin) Import:Validation took 0.31 seconds (DefaultObjectBundleValidationService.java [http-bio-8080-exec-7])

  • INFO 2017-08-24 15:53:11,191 (admin) Creating 14458 object(s) of type OrganisationUnit (DefaultObjectBundleService.java [http-bio-8080-exec-7])

  • INFO 2017-08-24 15:53:35,991 (admin) Import:Commit took 24.81 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-7])

  • INFO 2017-08-24 15:53:35,994 (admin) Import:Done took 25.39 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-7])

This is the log from 2.27:

  • INFO 2017-08-24 15:56:59,099 (admin) Import:Start (DefaultMetadataImportService.java [http-bio-8080-exec-4])

  • INFO 2017-08-24 15:56:59,265 (admin) Import:Preheat[REFERENCE] took 0.16 seconds (DefaultPreheatService.java [http-bio-8080-exec-4])

  • INFO 2017-08-24 15:56:59,912 (admin) Import:Validation took 0.36 seconds (DefaultObjectBundleValidationService.java [http-bio-8080-exec-4])

  • INFO 2017-08-24 15:56:59,925 (admin) Creating 14458 object(s) of type OrganisationUnit (DefaultObjectBundleService.java [http-bio-8080-exec-4])

  • INFO 2017-08-24 16:12:41,690 Cleared Hibernate caches (DefaultHibernateCacheManager.java [http-bio-8080-exec-4])

  • INFO 2017-08-24 16:12:41,721 (admin) Import:Commit took 941.80 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-4])

  • INFO 2017-08-24 16:12:41,723 (admin) Import:Done took 942.62 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-4])

Thanks,

Vlad

Hi Vlad

No, it should not be like that. Would you mind filing a JIRA issue? and share the payload (either in JIRA, or directly to me)

···

On Thu, Aug 24, 2017 at 10:13 PM, Vladimer Shioshvili vshioshvili@gmail.com wrote:

I am getting really large import time discrepancies between 2.26 and 2.27.

I stand up a blank DHIS2 locally with postgres 9.5. Import one very small file (attribute definition used in org units, and one level 1 and one level 2 org units). That takes under one second in both.

Then I try to import a hierarchy that starts at level 3 and has 14458 org units. This is the call i make on both versions of DHIS2 to import is:

curl -u ‘admin:district’ -H ‘Content-Type:application/xml’ -X POST ‘http://localhost:8080/api/26/metadata?atomicMode=NONE&importStrategy=CREATE’ --data-binary @import.xml

2.26 takes under 30 seconds. 2.27 takes over 15 minutes. Is this normal? I know it’s not a small hierarchy, but more than 30 fold increase between versions seems a bit much.

I’ve tried multiple times each, and get consistent results.

This is the log from 2.26:

  • INFO 2017-08-24 15:53:10,602 (admin) Import:Start (DefaultMetadataImportService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:10,788 (admin) Import:Preheat[REFERENCE] took 0.18 seconds (DefaultPreheatService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:11,178 (admin) Import:Validation took 0.31 seconds (DefaultObjectBundleValidationService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:11,191 (admin) Creating 14458 object(s) of type OrganisationUnit (DefaultObjectBundleService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:35,991 (admin) Import:Commit took 24.81 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:35,994 (admin) Import:Done took 25.39 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-7])

This is the log from 2.27:

  • INFO 2017-08-24 15:56:59,099 (admin) Import:Start (DefaultMetadataImportService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 15:56:59,265 (admin) Import:Preheat[REFERENCE] took 0.16 seconds (DefaultPreheatService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 15:56:59,912 (admin) Import:Validation took 0.36 seconds (DefaultObjectBundleValidationService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 15:56:59,925 (admin) Creating 14458 object(s) of type OrganisationUnit (DefaultObjectBundleService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 16:12:41,690 Cleared Hibernate caches (DefaultHibernateCacheManager.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 16:12:41,721 (admin) Import:Commit took 941.80 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 16:12:41,723 (admin) Import:Done took 942.62 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-4])

Thanks,

Vlad


Mailing list: https://launchpad.net/~dhis2-devs

Post to : dhis2-devs@lists.launchpad.net

Unsubscribe : https://launchpad.net/~dhis2-devs

More help : https://help.launchpad.net/ListHelp

Morten Olav Hansen

Senior Engineer, DHIS 2

University of Oslo

http://www.dhis2.org

Hi

I can echo Vlad here - I was VERY impressed with the huge performance improvement in 2.25 and 2.26 for importing meta-data. Recent imports into 2.27, on the other hand, were pathetic - importing 30,000 OUs would take up to 5 hours. I thought that maybe it was caused by including the “sharing” data, but seeing Vlad’s test results point to a different explanation…

Will see if I can find a good example for testing

Regards

Calle

···

On 25 August 2017 at 09:10, Morten Olav Hansen morten@dhis2.org wrote:

Hi Vlad

No, it should not be like that. Would you mind filing a JIRA issue? and share the payload (either in JIRA, or directly to me)


Mailing list: https://launchpad.net/~dhis2-devs

Post to : dhis2-devs@lists.launchpad.net

Unsubscribe : https://launchpad.net/~dhis2-devs

More help : https://help.launchpad.net/ListHelp

Morten Olav Hansen

Senior Engineer, DHIS 2

University of Oslo

http://www.dhis2.org

On Thu, Aug 24, 2017 at 10:13 PM, Vladimer Shioshvili vshioshvili@gmail.com wrote:

I am getting really large import time discrepancies between 2.26 and 2.27.

I stand up a blank DHIS2 locally with postgres 9.5. Import one very small file (attribute definition used in org units, and one level 1 and one level 2 org units). That takes under one second in both.

Then I try to import a hierarchy that starts at level 3 and has 14458 org units. This is the call i make on both versions of DHIS2 to import is:

curl -u ‘admin:district’ -H ‘Content-Type:application/xml’ -X POST ‘http://localhost:8080/api/26/metadata?atomicMode=NONE&importStrategy=CREATE’ --data-binary @import.xml

2.26 takes under 30 seconds. 2.27 takes over 15 minutes. Is this normal? I know it’s not a small hierarchy, but more than 30 fold increase between versions seems a bit much.

I’ve tried multiple times each, and get consistent results.

This is the log from 2.26:

  • INFO 2017-08-24 15:53:10,602 (admin) Import:Start (DefaultMetadataImportService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:10,788 (admin) Import:Preheat[REFERENCE] took 0.18 seconds (DefaultPreheatService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:11,178 (admin) Import:Validation took 0.31 seconds (DefaultObjectBundleValidationService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:11,191 (admin) Creating 14458 object(s) of type OrganisationUnit (DefaultObjectBundleService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:35,991 (admin) Import:Commit took 24.81 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-7])
  • INFO 2017-08-24 15:53:35,994 (admin) Import:Done took 25.39 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-7])

This is the log from 2.27:

  • INFO 2017-08-24 15:56:59,099 (admin) Import:Start (DefaultMetadataImportService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 15:56:59,265 (admin) Import:Preheat[REFERENCE] took 0.16 seconds (DefaultPreheatService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 15:56:59,912 (admin) Import:Validation took 0.36 seconds (DefaultObjectBundleValidationService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 15:56:59,925 (admin) Creating 14458 object(s) of type OrganisationUnit (DefaultObjectBundleService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 16:12:41,690 Cleared Hibernate caches (DefaultHibernateCacheManager.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 16:12:41,721 (admin) Import:Commit took 941.80 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-4])
  • INFO 2017-08-24 16:12:41,723 (admin) Import:Done took 942.62 seconds (DefaultMetadataImportService.java [http-bio-8080-exec-4])

Thanks,

Vlad


Mailing list: https://launchpad.net/~dhis2-devs

Post to : dhis2-devs@lists.launchpad.net

Unsubscribe : https://launchpad.net/~dhis2-devs

More help : https://help.launchpad.net/ListHelp


Calle Hedberg

46D Alma Road, 7700 Rosebank, SOUTH AFRICA

Tel/fax (home): +27-21-685-6472

Cell: +27-82-853-5352

Iridium SatPhone: +8816-315-19119

Email: calle.hedberg@gmail.com

Skype: calle_hedberg