summaryrefslogtreecommitdiff
path: root/graphics/pgf/base/doc/text-en/pgfmanual-en-library-profiler.tex
blob: 6e5200a9fe0edb699ca150a04e9e642cb1b303c2 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
% Copyright 2019 by Christian Feuersaenger
%
% This file may be distributed and/or modified
%
% 1. under the LaTeX Project Public License and/or
% 2. under the GNU Free Documentation License.
%
% See the file doc/generic/pgf/licenses/LICENSE for more details.


\section{Profiler Library}

{\noindent {\emph{by Christian Feuersänger}}}

\begin{pgflibrary}{profiler}
    A library to simplify the optimization of runtime speed of \TeX\ programs.

    It relies on the |pdftex| primitive
    \declareandlabel{\pdfelapsedtime}\footnote{The primitive is emulated in
    lua\TeX.} to count (fractional) seconds and counts total time and self time
    for macro invocations.
\end{pgflibrary}


\subsection{Overview}

The intended audience for this library are people writing \TeX\ code which
should be optimized. It is certainly \emph{not} useful for the end-user.

The work flow for the optimization is simple: the preamble contains
configuration commands like
%
\begin{codeexample}[code only]
\usepgflibrary{profiler}
\pgfprofilenewforenvironment{tikzpicture}
\pgfprofilenewforcommand{\pgfkeys}{1}
\end{codeexample}
%
\noindent and then, the time between |\begin{tikzpicture}| and
|\end{tikzpicture}| and the time required to call |\pgfkeys| will be collected.

At the end, a short usage summary like
%
\begin{codeexample}[code only, tikz syntax=false]
 pgflibraryprofiler(main job) {total time=1.07378sec; (100.0122%) self time=0.034sec; (3.1662%)}
 pgflibraryprofiler(<ENV>tikzpicture) {total time=1.03978sec; (96.84601%) self time=1.00415sec; (93.52722%)}
 pgflibraryprofiler(<CS>pgfkeys) {total time=0.03563sec; (3.31726%) self time=0.03563sec; (3.31726%)}
\end{codeexample}
%
\noindent will be provided in the log file, furthermore, the same information
is available in a text table called |\jobname.profiler.|\meta{datetime}|.dat|
which is of the form:
%
\begin{codeexample}[code only, tikz syntax=false]
profilerentry       totaltime[s]        totaltime[percent]  selftime[s]         selftime[percent]
main job            1.07378             100.0122            0.034               3.1662
<ENV>tikzpicture    1.03978             96.84601            1.00415             93.52722
<CS>pgfkeys         0.03563             3.31726             0.03563             3.31726
\end{codeexample}
%
Here, the |totaltime| means the time used for all invocations of the respective
profiler entry (one row in the table). The |selftime| measures time which is
not already counted for in another profiler entry which has been invoked within
the current one. The example above is not very exciting: the main job consists
only of several (quite complex) pictures and nothing else. Thus, its total time
is large. However, the self time is very small because the |tikzpicture|s are
counted separately, and they have been invoked within the |main job|. The
|\pgfkeys| control sequence has been invoked within the |tikzpicture|, that's
why the |selftime| for the |tikzpicture| is a little bit smaller than its
|totaltime|.


\subsection{Requirements}

The library works with |pdftex| and |luatex|. Furthermore, it requires a more
or less recent version of |pdftex| which supports the |\pdfelapsedtime|
directive.


\subsection{Defining Profiler Entries}

Unlike profilers for C/C++ or java, this library doesn't extract information
about every \TeX\ macro automatically, nor does it collect information for each
of them. Instead, every profiler entry needs to be defined explicitly. Only
defined profiler entries will be processed.

\begin{command}{\pgfprofilenew\marg{name}}
    Defines a new profiler entry named \meta{name}.

    This updates a set of internal registers used to track the profiler entry.
    The \meta{name} can be arbitrary, it doesn't need to be related to any
    \TeX\ macro.

    The actual job of counting seconds is accomplished using
    |\pgfprofilestart|\marg{name} followed eventually by the command
    |\pgfprofileend|\marg{name}.

    It doesn't hurt if |\pgfprofilenew| is called multiple times with the same
    name.
\end{command}

\begin{command}{\pgfprofilenewforcommand\oarg{profiler entry name}\marg{\textbackslash macro}\marg{arguments}}
    Defines a new profiler entry which will measure the time spent in
    \meta{\textbackslash macro}. This calls |\pgfprofilenew| and replaces the
    current definition of \meta{\textbackslash macro} with a new one.

    If \oarg{profiler entry name} has been provided, this defines the argument
    for |\pgfprofilenew|. It is allowed to use the same name for multiple
    commands; in this case, they are treated as if it where the same command.
    If the optional argument is not used, the profiler entry will be called
    `\declareandlabel{\pgfprofilecs}\meta{macro}' (\meta{macro} without
    backslash) where |\pgfprofilecs| is predefined to be |<CS>|.

    The replacement macro will collect all required arguments, start counting,
    invoke the original macro definition and stop counting.

    The following macro types are supported within |\pgfprofilenewforcommand|:
    %
    \begin{itemize}
        \item commands which take one (optional) argument in square brackets
            followed by one optional argument which has to be delimited by
            curly braces (use an empty argument for \meta{arguments} in this
            case),
        \item commands which take one (optional) argument in square brackets
            and \emph{exactly} \meta{arguments} arguments afterwards.
    \end{itemize}

    Take a look at |\pgfprofilenewforcommandpattern| in case you have more
    complicated commands.

    Note that the library can't detect if a command has been redefined
    somewhere.
\end{command}

\begin{command}{\pgfprofilenewforcommandpattern\oarg{profiler entry name}\marg{\textbackslash macro}\marg{argument pattern}\marg{invocation pattern}}
    A variant of |\pgfprofilenewforcommand| which can be used with arbitrary
    \meta{argument patterns}. Example:
    %
\begin{codeexample}[code only]
\def\mymacro#1\to#2\in#3{ ... }
\pgfprofilenewforcommandpattern{\mymacro}{#1\to#2\in#3}{{#1}\to{#2}\in{#3}}
\end{codeexample}

    Note that |\pgfprofilenewforcommand| is a special case of
    |\pgfprofilenewforcommandpattern|:
    %
\begin{codeexample}[code only]
\def\mymacro#1#2{ ... }
\pgfprofilenewforcommand\macro{2}
\pgfprofilenewforcommandpattern{\mymacro}{#1#2}{{#1}{#2}}
\end{codeexample}
    %
    Thus, \meta{argument pattern} is a copy-paste from the definition of your
    command. The \meta{invocation pattern} is used by the |profiler| library to
    invoke the \emph{original} command, so it is closely related to
    \meta{argument pattern}, but it needs extra curly braces around each
    argument.

    The behavior of |\pgfprofilenewforcommandpattern| is the same as discussed
    above: it defines a new profiler entry which will measure the time spent in
    \meta{\textbackslash macro}. The details about this definition has already
    been described. Note that up to one optional argument in square brackets is
    also checked automatically.

    If you like to profile a command which doesn't match here for whatever
    reasons, you'll have to redefine it manually and insert |\pgfprofilestart|
    and |\pgfprofileend| in appropriate places.
\end{command}

\begin{command}{\pgfprofileshowinvocationsfor\marg{profiler entry name}}
    Enables verbose output for \emph{every} invocation of \meta{profiler entry
    name}.

    This is only available for profiler entries for commands (those created by
    |\pgfprofilenewforcommand| for example). It will also show all given
    arguments.
\end{command}

\begin{command}{\pgfprofileshowinvocationsexpandedfor\marg{profiler entry name}}
    A variant of |\pgfprofileshowinvocationsfor| which will expand all
    arguments for \meta{profiler entry name} before showing them. The
    invocation as such is not affected by this expansion.

    This expansion (with |\edef|) might yield unrecoverable errors for some
    commands. Handle with care.
\end{command}

\begin{command}{\pgfprofilenewforenvironment\oarg{profiler entry name}\marg{environment name}}
    Defines a new profiler entry which measures time spent in the environment
    \meta{environment name}.

    This calls |\pgfprofilenew| and handles the begin/end of the environment
    automatically.

    The argument for |\pgfprofilenew| is \meta{profiler entry name}, or, if
    this optional argument is not used, it is
    `\declareandlabel{\pgfprofileenv}\meta{environment name}' where
    |\pgfprofileenv| is predefined as |<ENV>|. Again, it is permitted to use
    the same \meta{profiler entry name} multiple times to merge different
    commands into one output section.
\end{command}

\begin{command}{\pgfprofilestart\marg{profiler entry name}}
    Starts (or resumes) timing of \meta{profiler entry name}. The argument must
    have been declared in the preamble using |\pgfprofilenew|.

    Nested calls of |\pgfprofilestart| with the same argument will be ignored.

    The invocation of this command doesn't change the environment: it doesn't
    introduce any \TeX\ groups nor does it modify the token list.
\end{command}

\begin{command}{\pgfprofileend\marg{profiler entry name}}
    Stops (or interrupts) timing of \meta{profiler entry name}.

    This command finishes a preceding call to |\pgfprofilestart|.
\end{command}

\begin{command}{\pgfprofilepostprocess}
    For \LaTeX, this command is installed automatically in |\end{document}|. It
    stops all running timings, evaluates them and returns the result into the
    logfile. Furthermore, it generates a text table called
    |\jobname.profiler.|\meta{YYYY}|-|\meta{MM}|-|\meta{DD}|_|\meta{HH}|h_|\meta{MM}|m.dat|
    with the same information.

    Note that the |profiler| library predefines two profiler entries, namely
    |main job| which counts time from the beginning of the document until
    |\pgfprofilepostprocess| and |preamble| which counts time from the
    beginning of the document until |\begin{document}|.
\end{command}

\begin{command}{\pgfprofilesetrel\marg{profiler entry name} (initially main job)}
    Sets the profiler entry whose total time will be used to compute all other
    relative times. Thus, \meta{profiler entry name} will use $100\%$ of the
    total time per definition, all other relative times are relative to this
    one.
\end{command}

\begin{command}{\pgfprofileifisrunning\marg{profiler entry name}\marg{true code}\marg{false code}}
    Invokes \marg{true code} if \marg{profiler entry name} is currently running
    and \marg{false code} otherwise.
\end{command}