use TimerOutputs

Author: IanButterworth

Project.toml

@@ -28,6 +28,7 @@ RegistryTools = "d1eb7eb1-105f-429d-abf5-b0f65cb9e2c4"
 SHA = "ea8e919c-243c-51af-8825-aaa63cd721ce"
 Scratch = "6c6a2e73-6563-6170-7368-637461726353"
 Sockets = "6462fe0b-24de-5631-8697-dd941f90decc"
+TimerOutputs = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f"
 TOML = "fa267f1f-6049-4f14-aa54-33bafae1ed76"
 UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4"
 ghr_jll = "07c12ed4-43bc-5495-8a2a-d5838ef8d533"
@@ -50,6 +51,7 @@ Registrator = "1.1"
 RegistryTools = "2.1"
 SHA = "0.7, 1"
 Scratch = "1.0"
+TimerOutputs = "0.5"
 TOML = "1"
 ghr_jll = "0.13, 0.14, 0.17"
 julia = "1.7"

src/Auditor.jl

@@ -5,7 +5,8 @@ using Base.BinaryPlatforms
 using Pkg
 using ObjectFile
 
-using BinaryBuilderBase: march
+using BinaryBuilderBase: march, BBB_TIMER
+using TimerOutputs: @timeit
 
 export audit, collect_files, collapse_symlinks
 
@@ -30,17 +31,22 @@ This prevents concurrent patchelf operations on the same file.
 """
 function with_patchelf_lock(f, path::AbstractString)
     # Normalize the path to ensure consistent locking
-    path = realpath(path)
+    norm_path = realpath(path)
+    filename = basename(norm_path)
 
     # Get or create the lock for this file
     file_lock = Base.@lock PATCHELF_FILE_LOCKS_LOCK begin
-        get!(PATCHELF_FILE_LOCKS, path) do
+        get!(PATCHELF_FILE_LOCKS, norm_path) do
             ReentrantLock()
         end
     end
 
-    # Execute with the file-specific lock held
-    Base.@lock file_lock f()
+    # Execute with the file-specific lock held, timing both the lock wait and the inner operation
+    @timeit BBB_TIMER "patchelf $(filename) (incl. lock)" begin
+        Base.@lock file_lock begin
+            @timeit BBB_TIMER "patchelf $(filename)" f()
+        end
+    end
 end
 
 # Helper function to run a command and print to `io` its invocation and full

src/AutoBuild.jl

@@ -2,6 +2,8 @@ export build_tarballs, autobuild, build, get_meta_json
 import GitHub: gh_get_json, DEFAULT_API
 import SHA: sha256, sha1
 using TOML, Dates, UUIDs
+using TimerOutputs: @timeit, print_timer
+using BinaryBuilderBase: BBB_TIMER, reset_bbb_timer!
 using RegistryTools
 import LibGit2
 import PkgLicenses
@@ -193,6 +195,7 @@ function build_tarballs(ARGS, src_name, src_version, sources, script,
                         compression_format::String="gzip",
                         kwargs...)
     @nospecialize
+    reset_bbb_timer!()
     # See if someone has passed in `--help`, and if so, give them the
     # assistance they so clearly long for
     if "--help" in ARGS
@@ -441,6 +444,8 @@ function build_tarballs(ARGS, src_name, src_version, sources, script,
         upload_to_github_releases(deploy_bin_repo, tag, products_dir; verbose=verbose)
     end
 
+    print_timer(BBB_TIMER; sortby=:firstexec)
+    println()
     return build_output_meta
 end
 
@@ -836,13 +841,14 @@ function autobuild(dir::AbstractString,
     end
 
     # We must prepare our sources.  Download them, hash them, etc...
-    source_files = download_source.(sources; verbose=verbose)
+    source_files = @timeit BBB_TIMER "Downloading sources" download_source.(sources; verbose=verbose)
 
     # Our build products will go into ./products
     out_path = joinpath(dir, "products")
     try mkpath(out_path) catch; end
 
     for platform in sort(collect(platforms), by = triplet)
+        @timeit BBB_TIMER "Building for $(triplet(platform))" begin
         timer = BuildTimer()
         timer.begin_setup = time()
 
@@ -928,7 +934,7 @@ function autobuild(dir::AbstractString,
         """
 
         dest_prefix = Prefix(BinaryBuilderBase.destdir(prefix.path, concrete_platform))
-        did_succeed = with_logfile(dest_prefix, "$(src_name).log"; subdir=src_name) do io
+        did_succeed = @timeit BBB_TIMER "Running build script" with_logfile(dest_prefix, "$(src_name).log"; subdir=src_name) do io
             # Let's start the presentations with BinaryBuilder.jl
             write(io, "BinaryBuilder.jl version: $(get_bb_version())\n\n")
             # Get the list of compilers...
@@ -959,6 +965,7 @@ function autobuild(dir::AbstractString,
         # Run an audit of the prefix to ensure it is properly relocatable
         timer.begin_audit = time()
         if !skip_audit
+            @timeit BBB_TIMER "Auditing build artifacts" begin
             audit_result = audit(dest_prefix, src_name;
                                  platform=platform, verbose=verbose,
                                  has_csl = any(getname.(dependencies) .== "CompilerSupportLibraries_jll"),
@@ -971,6 +978,7 @@ function autobuild(dir::AbstractString,
                 """, '\n' => ' ')
                 error(strip(msg))
             end
+            end  # @timeit audit
         end
         timer.end_audit = time()
 
@@ -1075,6 +1083,7 @@ function autobuild(dir::AbstractString,
             rm(build_path; recursive=true)
         end
         verbose && @info "$(timer)"
+        end  # @timeit platform
     end
 
     # Return our product hashes