Details

    • Number of attachments :
      0

      Description

      Seems like the MessageDigest instance might need to be cached? Ran into this when running an app that hits a cloud service that requires digest auth. When it hits it's locking up 20% or so of our tomcat app threads.

      java.lang.Thread.State: BLOCKED (on object monitor)
              at java.security.Provider.getService(Provider.java:663)
              - locked <0x00000005e0066ee0> (a sun.security.provider.Sun)
              at sun.security.jca.ProviderList.getService(ProviderList.java:314)
              at sun.security.jca.GetInstance.getInstance(GetInstance.java:140)
              at java.security.Security.getImpl(Security.java:659)
              at java.security.MessageDigest.getInstance(MessageDigest.java:129)
              at org.jruby.RubyDigest.createMessageDigest(RubyDigest.java:94)
              at org.jruby.RubyDigest.access$100(RubyDigest.java:55)
              at org.jruby.RubyDigest$DigestBase.setAlgorithm(RubyDigest.java:436)
              at org.jruby.RubyDigest$DigestBase.<init>(RubyDigest.java:367)
              at org.jruby.RubyDigest$DigestBase$1.allocate(RubyDigest.java:347)
              at org.jruby.RubyClass.allocate(RubyClass.java:219)
              at org.jruby.RubyClass.newInstance(RubyClass.java:833)
              at org.jruby.RubyDigest$DigestClass.s_digest(RubyDigest.java:330)
              at org.jruby.RubyDigest$DigestClass$s$0$0$s_digest.call(RubyDigest$DigestClass$s$0$0$s_digest.gen:65535)
              at org.jruby.RubyClass.finvoke(RubyClass.java:557)
              at org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:541)
              at org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:385)
              at org.jruby.RubyDigest$DigestClass.s_hexdigest(RubyDigest.java:337)
              at org.jruby.RubyDigest$DigestClass$s$0$1$s_hexdigest.call(RubyDigest$DigestClass$s$0$1$s_hexdigest.gen:65535)
              at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:211)
              at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:207)
              at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
              at rubyjit.Net::HTTP::DigestAuth#auth_header_D173E8C29FEF2D3CE8377C6586B4B48E8974A164.__file__(/home/tomcat/e1-apache-tomcat-7.0.23/webapps/ROOT/WEB-INF/config/initializers/extensions/digest_auth.rb:49)
      

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        I dug into OpenJDK code and found that the contention is actually happening after the JCA subsystem has a Provider in hand, when requesting a Service from which it can create MD5 digest objects. The search for the correct Service happens under lock in the getService method shown in the bug description. That tells me the simplest way to avoid the contention (and all the searching) is to do what I did originally: clone an unused instance of MessageDigest for each new use.

        Revisiting that yields mixed results. It definitely speeds up the uncontended case, but the numbers for contended cases vary wildly...probably because it's spinning up a bunch of short-lived threads and joining them. The thread overhead may be clouding these numbers.

        Are you at liberty to test this? I could provide a patch that replaces MessageDigest.getInstance calls with cloning for the common digests and you could see how it looks on your system.

        Show
        Charles Oliver Nutter added a comment - I dug into OpenJDK code and found that the contention is actually happening after the JCA subsystem has a Provider in hand, when requesting a Service from which it can create MD5 digest objects. The search for the correct Service happens under lock in the getService method shown in the bug description. That tells me the simplest way to avoid the contention (and all the searching) is to do what I did originally: clone an unused instance of MessageDigest for each new use. Revisiting that yields mixed results. It definitely speeds up the uncontended case, but the numbers for contended cases vary wildly...probably because it's spinning up a bunch of short-lived threads and joining them. The thread overhead may be clouding these numbers. Are you at liberty to test this? I could provide a patch that replaces MessageDigest.getInstance calls with cloning for the common digests and you could see how it looks on your system.
        Hide
        Charles Oliver Nutter added a comment -

        I committed my implementation to master. It caches cloneable instances for all the standard JCA MessageDigest algorithms. The commit message is below.

        We could possibly merge this into 1.6.7, but we're trying to quiet down for release. If you can confirm that it looks better for you by applying the patch manually, it would give us more motivation. Without confirmation, it will probably wait until a 1.6.8 or 1.7 release.

        commit e840823c435393e8365be1bae93f646c1bb0043f
        Author: Charles Oliver Nutter <headius@headius.com>
        Date:   Mon Feb 20 17:22:11 2012 -0600
        
            Fix JRUBY-6475: md5 digest causes thread lock
            
            My investigation led me to Provider.getService, which synchronizes
            on itself while scanning services for the requested name. Under
            heavy load, this could mean simply creating a new MessageDigest
            hits a contended lock. My solution is to cache cloneable instances
            of the common digest algorithms and use those when possible,
            rather than doing the full JCA/SPI dance every time.
            
            Numbers are not conclusive for high numbers of threads, probably
            because the overhead of starting and joining those threads clouds
            real numbers, but for uncontended and lightly-contended cases the
            improvement is fairly clear:
            
            before:
            
            uncontended MD5 'foo'
                                   794320.2 (3.6%) i/s -    3966768 in   5.000912s (cycle=19071)
            uncontended MD5 'foo' * 1000
                                    84978.3 (8.4%) i/s -     424840 in   5.040786s (cycle=6536)
            4x contended MD5 'foo'
                                   164143.3 (17.4%) i/s -     743796 in   4.912694s (cycle=142)
            4x contended MD5 'foo' * 1000
                                    47155.2 (13.2%) i/s -     229680 in   4.974455s (cycle=165)
            
            after:
            
            uncontended MD5 'foo'
                                   915251.0 (2.4%) i/s -    4567572 in   4.994108s (cycle=21444)
            uncontended MD5 'foo' * 1000
                                    91104.0 (0.9%) i/s -     459492 in   5.044020s (cycle=6962)
            4x contended MD5 'foo'
                                   248055.6 (26.5%) i/s -    1037427 in   4.916294s (cycle=183)
            4x contended MD5 'foo' * 1000
                                    53960.2 (18.7%) i/s -     255029 in   4.974802s (cycle=181)
            
            Note that the small input digests show the benefit more clearly,
            since they are heavy on new digest creation.
        
        Show
        Charles Oliver Nutter added a comment - I committed my implementation to master. It caches cloneable instances for all the standard JCA MessageDigest algorithms. The commit message is below. We could possibly merge this into 1.6.7, but we're trying to quiet down for release. If you can confirm that it looks better for you by applying the patch manually, it would give us more motivation. Without confirmation, it will probably wait until a 1.6.8 or 1.7 release. commit e840823c435393e8365be1bae93f646c1bb0043f Author: Charles Oliver Nutter <headius@headius.com> Date: Mon Feb 20 17:22:11 2012 -0600 Fix JRUBY-6475: md5 digest causes thread lock My investigation led me to Provider.getService, which synchronizes on itself while scanning services for the requested name. Under heavy load, this could mean simply creating a new MessageDigest hits a contended lock. My solution is to cache cloneable instances of the common digest algorithms and use those when possible, rather than doing the full JCA/SPI dance every time. Numbers are not conclusive for high numbers of threads, probably because the overhead of starting and joining those threads clouds real numbers, but for uncontended and lightly-contended cases the improvement is fairly clear: before: uncontended MD5 'foo' 794320.2 (3.6%) i/s - 3966768 in 5.000912s (cycle=19071) uncontended MD5 'foo' * 1000 84978.3 (8.4%) i/s - 424840 in 5.040786s (cycle=6536) 4x contended MD5 'foo' 164143.3 (17.4%) i/s - 743796 in 4.912694s (cycle=142) 4x contended MD5 'foo' * 1000 47155.2 (13.2%) i/s - 229680 in 4.974455s (cycle=165) after: uncontended MD5 'foo' 915251.0 (2.4%) i/s - 4567572 in 4.994108s (cycle=21444) uncontended MD5 'foo' * 1000 91104.0 (0.9%) i/s - 459492 in 5.044020s (cycle=6962) 4x contended MD5 'foo' 248055.6 (26.5%) i/s - 1037427 in 4.916294s (cycle=183) 4x contended MD5 'foo' * 1000 53960.2 (18.7%) i/s - 255029 in 4.974802s (cycle=181) Note that the small input digests show the benefit more clearly, since they are heavy on new digest creation.
        Hide
        Charles Oliver Nutter added a comment -

        BTW Chris, regarding your JavaSecuredFile comment... they should be entirely unrelated, at least as far as JRuby itself goes. If you are seeing a lot of contention or load in that method, I would recommend opening a separate issue with as much information as you can provide. We'll investigate that independent of this bug.

        Show
        Charles Oliver Nutter added a comment - BTW Chris, regarding your JavaSecuredFile comment... they should be entirely unrelated, at least as far as JRuby itself goes. If you are seeing a lot of contention or load in that method, I would recommend opening a separate issue with as much information as you can provide. We'll investigate that independent of this bug.
        Hide
        Charles Oliver Nutter added a comment -

        Fixed for 1.7. I think we should close the door on 1.6.7, but feel free to lobby for it to get into 1.6.8 if it helps you.

        Show
        Charles Oliver Nutter added a comment - Fixed for 1.7. I think we should close the door on 1.6.7, but feel free to lobby for it to get into 1.6.8 if it helps you.
        Hide
        Chris Ochs added a comment -

        Thanks Charles. I'll try the patch, and we also have the option of just using a different md5 library also, so it's not a big deal if it's only fixed in 1.7.

        I'll open up a separate ticket on the JavaSecuredFile thing.

        Show
        Chris Ochs added a comment - Thanks Charles. I'll try the patch, and we also have the option of just using a different md5 library also, so it's not a big deal if it's only fixed in 1.7. I'll open up a separate ticket on the JavaSecuredFile thing.

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Chris Ochs
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: