RFR: 8334904: Add some perf counters to monitor the usage of VM locks

[David Holmes]

On Fri, 28 Jun 2024 23:30:45 GMT, Calvin Cheung <ccheung at openjdk.org> wrote:

> Adding a few perf counters to monitor the usage of VM locks. The counters include hold time, wait time, and number of events. They can be enabled via `-Xlog:pref+vmlocks`.
> 
> Please refer to the [comment](https://bugs.openjdk.org/browse/JDK-8334904?focusedId=14684322&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14684322) in the bug report for an example output.
> 
> Passed tiers 1 - 4 testing.

This isn't monitoring all VM locks only those used via `MutexLocker` - why?

It isn't clear to me exactly how this all hangs together, or why. A number of queries and requests below.

Thanks.

src/hotspot/share/logging/logTag.hpp line 216:

> 214:   LOG_TAG(verify) \
> 215:   LOG_TAG(vmlocks) \
> 216:   LOG_TAG(vmmutex) \

Why not just use the existing `vmmutex` tag?

src/hotspot/share/runtime/mutex.hpp line 101:

> 99:   PlatformMonitor _lock;                 // Native monitor implementation
> 100:   const char* _name;                     // Name of mutex/monitor
> 101:   int _id;                               // ID for named mutexes

It would be clearer if this were described in terms of how it is used - IIUC it is an index into the name array. `_id` is somewhat vague.

src/hotspot/share/runtime/mutexLocker.cpp line 192:

> 190:   int id = _num_mutex++;
> 191:   _mutex_array[id] = var;
> 192:   var->set_id(id);

It is not obvious how the setting of the `_id` by the constructor interacts with this code. So IIUC the `_id` of each Mutex in the array is the Mutex's index into the array. So what does `_id` mean for mutexes that are not in the array?

src/hotspot/share/runtime/mutexLocker.cpp line 380:

> 378: static const int MAX_NAMES = 200;
> 379: static const char* _names[MAX_NAMES] = { nullptr };
> 380: static bool _is_unique[MAX_NAMES] = { false };

Some explanatory comments would be useful. Why do we need to duplicate all the names? What does the `is_unique` array signify? The way it is used in `name2Id` doesn't make sense to me.

src/hotspot/share/runtime/mutexLocker.cpp line 387:

> 385: PerfCounter** MutexLockerImpl::_perf_lock_hold_time = nullptr;
> 386: 
> 387: void MutexLockerImpl::init_counters() {

It looks very odd to put an externally callable function in the Impl class. Impl classes are supposed to be private internal details.

src/hotspot/share/runtime/mutexLocker.cpp line 397:

> 395:     NEWPERFEVENTCOUNTER(_perf_lock_count[0],     SUN_RT, PerfDataManager::counter_name("Other", "Count"));
> 396:     NEWPERFEVENTCOUNTER(_perf_lock_wait_time[0], SUN_RT, PerfDataManager::counter_name("Other", "BeforeTime"));
> 397:     NEWPERFEVENTCOUNTER(_perf_lock_hold_time[0], SUN_RT, PerfDataManager::counter_name("Other", "AfterTime"));

I don't understand the "BeforeTime" and "AfterTime" on these. "before" or "After" what?
EDIT: okay see later comment on naming.

src/hotspot/share/runtime/mutexLocker.cpp line 410:

> 408:       NEWPERFEVENTCOUNTER(_perf_lock_hold_time[i + 1], SUN_RT, PerfDataManager::counter_name(counter_name, "AfterTime"));
> 409:     }
> 410:     if (HAS_PENDING_EXCEPTION) {

What code above could raise a Java exception??? I'm not sure the VM is initialized enough to throw an exception when this is called.

src/hotspot/share/runtime/mutexLocker.hpp line 196:

> 194:   bool _prof;
> 195:   elapsedTimer _before;
> 196:   elapsedTimer _after;

It would be a lot clearer if these were also called `_wait_time` and `_hold_time`! And add a descriptive comment.

src/hotspot/share/runtime/thread.hpp line 643:

> 641:   VMErrorCallback* _vm_error_callbacks;
> 642: 
> 643:   bool  _profile_vm_locks;

It is not clear what role this plays - why do we only profile certain threads?

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

Changes requested by dholmes (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/19954#pullrequestreview-2155266476
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663436302
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663437997
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663440114
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663440609
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663424385
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663427795
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663428590
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663434538
PR Review Comment: https://git.openjdk.org/jdk/pull/19954#discussion_r1663444782