Safepointing & Locking issue

[Nicolas Michael]

Hi all,

I have yesterday been investigating a performance problem with one of our
applications where I observed some "strange" JVM behavior (which might be as
expected, but I'm not sure...).

It's a heavily multi-threaded Java application with about 300 threads, running
on a 4 CPU Solaris x86 box using a 32bit HotSpot Client VM build 16.3-b01 (JDK
1.6.0_20-b02). It seems to make extensive use of synchronization and suffers
badly from lock contention. Thread #10 (the VM Thread) eats close to one CPU,
mostly doing lock deflations during safepoints in stacks like this:

              libjvm.so`__1cNObjectMonitorHis_busy6kM_i_+0x26
              libjvm.so`__1cSObjectSynchronizerVdeflate_idle_monitors6F_v_+0x210
              libjvm.so`__1cUSafepointSynchronizeQdo_cleanup_tasks6F_v_+0x19
              libjvm.so`__1cUSafepointSynchronizeFbegin6F_v_+0x3d0
              libjvm.so`__1cIVMThreadEloop6M_v_+0x26c
              libjvm.so`__1cIVMThreadDrun6M_v_+0x88
              libjvm.so`java_start+0xf9
              libc.so.1`_thr_setup+0x4e
              libc.so.1`_lwp_start
              287

>From safepointing point-of-view, the process isn't doing much useful work -- it
only got short periods of work interrupted by safepoints that take longer than
the actual application runtime -- at a rate of 1709 safepoints per second (see
below):

Application time: 0.0000450 seconds
Total time for which application threads were stopped: 0.0002397 seconds
Application time: 0.0001607 seconds
Total time for which application threads were stopped: 0.0002603 seconds
Application time: 0.0000469 seconds
Total time for which application threads were stopped: 0.0011530 seconds
..

>From the perfdata statistics, I see
sun.rt._sync_ContendedLockAttempts    increasing by   12 / sec
sun.rt._sync_Deflations               increasing by  477 / sec
sun.rt._sync_Inflations               increasing by  477 / sec
sun.rt._sync_Notifications            increasing by  791 / sec
sun.rt._sync_Parks                    increasing by  795 / sec
sun.rt.safepoints                     increasing by 1709 / sec
sun.rt.safepointTime is 0.82s and sun.rt.safepointSyncTime 0.15s per second.

I guess we're using too much synchronization, Object.wait(ms) and notify() (or
even notifyAll()) ... ;-) but I'm wondering whether it was "normal" to have that
many safepoints and lock inflations/deflations because of that?

My understanding was that safepoints are mainly caused by GC (not the case here)
or deoptimization (should be visible with +LogCompilation, right? but nothing
there either). Or bias revocation. Indeed, we do have some bias revocations
(like this, see below), but this is at a much lower rate (only ~ 3.4 times per
second):

<writer thread='10'/>
Revoking bias with potentially per-thread safepoint:
Revoking bias of object 0x6df887d0 , mark 0x08ee3805 , type
org.jacorb.poa.RequestQueue , prototype header 0x00000005 , allow rebias 0 ,
requesting thread 0x09065800
  Revoked bias of currently-unlocked object
<writer thread='149'/>
Revoking bias by walking my own stack:
Revoking bias of object 0x6df887c8 , mark 0x09065805 , type java.lang.Object ,
prototype header 0x00000005 , allow rebias 0 , requesting thread 0x09065800
  Revoked bias of currently-locked object
Inflating object 0x6df887c8 , mark 0x0906042a , type java.lang.Object

Also, disabling biased locking has no effect on the magnitude of safepointing,
so I concluded that safepointing must then be caused by lock inflation/deflation
(which seems to be supported by the stack above).

Afaik a lock is being inflated when the leight-weight locking algorithm can't
acquire the lock immediately ("contention"). It will then fall back to
heavy-weight locking (OS mutex?) and notify (wake up) all waiting threads (?).
We have about 40 lock inflations per contended lock attempt (see the perfdata
statistics above), does that mean there were (on average) 40 threads waiting on
that contended lock?

Since we have the same amount of deflations as we have inflations, I would
assume that each heavy-weight lock is shortly after being "contended" reverted
to a leight-weight lock again (during a safepoint in deflate_idle_monitors() as
in the stack above??). But why? Couldn't it stay as a heavy-weight lock, instead
of being deflated, only to be inflated shortly after again?

In the example below, lock 0x96568a60 is being inflated, deflated, inflated
again and then deflated again:

<writer thread='143'/>
Inflating object 0x96568a60 , mark 0x08677ffe , type org.jacorb.poa.RequestProcessor
<writer thread='10'/>
Deflating object 0x96568a60 , mark 0x08677ffe , type org.jacorb.poa.RequestProcessor
<writer thread='143'/>
Inflating object 0x96568a60 , mark 0x0918f4fe , type org.jacorb.poa.RequestProcessor
<writer thread='240'/>
Inflating object 0x79bceee8 , mark 0x08c0b662 , type java.lang.Object
<writer thread='243'/>
Inflating object 0x79bceeb0 , mark 0x0914e9ee , type org.jacorb.orb.ReplyReceiver
<writer thread='10'/>
Deflating object 0x79bceee8 , mark 0x08c0b662 , type java.lang.Object
Deflating object 0x79bceeb0 , mark 0x0914e9ee , type org.jacorb.orb.ReplyReceiver
Deflating object 0x96568a60 , mark 0x0918f4fe , type org.jacorb.poa.RequestProcessor

I was just curious whether this is the intended behavior in case of lock
contention, or whether we're seing some pathological strange thing happen here.

Btw, I've also ran the workload with Hotspot 19.0-b03 from the latest JDK 7
build with the same results.

Any comments appreciated!

Thanks,
Nick.