Latex measure compilation time of specific parts of document

Question

due to long compilation time of a complex tex-file I would like to measure specific code parts inside this tex-file. I tried using l3benchmark (https://ctan.math.washington.edu/tex-archive/macros/latex/contrib/l3experimental/l3benchmark.pdf) but I can only run it on the whole document not on specific parts.

I tried to run \benchmark_once:n { specific code part } & \benchmark_silent:n { specific code part } already. on top of the document I included the l3benchmark package once with \RequirePackage{l3benchmark} and once with \usepackage{l3benchmark} for each method.

Am I missing something or how could it be possible to just measure the compilation time of parts of the code?

Thanks in advance!

Welcome to tex.sx. Please let us at least know what document class you are using. — barbara beeton, Dec 04 '23 at 16:36
It is possible to measure any part. If you can use LuaLaTeX, I can post some code. I use this code to read the time elapsed between 2 points in a document, using the socket library for Lua. — yannisl, Dec 05 '23 at 00:24
Hey @barbarabeeton, if I read my master.tex file correctly I am using "\documentclass[10pt,a4paper]{article}" with lualatex. So yes with using lualatex (yiannislazarides) your code could be of good help. Do you have an example that you want to share for better understanding? — simonroof, Dec 05 '23 at 20:24
@YiannisLazarides -- A comment from the OP says "yes with using lualatex [...] your code could be of good help." Since a comment here can only ping one person, I think you probably didn't see it. — barbara beeton, Dec 05 '23 at 21:24

score 4 · Answer 1 · answered Dec 06 '23 at 05:50

Here some lua code for timing performance of code. The socket library is build-in with the LuaTeX compiler, ensure is enabled with the --socket option. As you will see LaTeX programs run very fast. They are slowed down by loading too many large fonts, large images and tikz graphics.

\begin{filecontents*}[overwrite]{mytimer.lua}
-- table to hold time performance

 M = M or {}
  local socket = require('socket')
  local time_stat = time_stat or {}
  local gettime = socket.gettime
-- start time measurement
time_stat["total"] = 0
-- @param done indicates timer was stopped
function start_time_measure(field)

    time_stat[field] = {start = gettime(), done = false}
end
-- stop time measurement

-- if two calls to stop will return wrong value
function stop_time_measure(field)

    if not time_stat[field].done then 
       time_stat[field] = {total = gettime() - time_stat[field].start, done=true} 
    end

end
M.start = start_time_measure
 M.stop  = stop_time_measure 
 M.statistics = function(name) return time_stat[name].total end
-- M.start("document")
-- local s = 0
-- for i=1, 1 do s=s+1 end 
-- M.stop("document")
-- print(M.statistics("document"))
-- print(M.statistics("document"))
return M
\end{filecontents*}
\directlua{timer = require("mytimer")}
\def\timerstart#1{\directlua{timer.start("#1")}}
\def\timerstop#1{\directlua{timer.stop("#1")}}
\def\timerprint#1{
\directlua{
timer.stop("#1")
tex.print("elapsed time (#1):", timer.statistics("#1").." s")
}}
\timerstart{document}
\documentclass{article}
\timerstart{package}
\usepackage{fontspec}
\setmainfont{Arial Unicode MS}
\timerstop{package}
\usepackage{lipsum}
\usepackage{luacode}
\usepackage{microtype}
\begin{document}
Hello
\timerprint{package}
\begin{luacode}
z=0
for i=0,150000000,1 do
  i=i+1
  z=i
end
tex.print(z)
\end{luacode}
\timerstart{lipsum}
\lipsum[1-12]
\timerstop{lipsum}
\timerprint{package}
\timerprint{lipsum}
\timerprint{document}
\end{document}

Thank you for nice answer. I added your code to OpTeX tricks too. See http://petr.olsak.net/optex/optex-tricks.html#timer — wipet, Dec 07 '23 at 08:26
I have found that elapsed time reported by time lualatex --socket document is about 0.6 second more than elapsed time printed by \timerprint (in my computer). The reason is: LuaLaTeX does an extensive work in \everyjob, namely it loads luaotfload which spend 0.25 seconds. On the other hand, time optex reports only 0.2 s more, because luaotfload is loaded when first \fontfam is used. I compare time of the whole document with \lipsum[1-12], without the loop 0,150000000 and with luaotfolad initialized: time lualatex reports 1.65 s and time optex reports 0.65 s. — wipet, Dec 07 '23 at 08:42
@wipet Thanks. It is about time I try OpTeX again. Tried it some years back, but I see it has come a long way, especially the English documentation. — yannisl, Dec 07 '23 at 08:42
Thanks a lot @YiannisLazarides! This helps a bit to find out why my latex file compilation is too slow. — simonroof, Dec 07 '23 at 19:08
@YiannisLazarides - Another question that came up regarding your code. Does it matter if I use that lua code inside the tex-file itself or import it from a separate lua-file where I insert your code? Seems I am not getting the time for specific parts each time I am compiling the tex-file. Thinking of tracing race conditions right now, as including some try-catch logic into the lua-code didn't help. Have you ever noticed something similar or did your code always print the time correctly? — simonroof, Dec 08 '23 at 09:10

Latex measure compilation time of specific parts of document

1 Answers1