use TimerOutputs

Author: IanButterworth

Project.toml

@@ -1,7 +1,7 @@
 name = "BinaryBuilder"
 uuid = "12aac903-9f7c-5d81-afc2-d9565ea332ae"
-authors = ["Elliot Saba <staticfloat@gmail.com>"]
 version = "0.6.5"
+authors = ["Elliot Saba <staticfloat@gmail.com>"]
 
 [deps]
 ArgParse = "c7e460c6-2fb9-53a9-8c5b-16f535851c63"
@@ -29,6 +29,7 @@ SHA = "ea8e919c-243c-51af-8825-aaa63cd721ce"
 Scratch = "6c6a2e73-6563-6170-7368-637461726353"
 Sockets = "6462fe0b-24de-5631-8697-dd941f90decc"
 TOML = "fa267f1f-6049-4f14-aa54-33bafae1ed76"
+TimerOutputs = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f"
 UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4"
 ghr_jll = "07c12ed4-43bc-5495-8a2a-d5838ef8d533"
 
@@ -51,6 +52,7 @@ RegistryTools = "2.1"
 SHA = "0.7, 1"
 Scratch = "1.0"
 TOML = "1"
+TimerOutputs = "0.5"
 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
 
@@ -31,16 +32,21 @@ 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)
-    
+    filename = basename(path)
+
     # Get or create the lock for this file
     file_lock = Base.@lock PATCHELF_FILE_LOCKS_LOCK begin
         get!(PATCHELF_FILE_LOCKS, 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
@@ -148,7 +154,7 @@ function audit(prefix::Prefix, src_name::AbstractString = "";
                         # for Windows, for which however we have to set autofix=false:
                         # https://github.com/JuliaPackaging/Yggdrasil/pull/922.
                         all_ok[] &= ensure_executability(oh; verbose, silent)
-                    
+
                         # If this is a dynamic object, do the dynamic checks
                         if isdynamic(oh)
                             # Check that the libgfortran version matches

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
@@ -1473,11 +1482,11 @@ function build_jll_package(src_name::String,
                     libgfortran_version_mapping = BinaryPlatforms.libgfortran_version_mapping
                     cxxstring_abi_mapping = BinaryPlatforms.cxxstring_abi_mapping
                     libstdcxx_version_mapping = BinaryPlatforms.libstdcxx_version_mapping
-                
+
                     # Helper function to collapse dictionary of mappings down into a regex of
                     # named capture groups joined by "|" operators
                     c(mapping) = string("(",join(["(?<$k>$v)" for (k, v) in mapping], "|"), ")")
-                
+
                     # We're going to build a mondo regex here to parse everything:
                     triplet_regex = Regex(string(
                         "^",
@@ -1494,7 +1503,7 @@ function build_jll_package(src_name::String,
                         "(?<tags>(?:-[^-]+\\+[^-]+)*)?",
                         "\$",
                     ))
-                
+
                     m = match(triplet_regex, triplet)
                     if m !== nothing
                         # Helper function to find the single named field within the giant regex
@@ -1517,7 +1526,7 @@ function build_jll_package(src_name::String,
                                 end
                             end
                         end
-                
+
                         # Extract the information we're interested in:
                         arch = get_field(m, arch_mapping)
                         os = get_field(m, os_mapping)
@@ -1534,7 +1543,7 @@ function build_jll_package(src_name::String,
                             return map(v -> Symbol(v[1]) => v[2], split.(tag_fields, "+"))
                         end
                         tags = split_tags(m["tags"])
-                
+
                         # Special parsing of os version number, if any exists
                         function extract_os_version(os_name, pattern)
                             m_osvn = match(pattern, m[os_name])
@@ -1553,7 +1562,7 @@ function build_jll_package(src_name::String,
                         if os == "openbsd"
                             os_version = extract_os_version("openbsd", r".*openbsd([\d.]+)"sa)
                         end
-                
+
                         return Platform(
                             arch, os;
                             validate_strict,