[BUG] JIT symbols not resolved after mprotect() combined vma

[BUG] JIT symbols not resolved after mprotect() combined vma

[Zhang Boyang]

[-- Attachment #1: Type: text/plain, Size: 2226 bytes --]

Hello,

   I'm using perf to measure my LLVM jitted code performance. However, I 
found with some condition, perf will unable to resolve or annotate JIT 
symbols. After some debugging, I found the cause is mprotect() combined 
two adjacent vma, and report a MMAP2 event of merged vma, confusing perf.
   I wrote a sample program (sample.c). It creates function computing 
factorial. First it creates test1() and exec it for 10000 times. Then, 
it creates test2() and exec both test1() and test2() for 10000 times 
respectively. As a result, test1() was executed 20000 times, and test2() 
was executed 10000 times.
   However, perf report shows:

   33.33%  a.out    jitted-10742-3.so    [.] test2
   33.30%  a.out    jitted-10742-2.so    [.] test1
   33.26%  a.out    [JIT] tid 10742      [.] 0x00007f4b8cb3d010 // test1

   This is because LLVM create jitted code by using mmap() and 
mprotect(): (the address is different because of ASLR)

//// compile test1
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) 
= 0x7fca1a491000
mprotect(0x7fca1a491000, 4096, PROT_READ|PROT_EXEC) = 0
//// compile test2
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) 
= 0x7fca1a490000
mprotect(0x7fca1a490000, 4096, PROT_READ|PROT_EXEC) = 0

   The second mprotect will merge two adjacent vma, and report a MMAP2 
event of merged vma. The pref tool saw this:

9547033496331 0x2510 [0x60]: PERF_RECORD_MMAP2 10742/10742: 
[0x7f4b8cb3d000(0x2000) @ 0x7f4b8cb3d000 00:00 0 0]: r-xp //anon
9547033524086 0xf00 [0xb0]: PERF_RECORD_MMAP2 10742/10742: 
[0x7f4b8cb3d000(0x18) @ 0x40 08:02 10224200 1]: --xs 
/home/zby/src/qemuproject/qemu/.debug/jit/llvm-IR-jit-20210109-ad4573/jitted-10742-2.so
9553628266188 0x103898 [0x60]: PERF_RECORD_MMAP2 10742/10742: 
[0x7f4b8cb3c000(0x3000) @ 0x7f4b8cb3c000 00:00 0 0]: r-xp //anon
9553628283472 0xfb0 [0xb0]: PERF_RECORD_MMAP2 10742/10742: 
[0x7f4b8cb3c000(0x18) @ 0x40 08:02 10224201 1]: --xs 
/home/zby/src/qemuproject/qemu/.debug/jit/llvm-IR-jit-20210109-ad4573/jitted-10742-3.so

   The event of third line, confusing perf, make it thinks test1() had 
disappear. Then perf if unable to resolve test1() or annotate it.


Thank you very much!
Zhang Boyang

[-- Attachment #2: sample.c --]
[-- Type: text/x-csrc, Size: 4502 bytes --]

// Compile me with: (NOTE: LLVM must be compiled with LLVM_USE_PERF=On)
//   gcc -O2 -Wall sample.c $(llvm-config --cflags --ldflags --libs --system-libs) -lstdc++
// Run me with:
//   perf record -k 1 ./a.out
// View perf result with:
//   perf inject -j -i perf.data -o perf.data.jitted && perf report -i perf.data.jitted


#include <assert.h>
#include <stdio.h>
#include <stdlib.h>
#include <llvm-c/Core.h>
#include <llvm-c/Target.h>
#include <llvm-c/Orc.h>
#include <llvm-c/OrcEE.h>
#include <llvm-c/LLJIT.h>
#include <llvm-c/Analysis.h>
#include <llvm-c/Transforms/PassManagerBuilder.h>

static LLVMOrcLLJITRef jit;
static LLVMOrcThreadSafeContextRef tsctx;
static LLVMContextRef ctx;
static LLVMBuilderRef bldr;
static LLVMOrcJITDylibRef jd;
static LLVMPassManagerBuilderRef pmb;
static LLVMPassManagerRef mpm;
static LLVMTypeRef int_ty;
static LLVMValueRef int_0, int_1;

typedef int (*MyFunc)(int n);

static inline void check_error(LLVMErrorRef e)
{
    if (e) {
        char *m = LLVMGetErrorMessage(e);
        puts(m);
        LLVMDisposeErrorMessage(m);
        exit(1);
    }
}
static inline void dump_module(LLVMModuleRef mdl)
{
    char *str = LLVMPrintModuleToString(mdl);
    puts(str);
    LLVMDisposeMessage(str);
}

static MyFunc create_function(const char *name)
{
    LLVMModuleRef mod;
    LLVMValueRef fn, next;
    LLVMTypeRef fn_type;
    LLVMBasicBlockRef entry_bb, recurse_bb, return_bb;
    LLVMOrcJITTargetAddress addr;
    LLVMOrcThreadSafeModuleRef tsm;

    mod = LLVMModuleCreateWithNameInContext(name, ctx);
    fn_type = LLVMFunctionType(int_ty, &int_ty, 1, 0);

    fn = LLVMAddFunction(mod, name, fn_type);
    entry_bb = LLVMAppendBasicBlockInContext(ctx, fn, "entrybb");
    recurse_bb = LLVMAppendBasicBlockInContext(ctx, fn, "recursebb");
    return_bb = LLVMAppendBasicBlockInContext(ctx, fn, "returnbb");

    LLVMPositionBuilderAtEnd(bldr, entry_bb);
    LLVMBuildCondBr(bldr,
        LLVMBuildICmp(bldr,
            LLVMIntEQ,
            LLVMGetParam(fn, 0),
            int_0, ""),
        return_bb,
        recurse_bb);
    
    LLVMPositionBuilderAtEnd(bldr, return_bb);
    LLVMBuildRet(bldr, int_1);

    LLVMPositionBuilderAtEnd(bldr, recurse_bb);
    next = LLVMBuildSub(bldr,
        LLVMGetParam(fn, 0),
        int_1, "");
    LLVMBuildRet(bldr,
        LLVMBuildMul(bldr,
            LLVMBuildCall(bldr, fn, &next, 1, ""),
            LLVMGetParam(fn, 0), ""));

    LLVMVerifyFunction(fn, LLVMAbortProcessAction);

    LLVMRunPassManager(mpm, mod);
    //dump_module(mod);

    tsm = LLVMOrcCreateNewThreadSafeModule(mod, tsctx);
    check_error(LLVMOrcLLJITAddLLVMIRModule(jit, jd, tsm));
    LLVMOrcLLJITLookup(jit, &addr, name);
    
    printf("COMPILE DONE! %s = %p\n", name, (void *)addr);
    return (void *)addr;
}

static LLVMOrcObjectLayerRef create_oll(
    void *Ctx, LLVMOrcExecutionSessionRef ES, const char *Triple)
{
    LLVMOrcObjectLayerRef ol;
    LLVMJITEventListenerRef perf;
    ol = LLVMOrcCreateRTDyldObjectLinkingLayerWithSectionMemoryManager(ES);
    perf = LLVMCreatePerfJITEventListener();
    assert(perf); // LLVM must be compiled with LLVM_USE_PERF=On
    LLVMOrcRTDyldObjectLinkingLayerRegisterJITEventListener(ol, perf);
    return ol;
}

int main()
{
    int i;
    MyFunc factorial, test1, test2;
    LLVMOrcLLJITBuilderRef jb;

    LLVMInitializeNativeTarget();
    LLVMInitializeNativeAsmPrinter();
    LLVMInitializeNativeAsmParser();

    jb = LLVMOrcCreateLLJITBuilder();
    LLVMOrcLLJITBuilderSetObjectLinkingLayerCreator(jb, create_oll, NULL);

    check_error(LLVMOrcCreateLLJIT(&jit, jb));
    tsctx = LLVMOrcCreateNewThreadSafeContext();
    ctx = LLVMOrcThreadSafeContextGetContext(tsctx);
    bldr = LLVMCreateBuilderInContext(ctx);
    jd = LLVMOrcLLJITGetMainJITDylib(jit);
    
    pmb = LLVMPassManagerBuilderCreate();
    mpm = LLVMCreatePassManager();
    LLVMPassManagerBuilderSetOptLevel(pmb, 2);
    LLVMPassManagerBuilderPopulateModulePassManager(pmb, mpm);

    int_ty = LLVMInt32TypeInContext(ctx);
    int_0 = LLVMConstInt(int_ty, 0, 0);
    int_1 = LLVMConstInt(int_ty, 1, 0);

    factorial = create_function("factorial");
    printf("10! = %d\n", factorial(10)); // should be 3628800

    puts("TEST BEGIN!");
    test1 = create_function("test1");
    for (i = 0; i < 10000; i++) {
        test1(1000000);
    }
    test2 = create_function("test2");
    for (i = 0; i < 10000; i++) {
        test1(1000000);
        test2(1000000);
    }
    puts("TEST END!");
    return 0;
}

Re: [BUG] JIT symbols not resolved after mprotect() combined vma

[Zhang Boyang]

Hello,

The problem had been solved. I'm using a old kernel so I encountered 
this problem. I should try my program on latest kernel first.

Here are some pointers about this problem:

https://www.spinics.net/lists/linux-perf-users/msg09833.html
https://lkml.org/lkml/2019/10/31/785

Thank you all!
Zhang Boyang

On 2021/1/9 16:59, Zhang Boyang wrote:
> Hello,
> 
>    I'm using perf to measure my LLVM jitted code performance. However, I 
> found with some condition, perf will unable to resolve or annotate JIT 
> symbols. After some debugging, I found the cause is mprotect() combined 
> two adjacent vma, and report a MMAP2 event of merged vma, confusing perf.
>    I wrote a sample program (sample.c). It creates function computing 
> factorial. First it creates test1() and exec it for 10000 times. Then, 
> it creates test2() and exec both test1() and test2() for 10000 times 
> respectively. As a result, test1() was executed 20000 times, and test2() 
> was executed 10000 times.
>    However, perf report shows:
> 
>    33.33%  a.out    jitted-10742-3.so    [.] test2
>    33.30%  a.out    jitted-10742-2.so    [.] test1
>    33.26%  a.out    [JIT] tid 10742      [.] 0x00007f4b8cb3d010 // test1
> 
>    This is because LLVM create jitted code by using mmap() and 
> mprotect(): (the address is different because of ASLR)
> 
> //// compile test1
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) 
> = 0x7fca1a491000
> mprotect(0x7fca1a491000, 4096, PROT_READ|PROT_EXEC) = 0
> //// compile test2
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) 
> = 0x7fca1a490000
> mprotect(0x7fca1a490000, 4096, PROT_READ|PROT_EXEC) = 0
> 
>    The second mprotect will merge two adjacent vma, and report a MMAP2 
> event of merged vma. The pref tool saw this:
> 
> 9547033496331 0x2510 [0x60]: PERF_RECORD_MMAP2 10742/10742: 
> [0x7f4b8cb3d000(0x2000) @ 0x7f4b8cb3d000 00:00 0 0]: r-xp //anon
> 9547033524086 0xf00 [0xb0]: PERF_RECORD_MMAP2 10742/10742: 
> [0x7f4b8cb3d000(0x18) @ 0x40 08:02 10224200 1]: --xs 
> /home/zby/src/qemuproject/qemu/.debug/jit/llvm-IR-jit-20210109-ad4573/jitted-10742-2.so 
> 
> 9553628266188 0x103898 [0x60]: PERF_RECORD_MMAP2 10742/10742: 
> [0x7f4b8cb3c000(0x3000) @ 0x7f4b8cb3c000 00:00 0 0]: r-xp //anon
> 9553628283472 0xfb0 [0xb0]: PERF_RECORD_MMAP2 10742/10742: 
> [0x7f4b8cb3c000(0x18) @ 0x40 08:02 10224201 1]: --xs 
> /home/zby/src/qemuproject/qemu/.debug/jit/llvm-IR-jit-20210109-ad4573/jitted-10742-3.so 
> 
> 
>    The event of third line, confusing perf, make it thinks test1() had 
> disappear. Then perf if unable to resolve test1() or annotate it.
> 
> 
> Thank you very much!
> Zhang Boyang