记录java锁等待的时间

java中synchronized锁是语言层面实现的锁，也是我们比较常用的一种。经过jdk层面的优化，这个关键字在重入锁的层面已经和ReentrantLock接近，而且有更丰富的场景（锁膨胀的过程）。现在有一个场景就是我们需要去评估的，就是线程在等待锁的时候究竟等待了多长时间。这个数据可以用来作为设置线程数以及减少锁时间的优化指标。

特定实现

最直接的实现方式就是硬编码，我们只要打印出锁内方法执行的时间就可以知道其他锁等待的时间了，我们可以通过这种日志来确保锁的获取，以及锁的时间。缺点就是当要注意的点比较多的时候，硬编码的地方会比较多。

通用实现

我们可以利用jvmti锁的事件来做一个通用实现。

1. 找出合理的事件 我们可以直接查看jvmti.h文件中枚举的jvm事件，既然我们是关注的是synchronized，那么关键词，我们就得看MONITOR。通过筛选，我们可以选出下面四个事件。

    JVMTI_EVENT_MONITOR_WAIT 
    JVMTI_EVENT_MONITOR_WAITED 
    JVMTI_EVENT_MONITOR_CONTENDED_ENTER 
    JVMTI_EVENT_MONITOR_CONTENDED_ENTERED 

事件可以查阅jvmti的官方文档也可以直接看命名的含义，如果想再次确认，那还是看官方文档吧。 我们选择的事件是

    JVMTI_EVENT_MONITOR_CONTENDED_ENTER //开始进入锁事件
    JVMTI_EVENT_MONITOR_CONTENDED_ENTERED//开始获取到锁的事件

上面两个事件触发的时间差就是锁等待的时间。

2. 确定唯一标志 想要唯一标识一个锁的等待，必须要求线程id相同，锁的对象相同。这两个信息在通知事件的函数指针中可以获取到。

typedef void (JNICALL *jvmtiEventMonitorContendedEntered)
    (jvmtiEnv *jvmti_env,
     JNIEnv* jni_env,
     jthread thread,
     jobject object);

thread就是java线程的对象，object就是锁的对象。 这里都是jni的对象，我们还得通过jni的调用来获取我们想要的信息，例如下面的例子，我们获取线程id，线程name，对象的hashcode。最后通过直接的字符串拼接作为一个唯一id。

void JNICALL jvmti_EventMonitorContendedEnter(jvmtiEnv *jvmti_env,
                                              JNIEnv *jni_env,
                                              jthread thread,
                                              jobject object) {

    jclass threadClass = jni_env->GetObjectClass(thread);
    jmethodID getId = jni_env->GetMethodID(threadClass, "getId", "()J");
    jlong id = (jlong) jni_env->CallObjectMethod(thread, getId);
    jmethodID getName = jni_env->GetMethodID(threadClass, "getName", "()Ljava/lang/String;");
    const char *name = jni_env->GetStringUTFChars((jstring) jni_env->CallObjectMethod(thread, getName), NULL);
    jclass objectClass = jni_env->GetObjectClass(object);
    jmethodID hashcode = jni_env->GetMethodID(objectClass, "hashCode", "()I");
    jint code = jni_env->CallIntMethod(objectClass, hashcode);
    std::string str = std::to_string(id) + name + std::to_string(code);
    upset(str);
}

3. 更新时间 上面的upset方法就是一个利用唯一id更新时间的方式。

//用来记录时间的对象
class Time {
public:
    long start;
    long end;
};

std::map<std::string, Time *> mapstring;
std::mutex mutex;
void upset(std::string &key) {
    mutex.lock();
    time_t now = time(0);
    std::map<std::string, Time *>::iterator l_it;;
    l_it = mapstring.find(key);
    if (l_it == mapstring.end()) {
        Time *time = new Time();
        time->start = now;
        mapstring[key] = time;
    } else {
        l_it->second->end = now;
    }

    mutex.unlock();

}

这里考虑是多线程的操作，所以通过加锁来保证记录准确性。

4. 输出记录 我这里选择进程结束的时候输出记录。所以把输出方法加在了Agent_OnUnload方法中。

JNIEXPORT void JNICALL
Agent_OnUnload(JavaVM *vm) {
    std::cout << mapstring.size() << std::endl;
    for (std::map<std::string, Time *>::iterator itr = mapstring.begin(); itr != mapstring.end(); itr++)
        std::cout << itr->first << " " << (itr->second->end - itr->second->start) << std::endl;

}

测试结果

我们把动态库生成以后，通过-agentpath加载我们生成的对象方法上。我们自己写了一个特别简单的例子，就是方法睡3秒，多线程执行。我们看看展示的结果。

12Thread-11846274136 9
13Thread-21846274136 3
1main1846274136 6

时间获取的时候单位是秒，所以这里打印的线程以及等待的时间都是秒级别的。