diff options
-rw-r--r-- | Build/source/texk/web2c/texprofdir/am/texprof.am | 3 | ||||
-rw-r--r-- | Build/source/texk/web2c/texprofdir/doc/texprofile.hnt | bin | 968080 -> 968072 bytes | |||
-rw-r--r-- | Build/source/texk/web2c/texprofdir/doc/texprofile.pdf | bin | 328227 -> 328206 bytes | |||
-rw-r--r-- | Build/source/texk/web2c/texprofdir/doc/texprofileman.hnt | bin | 459243 -> 518370 bytes | |||
-rw-r--r-- | Build/source/texk/web2c/texprofdir/doc/texprofileman.pdf | bin | 176881 -> 193602 bytes | |||
-rw-r--r-- | Build/source/texk/web2c/texprofdir/man/texprofile.man (renamed from Build/source/texk/web2c/texprofdir/doc/texprofile.1) | 264 | ||||
-rw-r--r-- | Build/source/texk/web2c/texprofdir/texprofile.w | 8 | ||||
-rw-r--r-- | Build/source/texk/web2c/texprofdir/texprofileman.tex | 202 |
8 files changed, 383 insertions, 94 deletions
diff --git a/Build/source/texk/web2c/texprofdir/am/texprof.am b/Build/source/texk/web2c/texprofdir/am/texprof.am index 5c5b5f8a956..6b5ae25f3e5 100644 --- a/Build/source/texk/web2c/texprofdir/am/texprof.am +++ b/Build/source/texk/web2c/texprofdir/am/texprof.am @@ -11,8 +11,7 @@ bin_PROGRAMS += texprof texprofile texprofall: texprof texprofile # See hitex.am for comments about handling man. -man1_MANS = texprofdir/man/texprof.man -# not yet there: texprofdir/man/texprofile.man +man1_MANS = texprofdir/man/texprof.man texprofdir/man/texprofile.man endif TEXPROF texprof_CPPFLAGS = $(AM_CPPFLAGS) diff --git a/Build/source/texk/web2c/texprofdir/doc/texprofile.hnt b/Build/source/texk/web2c/texprofdir/doc/texprofile.hnt Binary files differindex a6376e36a00..507675ef317 100644 --- a/Build/source/texk/web2c/texprofdir/doc/texprofile.hnt +++ b/Build/source/texk/web2c/texprofdir/doc/texprofile.hnt diff --git a/Build/source/texk/web2c/texprofdir/doc/texprofile.pdf b/Build/source/texk/web2c/texprofdir/doc/texprofile.pdf Binary files differindex 741a48ba3c4..eca97af5571 100644 --- a/Build/source/texk/web2c/texprofdir/doc/texprofile.pdf +++ b/Build/source/texk/web2c/texprofdir/doc/texprofile.pdf diff --git a/Build/source/texk/web2c/texprofdir/doc/texprofileman.hnt b/Build/source/texk/web2c/texprofdir/doc/texprofileman.hnt Binary files differindex 5094ff0e369..8cd8af1aa55 100644 --- a/Build/source/texk/web2c/texprofdir/doc/texprofileman.hnt +++ b/Build/source/texk/web2c/texprofdir/doc/texprofileman.hnt diff --git a/Build/source/texk/web2c/texprofdir/doc/texprofileman.pdf b/Build/source/texk/web2c/texprofdir/doc/texprofileman.pdf Binary files differindex 34a6b077c45..57e23386aa7 100644 --- a/Build/source/texk/web2c/texprofdir/doc/texprofileman.pdf +++ b/Build/source/texk/web2c/texprofdir/doc/texprofileman.pdf diff --git a/Build/source/texk/web2c/texprofdir/doc/texprofile.1 b/Build/source/texk/web2c/texprofdir/man/texprofile.man index bdbf47d9d60..6fe0ce616e3 100644 --- a/Build/source/texk/web2c/texprofdir/doc/texprofile.1 +++ b/Build/source/texk/web2c/texprofdir/man/texprofile.man @@ -1,5 +1,5 @@ '\" t -.\" Manual page created with latex2man on Mon Sep 9 10:03:20 2024 +.\" Manual page created with latex2man on Mon Sep 9 16:27:26 2024 .\" NOTE: This file is generated, DO NOT EDIT. .de Vb .ft CW @@ -194,18 +194,19 @@ to file number 2. .SS TIME If the option \fB\-m\fP 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). +Otherwise, times are rounded to at most 4 digits precission and +displayed with a unit: seconds (s), milliseconds (ms), microseconds +(um), or nanoseconds (ns). .PP .SS MACRO NAMES -Macro names are shown with the leading backslash. -Since macro names are often not unique, the command line option \fB\-i\fP -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 +Macro names are shown with the leading backslash. Since macro names +are often not unique, the command line option \fB\-i\fP +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. .PP @@ -215,30 +216,31 @@ Let\&'s assume that you issue the command texprof \fB\-prof\fP \fIhello.tex\fP\&. This will run texprof -on the input file \fIhello.tex\fP +on the input file +\fIhello.tex\fP with option \fB\-prof\fP\&. The program texprof -will load the plain TeX format and then -process hello.tex -to produce hello.log +will load the plain TeX format and then process hello.tex +to +produce hello.log and hello.dvi\&. -It will execute exactly the same steps that TeX would execute if you had -issued the command tex +It will execute +exactly the same steps that TeX would execute if you had issued the +command tex \fIhello.tex\fP\&. .PP In addition to hello.log and hello.dvi, texprof -will -also produce the file hello.tprof -containing time measurements -made while texprof -was running. -The option \fB\-prof\fP -will switch on the gathering of -timing data as soon as texprof -enters its main control procedure; -The file hello.tprof +will also produce the file hello.tprof +containing time +measurements made while texprof +was running. The option +\fB\-prof\fP +will switch on the gathering of timing data as soon as +texprof +enters its main control procedure; The 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 @@ -246,10 +248,10 @@ form. Still the file hello.tprof might become very big. .PP The program texprofile -is used to extract and analyse the -data contained in hello.tprof -and produce useful output. -Here are some examples: +is used to extract and analyse the data +contained in hello.tprof +and produce useful output. Here are +some examples: .PP .TP texprofile \fIhello\fP @@ -276,9 +278,6 @@ The table has the following seven columns: 1. file The first column contains the input file number as explained above. The input file name if shown in column 7. -.RS -.PP -.RE .TP 2. line The line number. @@ -317,14 +316,14 @@ 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 section is devoted +is devoted to file input, each of the following sections is devoted to a specific macro. .br Each section starts with a header. The header of the first section is ``File\&'' the header of a later section is the macro name. .br The first line after the header gives the total time spent in the section -in column 1 and 3 in different formats: +in two different formats: .RS .TP 1. time @@ -341,11 +340,11 @@ did spent all the time processing the file \fIhello\fP\&. And consequently the value in column 3 will be 100%\&. .br To accomplish a task, a macro usually calls other -macros, that we call child macros in the following. -The following lines will give a breakdown of the time shown in the -first line. -The next line after the header gives the time spent in the section -excluding the time spent in child macros. It adds in column 4 the number +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. .RS .RE @@ -363,6 +362,189 @@ Column 4 gives the number of times the section was called. .RE .RS .PP +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. +.RS +.RE +.TP +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. +.br +Therefore texprofile +maintains for each child macro two +accumulators for the elapsed time: For the time shown in +column 2 labeled ``loop\&'', 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. +.TP +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\&. +.RS +.PP +.RE +.TP +5. child +Column 5 shows the name of the child macro as explained above. +.RE +.RS +.PP +.RE +.TP +texprofile \fB\-G\fP \fB\-m\fP \fIhello\fP + This table will contain the same data as the previous example +but this time the \fB\-m\fP +option will optimize the output for +machine readability. +.RS +.TP +.B * +There are no column headers. +.TP +.B * +The times in column 1 ``time\&'' and column 2 ``loop\&'' +are given in nanoseconds without a unit identifier. +.TP +.B * +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. +.RE +.RS +.PP +.RE +.TP +texprofile \fB\-F\fP \fIhello\fP + With the option \fB\-F\fP, +texprofile +outputs the table +of all of TeX\&'s input files using 5 columns: +.RS +.TP +1. file +The file number as explained above. +.TP +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. +.TP +3. percent +The percentage of the total time measured that is attibuted to the file. +.TP +4. time +The absolute time that is attibuted to the file. +.TP +5. name +The full file name of the file. +.RE +.RS +.PP +.RE +.TP +texprofile \fB\-C\fP \fIhello\fP + With the option \fB\-C\fP, +texprofile +outputs the table +of all TeX commands executed while profiling +using 6 columns: +.RS +.TP +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. +.TP +2. time +The total time used for the command. +.TP +3. percent +The percentage of the total time measured used for the command. +.TP +4. count +The number of times this command was executed. +.TP +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. +.TP +6. name +A verbal description of the command or commands that share this +command code. +.RE +.RS +.PP +.RE +.TP +texprofile \fB\-R\fP \fB\-m\fP \fB\-n\fP \fIhello\fP + With the options \fB\-R\fP +\fB\-m\fP, +texprofile +outputs the table +of raw time measurements as observed by texprof +optimized for machine +readability. The option \fB\-n\fP +adds a column for the number +of each time measurements. +Because of the \fB\-m\fP +option, the table has no column headers. +The table has 7 columns: +.RS +.TP +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. +.TP +2. file +The file number as explained above. +.TP +3. line +The line number as explained above. +.TP +4. time +The time interval in nano seconds. +.TP +5. command +The command name as given in column 6 of the previous example. +.TP +6. level +The nesting level of the macro call stack. +.TP +7. macro +The macro name. +.RE +.RS +.PP +This table contains all the timing information gathered during the run +of texprof\&. +Some information about macro calls is contained in +column 6. More information about macro calls could be added +by using the \fB\-s\fP +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. .RE .PP .SH BUGS diff --git a/Build/source/texk/web2c/texprofdir/texprofile.w b/Build/source/texk/web2c/texprofdir/texprofile.w index 5783caff1bf..42ef5ed324c 100644 --- a/Build/source/texk/web2c/texprofdir/texprofile.w +++ b/Build/source/texk/web2c/texprofdir/texprofile.w @@ -980,7 +980,7 @@ Next we can print a summary table for the files: @<show the file summary if requested@>= if (opt_files) { Mprintf("\nFiles in the order of appearance:\n"); - Mprintf(" file\t lines\tpercent\t absolute" + Mprintf(" file\t lines\tpercent\t time" "\tname\n"); for (i=0; i<file_num; i++) { double p=(100.0*file_time[i])/total_time; @@ -1014,10 +1014,10 @@ if (opt_cmd) { int *cmd_link=NULL; @<sort the commands by time@>@; Mprintf("\nCommand summary:\n"); - Mprintf(" cmd\t time\t time%%\t freq\t average\tname\n"); + Mprintf(" cmd\t time\tpercent\t count\t average\tname\n"); for (i=cmd_link[cmd_num]; i>=0; i=cmd_link[i]) if (cmd_freq[i]>0) - { printf("%4d\t%s\t%5.2f%%", + { printf("%4d\t%s\t%6.2f%%", i, time_str(cmd_time[i]), (100.0*cmd_time[i])/total_time); printf("\t%6d\t %s\t%s\n", @@ -1275,7 +1275,7 @@ if (opt_lines) k=file_line[i+1]; else { printf("%s\n",file_names[i]); - printf(" file\t line\tpercent\t absolute" + printf(" file\t line\tpercent\t time" "\t count\t average\n"); printf("%6d\t\t%6.2f%%\t%s\n", i, (100.0*file_time[i])/total_time,time_str(file_time[i])); diff --git a/Build/source/texk/web2c/texprofdir/texprofileman.tex b/Build/source/texk/web2c/texprofdir/texprofileman.tex index 3725a0b1072..4a6f5c2e2b0 100644 --- a/Build/source/texk/web2c/texprofdir/texprofileman.tex +++ b/Build/source/texk/web2c/texprofdir/texprofileman.tex @@ -117,7 +117,7 @@ as well as the selection of information that is shown in the tables. 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. + within a category sorted by time. \item[\Opt{-s}] Show the changes of the macro stack. @@ -169,43 +169,44 @@ use of macros but simply on the size of the document. \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. +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: +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}] @@ -225,7 +226,6 @@ use of macros but simply on the size of the document. \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] @@ -253,14 +253,14 @@ use of macros but simply on the size of the document. 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 section is devoted - to a specific macro. + 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 column 1 and 3 in different formats: + in two different formats: \begin{description} \item[1. time] Column 1 gives it as an absolut time. @@ -273,11 +273,11 @@ use of macros but simply on the size of the document. 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 will give a breakdown of the time shown in the - first line. - The next line after the header gives the time spent in the section - excluding the time spent in child macros. It adds in column 4 the number + 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] @@ -289,9 +289,117 @@ use of macros but simply on the size of the document. \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} |