Debugging why late profiling detail still shows optics unexpectedly

Learn
#1

Recently, I’ve been experimenting with the -fprof-late profiling flag in Haskell (or equivalently, --profiling-detail=late in cabal) trying to gain a more realistic profiling of some Haskell applications, particularly those with extensive use of optics.

Despite implementing this flag, I’ve observed no significant changes in the profiling results.

One possibility could be that the optics aren’t getting inlined as initially thought, or something is hindering the inlining process during profiling. However, these are only hypotheses at this point and warrant further investigation.

Has anyone experienced similar issues or observed non-typical results while using -fprof-late? Or, does anyone have insights into why there might be no noticeable difference in the profiling results despite implementing this flag?

Any input or advice would be greatly appreciated.

Here’s the flame graph for the Echidna project, ran with cabal run --enable-profiling echidna --profiling-detail=late -- +RTS -pj -RTS mod.sol --seed 0 --test-limit 10000 --format text

Imgur

Here’s another flame graph for the same project, this time without late profiling detail:

Imgur

1 Like
#2

What GHC version are you using? I imagine you are running into this cabal issue.

1 Like
#3 
$ ghc --version
The Glorious Glasgow Haskell Compilation System, version 9.2.7
$ cabal --version
cabal-install version 3.10.1.0
compiled using version 3.10.1.0 of the Cabal library

Ah, maybe I’m running into that issue. I can try to rerun everything with a newer GHC version and see.

1 Like
#4

I’ve updated the compiler version and the late profiling seems to work. However when profiling, even with optimization flags I still see optics as one of the top cost centers in the program. I thought that they would be inlined by the time optimizations are run.

The program was written with lens before, and the tests ran around the same time, however lens did not show up in the profiling, whereas optics does now.

Does anyone know what the underlying reasons might be for this?

Relevant: Missing INLINE pragma on castOptic? · Issue #469 · well-typed/optics · GitHub

        Tue Jun 13 22:21 2023 Time and Allocation Profiling Report  (Final)

           ethereum-tests +RTS -p -RTS

        total time  =      303.96 secs   (303961 ticks @ 1000 us, 1 processor)
        total alloc = 670,893,307,192 bytes  (excludes profiling overheads)

COST CENTRE                   MODULE                     SRC                                            %time %alloc

exec1                         EVM                        src/EVM.hs:(188,1)-(855,42)                     15.6    3.3
%                             Optics.Internal.Optic      src/Optics/Internal/Optic.hs:(120,1)-(130,54)    9.5    9.4
#.                            Data.Profunctor.Indexed    src/Data/Profunctor/Indexed.hs:668:1-16          9.1    2.7
$fNumAddr                     EVM.Types                  src/EVM/Types.hs:1048:7-9                        6.7    3.0
accessAndBurn5                EVM                        <no location info>                               6.2   14.0
$wg1                          EVM.Expr                   <no location info>                               4.7    5.7
castOptic                     Optics.Internal.Optic      src/Optics/Internal/Optic.hs:(102,1)-(108,44)    3.8    3.4
prompt                        Data.Attoparsec.Internal   Data/Attoparsec/Internal.hs:(55,1)-(58,45)       3.8    3.2
accessAndBurn4                EVM                        <no location info>                               3.1    5.2
burn                          EVM                        src/EVM.hs:(1317,1)-(1325,36)                    3.1    1.8
$w$creadsPrec                 EVM.Types                  src/EVM/Types.hs:1053:3-11                       3.0    2.8
next                          EVM                        src/EVM.hs:184:1-48                              2.1    2.4
checkJump5                    EVM                        <no location info>                               2.0    4.6
$fFromJSONKeyW256_$creadsPrec EVM.Types                  src/EVM/Types.hs:983:3-11                        1.7    2.7
$fEqAddr                      EVM.Types                  src/EVM/Types.hs:1049:7-8                        1.5    0.0
checkJump3                    EVM                        <no location info>                               1.4    3.2
jstring                       Data.Aeson.Parser.Internal src/Data/Aeson/Parser/Internal.hs:316:1-45       1.2    1.0
padRight                      EVM.Types                  src/EVM/Types.hs:1261:1-55                       1.2    8.6
bytesRead                     Data.Serialize.Get         src/Data/Serialize/Get.hs:847:1-45               0.8    1.4
encode                        Data.Serialize             src/Data/Serialize.hs:109:1-21                   0.6    5.3
#5

I’ve created a minimal, reproducible example showing the performance differences between lens and optics while profiling here: GitHub - siraben/lens-optics-profiling: Haskell Lens vs Optics Performance Under Profiling