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
Here’s another flame graph for the same project, this time without late profiling detail:
1 Like
What GHC version are you using? I imagine you are running into this cabal issue.
1 Like
$ 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
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
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