diff --git a/example/.gitignore b/example/.gitignore index 45cbd136..7c70356f 100644 --- a/example/.gitignore +++ b/example/.gitignore @@ -1,3 +1,4 @@ simple_uretprobe_test* malloc-perf* go-trace-test* +/simple-map-test diff --git a/runtime/src/bpf_map/shared/array_map_kernel_user.cpp b/runtime/src/bpf_map/shared/array_map_kernel_user.cpp index cc56e7cb..9b714903 100644 --- a/runtime/src/bpf_map/shared/array_map_kernel_user.cpp +++ b/runtime/src/bpf_map/shared/array_map_kernel_user.cpp @@ -52,8 +52,9 @@ void array_map_kernel_user_impl::init_map_fd() // return; // } size_t mmap_sz = bpf_map_mmap_sz(_value_size, _max_entries); - spdlog::debug("mmap shared array map, fd={}, mmap_sz={}", map_fd, - mmap_sz); + spdlog::debug( + "mmap shared array map, fd={}, mmap_sz={}, name={}, value_size={}, flags={}", + map_fd, mmap_sz, info.name, info.value_size, info.map_flags); mmap_ptr = mmap(NULL, mmap_sz, PROT_READ | PROT_WRITE, MAP_SHARED | MAP_ANONYMOUS, -1, 0); if (mmap_ptr == MAP_FAILED) { @@ -70,8 +71,9 @@ void array_map_kernel_user_impl::init_map_fd() void *mmaped = mmap(mmap_ptr, mmap_sz, prot, MAP_SHARED | MAP_FIXED, map_fd, 0); if (mmaped == MAP_FAILED) { - spdlog::error("Failed to mmap for kernel map id {}, err={}", - kernel_map_id, errno); + spdlog::error( + "Failed to re-mmap for kernel map id {}, err={}, prot={}", + kernel_map_id, errno, prot); return; } mmap_ptr = mmaped; @@ -88,13 +90,20 @@ void *array_map_kernel_user_impl::elem_lookup(const void *key) if (map_fd < 0) { init_map_fd(); } + spdlog::debug("Run lookup of shared array map, key={:x}", + (uintptr_t)key); if (mmap_ptr != nullptr) { auto key_val = *(uint32_t *)key; + + spdlog::debug("mmap handled, key={}", key_val); if (key_val >= _max_entries) { errno = ENOENT; + spdlog::debug("Returned ENOENT"); return nullptr; } - return &((uint8_t *)mmap_ptr)[key_val * _value_size]; + auto result = &((uint8_t *)mmap_ptr)[key_val * _value_size]; + spdlog::debug("Returned value addr: {:x}", (uintptr_t)result); + return result; } // fallback to read kernel maps int res = bpf_map_lookup_elem(map_fd, key, value_data.data()); diff --git a/runtime/src/bpf_map/shared/array_map_kernel_user.hpp b/runtime/src/bpf_map/shared/array_map_kernel_user.hpp index 14c77752..1bde0c2d 100644 --- a/runtime/src/bpf_map/shared/array_map_kernel_user.hpp +++ b/runtime/src/bpf_map/shared/array_map_kernel_user.hpp @@ -17,7 +17,7 @@ class array_map_kernel_user_impl { void init_map_fd(); public: - const static bool should_lock = true; + const static bool should_lock = false; array_map_kernel_user_impl(boost::interprocess::managed_shared_memory &memory, int km_id); ~array_map_kernel_user_impl(); diff --git a/runtime/src/bpftime_prog.cpp b/runtime/src/bpftime_prog.cpp index 900517fa..eb7af34b 100644 --- a/runtime/src/bpftime_prog.cpp +++ b/runtime/src/bpftime_prog.cpp @@ -72,10 +72,16 @@ int bpftime_prog::bpftime_prog_exec(void *memory, size_t memory_size, { uint64_t val = 0; int res = 0; - + spdlog::debug( + "Calling bpftime_prog::bpftime_prog_exec, memory={:x}, memory_size={}, return_val={:x}, prog_name={}", + (uintptr_t)memory, memory_size, (uintptr_t)return_val, + this->name); if (jitted) { + spdlog::debug("Directly call jitted function at {:x}", + (uintptr_t)fn); val = fn(memory, memory_size); } else { + spdlog::debug("Running using ebpf_exec"); res = ebpf_exec(vm, memory, memory_size, &val); if (res < 0) { spdlog::error("ebpf_exec returned error: {}", res); diff --git a/runtime/src/bpftime_shm.cpp b/runtime/src/bpftime_shm.cpp index c90d5b49..a962d4ca 100644 --- a/runtime/src/bpftime_shm.cpp +++ b/runtime/src/bpftime_shm.cpp @@ -384,10 +384,12 @@ const uint64_t INVALID_MAP_PTR = ((uint64_t)0 - 1); extern "C" uint64_t map_ptr_by_fd(uint32_t fd) { + spdlog::debug("Call map_ptr_by_fd with fd={}", fd); if (!shm_holder.global_shared_memory.get_manager() || !shm_holder.global_shared_memory.is_map_fd(fd)) { errno = ENOENT; - spdlog::error("Expected fd {} to be a map fd", fd); + spdlog::error("Expected fd {} to be a map fd (map_ptr_by_fd)", + fd); // Here we just ignore the wrong maps return INVALID_MAP_PTR; } @@ -397,10 +399,12 @@ extern "C" uint64_t map_ptr_by_fd(uint32_t fd) extern "C" uint64_t map_val(uint64_t map_ptr) { + spdlog::debug("Call map_val with map_ptr={:x}", map_ptr); int fd = (int)(map_ptr >> 32); if (!shm_holder.global_shared_memory.get_manager() || !shm_holder.global_shared_memory.is_map_fd(fd)) { - spdlog::error("Expected fd {} to be a map fd", fd); + spdlog::error("Expected fd {} to be a map fd (map_val call)", + fd); // here we just ignore the wrong maps errno = ENOENT; return 0; diff --git a/vm/llvm-jit/src/bpf_jit.cpp b/vm/llvm-jit/src/bpf_jit.cpp index 4ca13caa..a67afac2 100644 --- a/vm/llvm-jit/src/bpf_jit.cpp +++ b/vm/llvm-jit/src/bpf_jit.cpp @@ -75,7 +75,7 @@ ebpf_jit_fn bpf_jit_context::compile() spdlog::debug("Defining LDDW helper {} with addr {:x}", name, (uintptr_t)func); auto sym = - JITEvaluatedSymbol::fromPointer(vm->map_by_fd); + JITEvaluatedSymbol::fromPointer(func); sym.setFlags(JITSymbolFlags::Callable | JITSymbolFlags::Exported); lddwSyms.try_emplace(jit->mangleAndIntern(name), sym); diff --git a/vm/llvm-jit/src/bpf_jit_compile_module.cpp b/vm/llvm-jit/src/bpf_jit_compile_module.cpp index 3ce361db..476c0953 100644 --- a/vm/llvm-jit/src/bpf_jit_compile_module.cpp +++ b/vm/llvm-jit/src/bpf_jit_compile_module.cpp @@ -624,6 +624,8 @@ bpf_jit_context::generateModule(const LLJIT &jit, val, (uint64_t)inst.imm, (uint64_t)nextInst.imm); if (inst.src_reg == 0) { + spdlog::debug("Emit lddw helper 0 at pc {}", + pc); builder.CreateStore(builder.getInt64(val), regs[inst.dst_reg]); } else if (inst.src_reg == 1) { @@ -632,6 +634,9 @@ bpf_jit_context::generateModule(const LLJIT &jit, itr != lddwHelper.end()) { + spdlog::debug( + "Emit lddw helper 1 (map_by_fd) at pc {}, imm={}", + pc, inst.imm); builder.CreateStore( builder.CreateCall( lddwHelperWithUint32, @@ -668,6 +673,10 @@ bpf_jit_context::generateModule(const LLJIT &jit, builder.CreateStore( finalRet, regs[inst.dst_reg]); + spdlog::debug( + "Emit lddw helper 2 (map_by_fd + map_val) at pc {}, imm1={}, imm2={}", + pc, inst.imm, + nextInst.imm); } else { return llvm::make_error< llvm::StringError>( @@ -692,6 +701,9 @@ bpf_jit_context::generateModule(const LLJIT &jit, { builder.getInt32( inst.imm) }), regs[inst.dst_reg]); + spdlog::debug( + "Emit lddw helper 3 (var_addr) at pc {}, imm1={}", + pc, inst.imm); } else { return llvm::make_error< llvm::StringError>( @@ -709,6 +721,9 @@ bpf_jit_context::generateModule(const LLJIT &jit, { builder.getInt32( inst.imm) }), regs[inst.dst_reg]); + spdlog::debug( + "Emit lddw helper 4 (code_addr) at pc {}, imm1={}", + pc, inst.imm); } else { return llvm::make_error< llvm::StringError>( @@ -726,6 +741,9 @@ bpf_jit_context::generateModule(const LLJIT &jit, { builder.getInt32( inst.imm) }), regs[inst.dst_reg]); + spdlog::debug( + "Emit lddw helper 4 (map_by_idx) at pc {}, imm1={}", + pc, inst.imm); } else { return llvm::make_error< llvm::StringError>( @@ -755,6 +773,10 @@ bpf_jit_context::generateModule(const LLJIT &jit, builder.CreateStore( finalRet, regs[inst.dst_reg]); + spdlog::debug( + "Emit lddw helper 6 (map_by_idx + map_val) at pc {}, imm1={}, imm2={}", + pc, inst.imm, + nextInst.imm); } else { return llvm::make_error< llvm::StringError>( @@ -832,7 +854,7 @@ bpf_jit_context::generateModule(const LLJIT &jit, } else { if (auto exp = emitExtFuncCall( builder, inst, extFunc, ®s[0], - helperFuncTy); + helperFuncTy, pc); !exp) { return exp.takeError(); } diff --git a/vm/llvm-jit/src/bpf_jit_helpers.h b/vm/llvm-jit/src/bpf_jit_helpers.h index 8e2efe82..57d1b58a 100644 --- a/vm/llvm-jit/src/bpf_jit_helpers.h +++ b/vm/llvm-jit/src/bpf_jit_helpers.h @@ -331,12 +331,13 @@ static llvm::Expected emitCondJmpWithDstAndSrc( static inline llvm::Expected emitExtFuncCall(llvm::IRBuilder<> &builder, const ebpf_inst &inst, const std::map &extFunc, - llvm::Value **regs, llvm::FunctionType *helperFuncTy) + llvm::Value **regs, llvm::FunctionType *helperFuncTy, + uint16_t pc) { auto funcNameToCall = ext_func_sym(inst.imm); if (auto itr = extFunc.find(funcNameToCall); itr != extFunc.end()) { - spdlog::debug("Emitting ext func call to {} name {}", inst.imm, - funcNameToCall); + spdlog::debug("Emitting ext func call to {} name {} at pc {}", + inst.imm, funcNameToCall, pc); auto callInst = builder.CreateCall( helperFuncTy, itr->second, { diff --git a/vm/llvm-jit/src/ebpf_vm.cpp b/vm/llvm-jit/src/ebpf_vm.cpp index 5fe69630..b11cac1e 100644 --- a/vm/llvm-jit/src/ebpf_vm.cpp +++ b/vm/llvm-jit/src/ebpf_vm.cpp @@ -272,6 +272,8 @@ int ebpf_exec(const struct ebpf_vm *vm, void *mem, size_t mem_len, { bpf_jit_context *jit_context; if (vm->jitted_function) { + spdlog::debug("LLJIT: called jitted function {:x}", + (uintptr_t)vm->jitted_function); // has jit yet auto ret = vm->jitted_function(mem, static_cast(mem_len)); @@ -284,6 +286,7 @@ int ebpf_exec(const struct ebpf_vm *vm, void *mem, size_t mem_len, if (!func) { return -1; } + spdlog::debug("LLJIT: compiled function: {:x}", (uintptr_t)func); // after compile, run return ebpf_exec(vm, mem, mem_len, bpf_return_value); }