Code Review: LaTeX Profiling in expl3

Question

I have a pretty big template of packages/classes for multiple different document types. Some of the users sometimes complain that the compile times are soooo long. However, to find the bottlenecks of my package I could not find a suitable method that can be used without adding many manual markers to the code (e.g. without having to add macros to my package code, like here or here). And since I wanted to try out expl3 anyways, I gave it a try.

Spoiler: I got something like this

I am no expert in LaTeX programming. Thus, I would like to ask for your suggestions, if you can find any big issues with the following code:

\ProvidesExplPackage{profiling}
  {2023/08/08}
  {1.0}
  {A package for profiling code using expl3}

\ExplSyntaxOn

\RequirePackage{expl3,l3keys2e}

\bool_new:N \g_profiling_enabled_bool
\bool_new:N \g_profiling_total_bool
\bool_new:N \g_profiling_packages_bool
\bool_new:N \g_profiling_document_bool
\bool_new:N \g_profiling_preamble_bool
\bool_set_true:N \g_profiling_enabled_bool
\bool_set_true:N \g_profiling_total_bool
\bool_set_true:N \g_profiling_packages_bool
\bool_set_true:N \g_profiling_document_bool
\bool_set_true:N \g_profiling_preamble_bool

\int_new:N \g_profiling_max_level_int

\tl_new:N \g_profiling_file_name_tl

\keys_define:nn { profiling }
{
    disable  .bool_gset_inverse:N = \g_profiling_enabled_bool,
    disable  .default:n  = true,
    total .bool_gset:N = \g_profiling_total_bool,
    total .default:n  = true,
    packages .bool_gset:N = \g_profiling_packages_bool,
    packages .default:n  = true,
    document .bool_gset:N = \g_profiling_document_bool,
    document .default:n  = true,
    preamble .bool_gset:N = \g_profiling_preamble_bool,
    preamble .default:n  = true,
    file-name .tl_gset:N = \g_profiling_file_name_tl,
    file-name .initial:n  = profiling,
    max-level .int_gset:N = \g_profiling_max_level_int,
    max-level .initial:n = 9999,
}

\ProcessKeysOptions{profiling}

% ---------------------------- Package is Disabled --------------------------- %
\bool_if:NF \g_profiling_enabled_bool
{
    \NewDocumentCommand\StartProfiling{ m }{}
    \NewDocumentCommand\StopProfiling{ m }{}
    \NewDocumentCommand\WriteProfilingResults{ O{profiling} }{}
    \NewDocumentCommand\ProfileMacro{ m }{}
    \ExplSyntaxOff
    \endinput
}

% required variants
\cs_generate_variant:Nn \int_gset:Nn { cf }
\cs_generate_variant:Nn \int_gset:Nn { Nf }

% initialize a list of tags to output all the data at the end
\seq_new:N \g_profiling_all_instances_seq

% initialize a second list of tags to keep track of the scope that is currently being profiled
\seq_new:N \g_profiling_instances_seq

% initialize a counter to keep track of the current scope level
\int_new:N \g_profiling_scope_int

% global start and end time
\int_new:N \g_profiling_end_int
\int_new:N \g_profiling_start_int
\int_gset:Nf \g_profiling_start_int { \sys_timer: }


% define a message for when the scope doesn't match
\msg_new:nnn { profiling } { scope-mismatch }
{
    The~scope~'#1'~does~not~match~the~current~scope~'#2'.~
    Maybe~you~forgot~to~close~a~scope~or~you~closed~a~scope~too~early?
}

\msg_new:nnn { profiling } { instance-exists } 
{
    The~profiling~instance~'#1'~already~exists.~This~is~a~bug!
}

% ---------------------------------------------------------------------------- %
%                                Start Profiling                               %
% ---------------------------------------------------------------------------- %
% Start profiling for a given tag. The tag might be profiled multiple times.
% Each time it is profiled, it will be called a new "instance".
% The general instance name will be <tag>/<instance number>.
% If the instance name is specified, the actual profiling will be started in 
% \profiling_start_instance:n
\cs_new:Npn \profiling_start:n #1 {
    % check if the tag already exists
    \int_if_exist:cTF { g_profiling_tag_#1_total_int }
    {
        \int_gincr:c { g_profiling_tag_#1_total_int }
    }{
        \seq_new:c { g_profiling_tag_#1_recurse_seq }
        \int_new:c { g_profiling_tag_#1_total_int }
        \int_gset:cn { g_profiling_tag_#1_total_int } { 1 }
    }
    \seq_gput_right:cx 
        { g_profiling_tag_#1_recurse_seq } 
        { \int_use:c { g_profiling_tag_#1_total_int } }
    \seq_get_right:cN { g_profiling_tag_#1_recurse_seq } \l_tmpa_tl
    \profiling_start_instance:x { #1/\tl_use:N \l_tmpa_tl }
}

% ---------------------------------------------------------------------------- %
% Define a function to record the current timestamp and store it in a new macro
% with the name '\g_profiling_<tag>_start_int'.
\cs_new:Npn \profiling_start_instance:n #1
{
    \int_if_exist:cTF { g_profiling_#1_start_int }
    {
        % warning if the tag already exists
        \msg_critical:nnn { profiling } { instance-exists } { #1 }
    }{
        \int_new:c { g_profiling_#1_start_int }
        \int_gset:cf { g_profiling_#1_start_int } { \sys_timer: }
        \seq_gput_right:Nn \g_profiling_all_instances_seq { #1 }
        \seq_gput_right:Nn \g_profiling_instances_seq { #1 }
        \int_gincr:N \g_profiling_scope_int
    }
}
% ---------------------------------------------------------------------------- %
\cs_generate_variant:Nn \profiling_start:n { x }
\cs_generate_variant:Nn \profiling_start_instance:n { x }

% ---------------------------------------------------------------------------- %
%                                Stop Profiling                                %
% ---------------------------------------------------------------------------- %
% Stop profiling for a given tag. The tag might be profiled multiple times.
% This function will stop the most recent instance of the tag (also, if the tag
% has been started recursively)
\cs_new:Npn \profiling_stop:n #1 {
    \seq_gpop_right:cN { g_profiling_tag_#1_recurse_seq } \l_tmpa_tl
    \profiling_stop_instance:x { #1/\tl_use:N \l_tmpa_tl }
}

% ---------------------------------------------------------------------------- %
\cs_new:Npn \profiling_stop_instance:n #1
{
    % check if the currently profiled instance is the same as the instance that should be stopped
    % the scopes of the profiled instances may not overlap!
    \seq_gpop_right:NN \g_profiling_instances_seq \l_tmpa_tl
    \tl_set:Nf \l_tmpb_tl { #1 }
    \tl_if_eq:NNTF \l_tmpa_tl \l_tmpb_tl
    {
        % if it is, save the data in a macro and store it in a list of results
        % it will be written to the file at the end of the document to avoid influencing the timing
        \int_new:c   { g_profiling_#1_end_int }
        \int_gset:cf { g_profiling_#1_end_int } { \sys_timer: }
        
        \int_new:c      { g_profiling_#1_scope_int }
        \int_gset_eq:cN { g_profiling_#1_scope_int } \g_profiling_scope_int

        % decrement the scope counter
        \int_gdecr:N \g_profiling_scope_int
    }
    {
        % if it isn't, then something went wrong
        \msg_critical:nnxx 
            { profiling } 
            { scope-mismatch } 
            { \tl_use:N \l_tmpb_tl } 
            { \tl_use:N \l_tmpa_tl }
    }
}

% ---------------------------------------------------------------------------- %
\cs_generate_variant:Nn \profiling_stop:n { x }
\cs_generate_variant:Nn \profiling_stop_instance:n { x }

% ---------------------------------------------------------------------------- %
%                                 Write Results                                %
% ---------------------------------------------------------------------------- %
\fp_new:N \l_profiling_diff_fp
\fp_new:N \l_profiling_perc_fp
\iow_new:N \g_profiling_iow

% This function will write the results of a single instance to the file
% #1: tag
% #2: scope
% #3: start (unscaled)
% #4: end (unscaled)
% #5: total time (scaled!)
\cs_new:Npn \profiling_write_line:nnnnn #1 #2 #3 #4 #5{
    % time difference ( * 1/(2^16) )
    \fp_set:Nn \l_tmpa_fp { #3 * 0.0000152587890625 }
    \fp_set:Nn \l_tmpb_fp { #4 * 0.0000152587890625 }
    \fp_set:Nn \l_profiling_diff_fp { \l_tmpb_fp - \l_tmpa_fp }

    % percentage of the total time
    \fp_set:Nn \l_profiling_perc_fp { \l_profiling_diff_fp / #5 * 100 }

    \iow_now:Nx \g_profiling_iow { 
        #1, % tag
        #2, % scope
        \fp_use:N \l_tmpa_fp, % start 
        \fp_use:N \l_tmpb_fp, % end
        \fp_use:N \l_profiling_diff_fp, % difference
        \fp_use:N \l_profiling_perc_fp % percentage
    }
}
% ---------------------------------------------------------------------------- %

\fp_new:N \l_profiling_total_fp
\int_new:N \l_profiling_scope_int

% This function will write the results of all instances to the file
\cs_new:Npn \profiling_write_results:n #1
{
    % if profiling of packages is enabled, remove the first element of the list of tags, 
    % as it is the name of the current file
    \bool_if:NT \g_profiling_packages_bool
    {
        \seq_gpop_left:NN \g_profiling_all_instances_seq \l_tmpa_tl
    }

    % get current time (latest possible moment)
    \int_gset:Nf \g_profiling_end_int { \sys_timer: }
    \fp_set:Nn \l_profiling_total_fp { \g_profiling_end_int * 0.0000152587890625 }

    % open a new file named 'profiling.csv' to write the data
    \iow_open:Nn \g_profiling_iow { \tl_use:N \g_profiling_file_name_tl .csv }

    % write the header
    \iow_now:Nx \g_profiling_iow{Tag,Scope,Start,End,Difference,Percentage}

    % write total time (if requested)
    \bool_if:NT \g_profiling_total_bool {
        \profiling_write_line:nnnnn 
            { total } 
            { 0 } 
            { 0 } 
            { \g_profiling_end_int } 
            { \fp_use:N \l_profiling_total_fp }
    }

    % loop through the list of tags and write the data to the file
    \seq_map_inline:Nn \g_profiling_all_instances_seq
    {
        \int_compare:nNnT 
            { \int_use:c {g_profiling_##1_scope_int} } < 
            { \int_use:N \g_profiling_max_level_int + 1 }
        {
            \profiling_write_line:nnnnn 
                { ##1 } 
                { \int_use:c {g_profiling_##1_scope_int} } 
                { \int_use:c {g_profiling_##1_start_int} } 
                { \int_use:c {g_profiling_##1_end_int} } 
                { \fp_use:N \l_profiling_total_fp }
        }
    }
}

% ---------------------------------------------------------------------------- %
%                             User level functions                             %
% ---------------------------------------------------------------------------- %
% Create user-level functions for starting and stopping profiling
\NewDocumentCommand\StartProfiling{ m }{ 
    \profiling_start:x { #1 } 
}

\NewDocumentCommand\StopProfiling{ m }{ 
    \profiling_stop:x { #1 } 
}

\NewDocumentCommand\WriteProfilingResults{O{profiling}}{
    \profiling_write_results:n {#1}
}

\NewDocumentCommand{\ProfileMacro}{ m }{
    \AddToHook{cmd/#1/before}[profiling/start]{ \profiling_start:x { m/#1 } }
    \AddToHook{cmd/#1/after}[profiling/stop]{ \profiling_stop:x { m/#1 } }
}


% ---------------------------------------------------------------------------- %
%                            Attach to default hooks                           %
% ---------------------------------------------------------------------------- %

% --------------------------------- Preamble --------------------------------- %
\bool_if:NT \g_profiling_preamble_bool
{
    \AddToHookNext{package/after}{
        % this will be the earliest call possible.
        % as the package profiling will append a stop call at the end of the 
        % package, we have to fake, that we started profiling before.
        % Therefore, starting the preamble profiling should start after that.
        \profiling_start:n{d/preamble} 
    }

    \AddToHook{begindocument/before}{\profiling_stop:n{d/preamble}}
}

% --------------------------------- Document --------------------------------- %
\bool_if:NT \g_profiling_document_bool
{
    \AddToHook{begindocument/before}{\profiling_start:n{d/document}}
    \AddToHook{enddocument/end}{\profiling_stop:n{d/document}}
}

% --------------------------------- Packages --------------------------------- %
\bool_if:NT \g_profiling_packages_bool
{
    \AddToHook{package/before}{\profiling_start:x{p/\CurrentFile}}
    \AddToHook{package/after}{\profiling_stop:x{p/\CurrentFile}}

    % as the profiling will attach to the end of this package as well, 
    % but did not start at the beginning of this package,
    % we have to fake, that we started profiling before.
    \profiling_start:x {p/\CurrentFile}
}

% --------------------------- Write Results to File -------------------------- %
\AddToHook{enddocument/end}{
    \WriteProfilingResults
}
\ExplSyntaxOff

Usage

Just load it at the top of your document and use the options to specify, if the package should automatically hook into your preamble, document and package loading. If you are interested in specific macro calls, use the \ProfileMacro{<cs>} command.

Each profiled part has a tag (e.g. a package will have the tag p/<package>). As some tags (especially macros) can be called multiple times (or recursively) each instance of a profiled tag will get a number. A macro will be named m/<macroname>/<instance> where <instance> is the number of the call. Package, Preamble and Document instances should obviously be only called once.

As a result, the package will output all the profiling data to a csv-file with

• the tag (or better: instance)
  • for the preamble d/preamble/1 or the document d/document/1
  • a package p/mypackage/1
  • a macro call m/mymacro/3
• the scope (for nested measurements, the scope level will increase)
  • preamble and document are level 1
  • e.g. a package that is loaded inside another package will have level 3
• Start time
• End time
• Time difference
• Percentage of the total run

Testcase

With the following input document

\RequirePackage[
  disable=false,
  total=true,
  document=true,
  preamble=true,
  packages=true,
  max-level=10,
]{profiling}

\documentclass{scrartcl}

\title{Some Title}
\author{Some Author}

% dummy text
\usepackage{blindtext} 

% some big packages
\usepackage{tikz}
\usepackage{pgfplots}

% loops
\usepackage{pgffor}
\newcommand{\foo}[1]{
  \foreach \n in {1,...,#1}{
    \Blinddocument
  }
}

% recursion
\newcounter{a}
\setcounter{a}{0}
\newcommand{\baz}[1]{
  \ifnum\value{a}<#1
    \stepcounter{a}
    \baz{#1}
  \else 
    \foo{1}
  \fi
  Recursive Hello World (\arabic{a})
  \addtocounter{a}{-1}
}

\ProfileMacro{maketitle}
\ProfileMacro{Blinddocument}
\ProfileMacro{foo}
\ProfileMacro{baz}

\begin{document}
  \maketitle
  \baz{4} % recursive
  \foo{10} % loop
  \foo{3} % another loop 
\end{document}

Resulting CSV

Tag,Scope,Start,End,Difference,Percentage
total,0,0,6.8487548828125,6.8487548828125,100
d/preamble/1,1,1.069259643554688,2.860107421875,1.790847778320312,26.14851617502896
p/scrkbase.sty/1,2,1.101547241210938,1.235610961914062,0.134063720703124,1.957490419748671
p/scrbase.sty/1,3,1.1217041015625,1.231094360351562,0.109390258789062,1.597228411015054
p/scrlfile.sty/1,4,1.141494750976562,1.19921875,0.057723999023438,0.8428393191337743
p/scrlfile-hook.sty/1,5,1.161605834960938,1.196548461914062,0.034942626953124,0.5102040816326385
p/scrlogo.sty/1,6,1.187728881835938,1.195953369140625,0.008224487304687,0.1200873362445342
p/keyval.sty/1,4,1.211822509765625,1.219970703125,0.008148193359375,0.1189733535335532
p/tocbasic.sty/1,2,1.248062133789062,1.269577026367188,0.021514892578126,0.3141431244987224
p/typearea.sty/1,2,1.3653564453125,1.40625,0.0408935546875,0.5970947330897424
p/blindtext.sty/1,2,1.718521118164062,1.75238037109375,0.033859252929688,0.4943855271366261
p/xspace.sty/1,3,1.738876342773438,1.747787475585938,0.0089111328125,0.1301131806434364
p/tikz.sty/1,2,1.765106201171875,2.393463134765625,0.62835693359375,9.174761607699848
p/pgf.sty/1,3,1.785064697265625,2.257064819335938,0.472000122070313,6.891765439800382
p/pgfrcs.sty/1,4,1.80474853515625,1.831787109375,0.02703857421875,0.3947954727742625
p/pgfcore.sty/1,4,1.844268798828125,2.196792602539062,0.352523803710937,5.147268514392649
p/graphicx.sty/1,5,1.863815307617188,1.942626953125,0.078811645507812,1.150744140450933
p/graphics.sty/1,6,1.885528564453125,1.941574096679688,0.056045532226563,0.8183316994920312
p/trig.sty/1,7,1.905487060546875,1.913589477539062,0.008102416992187,0.1183049639069529
p/pgfsys.sty/1,5,1.955001831054688,2.013534545898438,0.05853271484375,0.8546475358702433
p/xcolor.sty/1,5,2.027618408203125,2.07135009765625,0.043731689453125,0.6385348899385082
p/pgfcomp-version-0-65.sty/1,4,2.218948364257812,2.233642578125,0.014694213867188,0.2145530701363588
p/pgfcomp-version-1-18.sty/1,4,2.246505737304688,2.25653076171875,0.010025024414062,0.1463773282238587
p/pgffor.sty/1,3,2.269302368164062,2.347213745117188,0.077911376953126,1.137599144461293
p/pgfkeys.sty/1,4,2.2906494140625,2.305801391601562,0.015151977539062,0.2212369664022741
p/pgfmath.sty/1,4,2.318084716796875,2.336898803710938,0.018814086914063,0.2747081365297284
p/pgfplots.sty/1,2,2.405838012695312,2.838897705078125,0.433059692382813,6.32318866411194
d/document/1,1,2.860183715820312,6.848587036132812,3.9884033203125,58.23545138579449
p/epstopdf-base.sty/1,2,2.918594360351562,2.97186279296875,0.053268432617188,0.7777827288120561
m/maketitle/1,2,2.98553466796875,3.02850341796875,0.04296875,0.6273950628286249
m/baz/1,2,3.028579711914062,3.355819702148438,0.327239990234376,4.77809464397114
m/baz/2,3,3.028640747070312,3.35577392578125,0.327133178710938,4.776535068175749
m/baz/3,4,3.028701782226562,3.355728149414062,0.3270263671875,4.774975492380358
m/baz/4,5,3.02874755859375,3.355682373046875,0.326934814453125,4.773638713127172
m/baz/5,6,3.02880859375,3.355636596679688,0.326828002929688,4.772079137331796
m/foo/1,7,3.02886962890625,3.355575561523438,0.326705932617188,4.770296764994215
m/Blinddocument/1,8,3.02899169921875,3.355422973632812,0.326431274414062,4.766286427234642
m/foo/2,2,3.355880737304688,6.015274047851562,2.659393310546874,38.83031815346224
m/Blinddocument/2,3,3.355987548828125,3.624313354492188,0.268325805664063,3.917877194545948
m/Blinddocument/3,3,3.624465942382812,3.897811889648438,0.273345947265626,3.991177256928987
m/Blinddocument/4,3,3.89794921875,4.169235229492188,0.271286010742188,3.961099723732295
m/Blinddocument/5,3,4.169357299804688,4.43212890625,0.262771606445312,3.836779253185983
m/Blinddocument/6,3,4.4322509765625,4.696945190429688,0.264694213867188,3.864851617502904
m/Blinddocument/7,3,4.697067260742188,4.9681396484375,0.271072387695312,3.957980572141513
m/Blinddocument/8,3,4.96826171875,5.227554321289062,0.259292602539062,3.785981641564916
m/Blinddocument/9,3,5.227676391601562,5.490768432617188,0.263092041015626,3.841457980572156
m/Blinddocument/10,3,5.49090576171875,5.754837036132812,0.263931274414062,3.853711790393006
m/Blinddocument/11,3,5.754959106445312,6.015182495117188,0.260223388671876,3.799572230638995
m/foo/3,2,6.015335083007812,6.836822509765625,0.821487426757813,11.9946974422957
m/Blinddocument/12,3,6.015457153320312,6.291397094726562,0.27593994140625,4.029052669102576
m/Blinddocument/13,3,6.291549682617188,6.569900512695312,0.278350830078124,4.064254522769792
m/Blinddocument/14,3,6.570022583007812,6.83673095703125,0.266708374023438,3.894260761072995

Postprocessing

Using this Python script

import plotly.express as px
import pandas as pd
import plotly.io as pio

pio.renderers.default = "browser"
df = pd.read_csv("profiling.csv")

parent_queue = ["total"]
parents = [""]
prev_scope = 0
for row in df.iloc[1:,:].itertuples():
    if row.Scope == prev_scope:
        parent_queue.pop()
        parents.append(parent_queue[-1])
        parent_queue.append(row.Tag)
    elif row.Scope > prev_scope:
        parents.append(parent_queue[-1])
        parent_queue.append(row.Tag)
    elif row.Scope < prev_scope:
        parent_queue = parent_queue[:row.Scope]
        parents.append(parent_queue[-1])
        parent_queue.append(row.Tag)

    prev_scope = row.Scope

# insert parent column as second column
df.insert(1, "Parent", parents)

# generate column that contains tag without the call count
df['Type'] = df['Tag'].str.replace(r"(.*)/\d+$", r"\1", regex=True)

fig = px.sunburst(
    df,
    names='Tag',
    parents='Parent',
    values='Difference',
    color='Type',
)
fig.show()

---

I know that this code is far from perfect and introduces quite some overhead. But it is at least capable of producing a visual representation to find possible bottlenecks of a package. Maybe not in absolute numbers, but relative to other parts of a package.

There are some open questions:

• Where is the "white space" that I did not measure in the document and in the preamble?
• Is there any way to produce this kind of visual representation without having to use python? Maybe with pgfplots in a second run?

Answer 1

First off, you've done a really good job with this package! I didn't see any major issues, just a few stylistic things:

\ProvidesExplPackage{profiling}
  {2023/08/08}
  {1.0}
  {A package for profiling code using expl3}

I'd add \NeedsTeXFormat{LaTeX2e}[2020/10/01] before this since your package needs hook support.

\ExplSyntaxOn

\ProvidesExplPackage already does \ExplSyntaxOn, so you don't need it here.

\RequirePackage{expl3,l3keys2e}

\ProvidesExplPackage and \ExplSyntaxOn won't work without expl3, so if you've gotten this far already, expl3 is already loaded. You could load the package earlier, but since you use hooks in this package, you already require a LaTeX kernel that includes expl3.

\bool_new:N \g_profiling_enabled_bool
\bool_new:N \g_profiling_total_bool
\bool_new:N \g_profiling_packages_bool
\bool_new:N \g_profiling_document_bool
\bool_new:N \g_profiling_preamble_bool
\bool_set_true:N \g_profiling_enabled_bool
\bool_set_true:N \g_profiling_total_bool
\bool_set_true:N \g_profiling_packages_bool
\bool_set_true:N \g_profiling_document_bool
\bool_set_true:N \g_profiling_preamble_bool

\int_new:N \g_profiling_max_level_int

\tl_new:N \g_profiling_file_name_tl

Redundant since the key–val setup initializes these variables to the same values.

Also, these variables should probably be “internal”, so use \g__… to represent that.

\keys_define:nn { profiling }
{
    disable  .bool_gset_inverse:N = \g_profiling_enabled_bool,
    disable  .default:n  = true,
    total .bool_gset:N = \g_profiling_total_bool,
    total .default:n  = true,
    packages .bool_gset:N = \g_profiling_packages_bool,
    packages .default:n  = true,
    document .bool_gset:N = \g_profiling_document_bool,
    document .default:n  = true,
    preamble .bool_gset:N = \g_profiling_preamble_bool,
    preamble .default:n  = true,
    file-name .tl_gset:N = \g_profiling_file_name_tl,
    file-name .initial:n  = profiling,
    max-level .int_gset:N = \g_profiling_max_level_int,
    max-level .initial:n = 9999,
}

I'd recommend a blank line between each new key, but that's just personal preference.

\ProcessKeysOptions{profiling}

The kernel includes its own key–val processor with newer versions, so I'd recommend the following instead:

\IfFormatAtLeastTF { 2022-06-01 } {
    \ProcessKeyOptions [ profiling ]
}{
    \RequirePackage { l3keys2e }
    \ProcessKeysOptions { profiling }
}

\bool_if:NF \g_profiling_enabled_bool
{
    \NewDocumentCommand\StartProfiling{ m }{}
    \NewDocumentCommand\StopProfiling{ m }{}
    \NewDocumentCommand\WriteProfilingResults{ O{profiling} }{}
    \NewDocumentCommand\ProfileMacro{ m }{}
    \ExplSyntaxOff

\ExplSyntaxOff is redundant.

    \endinput

Replace with \file_input_stop:.

}

% required variants
\cs_generate_variant:Nn \int_gset:Nn { cf }
\cs_generate_variant:Nn \int_gset:Nn { Nf }

Don't use f variants unless you have a very specific reason. Use e instead.

% initialize a list of tags to output all the data at the end
\seq_new:N \g_profiling_all_instances_seq

% initialize a second list of tags to keep track of the scope that is currently being profiled
\seq_new:N \g_profiling_instances_seq

% initialize a counter to keep track of the current scope level
\int_new:N \g_profiling_scope_int

% global start and end time
\int_new:N \g_profiling_end_int
\int_new:N \g_profiling_start_int
\int_gset:Nf \g_profiling_start_int { \sys_timer: }

\g_profiling_start_int is never used (and would be better as a constant anyways).

% define a message for when the scope doesn't match
\msg_new:nnn { profiling } { scope-mismatch }
{
    The~scope~'#1'~does~not~match~the~current~scope~'#2'.~
    Maybe~you~forgot~to~close~a~scope~or~you~closed~a~scope~too~early?
}

\msg_new:nnn { profiling } { instance-exists }
{
    The~profiling~instance~'#1'~already~exists.~This~is~a~bug!
}

I've usually seen messages generally defined right at the start of the package, or somewhere near where they're used. Doing this in the middle-ish is unconventional (although not incorrect in any way).

% ---------------------------------------------------------------------------- %
%                                Start Profiling                               %
% ---------------------------------------------------------------------------- %
% Start profiling for a given tag. The tag might be profiled multiple times.
% Each time it is profiled, it will be called a new "instance".
% The general instance name will be <tag>/<instance number>.
% If the instance name is specified, the actual profiling will be started in
% \profiling_start_instance:n
\cs_new:Npn \profiling_start:n #1 {

This command body is unexpandable, so you should use \cs_new_protected:Npn instead. In fact, you should use \cs_new_protected:Npn for all the commands that you've defined in this package.

    % check if the tag already exists
    \int_if_exist:cTF { g_profiling_tag_#1_total_int }
    {
        \int_gincr:c { g_profiling_tag_#1_total_int }
    }{
        \seq_new:c { g_profiling_tag_#1_recurse_seq }
        \int_new:c { g_profiling_tag_#1_total_int }
        \int_gset:cn { g_profiling_tag_#1_total_int } { 1 }
    }
    \seq_gput_right:cx
        { g_profiling_tag_#1_recurse_seq }
        { \int_use:c { g_profiling_tag_#1_total_int } }
    \seq_get_right:cN { g_profiling_tag_#1_recurse_seq } \l_tmpa_tl
    \profiling_start_instance:x { #1/\tl_use:N \l_tmpa_tl }
}

Instead of retrieving the tag data by a csname, I'd recommend using a property list. You could either have <tag name> as the key and seq(total, recurse) as the value, or <tag name>-total and <tag name>-recurse as the keys and their values as the values.

% Define a function to record the current timestamp and store it in a new macro
% with the name '\g_profiling_<tag>_start_int'.
\cs_new:Npn \profiling_start_instance:n #1
{
    \int_if_exist:cTF { g_profiling_#1_start_int }
    {
        % warning if the tag already exists
        \msg_critical:nnn { profiling } { instance-exists } { #1 }

critical is too severe here. I'd recommend warning, but error would be fine too.

    }{
        \int_new:c { g_profiling_#1_start_int }
        \int_gset:cf { g_profiling_#1_start_int } { \sys_timer: }
        \seq_gput_right:Nn \g_profiling_all_instances_seq { #1 }
        \seq_gput_right:Nn \g_profiling_instances_seq { #1 }
        \int_gincr:N \g_profiling_scope_int
    }
}


\cs_generate_variant:Nn \profiling_start:n { x }
\cs_generate_variant:Nn \profiling_start_instance:n { x }

I'd prefer e variants over x variants.

% ---------------------------------------------------------------------------- %
%                                Stop Profiling                                %
% ---------------------------------------------------------------------------- %
% Stop profiling for a given tag. The tag might be profiled multiple times.
% This function will stop the most recent instance of the tag (also, if the tag
% has been started recursively)
\cs_new:Npn \profiling_stop:n #1 {
    \seq_gpop_right:cN { g_profiling_tag_#1_recurse_seq } \l_tmpa_tl
    \profiling_stop_instance:x { #1/\tl_use:N \l_tmpa_tl }

Spaces are ignored, so I'd write #1 / \tl_use:N \l_tmpa_tl for better readability.

}

\cs_new:Npn \profiling_stop_instance:n #1
{
    % check if the currently profiled instance is the same as the instance that should be stopped
    % the scopes of the profiled instances may not overlap!
    \seq_gpop_right:NN \g_profiling_instances_seq \l_tmpa_tl
    \tl_set:Nf \l_tmpb_tl { #1 }
    \tl_if_eq:NNTF \l_tmpa_tl \l_tmpb_tl

Skip the \tl_set:Nf \l_tmpb_tl, and instead use \tl_if_eq:NnTF \l_tmpa_tl { #1 } ….

    {
        % if it is, save the data in a macro and store it in a list of results
        % it will be written to the file at the end of the document to avoid influencing the timing
        \int_new:c   { g_profiling_#1_end_int }
        \int_gset:cf { g_profiling_#1_end_int } { \sys_timer: }

        \int_new:c      { g_profiling_#1_scope_int }
        \int_gset_eq:cN { g_profiling_#1_scope_int } \g_profiling_scope_int

        % decrement the scope counter
        \int_gdecr:N \g_profiling_scope_int
    }
    {
        % if it isn't, then something went wrong
        \msg_critical:nnxx
            { profiling }
            { scope-mismatch }
            { \tl_use:N \l_tmpb_tl }
            { \tl_use:N \l_tmpa_tl }

Again, prefer warning or error.

    }
}

% ---------------------------------------------------------------------------- %
\cs_generate_variant:Nn \profiling_stop:n { x }
\cs_generate_variant:Nn \profiling_stop_instance:n { x }

% ---------------------------------------------------------------------------- %
%                                 Write Results                                %
% ---------------------------------------------------------------------------- %
\fp_new:N \l_profiling_diff_fp
\fp_new:N \l_profiling_perc_fp
\iow_new:N \g_profiling_iow

% This function will write the results of a single instance to the file
% #1: tag
% #2: scope
% #3: start (unscaled)
% #4: end (unscaled)
% #5: total time (scaled!)
\cs_new:Npn \profiling_write_line:nnnnn #1 #2 #3 #4 #5{
    % time difference ( * 1/(2^16) )
    \fp_set:Nn \l_tmpa_fp { #3 * 0.0000152587890625 }

I'd recommend using \fp_const:Nn \c__profiling_scale_fp { 2 ^ -16 } instead of a hand-typed hard-coded number.

    \fp_set:Nn \l_tmpb_fp { #4 * 0.0000152587890625 }
    \fp_set:Nn \l_profiling_diff_fp { \l_tmpb_fp - \l_tmpa_fp }

Do your subtraction with the ints first to avoid any loss of precision. So \int_set \l_tmpa_int { #4 - #3 } first, followed by \fp_set:Nn \l_tmpa_fp { \l_tmpa_int * \c__profiling_scale_fp }.

    % percentage of the total time
    \fp_set:Nn \l_profiling_perc_fp { \l_profiling_diff_fp / #5 * 100 }

    \iow_now:Nx \g_profiling_iow {
        #1, % tag
        #2, % scope
        \fp_use:N \l_tmpa_fp, % start
        \fp_use:N \l_tmpb_fp, % end
        \fp_use:N \l_profiling_diff_fp, % difference
        \fp_use:N \l_profiling_perc_fp % percentage
    }
}
% ---------------------------------------------------------------------------- %

\fp_new:N \l_profiling_total_fp
\int_new:N \l_profiling_scope_int

% This function will write the results of all instances to the file
\cs_new:Npn \profiling_write_results:n #1
{
    % if profiling of packages is enabled, remove the first element of the list of tags,
    % as it is the name of the current file
    \bool_if:NT \g_profiling_packages_bool
    {
        \seq_gpop_left:NN \g_profiling_all_instances_seq \l_tmpa_tl
    }

    % get current time (latest possible moment)
    \int_gset:Nf \g_profiling_end_int { \sys_timer: }
    \fp_set:Nn \l_profiling_total_fp { \g_profiling_end_int * 0.0000152587890625 }

    % open a new file named 'profiling.csv' to write the data
    \iow_open:Nn \g_profiling_iow { \tl_use:N \g_profiling_file_name_tl .csv }

The file name is only expanded here for implementation reasons, so using \iow_open:Ne would be better.

    % write the header
    \iow_now:Nx \g_profiling_iow{Tag,Scope,Start,End,Difference,Percentage}

    % write total time (if requested)
    \bool_if:NT \g_profiling_total_bool {
        \profiling_write_line:nnnnn
            { total }
            { 0 }
            { 0 }
            { \g_profiling_end_int }
            { \fp_use:N \l_profiling_total_fp }
    }

    % loop through the list of tags and write the data to the file
    \seq_map_inline:Nn \g_profiling_all_instances_seq
    {
        \int_compare:nNnT
            { \int_use:c {g_profiling_##1_scope_int} } <

Use \int_compare:cNnT { g_profiling_##1_scope_int } … instead.

            { \int_use:N \g_profiling_max_level_int + 1 }

No need for the \int_use:N here since \int_compare will expand any int variables itself.

        {
            \profiling_write_line:nnnnn
                { ##1 }
                { \int_use:c {g_profiling_##1_scope_int} }
                { \int_use:c {g_profiling_##1_start_int} }
                { \int_use:c {g_profiling_##1_end_int} }
                { \fp_use:N \l_profiling_total_fp }

This is what the v variant is for. Assuming that you've defined the variant, you should instead use \profiling_write_line:nvvvv { ##1 } { g_profiling_##1_scope_int } … { \l_profiling_total_fp }.

        }
    }
}

% ---------------------------------------------------------------------------- %
%                             User level functions                             %
% ---------------------------------------------------------------------------- %
% Create user-level functions for starting and stopping profiling
\NewDocumentCommand\StartProfiling{ m }{
    \profiling_start:x { #1 }
}

\NewDocumentCommand\StopProfiling{ m }{
    \profiling_stop:x { #1 }
}

\NewDocumentCommand\WriteProfilingResults{O{profiling}}{
    \profiling_write_results:n {#1}
}

\NewDocumentCommand{\ProfileMacro}{ m }{
    \AddToHook{cmd/#1/before}[profiling/start]{ \profiling_start:x { m/#1 } }
    \AddToHook{cmd/#1/after}[profiling/stop]{ \profiling_stop:x { m/#1 } }
}

I'd recommend using more whitespace. Example:

\NewDocumentCommand \ProfileMacro { m } {
    \AddToHook
        { cmd / #1 / before }
        [ profiling / start ]
        { \profiling_start:x { m / #1 } }

    \AddToHook
        { cmd / #1 / after }
        [ profiling / stop ]
        { \profiling_stop:x { m / #1 } }
}

Aside from the above, I didn't see any other obvious issues. (I also haven't tested any of my suggestions, so if something doesn't work, it's probably my fault.)

Where is the "white space" that I did not measure in the document and in the preamble?

That's everything that happens before the profiling is activated. Just subtract \g_profiling_start_int from \g_profiling_end_int to remove this. (Looking through the code, I'm guessing that you meant to do this but just forget somewhere.)

Is there any way to produce this kind of visual representation without having to use python? Maybe with pgfplots in a second run?

pgfplots can parse the CSV file fairly easily (look at the pgfplots and pgfplotstable manuals), and you should be able to get similar output with the polar pgfplots library and the right settings.

Answer 2

This library is awesome! But note that the GUI has an issue: you should use branchvalues='total', otherwise the length of the parent is the sum of its own value and of the values of the children (or something like that). For instance, in my csv I had:

m/robExtEvaluateCompileAndInclude/20,3,2.461822509765625,2.483901977539062,0.022079467773437,0.6834853501740443
m/robExtWriteFile/18,4,2.462203979492188,2.4759521484375,0.013748168945312,0.4255841745036665

so the second element takes 0.0137/0.022=0.62% of the time of its parent, but with the current status of the code, it takes less than 50%:

This is fixed with branchvalues='total':

import plotly.express as px
import pandas as pd
import plotly.io as pio

pio.renderers.default = "browser"
df = pd.read_csv("profiling.csv")

parent_queue = ["total"]
parents = [""]
prev_scope = 0
for row in df.iloc[1:,:].itertuples():
    if row.Scope == prev_scope:
        parent_queue.pop()
        parents.append(parent_queue[-1])
        parent_queue.append(row.Tag)
    elif row.Scope > prev_scope:
        parents.append(parent_queue[-1])
        parent_queue.append(row.Tag)
    elif row.Scope < prev_scope:
        parent_queue = parent_queue[:row.Scope]
        parents.append(parent_queue[-1])
        parent_queue.append(row.Tag)

    prev_scope = row.Scope

# insert parent column as second column
df.insert(1, "Parent", parents)

# generate column that contains tag without the call count
df['Type'] = df['Tag'].str.replace(r"(.*)/\d+$", r"\1", regex=True)

fig = px.sunburst(
    df,
    names='Tag',
    parents='Parent',
    values='Difference',
    color='Type',
    branchvalues='total',
)
fig.show()