RFR: 8294759: Print actual lock/monitor ranking

[Aleksey Shipilev]

On Tue, 4 Oct 2022 17:33:04 GMT, Coleen Phillimore <coleenp at openjdk.org> wrote:

>> When relative lock ranks are changing, it is useful to see what are the final lock ranks are. It can be dumped as optional logging shortly after VM startup. 
>> 
>> Sample output:
>> 
>> 
>> $ build/linux-x86_64-server-fastdebug/images/jdk/bin/java -Xlog:vmmutex
>> [0.073s][info][vmmutex] VM Mutex/Monitor ranks: 
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "service-2":
>> [0.073s][info][vmmutex]   Uncommit_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "service-1":
>> [0.073s][info][vmmutex]   FreeList_lock
>> [0.073s][info][vmmutex]   MonitoringSupport_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "service":
>> [0.073s][info][vmmutex]   Service_lock
>> [0.073s][info][vmmutex]   Notification_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "stackwatermark-1":
>> [0.073s][info][vmmutex]   JfrStacktrace_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "tty-1":
>> [0.073s][info][vmmutex]   SharedDecoder_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "tty":
>> [0.073s][info][vmmutex]   tty_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "nosafepoint-3":
>> [0.073s][info][vmmutex]   Metaspace_lock
>> [0.073s][info][vmmutex]   JfrMsg_lock
>> [0.073s][info][vmmutex]   ContinuationRelativize_lock
>> [0.073s][info][vmmutex]   ThreadsSMRDelete_lock
>> [0.073s][info][vmmutex]   CompiledMethod_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "nosafepoint-2":
>> [0.073s][info][vmmutex]   G1DetachedRefinementStats_lock
>> [0.073s][info][vmmutex]   JmethodIdCreation_lock
>> [0.073s][info][vmmutex]   CodeCache_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "nosafepoint-1":
>> [0.073s][info][vmmutex]   RootRegionScan_lock
>> [0.073s][info][vmmutex]   RawMonitor_lock
>> [0.073s][info][vmmutex]   MetaspaceCritical_lock
>> [0.073s][info][vmmutex]   NonJavaThreadsList_lock
>> [0.073s][info][vmmutex]   Zip_lock
>> [0.073s][info][vmmutex]   InlineCacheBuffer_lock
>> [0.073s][info][vmmutex]   VtableStubs_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "nosafepoint":
>> [0.073s][info][vmmutex]   STS_lock
>> [0.073s][info][vmmutex]   CGC_lock
>> [0.073s][info][vmmutex]   OldSets_lock
>> [0.073s][info][vmmutex]   MarkStackFreeList_lock
>> [0.073s][info][vmmutex]   MarkStackChunkList_lock
>> [0.073s][info][vmmutex]   StringDedup_lock
>> [0.073s][info][vmmutex]   StringDedupIntern_lock
>> [0.073s][info][vmmutex]   Patching_lock
>> [0.073s][info][vmmutex]   MonitorDeflation_lock
>> [0.073s][info][vmmutex]   SymbolArena_lock
>> [0.073s][info][vmmutex]   NonJavaThreadsListSync_lock
>> [0.073s][info][vmmutex]   InitCompleted_lock
>> [0.073s][info][vmmutex]   CompiledIC_lock
>> [0.073s][info][vmmutex]   DirectivesStack_lock
>> [0.073s][info][vmmutex]   EscapeBarrier_lock
>> [0.073s][info][vmmutex]   JvmtiVTMSTransition_lock
>> [0.073s][info][vmmutex]   JfrBuffer_lock
>> [0.073s][info][vmmutex]   JfrThreadSampler_lock
>> [0.073s][info][vmmutex]   DCmdFactory_lock
>> [0.073s][info][vmmutex]   DumpTimeTable_lock
>> [0.073s][info][vmmutex]   CDSLambda_lock
>> [0.073s][info][vmmutex]   DumpRegion_lock
>> [0.073s][info][vmmutex]   ClassListFile_lock
>> [0.073s][info][vmmutex]   Bootclasspath_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "safepoint-3":
>> [0.073s][info][vmmutex]   PerfDataMemAlloc_lock
>> [0.073s][info][vmmutex]   PerfDataManager_lock
>> [0.073s][info][vmmutex]   VMOperation_lock
>> [0.073s][info][vmmutex]   SystemDictionary_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "safepoint-2":
>> [0.073s][info][vmmutex]   Heap_lock
>> [0.073s][info][vmmutex]   ClassInitError_lock
>> [0.073s][info][vmmutex]   G1OldGCCount_lock
>> [0.073s][info][vmmutex]   ParGCRareEvent_lock
>> [0.073s][info][vmmutex]   OopMapCacheAlloc_lock
>> [0.073s][info][vmmutex]   Module_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "safepoint-1":
>> [0.073s][info][vmmutex]   Threads_lock
>> [0.073s][info][vmmutex]   Compile_lock
>> [0.073s][info][vmmutex]   AdapterHandlerLibrary_lock
>> [0.073s][info][vmmutex]   ClassLoaderDataGraph_lock
>> [0.073s][info][vmmutex]   CompileTaskAlloc_lock
>> [0.073s][info][vmmutex]   JNICritical_lock
>> [0.073s][info][vmmutex]   JVMCI_lock
>> [0.073s][info][vmmutex] 
>> [0.073s][info][vmmutex] Rank "safepoint":
>> [0.073s][info][vmmutex]   InvokeMethodTable_lock
>> [0.073s][info][vmmutex]   SharedDictionary_lock
>> [0.073s][info][vmmutex]   VMStatistic_lock
>> [0.073s][info][vmmutex]   SignatureHandlerLibrary_lock
>> [0.073s][info][vmmutex]   ExceptionCache_lock
>> [0.073s][info][vmmutex]   FullGCALot_lock
>> [0.073s][info][vmmutex]   BeforeExit_lock
>> [0.073s][info][vmmutex]   RetData_lock
>> [0.073s][info][vmmutex]   Terminator_lock
>> [0.073s][info][vmmutex]   Notify_lock
>> [0.073s][info][vmmutex]   Heap_lock
>> [0.073s][info][vmmutex]   JfieldIdCreation_lock
>> [0.073s][info][vmmutex]   MethodCompileQueue_lock
>> [0.073s][info][vmmutex]   CompileStatistics_lock
>> [0.073s][info][vmmutex]   MultiArray_lock
>> [0.073s][info][vmmutex]   JvmtiThreadState_lock
>> [0.073s][info][vmmutex]   Management_lock
>> [0.073s][info][vmmutex]   ConcurrentGCBreakpoints_lock
>> [0.073s][info][vmmutex]   MethodData_lock
>> [0.073s][info][vmmutex]   TouchedMethodLog_lock
>> [0.073s][info][vmmutex]   CompileThread_lock
>> [0.073s][info][vmmutex]   PeriodicTask_lock
>> [0.073s][info][vmmutex]   RedefineClasses_lock
>> [0.073s][info][vmmutex]   Verify_lock
>> [0.073s][info][vmmutex]   CodeHeapStateAnalytics_lock
>> [0.073s][info][vmmutex]   ThreadIdTableCreate_lock
>> [0.073s][info][vmmutex]   NMTQuery_lock
>> [0.073s][info][vmmutex]   CDSClassFileStream_lock
>> [0.073s][info][vmmutex]   LambdaFormInvokers_lock
>> [0.073s][info][vmmutex]   JVMCIRuntime_lock
>> 
>> 
>> Additional testing:
>>  - [x] New test on Linux x86_64 {release,fastdebug,slowdebug}
>
> src/hotspot/share/runtime/mutexLocker.cpp line 440:
> 
>> 438:   }
>> 439: 
>> 440:   for (int r = min_rank; r <= max_rank; r++) {
> 
> I'm confused by this first loop. why can't min_rank be Mutex::event or static_cast<int>0 and max_rank should be Mutex::safepoint.

Ah, I was being defensive about this: computing min/max without relying on the actual `Rank` definition. While `0` is plausibly the lowest rank, I don't really want to rely on `safepoint` being the last rank. This is debugging code, so we can spend some time on this. Makes sense?

-------------

PR: https://git.openjdk.org/jdk/pull/10556