ReloadableResourceBundleMessageSource locks properties hashmap and fails under load. [SPR-10500]

[spring-projects-issues]

Ronald R. DiFrango opened SPR-10500 and commented

The ReloadableResourceBundleMessageSource class locks the whole hashmap that holds properties and in our case is making the network call (after acquiring lock). This terribly slows down the property look-up. Under load it’s more significant as multiple threads could potentially try to load the files if there is a timeout.

Ideally we’d like a background thread load the properties after a timeout and put them into hashmap without locking as we are read-heavy and can tolerate stale entries.

Another option is to use a concurrent hashmap. Therefore the change for RRB should allow a backing map and whether to lock or not.

Here is the stack trace, notice the line in red is holding lock on a hashmap, which is the hashmap that holds properties:

"[ACTIVE] ExecuteThread: '150' for queue: 'weblogic.kernel.Default (self-tuning)'" id=8927 idx=0x2fc tid=30297 prio=5 alive, native_blocked, daemon
                at jrockit/net/SocketNativeIO.readBytesPinned(Ljava/io/FileDescriptor;[BIII)I(Native Method)
                at jrockit/net/SocketNativeIO.socketRead(SocketNativeIO.java:32)[inlined]
                at java/net/SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I(SocketInputStream.java)[inlined]
                at java/net/SocketInputStream.read(SocketInputStream.java:129)[optimized]
                at java/io/BufferedInputStream.fill(BufferedInputStream.java:218)
                at java/io/BufferedInputStream.read1(BufferedInputStream.java:258)[optimized]
                at java/io/BufferedInputStream.read(BufferedInputStream.java:317)[optimized]
                ^-- Holding lock: java/io/BufferedInputStream@0x10f0f4cc0[thin lock]
                at weblogic/net/http/MessageHeader.isHTTP(MessageHeader.java:224)
                at weblogic/net/http/MessageHeader.parseHeader(MessageHeader.java:148)[optimized]
                at weblogic/net/http/HttpClient.parseHTTP(HttpClient.java:468)[optimized]
                at weblogic/net/http/HttpURLConnection.getInputStream(HttpURLConnection.java:395)[inlined]
                at weblogic/net/http/SOAPHttpURLConnection.getInputStream(SOAPHttpURLConnection.java:37)[optimized]
                ^-- Holding lock: weblogic/net/http/SOAPHttpURLConnection@0x10f0f2550[biased lock]
                at weblogic/net/http/HttpURLConnection.getResponseCode(HttpURLConnection.java:983)[optimized]
                at org/springframework/core/io/AbstractFileResolvingResource.exists(AbstractFileResolvingResource.java:103)[optimized]
                at com/capitalone/epf/context/support/ReloadableResourceBundleMessageSource.refreshProperties(ReloadableResourceBundleMessageSource.java:131)[optimized]
                at org/springframework/context/support/ReloadableResourceBundleMessageSource.getProperties(ReloadableResourceBundleMessageSource.java:439)[inlined]
                at org/springframework/context/support/ReloadableResourceBundleMessageSource.resolveCodeWithoutArguments(ReloadableResourceBundleMessageSource.java:272)[optimized]
                ^-- Holding lock: java/util/HashMap@0x10d49e228[fat lock]
                at org/springframework/context/support/AbstractMessageSource.getMessageInternal(AbstractMessageSource.java:193)[inlined]
                at org/springframework/context/support/AbstractMessageSource.getMessage(AbstractMessageSource.java:127)[optimized]
                at org/springframework/context/support/AbstractApplicationContext.getMessage(AbstractApplicationContext.java:1210)[optimized]
                at org/springframework/web/servlet/tags/MessageTag.resolveMessage(MessageTag.java:227)[inlined]
                at org/springframework/web/servlet/tags/MessageTag.doStartTagInternal(MessageTag.java:165)[optimized]
                at org/springframework/web/servlet/tags/RequestContextAwareTag.doStartTag(RequestContextAwareTag.java:79)[optimized]
                at jsp_servlet/_web_45_inf/_views/__viewrequiredinformation._jsp__tag12(__viewrequiredinformation.java:1381)
                at jsp_servlet/_web_45_inf/_views/__viewrequiredinformation._jspService(__viewrequiredinformation.java:441)
                at weblogic/servlet/jsp/JspBase.service(JspBase.java:34)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)[inlined]
                at weblogic/servlet/internal/ServletStubImpl.execute(ServletStubImpl.java:300)[optimized]
                at weblogic/servlet/internal/ServletStubImpl.execute(ServletStubImpl.java:183)[inlined]
                at weblogic/servlet/internal/RequestDispatcherImpl.invokeServlet(RequestDispatcherImpl.java:523)[optimized]
                at weblogic/servlet/internal/RequestDispatcherImpl.forward(RequestDispatcherImpl.java:253)[optimized]
                at org/springframework/web/servlet/view/InternalResourceView.renderMergedOutputModel(InternalResourceView.java:238)[optimized]
                at org/springframework/web/servlet/view/AbstractView.render(AbstractView.java:262)[optimized]
                at org/springframework/web/servlet/DispatcherServlet.render(DispatcherServlet.java:1157)[optimized]
                at org/springframework/web/servlet/DispatcherServlet.doDispatch(DispatcherServlet.java:927)[optimized]
                at org/springframework/web/servlet/DispatcherServlet.doService(DispatcherServlet.java:827)[inlined]
                at org/springframework/web/servlet/FrameworkServlet.processRequest(FrameworkServlet.java:882)[inlined]
                at org/springframework/web/servlet/FrameworkServlet.doGet(FrameworkServlet.java:778)[optimized]
                at javax/servlet/http/HttpServlet.service(HttpServlet.java:707)[optimized]
                at javax/servlet/http/HttpServlet.service(HttpServlet.java:820)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)[inlined]
                at weblogic/servlet/internal/ServletStubImpl.execute(ServletStubImpl.java:300)[optimized]
                at weblogic/servlet/internal/TailFilter.doFilter(TailFilter.java:26)[optimized]
                at weblogic/servlet/internal/FilterChainImpl.doFilter(FilterChainImpl.java:56)[optimized]
                at com/capitalone/epf/context/filters/EPFContextServletFilter.doFilter(EPFContextServletFilter.java:89)[optimized]
                at weblogic/servlet/internal/FilterChainImpl.doFilter(FilterChainImpl.java:56)[inlined]
                at weblogic/servlet/internal/WebAppServletContext$ServletInvocationAction.wrapRun(Lweblogic/servlet/internal/ServletStubImpl;Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)Ljava/lang/Object;(Unknown Source)[inlined]
                at weblogic/servlet/internal/WebAppServletContext$ServletInvocationAction.run()Ljava/lang/Object;(Unknown Source)[optimized]
                at weblogic/security/acl/internal/AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)[optimized]
                at weblogic/security/service/SecurityManager.runAs(SecurityManager.java:120)[inlined]
                at weblogic/servlet/internal/WebAppServletContext.securedExecute(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Z)V(Unknown Source)[inlined]
                at weblogic/servlet/internal/WebAppServletContext.execute(Lweblogic/servlet/internal/ServletRequestImpl;Lweblogic/servlet/internal/ServletResponseImpl;)V(Unknown Source)[optimized]
                at weblogic/servlet/internal/ServletRequestImpl.run()V(Unknown Source)[optimized]
                at weblogic/work/ExecuteThread.execute(ExecuteThread.java:209)[inlined]
                at weblogic/work/ExecuteThread.run(ExecuteThread.java:178)[optimized]
                at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

Now here are the lookup threads waiting on the lock [under load you could have literally hundreds as in our case]:

[ACTIVE] ExecuteThread: '146' for queue: 'weblogic.kernel.Default (self-tuning)'" id=8923 idx=0x300 tid=30008 prio=5 alive, blocked, native_blocked, daemon
                -- Blocked trying to get lock: java/util/HashMap@0x10d49e228[fat lock]
                at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)
                at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1411)[optimized]
                at jrockit/vm/Locks.lockFat(Locks.java:1512)[optimized]
                at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1054)[optimized]
                at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1005)[optimized]
                at org/springframework/context/support/ReloadableResourceBundleMessageSource.getProperties(ReloadableResourceBundleMessageSource.java:431)[inlined]
                at org/springframework/context/support/ReloadableResourceBundleMessageSource.resolveCodeWithoutArguments(ReloadableResourceBundleMessageSource.java:272)[optimized]
                at org/springframework/context/support/AbstractMessageSource.getMessageInternal(AbstractMessageSource.java:193)[inlined]
                at org/springframework/context/support/AbstractMessageSource.getMessage(AbstractMessageSource.java:127)[optimized]
                at org/springframework/context/support/AbstractApplicationContext.getMessage(AbstractApplicationContext.java:1210)[optimized]
                at org/springframework/web/servlet/tags/MessageTag.resolveMessage(MessageTag.java:227)[inlined]
                at org/springframework/web/servlet/tags/MessageTag.doStartTagInternal(MessageTag.java:165)[optimized]
                at org/springframework/web/servlet/tags/RequestContextAwareTag.doStartTag(RequestContextAwareTag.java:79)[optimized]
                at jsp_servlet/_web_45_inf/_views/__viewpaymentsalerts._jsp__tag34(__viewpaymentsalerts.java:2695)
                at jsp_servlet/_web_45_inf/_views/__viewpaymentsalerts._jsp__tag30(__viewpaymentsalerts.java:2523)
                at jsp_servlet/_web_45_inf/_views/__viewpaymentsalerts._jspService(__viewpaymentsalerts.java:601)
                at weblogic/servlet/jsp/JspBase.service(JspBase.java:34)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)[inlined]
                at weblogic/servlet/internal/ServletStubImpl.execute(ServletStubImpl.java:300)[optimized]
                at weblogic/servlet/internal/ServletStubImpl.execute(ServletStubImpl.java:183)[inlined]
                at weblogic/servlet/internal/RequestDispatcherImpl.invokeServlet(RequestDispatcherImpl.java:523)[optimized]
                at weblogic/servlet/internal/RequestDispatcherImpl.forward(RequestDispatcherImpl.java:253)[optimized]
                at org/springframework/web/servlet/view/InternalResourceView.renderMergedOutputModel(InternalResourceView.java:238)[optimized]
                at org/springframework/web/servlet/view/AbstractView.render(AbstractView.java:262)[optimized]
                at org/springframework/web/servlet/DispatcherServlet.render(DispatcherServlet.java:1157)[optimized]
                at org/springframework/web/servlet/DispatcherServlet.doDispatch(DispatcherServlet.java:927)[optimized]
                at org/springframework/web/servlet/DispatcherServlet.doService(DispatcherServlet.java:827)[inlined]
                at org/springframework/web/servlet/FrameworkServlet.processRequest(FrameworkServlet.java:882)[inlined]
                at org/springframework/web/servlet/FrameworkServlet.doGet(FrameworkServlet.java:778)[optimized]
                at javax/servlet/http/HttpServlet.service(HttpServlet.java:707)[optimized]
                at javax/servlet/http/HttpServlet.service(HttpServlet.java:820)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)[optimized]
                at weblogic/servlet/internal/StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)[inlined]
                at weblogic/servlet/internal/ServletStubImpl.execute(ServletStubImpl.java:300)[optimized]
                at weblogic/servlet/internal/TailFilter.doFilter(TailFilter.java:26)[optimized]
                at weblogic/servlet/internal/FilterChainImpl.doFilter(FilterChainImpl.java:56)[optimized]
                at com/capitalone/epf/context/filters/EPFContextServletFilter.doFilter(EPFContextServletFilter.java:89)[optimized]
                at weblogic/servlet/internal/FilterChainImpl.doFilter(FilterChainImpl.java:56)[inlined]
                at weblogic/servlet/internal/WebAppServletContext$ServletInvocationAction.wrapRun(Lweblogic/servlet/internal/ServletStubImpl;Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)Ljava/lang/Object;(Unknown Source)[inlined]
                at weblogic/servlet/internal/WebAppServletContext$ServletInvocationAction.run()Ljava/lang/Object;(Unknown Source)[optimized]
                at weblogic/security/acl/internal/AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)[optimized]
                at weblogic/security/service/SecurityManager.runAs(SecurityManager.java:120)[inlined]
                at weblogic/servlet/internal/WebAppServletContext.securedExecute(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Z)V(Unknown Source)[inlined]
                at weblogic/servlet/internal/WebAppServletContext.execute(Lweblogic/servlet/internal/ServletRequestImpl;Lweblogic/servlet/internal/ServletResponseImpl;)V(Unknown Source)[optimized]
                at weblogic/servlet/internal/ServletRequestImpl.run()V(Unknown Source)[optimized]
                at weblogic/work/ExecuteThread.execute(ExecuteThread.java:209)[inlined]
                at weblogic/work/ExecuteThread.run(ExecuteThread.java:178)[optimized]
                at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

---

Affects: 3.1 GA

Attachments:

• ReloadableResourceBundleMessageSource.java (26.71 kB)

Issue Links:

• ReloadableResourceBundleMessageSource performance issue when using many resource files [SPR-5476] #10149 ReloadableResourceBundleMessageSource performance issue when using many resource files ("is duplicated by")
• Method getMergedProperties in ReloadableResourceBundleMessageSource does not set fileTimestamp [SPR-14583] #19152 Method getMergedProperties in ReloadableResourceBundleMessageSource does not set fileTimestamp
• Remove synchronization from ResourceBundleMessageSource [SPR-16235] #20782 Remove synchronization from ResourceBundleMessageSource

Referenced from: commits a000dd7

7 votes, 6 watchers

[spring-projects-issues]

Ronald R. DiFrango commented

I think it does make sense to move this to an enhancement request, and as such I think the following should also be considered. In our use case we had to extend this class to support the notion of running in what I will call a "disconnected" mode. What I mean by that is that if the source system for the properties files isn't available we allow the processing to continue any ways. The current code does not support this and throws a run-time exception which was unacceptable to us.

In support of that, we extended this class but in order to do so we had to gain access via reflection to the following properties which were marked private:

private String[] basenames;
private String propertiesSuffix;
private String xmlSuffix;
private ResourceLoader resourceLoader;
private Map cachedProperties;
private long cacheMillis;

What in essence over-rode was:

loadProperties
refreshProperties

It would be nice if:

these properties weren't private
A new property was introduced that allowed me to set the notion of disconnected "ALLOWED"
And specifically for us, the properties files live in a CMS so having a plug-able loader mechanism where we can call the external system would be helpful.

[spring-projects-issues]

Bijender commented

I have used the following approach to avoid/mitigate locking. I have also changed the access level of members mentioned in jira ticket from private to protected.

I have introduced a new flag “preferStaleOverLock”. If this flag is true. Only one thread will update the cache remaining thread will use the stale data. If this flag is false, all thread will be locked until first thread updates the cache.

Locking strategy is also changed. Two new objects are introduced to acquire the lock for cachedFilenames and cachedMergedProperties. This allows reader threads to read the hashmap while update threads are busy in creating the new hashmap to replace the existing one's for cachedFilenames and cachedMergedProperties.

If we all agree on approach I will commit the change to spring-framework. See the attachment in next comment for full source code.

protected PropertiesHolder getProperties(String filename) {
		PropertiesHolder propHolder = this.cachedProperties.get(filename);
		if (propHolder != null &&
				(propHolder.getRefreshTimestamp() < 0 ||
				 propHolder.getRefreshTimestamp() > System.currentTimeMillis() - this.cacheMillis)) {
			// up to date
			return propHolder;
		}
		// If stale acceptable don't lock all threads
		if (propHolder != null && preferStaleOverLocking) {
			if (lockCachedProperties.tryLock()){
				try{
					return refreshProperties(filename, propHolder);
				} finally {
					lockCachedProperties.unlock();
				}
			} else {
				return this.cachedProperties.get(filename);
			}
		} else { // lock all threads and refresh cache
			lockCachedProperties.lock();
			try {
				propHolder = this.cachedProperties.get(filename);
				if (propHolder != null &&
					(propHolder.getRefreshTimestamp() < 0 ||
					 propHolder.getRefreshTimestamp() > System.currentTimeMillis() - this.cacheMillis)) {
				 	 // up to date
					return propHolder;
				}
				return refreshProperties(filename, propHolder);
			}finally {
				lockCachedProperties.unlock();
			}
		}
	}

[spring-projects-issues]

Juergen Hoeller commented

In a revision inspired by your suggestions, ReloadableResourceBundleMessageSource uses ConcurrentHashMaps and per-file ReentrantLocks instead of synchronization now. I've opted for making such concurrent refresh behavior the default as of 4.1; it can be turned off through setting the concurrentRefresh flag to false.

This works fine in local tests but still needs to be tested more widely. Please give it a try in the upcoming 4.1 snapshot! Alternatively, you could patch your local ReloadableResourceBundleMessageSource with the new code...

Juergen

[spring-projects-issues]

Bijender commented

The changes looks good, thanks for accommodating the request. We are utilizing this class after extending it. We have to use reflection to get hold of some private variables as mentioned by Ron, can we make these variables protected.
Bijender

[spring-projects-issues]

Juergen Hoeller commented

Bijender, which variables are you interested in? Which methods are you overriding there? That'd be interesting to know design-wise... We generally rather provide dedicated template methods with some related settings as parameters than plain protected accessors.

In order to get access to a setting from the base class and avoid reflection, you could also override the setter and locally store the setting in your own field in the subclass.

Juergen

[spring-projects-issues]

Ronald R. DiFrango commented

Juergen,

Before I repeat the fields, the use case we have is that our properties are fetched from a CMS system which may or may NOT be available. Therefore, upon startup we REQUIRE it to be online, but once the properties are loaded if we fail to load them, we accept that condition and do not reload, logging a warning along the way.

Furthermore, the URL's are CMS based so we have to implement custom fetching logic.

So, if you were looking for a "Spring" way, allowing clients to over-ride the fetching behavior when they aren't a standard URL and also allowing an over-ride that says its ok to fail post startup that would be ideal.

Make sense?

For completeness, here the fields are again:

private String[] basenames;
private String propertiesSuffix;
private String xmlSuffix;
private ResourceLoader resourceLoader;
private Map cachedProperties;
private long cacheMillis;
What in essence over-rode was:
loadProperties
refreshProperties

[spring-projects-issues]

Bijender commented

Juergen,
If you are okay with making the above members protected, I can make a change and create pull request. The main reason for the contribution was to fix the thread locking and avoid using reflection API while extending the current features in class.
Thanks