Add PyPerf, example of profiling Python using BPF (#2239)
This is a tool attaches BPF program to CPU Perf Events for profiling. The BPF program understands CPython internal data structure and hence able to walk actual Python stack-trace, as oppose to strac-trace of the CPython runtime itself as we would normally get with Linux perf.
To use the tool, just run the PyPerf binary:
Use -d / --duration to specify intended profiling duration, in milliseconds. Default value, if not specified, is 1000ms.
Use -c / --sample-rate to specify intended profiling sample rate, same as -c argument of Linux perf. Default value, if not specified, is 1e6.
You can also use -v / --verbose to specify logging verbosity 1 or 2 for more detailed information during profiling.
The tool is a prototype at this point is by no mean mature. It currently has follow limitation:
It only runs on CPU Cycles event.
It only works on Python 3.6 at this point. In fact all Python version from 3.0 to 3.6 should work, I just need to verify and change the constant value. However in Python 3.7 there are some internal data structure changes that the actual parsing logic needs to be updated.
It currently hard-codes the Python internal data structure offsets. It would be better to get a dependency of python-devel and get them directly from the header files.
The output is pretty horrible. No de-duplication across same stack, and we always output the GIL state, Thread state and output them in raw integer value. I will need to work on prettifying the output and make better sense of the enum values.
Landing it in C++ example for now, once it's mature enough I will move it to tools/.diff --git a/examples/cpp/pyperf/PyPerfUtil.cc b/examples/cpp/pyperf/PyPerfUtil.cc
new file mode 100644
index 0000000..d439083
--- /dev/null
+++ b/examples/cpp/pyperf/PyPerfUtil.cc
@@ -0,0 +1,398 @@
+/*
+ * Copyright (c) Facebook, Inc.
+ * Licensed under the Apache License, Version 2.0 (the "License")
+ */
+
+#include <algorithm>
+#include <cerrno>
+#include <chrono>
+#include <cstdio>
+#include <cstring>
+#include <exception>
+#include <unordered_map>
+
+#include <dirent.h>
+#include <linux/elf.h>
+#include <sys/stat.h>
+#include <sys/types.h>
+#include <unistd.h>
+
+#include "PyPerfLoggingHelper.h"
+#include "PyPerfUtil.h"
+#include "bcc_elf.h"
+#include "bcc_proc.h"
+#include "bcc_syms.h"
+
+namespace ebpf {
+namespace pyperf {
+
+extern OffsetConfig kPy36OffsetConfig;
+extern std::string PYPERF_BPF_PROGRAM;
+
+const static std::string kLostSymbol = "[Lost Symbol]";
+const static std::string kIncompleteStack = "[Truncated Stack]";
+const static std::string kErrorStack = "[Stack Error]";
+const static std::string kNonPythonStack = "[Non-Python Code]";
+const static int kPerfBufSizePages = 32;
+
+const static std::string kPidCfgTableName("pid_config");
+const static std::string kProgsTableName("progs");
+const static std::string kSamplePerfBufName("events");
+
+const static std::string kOnEventFuncName("on_event");
+
+const static std::string kPythonStackFuncName("read_python_stack");
+const static std::string kPythonStackProgIdxFlag("-DPYTHON_STACK_PROG_IDX=");
+const static int kPythonStackProgIdx = 0;
+
+const static std::string kNumCpusFlag("-DNUM_CPUS=");
+const static std::string kSymbolsHashSizeFlag("-D__SYMBOLS_SIZE__=");
+const static int kSymbolsHashSize = 16384;
+
+namespace {
+
+bool getRunningPids(std::vector<int>& output) {
+ auto dir = ::opendir("/proc/");
+ if (!dir) {
+ std::fprintf(stderr, "Open /proc failed: %d\n", errno);
+ return false;
+ }
+
+ dirent* result = nullptr;
+ do {
+ if ((result = readdir(dir))) {
+ std::string basename = result->d_name;
+ if (basename == "." || basename == "..") {
+ continue;
+ }
+
+ std::string fullpath = "/proc/" + basename;
+ struct stat st;
+ if (::stat(fullpath.c_str(), &st) != 0 || !S_ISDIR(st.st_mode)) {
+ continue;
+ }
+
+ try {
+ auto pid = std::stoi(basename);
+ output.push_back(pid);
+ } catch (const std::exception& e) {
+ continue;
+ }
+ }
+ } while (result);
+
+ if (::closedir(dir) == -1) {
+ std::fprintf(stderr, "Close /proc failed: %d\n", errno);
+ return false;
+ }
+
+ return true;
+}
+
+typedef struct {
+ int pid;
+ bool found;
+ uint64_t st;
+ uint64_t en;
+} FindPythonPathHelper;
+
+const static std::string kPy36LibName = "libpython3.6";
+
+int findPythonPathCallback(const char* name, uint64_t st, uint64_t en, uint64_t,
+ bool, void* payload) {
+ auto helper = static_cast<FindPythonPathHelper*>(payload);
+ std::string file = name;
+ auto pos = file.rfind("/");
+ if (pos != std::string::npos) {
+ file = file.substr(pos + 1);
+ }
+ if (file.find(kPy36LibName) == 0) {
+ logInfo(1, "Found Python library %s loaded at %lx-%lx for PID %d\n", name, st, en, helper->pid);
+ helper->found = true;
+ helper->st = st;
+ helper->en = en;
+ return -1;
+ }
+ return 0;
+}
+
+bool allAddrFound(const PidData& data) {
+ return (data.current_state_addr > 0) && (data.tls_key_addr > 0) &&
+ (data.gil_locked_addr > 0) && (data.gil_last_holder_addr > 0);
+}
+
+int getAddrOfPythonBinaryCallback(const char* name, uint64_t addr, uint64_t,
+ void* payload) {
+ PidData& data = *static_cast<PidData*>(payload);
+
+ auto checkAndGetAddr = [&](uintptr_t& targetAddr, const char* targetName) {
+ if (targetAddr == 0 && std::strcmp(name, targetName) == 0) {
+ targetAddr = addr;
+ }
+ };
+
+ checkAndGetAddr(data.tls_key_addr, "autoTLSkey");
+ checkAndGetAddr(data.current_state_addr, "_PyThreadState_Current");
+ checkAndGetAddr(data.gil_locked_addr, "gil_locked");
+ checkAndGetAddr(data.gil_last_holder_addr, "gil_last_holder");
+
+ if (allAddrFound(data)) {
+ return -1;
+ }
+ return 0;
+}
+
+bool getAddrOfPythonBinary(const std::string& path, PidData& data) {
+ std::memset(&data, 0, sizeof(data));
+
+ struct bcc_symbol_option option = {.use_debug_file = 0,
+ .check_debug_file_crc = 0,
+ .use_symbol_type = (1 << STT_OBJECT)};
+
+ bcc_elf_foreach_sym(path.c_str(), &getAddrOfPythonBinaryCallback, &option,
+ &data);
+
+ return allAddrFound(data);
+}
+} // namespace
+
+void handleSampleCallback(void* cb_cookie, void* raw_data, int data_size) {
+ auto profiler = static_cast<PyPerfUtil*>(cb_cookie);
+ profiler->handleSample(raw_data, data_size);
+}
+
+void handleLostSamplesCallback(void* cb_cookie, uint64_t lost_cnt) {
+ auto profiler = static_cast<PyPerfUtil*>(cb_cookie);
+ profiler->handleLostSamples(lost_cnt);
+}
+
+PyPerfUtil::PyPerfResult PyPerfUtil::init() {
+ std::vector<std::string> cflags;
+ cflags.emplace_back(kNumCpusFlag +
+ std::to_string(::sysconf(_SC_NPROCESSORS_ONLN)));
+ cflags.emplace_back(kSymbolsHashSizeFlag + std::to_string(kSymbolsHashSize));
+ cflags.emplace_back(kPythonStackProgIdxFlag +
+ std::to_string(kPythonStackProgIdx));
+
+ auto initRes = bpf_.init(PYPERF_BPF_PROGRAM, cflags);
+ if (initRes.code() != 0) {
+ std::fprintf(stderr, "Failed to compiled PyPerf BPF programs: %s\n",
+ initRes.msg().c_str());
+ return PyPerfResult::INIT_FAIL;
+ }
+
+ int progFd = -1;
+ auto loadRes =
+ bpf_.load_func(kPythonStackFuncName, BPF_PROG_TYPE_PERF_EVENT, progFd);
+ if (loadRes.code() != 0) {
+ std::fprintf(stderr, "Failed to load BPF program %s: %s\n",
+ kPythonStackFuncName.c_str(), loadRes.msg().c_str());
+ return PyPerfResult::INIT_FAIL;
+ }
+
+ auto progTable = bpf_.get_prog_table(kProgsTableName);
+ auto updateRes = progTable.update_value(kPythonStackProgIdx, progFd);
+ if (updateRes.code() != 0) {
+ std::fprintf(stderr,
+ "Failed to set BPF program %s FD %d to program table: %s\n",
+ kPythonStackFuncName.c_str(), progFd, updateRes.msg().c_str());
+ return PyPerfResult::INIT_FAIL;
+ }
+
+ std::vector<int> pids;
+ if (!getRunningPids(pids)) {
+ std::fprintf(stderr, "Failed getting running Processes\n");
+ return PyPerfResult::INIT_FAIL;
+ }
+
+ // Populate config for each Python Process
+ auto pid_hash = bpf_.get_hash_table<int, PidData>(kPidCfgTableName);
+ PidData pidData;
+ for (const auto pid : pids) {
+ if (!tryTargetPid(pid, pidData)) {
+ // Not a Python Process
+ continue;
+ }
+ pid_hash.update_value(pid, pidData);
+ }
+
+ // Open perf buffer
+ auto openRes = bpf_.open_perf_buffer(
+ kSamplePerfBufName, &handleSampleCallback, &handleLostSamplesCallback,
+ this, kPerfBufSizePages);
+ if (openRes.code() != 0) {
+ std::fprintf(stderr, "Unable to open Perf Buffer: %s\n",
+ openRes.msg().c_str());
+ return PyPerfResult::PERF_BUF_OPEN_FAIL;
+ }
+
+ initCompleted_ = true;
+ return PyPerfResult::SUCCESS;
+}
+
+void PyPerfUtil::handleSample(const void* data, int dataSize) {
+ const Event* raw = static_cast<const Event*>(data);
+ samples_.emplace_back(raw, dataSize);
+ totalSamples_++;
+}
+
+void PyPerfUtil::handleLostSamples(int lostCnt) { lostSamples_ += lostCnt; }
+
+PyPerfUtil::PyPerfResult PyPerfUtil::profile(int64_t sampleRate,
+ int64_t durationMs) {
+ if (!initCompleted_) {
+ std::fprintf(stderr, "PyPerfUtil::init not invoked or failed\n");
+ return PyPerfResult::NO_INIT;
+ }
+
+ // Attach to CPU cycles
+ auto attachRes =
+ bpf_.attach_perf_event(0, 0, kOnEventFuncName, sampleRate, 0);
+ if (attachRes.code() != 0) {
+ std::fprintf(stderr, "Attach to CPU cycles event failed: %s\n",
+ attachRes.msg().c_str());
+ return PyPerfResult::EVENT_ATTACH_FAIL;
+ }
+ logInfo(2, "Attached to profiling event\n");
+
+ // Get Perf Buffer and poll in a loop for a given duration
+ auto perfBuffer = bpf_.get_perf_buffer(kSamplePerfBufName);
+ if (!perfBuffer) {
+ std::fprintf(stderr, "Failed to get Perf Buffer: %s\n",
+ kSamplePerfBufName.c_str());
+ return PyPerfResult::PERF_BUF_OPEN_FAIL;
+ }
+ logInfo(2, "Started polling Perf Buffer\n");
+ auto start = std::chrono::steady_clock::now();
+ while (std::chrono::steady_clock::now() <
+ start + std::chrono::milliseconds(durationMs)) {
+ perfBuffer->poll(50 /* 50ms timeout */);
+ }
+ logInfo(2, "Profiling duration finished\n");
+
+ // Detach the event
+ auto detachRes = bpf_.detach_perf_event(0, 0);
+ if (detachRes.code() != 0) {
+ std::fprintf(stderr, "Detach CPU cycles event failed: %s\n",
+ detachRes.msg().c_str());
+ return PyPerfResult::EVENT_DETACH_FAIL;
+ }
+ logInfo(2, "Detached from profiling event\n");
+
+ // Drain remaining samples
+ logInfo(2, "Draining remaining samples\n");
+ while (perfBuffer->poll(0) > 0) {
+ }
+ logInfo(2, "Finished draining remaining samples\n");
+
+ // Get symbol names and output samples
+ auto symbolTable = bpf_.get_hash_table<Symbol, int32_t>("symbols");
+ std::unordered_map<int32_t, std::string> symbols;
+ for (auto& x : symbolTable.get_table_offline()) {
+ auto symbolName = getSymbolName(x.first);
+ logInfo(2, "Symbol ID %d is %s\n", x.second, symbolName.c_str());
+ symbols.emplace(x.second, std::move(symbolName));
+ }
+ logInfo(1, "Total %d unique Python symbols\n", symbols.size());
+
+ for (auto& sample : samples_) {
+ if (sample.threadStateMatch != THREAD_STATE_THIS_THREAD_NULL &&
+ sample.threadStateMatch != THREAD_STATE_BOTH_NULL) {
+ for (const auto stackId : sample.pyStackIds) {
+ auto symbIt = symbols.find(stackId);
+ if (symbIt != symbols.end()) {
+ std::printf(" %s\n", symbIt->second.c_str());
+ } else {
+ std::printf(" %s\n", kLostSymbol.c_str());
+ lostSymbols_++;
+ }
+ }
+ switch (sample.stackStatus) {
+ case STACK_STATUS_TRUNCATED:
+ std::printf(" %s\n", kIncompleteStack.c_str());
+ truncatedStack_++;
+ break;
+ case STACK_STATUS_ERROR:
+ std::printf(" %s\n", kErrorStack.c_str());
+ break;
+ default:
+ break;
+ }
+ } else {
+ std::printf(" %s\n", kNonPythonStack.c_str());
+ }
+
+ std::printf("PID: %d TID: %d (%s)\n", sample.pid, sample.tid,
+ sample.comm.c_str());
+ std::printf("GIL State: %d Thread State: %d PthreadID Match State: %d\n\n",
+ sample.threadStateMatch, sample.gilState,
+ sample.pthreadIDMatch);
+ }
+
+ logInfo(0, "%d samples collected\n", totalSamples_);
+ logInfo(0, "%d samples lost\n", lostSamples_);
+ logInfo(0, "%d samples with truncated stack\n", truncatedStack_);
+ logInfo(0, "%d times Python symbol lost\n", lostSymbols_);
+
+ return PyPerfResult::SUCCESS;
+}
+
+std::string PyPerfUtil::getSymbolName(Symbol& sym) const {
+ std::string nameStr = std::string(sym.name).substr(0, FUNCTION_NAME_LEN);
+ std::string classStr = std::string(sym.classname).substr(0, CLASS_NAME_LEN);
+ if (classStr.size() > 0) {
+ nameStr = classStr + "." + nameStr;
+ }
+
+ std::string file = std::string(sym.file).substr(0, FILE_NAME_LEN);
+ if (file.empty()) {
+ return nameStr;
+ }
+ if (file[0] == '/') {
+ file = file.substr(1);
+ }
+ if (file.find("./") == 0) {
+ file = file.substr(2);
+ }
+ if (file.find(".py", file.size() - 3) == (file.size() - 3)) {
+ file = file.substr(0, file.size() - 3);
+ }
+ std::replace(file.begin(), file.end(), '/', '.');
+
+ return file + "." + nameStr;
+}
+
+bool PyPerfUtil::tryTargetPid(int pid, PidData& data) {
+ FindPythonPathHelper helper{pid, false, 0, 0};
+ bcc_procutils_each_module(pid, &findPythonPathCallback, &helper);
+ if (!helper.found) {
+ logInfo(2, "PID %d does not contain Python library\n", pid);
+ return false;
+ }
+
+ char path[256];
+ int res = std::snprintf(path, sizeof(path), "/proc/%d/map_files/%lx-%lx", pid,
+ helper.st, helper.en);
+ if (res < 0 || size_t(res) >= sizeof(path)) {
+ return false;
+ }
+
+ if (!getAddrOfPythonBinary(path, data)) {
+ std::fprintf(stderr, "Failed getting addresses in potential Python library in PID %d\n", pid);
+ return false;
+ }
+ data.offsets = kPy36OffsetConfig;
+ data.current_state_addr += helper.st;
+ logInfo(2, "PID %d has _PyThreadState_Current at %lx\n", pid, data.current_state_addr);
+ data.tls_key_addr += helper.st;
+ logInfo(2, "PID %d has autoTLSKey at %lx\n", pid, data.current_state_addr);
+ data.gil_locked_addr += helper.st;
+ logInfo(2, "PID %d has gil_locked at %lx\n", pid, data.current_state_addr);
+ data.gil_last_holder_addr += helper.st;
+ logInfo(2, "PID %d has gil_last_holder at %lx\n", pid, data.current_state_addr);
+
+ return true;
+}
+
+} // namespace pyperf
+} // namespace ebpf