我有一个相当大的包/类模板,用于多种不同的文档类型。有些用户有时会抱怨编译时间太长了。然而,为了找到我的包的瓶颈,我找不到一种合适的方法,可以在不向代码中添加许多手动标记的情况下使用(例如,不必向我的包代码添加宏,如这里或者这里)。由于无论如何我都想尝试一下 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 }
再次,更喜欢warning
或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 }
我建议使用\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 }
先用int
s 进行减法以避免任何精度损失。因此,\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 文件(查看pgfplots
和
pgfplotstable
手册),并且您应该能够使用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()