代码审查:expl3 中的 LaTeX 分析

代码审查:expl3 中的 LaTeX 分析

我有一个相当大的包/类模板,用于多种不同的文档类型。有些用户有时会抱怨编译时间太长了。然而,为了找到我的包的瓶颈,我找不到一种合适的方法,可以在不向代码中添加许多手动标记的情况下使用(例如,不必向我的包代码添加宏,如这里或者这里)。由于无论如何我都想尝试一下 expl3,所以我尝试了一下。

剧透:我得到了类似的东西

测试用例图

我不是 LaTeX 编程专家。因此,如果您发现以下代码存在任何重大问题,我很乐意听取您的建议:

\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

用法

只需将其加载到文档顶部并使用选项来指定,如果包应该自动挂接到您的序言、文档和包加载中。如果您对特定的宏调用感兴趣,请使用命令\ProfileMacro{<cs>}

每个被分析的部分都有一个标签(例如,一个包将具有标签p/<package>)。由于某些标签(尤其是宏)可以多次调用(或递归调用),因此每个被分析的标签实例都将获得一个编号。宏将被命名为m/<macroname>/<instance>调用<instance>编号。Package、Preamble 和 Document 实例显然应该只调用一次。

因此,该包将把所有分析数据输出到 csv 文件中,文件内容如下:

  • 标签(或者更好的说法是:实例)
    • 序言d/preamble/1或文件d/document/1
    • 一套p/mypackage/1
    • 宏调用m/mymacro/3
  • 范围(对于嵌套测量,范围级别将增加)
    • 序言和正文为 1 级
    • 例如,加载到另一个包中的包将具有级别 3
  • 开始时间
  • 时间结束
  • 时间差异
  • 占总运行次数的百分比

测试用例

使用以下输入文档

\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}

生成的 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

后期处理

使用这个 Python 脚本

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()

我知道这段代码远非完美,而且会带来相当多的开销。但它至少能够生成一个可视化表示来查找包中可能存在的瓶颈。也许不是绝对数字,而是相对于包的其他部分而言。

还有一些悬而未决的问题:

  • 我在文档和序言中没有测量的“空白”在哪里?
  • 有没有办法不用 python 就能产生这种视觉表现?也许第二次运行的时候用 pgfplots?

答案1

首先,你对这个包做得非常好!我没有发现任何重大问题,只是一些风格上的问题:

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

\NeedsTeXFormat{LaTeX2e}[2020/10/01]由于您的包需要钩子支持,所以我会在此之前添加。

\ExplSyntaxOn

\ProvidesExplPackage已经有了\ExplSyntaxOn,所以这里不需要它。

\RequirePackage{expl3,l3keys2e}

\ProvidesExplPackage如果没有 ,和\ExplSyntaxOn将无法工作expl3,因此如果您已经到了这一步,expl3已经加载。您可以更早地加载包,但由于您在此包中使用了钩子,因此您已经需要一个包含 的 LaTeX 内核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

由于 key-val 设置将这些变量初始化为相同的值,因此是多余的。

此外,这些变量可能应该是“内部的”,因此用来\g__…表示它。

\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}

内核包含自己的具有较新版本的 key-val 处理器,因此我建议使用以下内容:

\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是多余的。

    \endinput

用。。。来代替\file_input_stop:

}

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

f除非有非常特殊的原因,否则不要使用变体。请使用e 替代。

% 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从未使用过(并且无论如何作为常量会更好)。

% 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 {

此命令主体不可扩展,因此您应该使用 \cs_new_protected:Npn。事实上,您应该 \cs_new_protected:Npn对您在此包中定义的所有命令使用。

    % 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 }
}

我建议不要通过 csname 检索标签数据,而是使用属性列表。您可以将<tag name>作为键和 seq(total, recurse)作为值,或者<tag name>-total将 和<tag name>-recurse作为键并将其值作为值。

% 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在这里太严厉了。我建议warning,但error 也可以。

    }{
        \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 }

我更喜欢e变体而非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 }

空格会被忽略,因此我会写得#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

跳过\tl_set:Nf \l_tmpb_tl, 而改用 \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 }

再次,更喜欢warningerror

    }
}

% ---------------------------------------------------------------------------- %
\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_const:Nn \c__profiling_scale_fp { 2 ^ -16 } 而不是手动输入的硬编码数字。

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

先用ints 进行减法以避免任何精度损失。因此,\int_set \l_tmpa_int { #4 - #3 }先用 ,然后用 \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 }

这里仅仅为了实现的原因而扩展了文件名,因此使用 \iow_open:Ne会更好。

    % 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_compare:cNnT { g_profiling_##1_scope_int } …

            { \int_use:N \g_profiling_max_level_int + 1 }

这里不需要,\int_use:N因为它本身\int_compare会扩展任何 int变量。

        {
            \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 }

这就是v变体的用途。假设您已经定义了变体,则应该使用 \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 } }
}

我建议使用更多空格。例如:

\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 } }
}

除上述情况外,我没有发现任何其他明显问题。(我也没有测试过我的任何建议,所以如果某些方法不起作用,那可能是我的错。)

我在文档和序言中没有测量的“空白”在哪里?

这就是激活分析之前发生的所有事情。只需\g_profiling_start_int从中减去\g_profiling_end_int即可将其删除。(查看代码,我猜您本来打算这样做,但忘了。)

有没有办法不用 python 就能产生这种视觉表现?也许第二次运行的时候用 pgfplots?

pgfplots可以相当容易地解析 CSV 文件(查看pgfplotspgfplotstable手册),并且您应该能够使用polar pgfplots库和正确的设置获得类似的输出。

答案2

这个库很棒!但请注意,GUI 有一个问题:您应该使用branchvalues='total',否则父级的长度是其自身值与子级值的总和(或类似的东西)。例如,在我的 csv 中我有:

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

因此第二个元素占用了0.0137/0.022=0.62%其父元素的时间,但根据代码的当前状态,它占用的时间不到 50%:

在此处输入图片描述

这是通过以下方式修复的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()

相关内容