Performance issue with caching changes in DefaultCalendarService

Support - Assistance technique
1

Hi team,

We’ve noticed a performance issue when exporting metadata through the API. The issue appears to have been introduced in revision 20839 on the 2.21 branch (revision 20854 on trunk) where local caching of systemSettings in the DefaultCalendarService was removed in favour of leveraging the Guava caching in the DefaultSystemSettingManager.

Performance impact when downloading full metadata export through API on a development machine (16GB RAM, 2.6 GHz quad-core CPU):

  • Before (revision 20838 on 2.21 branch): ~11 seconds for a ~20MB file
  • After (revision 20839 on 2.21 branch): ~180 seconds for a ~20MB file
    The caching performance issue seems to manifest itself when mapping the period dates for charts and reportTables which requires the system calendar setting (stacktrace below). Excluding charts and reportTables from the metadata export resolves the issue (download takes ~10 seconds for a ~13 MB file).

Have you experienced any similar issues with the Guava cache implemented in the DefaultSystemSettingManager (or anywhere else)? I wanted to check before investigating any further.

Cheers,

···

-doh

Stacktrace when mapping period dates for charts:

at org.hisp.dhis.setting.DefaultSystemSettingManager.getSystemSetting(DefaultSystemSettingManager.java:157)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:497)

at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)

at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)

at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)

at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)

at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)

at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)

at com.sun.proxy.$Proxy58.getSystemSetting(Unknown Source)

at org.hisp.dhis.calendar.DefaultCalendarService.getSystemCalendar(DefaultCalendarService.java:102)

at org.hisp.dhis.period.PeriodType.getCalendar(PeriodType.java:101)

at org.hisp.dhis.period.PeriodType.createLocalDateUnitInstance(PeriodType.java:364)

at org.hisp.dhis.period.PeriodType.getIsoDate(PeriodType.java:501)

at org.hisp.dhis.period.Period.getIsoDate(Period.java:158)

at org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:48)

at org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:42)

2

Hi David,

that seems very reasonable. I suspect the problem is that SystemSettingManager is transactional, meaning that you get one new transaction per call to the get method. I have done a fix now in trunk (rev 22301) and 2.22 for SystemSettingManager where a transaction is only initiated whenever there is a cache miss in the get method. Since calendar hardly changes the cache hit rate should be close to 100%.

Are you able to re-run your performance benchmark and see if this did the trick?

regards,

Lars

···

On Sun, Jan 10, 2016 at 2:34 PM, David Siang Fong Oh doh@thoughtworks.com wrote:

Hi team,

We’ve noticed a performance issue when exporting metadata through the API. The issue appears to have been introduced in revision 20839 on the 2.21 branch (revision 20854 on trunk) where local caching of systemSettings in the DefaultCalendarService was removed in favour of leveraging the Guava caching in the DefaultSystemSettingManager.

Performance impact when downloading full metadata export through API on a development machine (16GB RAM, 2.6 GHz quad-core CPU):

  • Before (revision 20838 on 2.21 branch): ~11 seconds for a ~20MB file
  • After (revision 20839 on 2.21 branch): ~180 seconds for a ~20MB file
    The caching performance issue seems to manifest itself when mapping the period dates for charts and reportTables which requires the system calendar setting (stacktrace below). Excluding charts and reportTables from the metadata export resolves the issue (download takes ~10 seconds for a ~13 MB file).

Have you experienced any similar issues with the Guava cache implemented in the DefaultSystemSettingManager (or anywhere else)? I wanted to check before investigating any further.

Cheers,

-doh

Stacktrace when mapping period dates for charts:

at org.hisp.dhis.setting.DefaultSystemSettingManager.getSystemSetting(DefaultSystemSettingManager.java:157)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:497)

at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)

at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)

at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)

at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)

at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)

at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)

at com.sun.proxy.$Proxy58.getSystemSetting(Unknown Source)

at org.hisp.dhis.calendar.DefaultCalendarService.getSystemCalendar(DefaultCalendarService.java:102)

at org.hisp.dhis.period.PeriodType.getCalendar(PeriodType.java:101)

at org.hisp.dhis.period.PeriodType.createLocalDateUnitInstance(PeriodType.java:364)

at org.hisp.dhis.period.PeriodType.getIsoDate(PeriodType.java:501)

at org.hisp.dhis.period.Period.getIsoDate(Period.java:158)

at org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:48)

at org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:42)

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

–

Lars Helge Øverland

Lead developer, DHIS 2

University of Oslo

Skype: larshelgeoverland

http://www.dhis2.org

3

Thanks Lars.

I’ve re-run the performance benchmark and the issue seems to be resolved. The metadata export is taking approximately 15 seconds to download a 50MB file. The file size seems to have increased which I’m assuming is related to the refactoring of the export service by Morten?

Cheers,

···

On Mon, Mar 14, 2016 at 9:26 PM, Lars Helge Øverland lars@dhis2.org wrote:

Hi David,

that seems very reasonable. I suspect the problem is that SystemSettingManager is transactional, meaning that you get one new transaction per call to the get method. I have done a fix now in trunk (rev 22301) and 2.22 for SystemSettingManager where a transaction is only initiated whenever there is a cache miss in the get method. Since calendar hardly changes the cache hit rate should be close to 100%.

Are you able to re-run your performance benchmark and see if this did the trick?

regards,

Lars

-doh

On Sun, Jan 10, 2016 at 2:34 PM, David Siang Fong Oh doh@thoughtworks.com wrote:

Hi team,

We’ve noticed a performance issue when exporting metadata through the API. The issue appears to have been introduced in revision 20839 on the 2.21 branch (revision 20854 on trunk) where local caching of systemSettings in the DefaultCalendarService was removed in favour of leveraging the Guava caching in the DefaultSystemSettingManager.

Performance impact when downloading full metadata export through API on a development machine (16GB RAM, 2.6 GHz quad-core CPU):

  • Before (revision 20838 on 2.21 branch): ~11 seconds for a ~20MB file
  • After (revision 20839 on 2.21 branch): ~180 seconds for a ~20MB file
    The caching performance issue seems to manifest itself when mapping the period dates for charts and reportTables which requires the system calendar setting (stacktrace below). Excluding charts and reportTables from the metadata export resolves the issue (download takes ~10 seconds for a ~13 MB file).

Have you experienced any similar issues with the Guava cache implemented in the DefaultSystemSettingManager (or anywhere else)? I wanted to check before investigating any further.

Cheers,

-doh

Stacktrace when mapping period dates for charts:

at org.hisp.dhis.setting.DefaultSystemSettingManager.getSystemSetting(DefaultSystemSettingManager.java:157)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:497)

at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)

at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)

at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)

at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)

at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)

at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)

at com.sun.proxy.$Proxy58.getSystemSetting(Unknown Source)

at org.hisp.dhis.calendar.DefaultCalendarService.getSystemCalendar(DefaultCalendarService.java:102)

at org.hisp.dhis.period.PeriodType.getCalendar(PeriodType.java:101)

at org.hisp.dhis.period.PeriodType.createLocalDateUnitInstance(PeriodType.java:364)

at org.hisp.dhis.period.PeriodType.getIsoDate(PeriodType.java:501)

at org.hisp.dhis.period.Period.getIsoDate(Period.java:158)

at org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:48)

at org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:42)

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

Lars Helge Øverland

Lead developer, DHIS 2

University of Oslo

Skype: larshelgeoverland

http://www.dhis2.org

–

4

Thanks Lars.

I've re-run the performance benchmark and the issue seems to be resolved.
The metadata export is taking approximately 15 seconds to download a 50MB
file.

Sounds good. Thanks for testing.

The file size seems to have increased which I'm assuming is related to the
refactoring of the export service by Morten?

Okay - will need Morten's input on that.

regards,

Lars

···

On Mon, Mar 21, 2016 at 8:14 AM, David Siang Fong Oh <doh@thoughtworks.com> wrote:

Cheers,

-doh

On Mon, Mar 14, 2016 at 9:26 PM, Lars Helge Øverland <lars@dhis2.org> > wrote:

Hi David,

that seems very reasonable. I suspect the problem is that
SystemSettingManager is transactional, meaning that you get one new
transaction per call to the get method. I have done a fix now in trunk (rev
22301) and 2.22 for SystemSettingManager where a transaction is only
initiated whenever there is a cache miss in the get method. Since calendar
hardly changes the cache hit rate should be close to 100%.

Are you able to re-run your performance benchmark and see if this did the
trick?

regards,

Lars

On Sun, Jan 10, 2016 at 2:34 PM, David Siang Fong Oh < >> doh@thoughtworks.com> wrote:

Hi team,

We've noticed a performance issue when exporting metadata through the
API. The issue appears to have been introduced in revision 20839
<http://bazaar.launchpad.net/~dhis2-devs-core/dhis2/2.21/revision/20839&gt; on
the 2.21 branch (revision 20854
<http://bazaar.launchpad.net/~dhis2-devs-core/dhis2/trunk/revision/20854&gt; on
trunk) where local caching of systemSettings in the DefaultCalendarService
was removed in favour of leveraging the Guava caching in the
DefaultSystemSettingManager.

Performance impact when downloading full metadata export through API on
a development machine (16GB RAM, 2.6 GHz quad-core CPU):

   - Before (revision 20838 on 2.21 branch): ~11 seconds for a ~20MB
   file
   - After (revision 20839 on 2.21 branch): ~180 seconds for a ~20MB
   file

The caching performance issue seems to manifest itself when mapping the
period dates for charts and reportTables which requires the system calendar
setting (stacktrace below). Excluding charts and reportTables from the
metadata export resolves the issue (download takes ~10 seconds for a ~13 MB
file).

Have you experienced any similar issues with the Guava cache implemented
in the DefaultSystemSettingManager (or anywhere else)? I wanted to check
before investigating any further.

Cheers,

-doh

Stacktrace when mapping period dates for charts:

*at
org.hisp.dhis.setting.DefaultSystemSettingManager.getSystemSetting(DefaultSystemSettingManager.java:157)*
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
at com.sun.proxy.$Proxy58.getSystemSetting(Unknown Source)
*at
org.hisp.dhis.calendar.DefaultCalendarService.getSystemCalendar(DefaultCalendarService.java:102)*
*at org.hisp.dhis.period.PeriodType.getCalendar(PeriodType.java:101)*
*at
org.hisp.dhis.period.PeriodType.createLocalDateUnitInstance(PeriodType.java:364)*
*at org.hisp.dhis.period.PeriodType.getIsoDate(PeriodType.java:501)*
*at org.hisp.dhis.period.Period.getIsoDate(Period.java:158)*
at
org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:48)
at
org.hisp.dhis.common.adapter.JacksonPeriodSerializer.serialize(JacksonPeriodSerializer.java:42)

_______________________________________________
Mailing list: DHIS 2 developers in Launchpad
Post to : dhis2-devs@lists.launchpad.net
Unsubscribe : DHIS 2 developers in Launchpad
More help : ListHelp - Launchpad Help

--
Lars Helge Øverland
Lead developer, DHIS 2
University of Oslo
Skype: larshelgeoverland
http://www.dhis2.org <https://www.dhis2.org/&gt;

--
Lars Helge Øverland
Lead developer, DHIS 2
University of Oslo
Skype: larshelgeoverland
http://www.dhis2.org <https://www.dhis2.org/&gt;

5

If you are using /api/metadata/export endpoint, nothing should have changed

···

On Mon, Mar 21, 2016 at 2:45 PM, Lars Helge Øverland <lars@dhis2.org> wrote:

The file size seems to have increased which I'm assuming is related to the

refactoring of the export service by Morten?

Okay - will need Morten's input on that.

--
Morten

6

We used the /api/metadata endpoint on the 2.22 branch.

···

On Mon, Mar 21, 2016 at 1:26 PM, Morten Olav Hansen morten@dhis2.org wrote:

-doh

On Mon, Mar 21, 2016 at 2:45 PM, Lars Helge Øverland lars@dhis2.org wrote:

The file size seems to have increased which I’m assuming is related to the refactoring of the export service by Morten?

Okay - will need Morten’s input on that.

Morten

If you are using /api/metadata/export endpoint, nothing should have changed

–

7

Ok, I don’t think the output from either of those endpoints should have changed because of this… if so, it must be related to something else

···

On Mon, Mar 21, 2016 at 4:18 PM, David Siang Fong Oh doh@thoughtworks.com wrote:

We used the /api/metadata endpoint on the 2.22 branch.

–

-doh

On Mon, Mar 21, 2016 at 1:26 PM, Morten Olav Hansen morten@dhis2.org wrote:

On Mon, Mar 21, 2016 at 2:45 PM, Lars Helge Øverland lars@dhis2.org wrote:

The file size seems to have increased which I’m assuming is related to the refactoring of the export service by Morten?

Okay - will need Morten’s input on that.

Morten

If you are using /api/metadata/export endpoint, nothing should have changed

–

Morten