从分析async-profiler的实现细节来学习jvmti

0.155字数 3441阅读 1630

作者: 一字马胡
转载标志 【2017-12-22】

更新日志

日期 更新内容 备注
2017-12-22 有趣、有用的性能分析工具分享 参考Java应用性能分析工具:async-profiler

厉害的内容分享

在上一篇文章中分享了一个用于分析java应用性能的厉害角色:async-profiler,具体的内容可以参考Java应用性能分析工具:async-profiler,如果想要研究async-profiler的具体实现细节,可以到github上将其源码下载下来进行分析研究。本文的内容接着上一篇的内容,并且将分析一下async-profiler的具体实现过程,当然不会涉及太过细节的实现内容,主要是分析async-profiler工具的工作模型,以及一些相关的内容。

本文也作为学习jvmti的开头,jvmti全称为java virtual machine tool interface,是jvm提供的一套用于和jvm交互的api,相当于操作系统中的系统调用的概念,只是系统调用面向的是os内核,而jvmti面向的是jvm内核,jvmti使得我们有能力增强jvm,可以让运行中的jvm运行我们的代码,或者向运行中的jvm要求产生一些profile数据,来分析系统的运行状况,总之,jvmti使得开发人员可以直接与jvm交互,并且有能力做一些较为偏向jvm底层的事情。

async-profiler工具也是基于jvmti来开发的,使用的是Attech技术,也就是async-profiler会向运行中的jvm发送数据(命令)来进行一些定制操作,而jvm启动的时候会随身启动用于监控项jvm发送的信号,并且做出一些相应,并且jvm会在合适的时候开启用于服务java agent的Attach Listener线程,async-profiler就是一个java agent,它会向运行中的jvm发送一个信号,使得jvm有能力对async-profiler发送的command进行一些相应,这其中细节较多,目前不做过多分析,大概了解jvm和async-profiler之间确实存在交互就可以了,而async-profiler是作为一个java agent,并且作为一个client而存在的,而jvm中会有专门的线程来负责和java agent交互(服务),所以一般来说,类似于async-profiler的工具并不会对运行的java应用造成什么影响(这一点有待研究)。

下面开始来分析async-profiler的具体实现内容,下面的图片首先展示了async-profiler的工作流程,理解async-profiler的工作流程很重要,否则可能不知道async-profiler的那一部分代码在负责什么,或者如果想要基于async-profiler做二次开发的话应该从何下手:

当然上面的图片只是大概展示了async-profiler的工作流程,具体的实现要比这个复杂得多,下面来具体分析一下整个工作流程。首先,我们使用async-profiler都是以一个脚本来开始的,比如下面这个命名:


./profiler.sh -d 2 -f /tmp/result.1222.txt pid

所以有必要去了解一下./profiler.sh这个脚本的内容,其实主要内容很简单,就是接受命令行的参数输入,然后开始与async-profiler进行交互,解析命令的过程就不做解释了,其中一个很重要的shell方法是jattach,下面是它的具体内容:


jattach() {
    $JATTACH $PID load "$PROFILER" true $1 > /dev/null
    RET=$?

    # Check if jattach failed
    if [ $RET -ne 0 ]; then
        if [ $RET -eq 255 ]; then
            echo "Failed to inject profiler into $PID"
            UNAME_S=$(uname -s)
            if [ "$UNAME_S" == "Darwin" ]; then
                otool -L "$PROFILER"
            else
                ldd "$PROFILER"
            fi
        fi
        exit $RET
    fi

    mirror_output
}

所以可以看出,在jattach方法一开始便会执行一条load指令,这一条指令的作用是将sync-profiler载入,使得后面的命令可以被sync-profiler来处理,在方法的最后调用了一个方法mirror_output:


mirror_output() {
    # Mirror output from temporary file to local terminal
    if [[ $USE_TMP ]]; then
        if [[ -f $FILE ]]; then
            cat $FILE
            rm $FILE
        fi
    fi
}

所以这就是为什么每次如果不指定-f的话总是会将结果打印出来的原因。下面是一些运行时默认参数设置:


OPTIND=1
SCRIPT_DIR=$(dirname $0)
JATTACH=$SCRIPT_DIR/build/jattach
PROFILER=$(abspath $SCRIPT_DIR/build/libasyncProfiler.so)
ACTION="collect"
EVENT="cpu"
DURATION="60"
FILE=""
USE_TMP="true"
INTERVAL=""
FRAMEBUF=""
THREADS=""
OUTPUT="summary,traces=200,flat=200"

这里需要注意的是默认的EVENT是cpu,默认的ACTION是collect,所以在我么没有指定ACTION的时候,总是执行collect的原因,其他指定了ACTION的话就执行相应的ACTION。

好了,./profiler.sh脚本就相当于sync-profiler的前端,它接收命令行输入,并且会将输入做一些处理,然后会将这些被处理过的命令发送给sync-profiler,接下来的部分就是进入了sync-profiler了。首先找到jattach.c这个文件,找到它的main方法,这是sync-profiler工具的入口,而./profiler.sh脚本接收的命令会传递给jattach.c这个文件的main方法,所以分析一下jattach.c这个文件是有必要的。

下面的代码截取自main方法,是我认为main方法中最为关键的几行代码:

首先是check_socket方法,来看一下具体的实现细节:

// Check if remote JVM has already opened socket for Dynamic Attach
static int check_socket(int pid) {
    char path[MAX_PATH];
    snprintf(path, MAX_PATH, "%s/.java_pid%d", get_temp_directory(), pid);

    struct stat stats;
    return stat(path, &stats) == 0 && S_ISSOCK(stats.st_mode);
}

它所实现的功能就是检查sync-profiler工具是否已经打开了一个用于Attach的socket,然后来看start_attach_mechanism方法:


// Force remote JVM to start Attach listener.
// HotSpot will start Attach listener in response to SIGQUIT if it sees .attach_pid file
static int start_attach_mechanism(int pid, int nspid) {
    char path[MAX_PATH];
    snprintf(path, MAX_PATH, "/proc/%d/cwd/.attach_pid%d", nspid, nspid);
    
    int fd = creat(path, 0660);
    if (fd == -1 || (close(fd) == 0 && !check_file_owner(path))) {
        // Failed to create attach trigger in current directory. Retry in /tmp
        snprintf(path, MAX_PATH, "%s/.attach_pid%d", get_temp_directory(), nspid);
        fd = creat(path, 0660);
        if (fd == -1) {
            return 0;
        }
        close(fd);
    }
    
    // We have to still use the host namespace pid here for the kill() call
    kill(pid, SIGQUIT);
    
    int result;
    struct timespec ts = {0, 100000000};
    int retry = 0;
    do {
        nanosleep(&ts, NULL);
        result = check_socket(nspid);
    } while (!result && ++retry < 10);

    unlink(path);
    return result;
}

这个方法实现的功能是让jvm开启Attach Listener线程来服务java agent,具体的实现方法是向jvm进程发送一个SIGQUIT信号,而这个SIGQUIT信号仅会被jvm中特殊的信号处理器接收,jvm接收到这个信号之后不是结束jvm进程(出大事了那就),而是会开启Attach Listener线程,这样,jvm就有服务java agent的能力了,下面就可以连接到jvm了,实现该功能的函数是connect_socket:


// Connect to UNIX domain socket created by JVM for Dynamic Attach
static int connect_socket(int pid) {
    int fd = socket(PF_UNIX, SOCK_STREAM, 0);
    if (fd == -1) {
        return -1;
    }
    
    struct sockaddr_un addr;
    addr.sun_family = AF_UNIX;
    snprintf(addr.sun_path, sizeof(addr.sun_path), "%s/.java_pid%d", get_temp_directory(), pid);

    if (connect(fd, (struct sockaddr*)&addr, sizeof(addr)) == -1) {
        close(fd);
        return -1;
    }
    return fd;
}

连接到jvm之后,就可以向jvm发送数据(command)了,具体实现发送数据的函数是write_command,下面是该函数的具体内容:


// Send command with arguments to socket
static int write_command(int fd, int argc, char** argv) {
    // Protocol version
    if (write(fd, "1", 2) <= 0) {
        return 0;
    }

    int i;
    for (i = 0; i < 4; i++) {
        const char* arg = i < argc ? argv[i] : "";
        if (write(fd, arg, strlen(arg) + 1) <= 0) {
            return 0;
        }
    }
    return 1;
}

好了,到此为止,sync-profiler作为Client的路径就到头了,如果没有理解开头的那张图片的话,就很难继续分析下去了。分析到这里,我们可以肯定的是,jvm已经可以接受我们的命令了,并且已经接受了一些命令了,还记得./profiler.sh这个脚本中的就jattach方法吧,这个方法会有一个load命令,而load命令式jvm可以是识别的命令,具体这部分内容会在其他的文章中具体分析,本文不做深入分析,但是我们应该知道,jvm已经把sync-profiler的agent部分的代码load进来了,它可以和agent交互了,接下来我们就可以去分析java agent的部分了,这很神奇,我们首先将我们的命令传递给了我们自己写的代码,然后我们的代码会将这些命令发送给jvm,jvm会做一些准备工作,然后将我们发送的命令再次发送给我们自己写的agent,然后具体处理过程就是我们自己的代码在进行的,这也就是所谓的jvm增强吧。

接着来看vmEntry.cpp这个文件,这就是我们来与jvm交互的地方,据我猜测,sync-profiler使用Attach的方式来和jvm交互,那么就应该关注Agent_OnAttach这个方法,这个方法大概是在jvm检测到Attach的java agent的时候会触发的一个函数,下面是vmEntry.cpp中Agent_OnAttach的具体实现细节:


extern "C" JNIEXPORT jint JNICALL
Agent_OnAttach(JavaVM* vm, char* options, void* reserved) {
    VM::init(vm, true);

    Arguments args;
    Error error = args.parse(options);
    if (error) {
        std::cerr << error.message() << std::endl;
        return -1;
    }

    // Save the arguments in case of shutdown
    _agent_args = args;
    Profiler::_instance.run(args);

    return 0;
}

该函数的options参数就是我们的jattach发送给jvm的数据内容(具体参数),接下来会有解析命令的代码,在Agent_OnAttach函数内部首先执行的是一个init方法,该方法中进行的内容就是传统的jvmti开发的套路(获取jvmtiEnv等等),init方法中首先会判断jvmtiEnv是否不为NULL,不为NULL代表以及获取过jvmtiEnv了,就不需要再次进行init方法了,否则继续走接下来的初始化逻辑。首先是获取jvmtiEnv:


    _vm->GetEnv((void**)&_jvmti, JVMTI_VERSION_1_0);

然后打开一些capabilities:


   capabilities.can_generate_all_class_hook_events = 1;
    capabilities.can_get_bytecodes = 1;
    capabilities.can_get_constant_pool = 1;
    capabilities.can_get_source_file_name = 1;
    capabilities.can_get_line_numbers = 1;
    capabilities.can_generate_compiled_method_load_events = 1;
    capabilities.can_generate_monitor_events = 1;
    capabilities.can_tag_objects = 1;
    _jvmti->AddCapabilities(&capabilities);

接着设置callbacks,也就是说,jvm会在发生了某种event的时候触发一些函数的执行,下面是sync-profiler的设置:


   jvmtiEventCallbacks callbacks = {0};
    callbacks.VMInit = VMInit;
    callbacks.VMDeath = VMDeath;
    callbacks.ClassLoad = ClassLoad;
    callbacks.ClassPrepare = ClassPrepare;
    callbacks.CompiledMethodLoad = Profiler::CompiledMethodLoad;
    callbacks.CompiledMethodUnload = Profiler::CompiledMethodUnload;
    callbacks.DynamicCodeGenerated = Profiler::DynamicCodeGenerated;
    callbacks.ThreadStart = PerfEvents::ThreadStart;
    callbacks.ThreadEnd = PerfEvents::ThreadEnd;
    callbacks.MonitorContendedEnter = LockTracer::MonitorContendedEnter;
    callbacks.MonitorContendedEntered = LockTracer::MonitorContendedEntered;
    _jvmti->SetEventCallbacks(&callbacks, sizeof(callbacks));

当然还需要设置通知,在发生event的时候通知一下:


  _jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_VM_INIT, NULL);
    _jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_VM_DEATH, NULL);
    _jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_CLASS_LOAD, NULL);
    _jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_CLASS_PREPARE, NULL);
    _jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_COMPILED_METHOD_LOAD, NULL);
    _jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_COMPILED_METHOD_UNLOAD, NULL);
    _jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_DYNAMIC_CODE_GENERATED, NULL);

接着执行了一个函数:PerfEvents::init(),比如在Mac OS上,这个方法就什么也不做,在linux上会做一些初始化,具体细节参考具体的代码就好了。接下来继续分析Agent_OnAttach方法,jvmti初始化之后,Agent_OnAttach将要做的事情是解析options,具体的参数解析过程参考Arguments::parse,主要需要注意的一点是下面的Arguments::parse方法中的代码:


    if (dumpRequested() && (_action == ACTION_NONE || _action == ACTION_STOP)) {
        _action = ACTION_DUMP;
    }

可以看到,当没有ACTION,或者ACTION为ACTION_STOP的时候都会将ACTION变为ACTION_DUMP,这一点需要特别注意,否则会优点懵逼为什么我们的命令和最后的结果不太符合。解析出的结果将被保存在Arguments对象中,接着,在Agent_OnAttach函数的最后执行了函数:Profiler::_instance.run(args)。下面是具体的代码:


void Profiler::run(Arguments& args) {
    if (args._file == NULL) {
        runInternal(args, std::cout);
    } else {
        std::ofstream out(args._file, std::ios::out | std::ios::trunc);
        if (out.is_open()) {
            runInternal(args, out);
            out.close();
        } else {
            std::cerr << "Could not open " << args._file << std::endl;
        }
    }
}

其实这个方法只是一个facade,具体的处理是在函数runInternal中进行的,这个facade的功能是准备一个输出流,如果指定了输出文件(-f命令),那么就打开这个文件作为输出流,否则将std::out作为输出流,下面来看runInternal方法的细节:


void Profiler::runInternal(Arguments& args, std::ostream& out) {
    switch (args._action) {
        case ACTION_START: {
            Error error = start(args._event, args._interval, args._framebuf, args._threads);
            if (error) {
                out << error.message() << std::endl;
            } else {
                out << "Started [" << args._event << "] profiling" << std::endl;
            }
            break;
        }
        case ACTION_STOP: {
            Error error = stop();
            if (error) {
                out << error.message() << std::endl;
            } else {
                out << "Stopped profiling after " << uptime() << " seconds" << std::endl;
            }
            break;
        }
        case ACTION_STATUS: {
            MutexLocker ml(_state_lock);
            if (_state == RUNNING) {
                out << "[" << _engine->name() << "] profiling is running for " << uptime() << " seconds" << std::endl;
            } else {
                out << "Profiler is not active" << std::endl;
            }
            break;
        }
        case ACTION_LIST: {
            out << "Perf events:" << std::endl;
            const char** perf_events = PerfEvents::getAvailableEvents();
            for (const char** event = perf_events; *event != NULL; event++) {
                out << "  " << *event << std::endl;
            }
            delete[] perf_events;

            out << "Java events:" << std::endl;
            out << "  " << EVENT_ALLOC << std::endl;
            out << "  " << EVENT_LOCK << std::endl;
            break;
        }
        case ACTION_DUMP:
            stop();
            out << " ::::::: Greet from Profiler  :::::::: " << std::endl;
            if (args._dump_collapsed) dumpCollapsed(out, args._counter);
            if (args._dump_summary) dumpSummary(out);
            if (args._dump_traces > 0) dumpTraces(out, args._dump_traces);
            if (args._dump_flat > 0) dumpFlat(out, args._dump_flat);
            break;
        default:
            break;
    }
}

其实这个函数类似于controller,是做dispatch的,现在回头看./proflier.sh脚本,我们以命令:


./profiler -d 2 -f /tmp/result.txt pid

为例,该命令中没有指定ACTION,所以根据脚本内容可以知道该ACTION为collect,下面展示了脚本中关于这部分的细节:


    collect)
        jattach start,event=$EVENT,file=$FILE$INTERVAL$FRAMEBUF$THREADS,$OUTPUT
        while (( DURATION-- > 0 )); do
            check_if_terminated
            sleep 1
        done
        jattach stop,file=$FILE,$OUTPUT
        ;;

所以开始是start,然后进行DURATION时间(-d命令指定),然后执行一次stop。所以现在先来看ACTION_START,它触发了一个start函数,下面的代码片段展示了start方法中的核心逻辑:

_engine就是真实的处理器,根据我们上面的示例命令,该_engine的结果应该是一个PerfEvents(),所以_engine->start(event, interval)执行的实际上是PerfEvents的相应方法,因为我是在Mac下做的实验,所以一Mac环境为例,实际执行的是perfEvents_macos.cpp中的PerfEvents::start方法:


Error PerfEvents::start(const char* event, long interval) {
    if (strcmp(event, EVENT_CPU) != 0) {
        return Error("Event is not supported on this platform");
    }

    if (interval < 0) {
        return Error("interval must be positive");
    }
    _interval = interval ? interval : DEFAULT_INTERVAL;

    installSignalHandler();

    long sec = _interval / 1000000000;
    long usec = (_interval % 1000000000) / 1000;
    struct itimerval tv = {{sec, usec}, {sec, usec}};
    setitimer(ITIMER_PROF, &tv, NULL);

    return Error::OK;
}

这里面调用了一个函数installSignalHandler,看名字应该是装载信号处理器的意思,具体看下其中的代码:


void PerfEvents::installSignalHandler() {
    struct sigaction sa;
    sigemptyset(&sa.sa_mask);
    sa.sa_handler = NULL;
    sa.sa_sigaction = signalHandler;
    sa.sa_flags = SA_RESTART | SA_SIGINFO;

    sigaction(SIGPROF, &sa, NULL);
}

我比较关心的是 sa.sa_sigaction = signalHandler这一句,这一句就是设定信号处理函数的语句,并且将这个信号处理器用来处理SIGPROF信号,先来看信号处理器signalHandler的具体内容:


void PerfEvents::signalHandler(int signo, siginfo_t* siginfo, void* ucontext) {
    Profiler::_instance.recordSample(ucontext, _interval, 0, NULL);
}

到此,回头看start方法中的接下来的内容,其中很关键的是调用了settimer函数来设定定时器,并且在定时器到时的时候会触发SIGPROF信号,这个时候上面设定的信号处理器signalHandler就会开始执行了。接着看signalHandler,调用了Profiler的recordSample方法,ucontext方法就是从jvm采集到的profile数据,需要提及的一点是,async-profiler借助AsyncGetCallTrace来获取jvm的profile数据,而我对于AsyncGetCallTrace的了解很少,所以先不做分析,知道signalHandler的参数的ucontext是AsyncGetCallTrace从jvm收集到的就可以了。接着看recordSample方法的细节:


void Profiler::recordSample(void* ucontext, u64 counter, jint event_type, jmethodID event) {
    u64 lock_index = atomicInc(_total_samples) % CONCURRENCY_LEVEL;
    if (!_locks[lock_index].tryLock()) {
        atomicInc(_failures[-ticks_skipped]);  // too many concurrent signals already
        return;
    }

    atomicInc(_total_counter, counter);

    ASGCT_CallFrame* frames = _calltrace_buffer[lock_index];
    int tid = PerfEvents::tid();

    int num_frames = event != NULL ? makeEventFrame(frames, event_type, event) : 0;
    num_frames += getNativeTrace(tid, frames);
    num_frames += getJavaTraceAsync(ucontext, frames + num_frames, MAX_STACK_FRAMES - 1 - num_frames);

    if (_threads) {
        num_frames += makeEventFrame(frames + num_frames, BCI_THREAD_ID, (jmethodID)(uintptr_t)tid);
    }

    if (num_frames > 0) {
        storeCallTrace(num_frames, frames, counter);
        storeMethod(frames[0].method_id, frames[0].bci, counter);
    }

    _locks[lock_index].unlock();
}

该方法的功能就是将从jvm收集到的profile数据经过一些统计出来之后存储起来,然后用于输出到原先准备好的流中去,到此,ACTION_START的流程已经走完了,现在来看一下上面脚本中分析的ACTION_STOP,最后执行的是ACTION_DUMP,下面来看一下ACTION_DUMP具体做哪些事情:


            stop();
            out << " ::::::: Greet from Profiler  :::::::: " << std::endl;
            if (args._dump_collapsed) dumpCollapsed(out, args._counter);
            if (args._dump_summary) dumpSummary(out);
            if (args._dump_traces > 0) dumpTraces(out, args._dump_traces);
            if (args._dump_flat > 0) dumpFlat(out, args._dump_flat);

首先会执行stop方法,然后就是几个dump方法,先来看stop方法具体做了什么:


Error Profiler::stop() {
    MutexLocker ml(_state_lock);
    if (_state != RUNNING) {
        return Error("Profiler is not active");
    }

    _engine->stop();
    delete _engine;

    _state = IDLE;
    return Error::OK;
}

更新状态为IDLE,并且执行_engine->stop,具体看Mac下执行的_engine->stop:


void PerfEvents::stop() {
    struct itimerval tv = {{0, 0}, {0, 0}};
    setitimer(ITIMER_PROF, &tv, NULL);
}

现在再来看一下ACTION_DUMP接下来做的事情,比如dumpTraces:


void Profiler::dumpTraces(std::ostream& out, int max_traces) {
    MutexLocker ml(_state_lock);
    if (_state != IDLE) return;

    FrameName fn(true);
    double percent = 100.0 / _total_counter;
    char buf[1024];

    qsort(_traces, MAX_CALLTRACES, sizeof(CallTraceSample), CallTraceSample::comparator);
    if (max_traces > MAX_CALLTRACES) max_traces = MAX_CALLTRACES;

    for (int i = 0; i < max_traces; i++) {
        CallTraceSample& trace = _traces[i];
        if (trace._samples == 0) break;

        snprintf(buf, sizeof(buf), "Total: %lld (%.2f%%)  samples: %lld\n",
                 trace._counter, trace._counter * percent, trace._samples);
        out << buf;

        if (trace._num_frames == 0) {
            out << "  [ 0] [frame_buffer_overflow]\n";
        }

        for (int j = 0; j < trace._num_frames; j++) {
            const char* frame_name = fn.name(_frame_buffer[trace._start_frame + j]);
            snprintf(buf, sizeof(buf), "  [%2d] %s\n", j, frame_name);
            out << buf;
        }
        out << "\n";
    }
}

该函数的功能就是按照格式将从jvm采集到的profile数据输出到提前准备好的输出流中去,如果我们指定了输出路径(-f命令),那么就会输出到具体的文件中去,否则会直接输出到控制台去。

好了,本文的内容基于async-profiler,对async-profiler的执行流程做了一定程度的梳理,当然本文内容还是相对较为浅显易懂的,async-profiler作为一个优秀的java性能检测工具,值得深究,深入学习jvmti以及做一些实践的计划已经列在了我的计划清单中,未来会持续学习jvmti相关的内容,并且会基于async-profiler工具进行一些扩展,本文算是对学习jvmti的开篇,也是对探索java性能检测工具的开篇,至少对我来说,jvm、jvmti、profile等内容还是充满诱惑的。

推荐阅读更多精彩内容