path: root/Build/source/texk/web2c/texprofdir/texprofileman.tex

% Copyright 2017-2024 Martin Ruckert, Hochschule Muenchen, Lothstrasse 64, 80336 Muenchen
%
% Permission is hereby granted, free of charge, to any person obtaining a copy
% of this software and associated documentation files (the "Software"), to deal
% in the Software without restriction, including without limitation the rights
% to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
% copies of the Software, and to permit persons to whom the Software is
% furnished to do so, subject to the following conditions:
%
% The above copyright notice and this permission notice shall be
% included in all copies or substantial portions of the Software.
%
% THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
% IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
% FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
% COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY,
% WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT
% OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
% THE SOFTWARE.
%
% Except as contained in this notice, the name of the copyright holders shall
% not be used in advertising or otherwise to promote the sale, use or other
% dealings in this Software without prior written authorization from the
% copyright holders.
\documentclass[a4paper,english]{article}
\usepackage{a4wide}
\usepackage{latex2man}

\setVersion{1.0}
\setDate{6-9-2024}

\begin{document}
\begin{Name}{1}{texprofile}{Martin Ruckert}{Displaying TeX profiles}{TeXprofile: Displaying TeX profiles}
  
  \Prog{texprofile} - Displaying the profile data collected by \Prog{texprof}.
\end{Name}

\section{Synopsis}

\Prog{texprofile} [Options] \Arg{inputfile}

\section{Description}
\Prog{texprofile} reads the binary \Arg{inputfile} as produced by
\Prog{texprof}.  The extension \File{.tprof} of the input file can be
omitted. It analyses the data and presents the results in a variety of
tables, either optimized for human readability or as CSV (comma
separated values) files for further processing.

The output is written to the standard output stream where it can be redirected
to a file or viewed immediately.

\section{Options}
There are four types of options: general options, table options,
selection options, and formatting options.

The general options:
\begin{description}
\item[\Opt{-?} \Opt{-h} \Opt{--help}]
  Display a short help text and exit the program.
\item[\Opt{--version}]
  Display the version information and exit.
\end{description}

The table options determine the tables that will be displayed.
These options all use upper case letters.
If no table option is given, only some global information is shown.

\begin{description}
\item[\Opt{-T}]
  Show the table of the top 10 input lines.
\item[\Opt{-G}]
  Show the table of the  macro call graph.
\item[\Opt{-C}]    Show the table of times per TeX command.
\item[\Opt{-L}]    Show the table of times per input line.
\item[\Opt{-R}]    Show the table of raw time stamps.
\item[\Opt{-S}]    Show the table of macro stack changes.
\item[\Opt{-F}]    Show the table of all input files.
\item[\Opt{-M}]    Show the table of all macros called.
\item[\Opt{-A}]    Show important tables (equal to -TGFC) tables.
\item[\Opt{-N}]    Do not show the table of global information.
\end{description}

The selection options allow to reduce the amount of data that is shown
in the table by omitting table entries that contribute little to the
overall runtime.

\begin{description}
\item[\OptArg{-p}{n}] Do not show information for table entries
  with cumulative time below \Arg{n} percent. The default is 1.0 percent.
\item[\OptArg{-t}{n}] Limit the number of input lines shown in the
  table of the ``Top Ten'' to \Arg{n}. This option is only useful
  with the \Opt{-T} option.
\end{description}

The formatting option determine the formatting of the information in the tables
as well as the selection of information that is shown in the tables.

\begin{description}
\item[\Opt{-i}]
  Add the macros file and line numbers after the macro name.
  This option is useful to distinguish two macros that share
  the same name.
\item[\Opt{-m}]
  Optimize output for machine readability. When optimized for human readability,
  times are rounded and given in a short form adding a unit identifier:
  s for seconds, ms for milliseconds, us for micro seconds, and ns for
  nanoseconds. This format is inconvenient if you want to import the data
  for example into a spread-sheet for further processing.
  With the \Opt{-m} option times are simply given in nano seconds without units.
  Similar the combined time for the total time used for a macro and the
  time used as a sub-macro from the call graph is given in a single column
  with a slash separating both numbers is nice for human readers.
  With the \Opt{-m} option both numbers will simply be given in separate columns.
  
\item[\Opt{-n}]
  Show the time stamp numbers. This option is useful together with
  the \Opt{-R} option, if you import the table into a database or spread-sheet.
  If you sort the data by various properties into different
  categories, the time stamp number can be used to keeping the entries
  within a category sorted by time.
  
\item[\Opt{-s}]
  Show the changes of the macro stack.
  This option is useful with the \Opt{-R} option if you want to see the changes
  in the macro stack (see \Opt{-S}) together with the timing information in
  a single table.
\end{description}


\section{Data Formats}
\subsection{File Numbers}
While \Prog{texprof} is running, every TeX input file is given a
unique file number. The file name alone is often not unique because
two files in different directories might have the same file
name. Displaying the full file name with the complete path is however often
not very
convenient. So if you observe the same file name together with
different file numbers, you can use the option \Opt{-F} to get a table of all
file numbers and their full file names.

But even within the same
directory, TeX can read different files with the same name during one
run: TeX can open a file for writing, write content to the file, close
it, open it for reading, read it and close it again. Then TeX might
repeat this process a second time, or multiple times, reusing the same
file name over and over again.  \Prog{texprof} will assign a new file
number to this file each time it is opened for reading. So you can
tell from the sequence of file numbers which one was the first, the
second, or the third.

Last not least, there are some special file
numbers:
\begin{description}
\item[0 - unknown]
  If the file is unknown, which should rarely happen,
  the file number 0 is used.
\item[1- system]
  \Prog{texprof} will map
  time intervals that are used to execute certain system routines
  to the ``system'' pseudo file 
using the line numbers to identify the specific routine
like producing the output DVI file (shipout), breaking
a paragraph into lines (linebrk), or breaking the
document into pages (buildpg). These times do not depend on the
use of macros but simply on the size of the document.
\item[2 - terminal]
  TeX commands entered on the command line or interactively are mapped
  to file number 2.
\end{description}

\subsection{Time}
If the option \Opt{-m} is given times are given as nanoseconds.
Otherwise, times are rounded to at most 4 digits precission and
displayed with a unit: seconds (s), milliseconds (ms), microseconds
(um), or nanoseconds (ns).

\subsection{Macro Names}
Macro names are shown with the leading backslash.  Since macro names
are often not unique, the command line option \Opt{-i} can be used to
show after the macro name in square brackets the file number and the
line number where the macro is defined.  Unless two macros with the
same name are defined in the same file and line this is sufficient to
uniquely identify a macro. A macro defined with ``let'' results in a
complet copy of the original macro. Therefore it will not reference
the file and line of the ``let'' command but the same file and line as
the original macro.

\section{Examples}
Let's assume that you issue the command \Prog{texprof} \Opt{-prof}
\Arg{hello.tex}.  This will run \Prog{texprof} on the input file
\Arg{hello.tex} with option \Opt{-prof}.  The program \Prog{texprof}
will load the plain TeX format and then process \File{hello.tex} to
produce \File{hello.log} and \File{hello.dvi}.  It will execute
exactly the same steps that TeX would execute if you had issued the
command \Prog{tex} \Arg{hello.tex}.

In addition to \File{hello.log} and \File{hello.dvi}, \Prog{texprof}
will also produce the file \File{hello.tprof} containing time
measurements made while \Prog{texprof} was running.  The option
\Opt{-prof} will switch on the gathering of timing data as soon as
\Prog{texprof} enters its main control procedure; The file
\File{hello.tprof} will contain a time measurement, called a time
stamp, for every command that TeX executed while processing the input.
A binary format is used to store all that data in a simple and compact
form. Still the file \File{hello.tprof} might become very big.

The program \Prog{texprofile} is used to extract and analyse the data
contained in \File{hello.tprof} and produce useful output.  Here are
some examples:
  
\begin{description}
\item[\Prog{texprofile} \Arg{hello}]
  Without further options \Prog{texprofile} will write some general
  information to the standard output, like the total time measured,
  the number of samples, the average time per sample, etc.
  The general information is always given unless explicitely disabled
  with the \Opt{-N} option or with the \Opt{-m} option.

\item[\Prog{texprofile} \Opt{-T} \Arg{hello}]
  With the option \Opt{-T}, \Prog{texprofile} will map each time stamp
  to a specific line of input, add up the time intervalls for each input
  line separately, and output a table showing the ten lines that have
  the highest cummulative time.
  The table has the following seven columns:
  \begin{description}
  \item[1. file]
    The first column contains the input file number as explained above.
    The input file name if shown in column 7.
  \item[2. line]
    The line number.
  \item[3. percent]
    The time spent in this line and file as a percentage of the total
    time measured as given as part of the general information.
  \item[4. absolute]
    The absolute time spent in this line and file.
  \item[5. count]
    The number of times the execution path entered this line.
    Note, that a
    macro call usually redirects the execution path to another line
    from where the execution will return after the macro call has completed.
    Reentering the line after such an excursion to an other line will
    cause this counter to be incremented. In summary, this counter might
    reflect the number of partial executions of a line not the number
    of full executions of the entire line.
  \item[6. average]
    The average time spent in the line is simply computed by dividing the
    value in column 4 by the value in column 5.
  \item[7. file]
    The input file name. The corresponding file number is shown in column 1.
  \end{description}

\item[\Prog{texprofile} \Opt{-G} \Arg{hello}]
  With the option \Opt{-G}, \Prog{texprofile} will map each time stamp
  either to file input or to a macro body.
  The table shown is divided into several sections, the first section
  is devoted to file input, each of the following sections is devoted
  to a specific macro.  
  \\
  Each section starts with a header. The header of the
  first section is ``File'' the header of a later section is the macro name.
  \\
  The first line after the header gives the total time spent in the section
  in two different formats:
  \begin{description}
    \item[1. time]
      Column 1 gives it as an absolut time.
    \item[3. percentage]
      Column 3 gives it as a percentage of the total time measured.
  \end{description}
  For the first section with the header ``File'', the absolute time
  will be equal to the total time measured because \Prog{texprof}
  did spent all the time processing the file \Arg{hello}.
  And consequently the value in column 3 will be 100\%.
  \\
  To accomplish a task, a macro usually calls other
  macros that we call child macros in the following.
  The following lines in the table will give a breakdown
  of the time shown in the first line.
  The breakdown starts with a line showing the time spent in the section
  excluding the time spent in child macros. It shows in column 4 the number
  of times the macro was called.
  \begin{description}
    \item[1. time]
      Column 1 gives the absolut time spent in the section excluding the time
      spent in child macros
    \item[3. percentage]
      Column 3 gives the time from column 1 as a percentage of the total time
      spent in this section as given in the previous line.
    \item[4. count/total]
      Column 4 gives the number of times the section was called.
  \end{description}
  The lines that follow in the table show the time spent in one of
  the child macros. Column 2, 4, and 5 need some explanation.
    \begin{description}
    \item[2. loop]
      The only case where column 2 is not empty is the case of a
      recursive macro. A recursive macro is a macro that along the
      chain of macro calls eventually calls itself creating a
      recursive loop. At this point, a macro becomesits own descendant
      and at the same time its own ancestor.
      \\
      Therefore \Prog{texprofile} maintains for each child macro two
      accumulators for the elapsed time: For the time shown in 
      column 2 labeled ``loop'', \Prog{texprofile} adds up the time
      differences observed at the return of a child macro.  For the
      time shown in the column labeled ``time'' and ``percent'', it
      subtracts from the time differences observed at the return of a
      child macro all those time differences that were already added
      to one of the other lines in the time breakdown: the macro itself
      or one of the other child macros.
      So the times shown in column 1 of line 2 and the following lines
      will add up to the time shown in column 1 of the line 1;
      and the percentages shown in column 3 of line 2 and the following lines
      will add up to 100\%.
      The time shown in column 3 will show show the total time needed
      to accomplish the sub task assigned to the respective child macro.
    \item[4. count/total]
      Column 4 shows two counts $n/m$ for the macro named in column 5.
      $m$ is the total number of calls to the macro and $n$ is the number of
      calls as a child macro in the current section. The number $n$ will
      always be less or equal to $m$.

    \item[5. child]
      Column 5 shows the name of the child macro as explained above.
  \end{description}
\item[\Prog{texprofile} \Opt{-G} \Opt{-m} \Arg{hello}]
  This table will contain the same data as the previous example
  but this time the \Opt{-m} option will optimize the output for
  machine readability.
  \begin{itemize}
    \item There are no column headers.
    \item The times in column 1 ``time'' and column 2 ``loop''
      are given in nanoseconds without a unit identifier.
    \item The numbers $n/m$ in column 4 are now shown in two separate
      columns 4 and 5; the macro name moves from column 5 to column 6.
  \end{itemize}

\item[\Prog{texprofile} \Opt{-F} \Arg{hello}]
  With the option \Opt{-F}, \Prog{texprofile} outputs the table
  of all of TeX's input files using 5 columns: 
    \begin{description}
    \item[1. file] The file number as explained above.
    \item[2. lines] The difference between the highest and the lowest
      line number found in the profile data for this file. This is
      usually only a subset of all the lines of the file.
    \item[3. percent]
      The percentage of the total time measured that is attibuted to the file.
    \item[4. time]
      The absolute time that is attibuted to the file.
    \item[5. name]
      The full file name of the file.
    \end{description}
\item[\Prog{texprofile} \Opt{-C} \Arg{hello}]
   With the option \Opt{-C}, \Prog{texprofile} outputs the table
   of all TeX commands executed while profiling
   using 6 columns: 
    \begin{description}
    \item[1. cmd] The command code used internaly by TeX.
      Usually the same number is used by TeX for several
      closely related tasks.
      There is a special command code 101 which is used to
      for the time that is spend on system routines that are
      mapped to the system file as explained above.
    \item[2. time]
      The total time used for the command.
    \item[3. percent]
      The percentage of the total time measured used for the command.
    \item[4. count]
      The number of times this command was executed.
    \item[5. average]
      The average time needed to execute the command.
      This is simpy the value in column 2 divided by the value in column 4.
    \item[6. name]
      A verbal description of the command or commands that share this
      command code.
    \end{description}
\item[\Prog{texprofile} \Opt{-R} \Opt{-m} \Opt{-n} \Arg{hello}]
  With the options \Opt{-R} \Opt{-m}, \Prog{texprofile} outputs the table
  of raw time measurements as observed by \Prog{texprof} optimized for machine
  readability. The option \Opt{-n} adds a column for the number
  of each time measurements.
  Because of the \Opt{-m} option, the table has no column headers.
  The table has  7 columns:
  \begin{description}
  \item[1. number] The number of the time measurment.
    These numbers are strictly increasing but not necessarily consecutive.
    They can be used to keep the measurements sorted in the order in which
    they were made.
    \item[2. file] The file number as explained above.
    \item[3. line] The line number as explained above.
    \item[4. time] The time interval in nano seconds.
    \item[5. command] The command name as given in column 6 of the previous example.
    \item[6. level ] The nesting level of the macro call stack.
    \item[7. macro] The macro name.
  \end{description}
  This table contains all the timing information gathered during the run
  of \Prog{texprof}. Some information about macro calls is contained in
  column 6. More information about macro calls could be added
  by using the \Opt{-s} option. The information about macro returns
  can be obtained from column 6.
  The table can be imported to a spread-sheet or a database for further
  analysis.
\end{description}


\section{Bugs}
If the last command in a macro body is a macro call, we call this a tail call.
If such a tail call reads ahead to scan the following input
for possible arguments, the look-ahead mechaism of TeX might push further
macros or new input files on TeX's input stack.
These entries will remain on top of TeXprof's macro nesting stack,
even if TeX backs up all these tokens on its input stack.
This can cause an attribution of runtime to those entries as sub entries
of the tail call. If this explanation sounds complicated to you, it is
because the situation is indeed complicated. 

\section{See Also}
  \Cmd{texprof}{1}


\section{Version}
Version: \Version\  of \Date
\begin{description}
\item[Copyright] \copyright\ 2024, Martin Ruckert,\\
     Hochschule München, Lothstrasse 64, D-80335 München

\item[Distribution]
  \Prog{texprofile} is distributed with TeX Live.
  More recent versions might be found on GitHub
  \URL{https://github.com/ruckertm/HINT}.

\item[License] This program can be redistributed and/or modified under the
  terms of the MIT/X11 license.
\end{description}

\section{Author}
\noindent
Martin Ruckert                        \\
Munich University of Applied Sciences \\
Email: \Email{martin.ruckert@hm.edu}  \\

\end{document}