search

llvm / llvm-project

The LLVM Project is a collection of modular and reusable compiler and toolchain technologies.
http://llvm.org
Other
29.39k stars 12.15k forks source link

bolt: --instrument merges files not correctly and gets overwritten from previous profile #56209

Open ptr1337 opened 2 years ago

ptr1337 commented 2 years ago

Hey,

As already mentioned here some time ago, https://github.com/ClangBuiltLinux/tc-build/issues/155#issuecomment-1106831385 the bug seems still present in the main branch.

If instrumenting a binary with:

llvm-bolt \
        --instrument \
        --instrumentation-file=/tmp/bolt.fdata \
        ${BINARY} \
        -o ${BINARY}.inst

The output of the profile does not get correctly merged automatically, only the latest process seems to profiled correctly. For example if running a workload with the instrumented binary will result into a profile which has very less branches.

example:

BOLT-INFO: shared object or position-independent executable detected
BOLT-INFO: Target architecture: x86_64
BOLT-INFO: BOLT version: f595b51f502b2f3c97d30e826784159438bde9c4
BOLT-INFO: first alloc address is 0x0
BOLT-INFO: enabling relocation mode
BOLT-INFO: enabling lite mode
BOLT-WARNING: Failed to analyze 2424 relocations
BOLT-INFO: pre-processing profile using branch profile reader
BOLT-INFO: forcing -jump-tables=move as PIC jump table was detected in function _ZN4llvm3sys4path11is_absoluteERKNS_5TwineENS1_5StyleE
BOLT-INFO: 1315 out of 96706 functions in the binary (1.4%) have non-empty execution profile
BOLT-INFO: 3 functions with profile could not be optimized
BOLT-INFO: profile for 1 objects was ignored
BOLT-INFO: the input contains 176 (dynamic count : 5974) opportunities for macro-fusion optimization. Will fix instances on a hot path.
BOLT-INFO: 13166 instructions were shortened
BOLT-INFO: removed 11 empty blocks
BOLT-INFO: ICF folded 316 out of 96983 functions in 4 passes. 0 functions had jump tables.
BOLT-INFO: Removing all identical functions will save 94.04 KB of code space. Folded functions were called 3316 times based on profile.
BOLT-INFO: basic block reordering modified layout of 330 (0.34%) functions
BOLT-INFO: UCE removed 1 blocks and 7 bytes of code.
BOLT-INFO: splitting separates 560689 hot bytes from 346146 cold bytes (61.83% of split functions is hot).
BOLT-INFO: 3 Functions were reordered by LoopInversionPass
BOLT-INFO: hfsort+ reduced the number of chains from 1002 to 552
BOLT-INFO: program-wide dynostats after all optimizations before SCTC and FOP:

              553848 : executed forward branches
               64210 : taken forward branches
              191942 : executed backward branches
              100756 : taken backward branches
               59984 : executed unconditional branches
              251734 : all function calls
              103854 : indirect calls
               96734 : PLT calls
             5738078 : executed instructions
             1228106 : executed load instructions
              632336 : executed store instructions
                 988 : taken jump table branches
                   0 : taken unknown indirect branches
              805774 : total branches
              224950 : taken branches
              580824 : non-taken conditional branches
              164966 : taken conditional branches
              745790 : all conditional branches

              525170 : executed forward branches (-5.2%)
               25848 : taken forward branches (-59.7%)
              220620 : executed backward branches (+14.9%)
               95176 : taken backward branches (-5.5%)
               30714 : executed unconditional branches (-48.8%)
              251734 : all function calls (=)
              103854 : indirect calls (=)
               96734 : PLT calls (=)
             5676670 : executed instructions (-1.1%)
             1228106 : executed load instructions (=)
              632336 : executed store instructions (=)
                 988 : taken jump table branches (=)
                   0 : taken unknown indirect branches (=)
              776504 : total branches (-3.6%)
              151738 : taken branches (-32.5%)
              624766 : non-taken conditional branches (+7.6%)
              121024 : taken conditional branches (-26.6%)
              745790 : all conditional branches (=)

BOLT-INFO: SCTC: patched 4 tail calls (4 forward) tail calls (0 backward) from a total of 4 while removing 0 double jumps and removing 4 basic blocks totalling 20 bytes of code. CTCs total execution count is 36 and the number of times CTCs are taken is 8.
BOLT-INFO: padding code to 0x5000000 to accommodate hot text
BOLT-INFO: setting __hot_start to 0x4e00000
BOLT-INFO: setting __hot_end to 0x4e956f4

running the same workload with following options:

llvm-bolt \
        --instrument \
        --instrumentation-file-append-pid \
        --instrumentation-file=~/data/bolt.fdata \
        ${BINARY} \
        -o ${BINARY}.inst

Will result into a massive amount of profiles which uses a lot of space. After compiling clang with the instrumented binary results into a over 100GB of fdata files. After merging them with merge-fdata and using the profile with llvm-bolt shows following stats:

BOLT-INFO: shared object or position-independent executable detected
BOLT-INFO: Target architecture: x86_64
BOLT-INFO: BOLT version: f595b51f502b2f3c97d30e826784159438bde9c4
BOLT-INFO: first alloc address is 0x0
BOLT-INFO: enabling relocation mode
BOLT-INFO: enabling lite mode
BOLT-WARNING: Failed to analyze 2424 relocations
BOLT-INFO: pre-processing profile using branch profile reader
BOLT-INFO: forcing -jump-tables=move as PIC jump table was detected in function _ZN5clang4Decl19castFromDeclContextEPKNS_11DeclContextE
BOLT-WARNING: 7 collisions detected while hashing binary objects. Use -v=1 to see the list.
BOLT-INFO: 16889 out of 96706 functions in the binary (17.5%) have non-empty execution profile
BOLT-INFO: 495 functions with profile could not be optimized
BOLT-WARNING: 9 (0.1% of all profiled) functions have invalid (possibly stale) profile. Use -report-stale to see the list.
BOLT-WARNING: 695817 out of 2165380220666 samples in the binary (0.0%) belong to functions with invalid (possibly stale) profile.
BOLT-INFO: profile for 1 objects was ignored
BOLT-INFO: the input contains 9616 (dynamic count : 19121657995) opportunities for macro-fusion optimization. Will fix instances on a hot path.
BOLT-INFO: 782089 instructions were shortened
BOLT-INFO: removed 1458 empty blocks
BOLT-INFO: ICF folded 1687 out of 96983 functions in 5 passes. 2 functions had jump tables.
BOLT-INFO: Removing all identical functions will save 192.87 KB of code space. Folded functions were called 6708861534 times based on profile.
BOLT-INFO: basic block reordering modified layout of 9503 (9.97%) functions
BOLT-INFO: UCE removed 1 blocks and 7 bytes of code.
BOLT-INFO: splitting separates 11629561 hot bytes from 11335899 cold bytes (50.64% of split functions is hot).
BOLT-INFO: 223 Functions were reordered by LoopInversionPass
BOLT-INFO: hfsort+ reduced the number of chains from 15697 to 7487
BOLT-INFO: program-wide dynostats after all optimizations before SCTC and FOP:

       1345852442580 : executed forward branches
        177695950568 : taken forward branches
        279784019546 : executed backward branches
        165552345783 : taken backward branches
         80707139554 : executed unconditional branches
        111711292644 : all function calls
         38436135059 : indirect calls
         20540549655 : PLT calls
      10555075375899 : executed instructions
       2627819906958 : executed load instructions
       1279424679765 : executed store instructions
         16846108018 : taken jump table branches
                   0 : taken unknown indirect branches
       1706343601680 : total branches
        423955435905 : taken branches
       1282388165775 : non-taken conditional branches
        343248296351 : taken conditional branches
       1625636462126 : all conditional branches

       1280317632631 : executed forward branches (-4.9%)
         78974541817 : taken forward branches (-55.6%)
        345318829495 : executed backward branches (+23.4%)
        155608698163 : taken backward branches (-6.0%)
         60656090585 : executed unconditional branches (-24.8%)
        111711292644 : all function calls (=)
         38436135059 : indirect calls (=)
         20540549655 : PLT calls (=)
      10505269253372 : executed instructions (-0.5%)
       2627819906958 : executed load instructions (=)
       1279424679765 : executed store instructions (=)
         16846108018 : taken jump table branches (=)
                   0 : taken unknown indirect branches (=)
       1686292552711 : total branches (-1.2%)
        295239330565 : taken branches (-30.4%)
       1391053222146 : non-taken conditional branches (+8.5%)
        234583239980 : taken conditional branches (-31.7%)
       1625636462126 : all conditional branches (=)

BOLT-INFO: SCTC: patched 78 tail calls (70 forward) tail calls (8 backward) from a total of 78 while removing 12 double jumps and removing 65 basic blocks totalling 325 bytes of code. CTCs total execution count is 54542385 and the number of times CTCs are taken is 51777916.
BOLT-INFO: setting __hot_start to 0x4e00000

Think the discussion at https://github.com/ClangBuiltLinux/tc-build/issues/155 could be also helpful since this bug is there a bit discussed.

The last tests ive run was with commit https://github.com/llvm/llvm-project/commit/96f6ec5090c2f7a1e4804693cbb84c29c574b3de and also their seems everything equal:

Regards.

ptr1337 commented 2 years ago

Here a example with the latest commit from main:

without --instrumentation-file-append-pid

Binary which will be used for the example: /usr/lib/gcc/x86_64-pc-linux-gnu/12/cc1

    LD_PRELOAD=/usr/lib/libjemalloc.so ${BOLTPATH}/llvm-bolt \
        --instrument \
        --instrumentation-file=${FDATA}/${BINARY}.fdata \
        ${BINARYPATH}/${BINARY} \
        -o ${BOLTBIN}/${BINARY} || (echo "Could not create instrumented binary"; exit 1)

Instrument binary with llvm-bolt
BOLT-INFO: Target architecture: x86_64
BOLT-INFO: BOLT version: f3caa98e495188b03ea7f38ffb40f3955d785553
BOLT-INFO: first alloc address is 0x400000
BOLT-INFO: creating new program header table at address 0x2400000, offset 0x2000000
BOLT-WARNING: debug info will be stripped from the binary. Use -update-debug-sections to keep it.
BOLT-INFO: enabling relocation mode
BOLT-INFO: forcing -jump-tables=move for instrumentation
BOLT-INFO: enabling -align-macro-fusion=all since no profile was specified
BOLT-INFO: enabling lite mode
BOLT-WARNING: Failed to analyze 4 relocations
BOLT-INSTRUMENTER: Number of indirect call site descriptors: 45030
BOLT-INSTRUMENTER: Number of indirect call target descriptors: 42195
BOLT-INSTRUMENTER: Number of function descriptors: 42195
BOLT-INSTRUMENTER: Number of branch counters: 574441
BOLT-INSTRUMENTER: Number of ST leaf node counters: 266846
BOLT-INSTRUMENTER: Number of direct call counters: 386
BOLT-INSTRUMENTER: Total number of counters: 841673
BOLT-INSTRUMENTER: Total size of counters: 6733384 bytes (static alloc memory)
BOLT-INSTRUMENTER: Total size of string table emitted: 2186532 bytes in file
BOLT-INSTRUMENTER: Total size of descriptors: 55086932 bytes in file
BOLT-INSTRUMENTER: Profile will be saved to file /home/ptr1337/toolchain/bolt/fdata/cc1.fdata
BOLT-INFO: 0 out of 42578 functions in the binary (0.0%) have non-empty execution profile
BOLT-INFO: the input contains 5885 (dynamic count : 0) opportunities for macro-fusion optimization that are going to be fixed
BOLT-INFO: 437397 instructions were shortened
BOLT-INFO: removed 1342 empty blocks
BOLT-INFO: merged 14 duplicate CFG edges
BOLT-INFO: UCE removed 19763 blocks and 1121388 bytes of code.
BOLT-INFO: SCTC: patched 0 tail calls (0 forward) tail calls (0 backward) from a total of 0 while removing 0 double jumps and removing 0 basic blocks totalling 0 bytes of code. CTCs total execution count is 0 and the number of times CTCs are taken is 0.
BOLT-INFO: output linked against instrumentation runtime library, lib entry point is 0x5c583f0
BOLT-INFO: clear procedure is 0x5c52340
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: patched build-id (flipped last bit)

Now running a workload and compiling gcc and then optimize the binary with the profile, when watching at the profile size when running the workload you'll see big jumps between 300kb and 50+MB. When I the compile was done the fdata has around 8 MB.

    LD_PRELOAD=/usr/lib/libjemalloc.so ${BOLTPATH}/llvm-bolt ${BOLTBIN}/${BINARY}.org \
        --data ${BOLTBIN}/${BINARY}-combined.fdata \
        -o ${BOLTBIN}/${BINARY}.bolt \
        -split-functions \
        -split-all-cold \
        -split-eh \
        -dyno-stats \
        -reorder-functions=hfsort+ \
        -icp-eliminate-loads \
        -reorder-blocks=ext-tsp \
        -icf || (echo "Could not optimize the binary"; exit 1)
Optimizing binary with generated profile
BOLT-INFO: Target architecture: x86_64
BOLT-INFO: BOLT version: f3caa98e495188b03ea7f38ffb40f3955d785553
BOLT-INFO: first alloc address is 0x400000
BOLT-INFO: creating new program header table at address 0x2400000, offset 0x2000000
BOLT-WARNING: debug info will be stripped from the binary. Use -update-debug-sections to keep it.
BOLT-INFO: enabling relocation mode
BOLT-INFO: enabling lite mode
BOLT-WARNING: Failed to analyze 4 relocations
BOLT-INFO: pre-processing profile using branch profile reader
BOLT-INFO: forcing -jump-tables=move as PIC jump table was detected in function _cpp_parse_expr
BOLT-INFO: 4969 out of 42578 functions in the binary (11.7%) have non-empty execution profile
BOLT-INFO: 44 functions with profile could not be optimized
BOLT-INFO: profile for 1 objects was ignored
BOLT-INFO: the input contains 1305 (dynamic count : 193784) opportunities for macro-fusion optimization. Will fix instances on a hot path.
BOLT-INFO: 108440 instructions were shortened
BOLT-INFO: removed 9942 empty blocks
BOLT-INFO: merged 3 duplicate CFG edges
BOLT-INFO: ICF folded 365 out of 42578 functions in 4 passes. 0 functions had jump tables.
BOLT-INFO: Removing all identical functions will save 14.59 KB of code space. Folded functions were called 5304 times based on profile.
BOLT-INFO: basic block reordering modified layout of 2160 (5.12%) functions
BOLT-INFO: UCE removed 0 blocks and 0 bytes of code.
BOLT-INFO: splitting separates 1106816 hot bytes from 2586495 cold bytes (29.97% of split functions is hot).
BOLT-INFO: 365 Functions were reordered by LoopInversionPass
BOLT-INFO: hfsort+ reduced the number of chains from 4672 to 451
BOLT-INFO: program-wide dynostats after all optimizations before SCTC and FOP:

             7261683 : executed forward branches
              915435 : taken forward branches
             1237970 : executed backward branches
              846764 : taken backward branches
              302350 : executed unconditional branches
             1292956 : all function calls
              298107 : indirect calls
                   0 : PLT calls
            56166826 : executed instructions
            12635237 : executed load instructions
             4072522 : executed store instructions
               82800 : taken jump table branches
                   0 : taken unknown indirect branches
             8802003 : total branches
             2064549 : taken branches
             6737454 : non-taken conditional branches
             1762199 : taken conditional branches
             8499653 : all conditional branches

             6370405 : executed forward branches (-12.3%)
              521763 : taken forward branches (-43.0%)
             2129240 : executed backward branches (+72.0%)
              770904 : taken backward branches (-9.0%)
              250568 : executed unconditional branches (-17.1%)
             1292956 : all function calls (=)
              298107 : indirect calls (=)
                   0 : PLT calls (=)
            56070842 : executed instructions (-0.2%)
            12635237 : executed load instructions (=)
             4072522 : executed store instructions (=)
               82800 : taken jump table branches (=)
                   0 : taken unknown indirect branches (=)
             8750213 : total branches (-0.6%)
             1543235 : taken branches (-25.3%)
             7206978 : non-taken conditional branches (+7.0%)
             1292667 : taken conditional branches (-26.6%)
             8499645 : all conditional branches (-0.0%)

BOLT-INFO: SCTC: patched 92 tail calls (80 forward) tail calls (12 backward) from a total of 92 while removing 11 double jumps and removing 62 basic blocks totalling 310 bytes of code. CTCs total execution count is 17440 and the number of times CTCs are taken is 7426.
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: setting __hot_start to 0x2600000
BOLT-INFO: setting __hot_end to 0x27368c7
BOLT-INFO: patched build-id (flipped last bit)
You can find now your optimzed binary at /home/ptr1337/toolchain/bolt/bin

Now a run with --instrumentation-file-append-pid

    LD_PRELOAD=/usr/lib/libjemalloc.so ${BOLTPATH}/llvm-bolt \
        --instrument \
        --instrumentation-file-append-pid \
        --instrumentation-file=${FDATA}/${BINARY}.fdata \
        ${BINARYPATH}/${BINARY} \
        -o ${BOLTBIN}/${BINARY} || (echo "Could not create instrumented binary"; exit 1)

Instrument binary with llvm-bolt
BOLT-INFO: Target architecture: x86_64
BOLT-INFO: BOLT version: f3caa98e495188b03ea7f38ffb40f3955d785553
BOLT-INFO: first alloc address is 0x400000
BOLT-INFO: creating new program header table at address 0x2400000, offset 0x2000000
BOLT-WARNING: debug info will be stripped from the binary. Use -update-debug-sections to keep it.
BOLT-INFO: enabling relocation mode
BOLT-INFO: forcing -jump-tables=move for instrumentation
BOLT-INFO: enabling -align-macro-fusion=all since no profile was specified
BOLT-INFO: enabling lite mode
BOLT-WARNING: Failed to analyze 4 relocations
BOLT-INSTRUMENTER: Number of indirect call site descriptors: 45030
BOLT-INSTRUMENTER: Number of indirect call target descriptors: 42195
BOLT-INSTRUMENTER: Number of function descriptors: 42195
BOLT-INSTRUMENTER: Number of branch counters: 574441
BOLT-INSTRUMENTER: Number of ST leaf node counters: 266846
BOLT-INSTRUMENTER: Number of direct call counters: 386
BOLT-INSTRUMENTER: Total number of counters: 841673
BOLT-INSTRUMENTER: Total size of counters: 6733384 bytes (static alloc memory)
BOLT-INSTRUMENTER: Total size of string table emitted: 2186532 bytes in file
BOLT-INSTRUMENTER: Total size of descriptors: 55086932 bytes in file
BOLT-INSTRUMENTER: Profile will be saved to file /home/ptr1337/toolchain/bolt/fdata/cc1.fdata
BOLT-INFO: 0 out of 42578 functions in the binary (0.0%) have non-empty execution profile
BOLT-INFO: the input contains 5885 (dynamic count : 0) opportunities for macro-fusion optimization that are going to be fixed
BOLT-INFO: 437397 instructions were shortened
BOLT-INFO: removed 1342 empty blocks
BOLT-INFO: merged 14 duplicate CFG edges
BOLT-INFO: UCE removed 19763 blocks and 1121388 bytes of code.
BOLT-INFO: SCTC: patched 0 tail calls (0 forward) tail calls (0 backward) from a total of 0 while removing 0 double jumps and removing 0 basic blocks totalling 0 bytes of code. CTCs total execution count is 0 and the number of times CTCs are taken is 0.
BOLT-INFO: output linked against instrumentation runtime library, lib entry point is 0x5c583f0
BOLT-INFO: clear procedure is 0x5c52340
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: patched build-id (flipped last bit)

After just running 3 min the workload I have 20.9 GB data gathered with the --instrumentation-file-append-pid , which I will merge now together. After merging the cc1.fdata has 61MB.

Used same options to optimize the target as above, using now the other profile:

Optimizing binary with generated profile
BOLT-INFO: Target architecture: x86_64
BOLT-INFO: BOLT version: f3caa98e495188b03ea7f38ffb40f3955d785553
BOLT-INFO: first alloc address is 0x400000
BOLT-INFO: creating new program header table at address 0x2400000, offset 0x2000000
BOLT-WARNING: debug info will be stripped from the binary. Use -update-debug-sections to keep it.
BOLT-INFO: enabling relocation mode
BOLT-INFO: enabling lite mode
BOLT-WARNING: Failed to analyze 4 relocations
BOLT-INFO: pre-processing profile using branch profile reader
BOLT-INFO: forcing -jump-tables=move as PIC jump table was detected in function get_DW_TAG_name
BOLT-INFO: 14989 out of 42578 functions in the binary (35.2%) have non-empty execution profile
BOLT-INFO: 99 functions with profile could not be optimized
BOLT-INFO: profile for 1 objects was ignored
BOLT-INFO: the input contains 3648 (dynamic count : 1361313899) opportunities for macro-fusion optimization. Will fix instances on a hot path.
BOLT-INFO: 339602 instructions were shortened
BOLT-INFO: removed 17619 empty blocks
BOLT-INFO: merged 4 duplicate CFG edges
BOLT-INFO: ICF folded 1248 out of 42578 functions in 4 passes. 0 functions had jump tables.
BOLT-INFO: Removing all identical functions will save 104.07 KB of code space. Folded functions were called 393930282 times based on profile.
BOLT-INFO: basic block reordering modified layout of 7658 (18.53%) functions
BOLT-INFO: UCE removed 0 blocks and 0 bytes of code.
BOLT-INFO: splitting separates 5337660 hot bytes from 5200983 cold bytes (50.65% of split functions is hot).
BOLT-INFO: 802 Functions were reordered by LoopInversionPass
BOLT-INFO: hfsort+ reduced the number of chains from 13856 to 3395
BOLT-INFO: program-wide dynostats after all optimizations before SCTC and FOP:

        151391987892 : executed forward branches
         19476986419 : taken forward branches
         19966266912 : executed backward branches
         12976486585 : taken backward branches
          5805983074 : executed unconditional branches
         27161239781 : all function calls
          3751089236 : indirect calls
                   0 : PLT calls
       1099387641420 : executed instructions
        298270895664 : executed load instructions
        139101555672 : executed store instructions
          2044189844 : taken jump table branches
                   0 : taken unknown indirect branches
        177164237878 : total branches
         38259456078 : taken branches
        138904781800 : non-taken conditional branches
         32453473004 : taken conditional branches
        171358254804 : all conditional branches

        147020862489 : executed forward branches (-2.9%)
         11684918898 : taken forward branches (-40.0%)
         24334482145 : executed backward branches (+21.9%)
          9986780158 : taken backward branches (-23.0%)
          5838845666 : executed unconditional branches (+0.6%)
         27161239781 : all function calls (=)
          3751089236 : indirect calls (=)
                   0 : PLT calls (=)
       1099418182516 : executed instructions (+0.0%)
        298270895664 : executed load instructions (=)
        139101555672 : executed store instructions (=)
          2044189844 : taken jump table branches (=)
                   0 : taken unknown indirect branches (=)
        177194190300 : total branches (+0.0%)
         27510544722 : taken branches (-28.1%)
        149683645578 : non-taken conditional branches (+7.8%)
         21671699056 : taken conditional branches (-33.2%)
        171355344634 : all conditional branches (-0.0%)

BOLT-INFO: SCTC: patched 229 tail calls (202 forward) tail calls (27 backward) from a total of 229 while removing 15 double jumps and removing 169 basic blocks totalling 845 bytes of code. CTCs total execution count is 1406120689 and the number of times CTCs are taken is 751591871.
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: setting _end to 0x210e9d8
BOLT-INFO: setting __hot_start to 0x2600000
BOLT-INFO: setting __hot_end to 0x2ba3ff7
BOLT-INFO: patched build-id (flipped last bit)
You can find now your optimzed binary at /home/ptr1337/toolchain/bolt/bin

Just some updated data.

llvmbot commented 2 years ago

@llvm/issue-subscribers-bolt