Add granular TimerOutputs reports

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"
 

azure-pipelines.yml

@@ -42,6 +42,7 @@ jobs:
   - bash: |
       set -e
       $(JULIA) -e 'using Pkg; Pkg.Registry.update(); Pkg.instantiate()'
+      $(JULIA) -e 'using Pkg; Pkg.add(name="BinaryBuilderBase", rev="ib/timeroutputs")'
       $(JULIA) -e 'using BinaryBuilder; BinaryBuilder.versioninfo()'
       $(JULIA) -e 'using Pkg; Pkg.status(; mode=PKGMODE_MANIFEST)'
     name: SystemInfo
@@ -66,7 +67,7 @@ jobs:
   - bash: |
       set -e
       $(JULIA) -e 'using Pkg; Pkg.gc()'
-      $(JULIA) --check-bounds=yes --inline=yes -e 'using Pkg; Pkg.Registry.update(); Pkg.instantiate(); Pkg.test(coverage=true)'
+      $(JULIA) --check-bounds=yes --inline=yes -e 'using Pkg; Pkg.Registry.update(); Pkg.add(name="BinaryBuilderBase", rev="ib/timeroutputs"); Pkg.instantiate(); Pkg.test(coverage=true)'
       $(JULIA) -e 'using Pkg; Pkg.add("Coverage"); using Coverage; Codecov.submit(process_folder())' || true
     name: Test
 

src/Auditor.jl

@@ -5,10 +5,18 @@ using Base.BinaryPlatforms
 using Pkg
 using ObjectFile
 
-using BinaryBuilderBase: march
+using BinaryBuilderBase: march, BBB_TIMER, merge_bbb_timer!
+using TimerOutputs: TimerOutput, @timeit, reset_timer!
 
 export audit, collect_files, collapse_symlinks
 
+"""
+    current_timer_path(to::TimerOutput)
+
+Get the current tree path as a vector of section names from the timer's stack.
+"""
+current_timer_path(to::TimerOutput) = [t.name for t in to.timer_stack]
+
 # Some functions need to run commands in sandboxes mounted on the same prefix and we
 # can't allow them to clash, otherwise one may be unmounting the filesystem while
 # another is still operating.
@@ -22,6 +30,37 @@ const AUDITOR_LOGGING_LOCK = ReentrantLock()
 const PATCHELF_FILE_LOCKS = Dict{String,ReentrantLock}()
 const PATCHELF_FILE_LOCKS_LOCK = ReentrantLock()
 
+# Collect thread-local timers for merging
+const THREAD_TIMERS = Set{TimerOutput}()
+const THREAD_TIMERS_LOCK = ReentrantLock()
+
+"""
+    get_thread_timer()
+
+Get or create a thread-local TimerOutput, registering it for later merging.
+"""
+function get_thread_timer()
+    get!(task_local_storage(), :auditor_timer) do
+        timer = TimerOutput()
+        Base.@lock THREAD_TIMERS_LOCK push!(THREAD_TIMERS, timer)
+        timer
+    end::TimerOutput
+end
+
+"""
+    merge_thread_timers!(tree_point::Vector{String})
+
+Merge all thread-local timers into BBB_TIMER at the given tree_point and reset them.
+"""
+function merge_thread_timers!(tree_point::Vector{String})
+    Base.@lock THREAD_TIMERS_LOCK begin
+        for timer in THREAD_TIMERS
+            merge_bbb_timer!(timer; tree_point)
+            reset_timer!(timer)
+        end
+    end
+end
+
 """
     with_patchelf_lock(f, path::AbstractString)
 
@@ -31,16 +70,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)
-
+    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
+    timer = get_thread_timer()
+    @timeit timer "patchelf $(filename) (incl. lock)" begin
+        Base.@lock file_lock begin
+            @timeit timer "patchelf $(filename)" f()
+        end
+    end
 end
 
 # Helper function to run a command and print to `io` its invocation and full
@@ -102,6 +147,9 @@ function audit(prefix::Prefix, src_name::AbstractString = "";
                                has_csl::Bool = true,
                                require_license::Bool = true,
                )
+    # Capture the current timer tree path for merging thread-local timers later
+    timer_tree_point = current_timer_path(BBB_TIMER)
+
     # This would be really weird, but don't let someone set `silent` and `verbose` to true
     if silent
         verbose = false
@@ -148,7 +196,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
@@ -359,6 +407,10 @@ function audit(prefix::Prefix, src_name::AbstractString = "";
 
     # Search for case-sensitive ambiguities
     all_ok[] &= check_case_sensitivity(prefix)
+
+    # Merge thread-local timers back into the main timer
+    merge_thread_timers!(timer_tree_point)
+
     return all_ok[]
 end
 

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,8 @@ function build_tarballs(ARGS, src_name, src_version, sources, script,
                         compression_format::String="gzip",
                         kwargs...)
     @nospecialize
+    reset_bbb_timer!()
+    @timeit BBB_TIMER "build_tarballs" begin
     # 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 +445,9 @@ function build_tarballs(ARGS, src_name, src_version, sources, script,
         upload_to_github_releases(deploy_bin_repo, tag, products_dir; verbose=verbose)
     end
 
+    end  # @timeit build_tarballs
+    print_timer(IOContext(stdout, :limit => false), BBB_TIMER; sortby=:firstexec)
+    println()
     return build_output_meta
 end
 
@@ -515,7 +522,7 @@ function get_compilers_versions(; compilers = [:c])
     return output
 end
 
-function upload_to_github_releases(repo, tag, path; gh_auth=Wizard.github_auth(;allow_anonymous=false),
+@timeit BBB_TIMER function upload_to_github_releases(repo, tag, path; gh_auth=Wizard.github_auth(;allow_anonymous=false),
                                    attempts::Int = 3, verbose::Bool = false)
     for attempt in 1:attempts
         try
@@ -602,7 +609,7 @@ is_yggdrasil() = get(ENV, "YGGDRASIL", "false") == "true"
 # Use a Buildkite environment variable to get the current commit hash
 yggdrasil_head() = get(ENV, "BUILDKITE_COMMIT", "")
 
-function register_jll(name, build_version, dependencies, julia_compat;
+@timeit BBB_TIMER function register_jll(name, build_version, dependencies, julia_compat;
                       deploy_repo="JuliaBinaryWrappers/$(namejll(name)).jl",
                       code_dir=codedir(name),
                       gh_auth=Wizard.github_auth(;allow_anonymous=false),
@@ -800,7 +807,7 @@ here are the relevant actors, broken down in brief:
 * `compression_format`: the compression format used for the generated tarballs.
 
 """
-function autobuild(dir::AbstractString,
+@timeit BBB_TIMER function autobuild(dir::AbstractString,
                    src_name::AbstractString,
                    src_version::VersionNumber,
                    sources::Vector{<:AbstractSource},
@@ -836,13 +843,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()
 
@@ -874,7 +882,7 @@ function autobuild(dir::AbstractString,
         target_artifact_paths = setup_deps(is_target_dependency, prefix, dependencies, concrete_platform, verbose)
 
         # Create a runner to work inside this workspace with the nonce built-in
-        ur = preferred_runner()(
+        ur = @timeit BBB_TIMER "Creating runner" preferred_runner()(
             prefix.path;
             cwd = "/workspace/srcdir",
             platform = concrete_platform,
@@ -928,7 +936,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 +967,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,10 +980,12 @@ function autobuild(dir::AbstractString,
                 """, '\n' => ' ')
                 error(strip(msg))
             end
+            end  # @timeit audit
         end
         timer.end_audit = time()
 
         # Finally, error out if something isn't satisfied
+        @timeit BBB_TIMER "Checking products" begin
         unsatisfied_so_die = false
         for p in products
             if platform isa AnyPlatform && !(p isa FileProduct)
@@ -1009,8 +1020,10 @@ function autobuild(dir::AbstractString,
                 )
             end
         end
+        end  # @timeit Checking products
 
         # Unsymlink all the deps from the dest_prefix
+        @timeit BBB_TIMER "Cleaning up" begin
         cleanup_dependencies(prefix, host_artifact_paths, default_host_platform)
         cleanup_dependencies(prefix, target_artifact_paths, concrete_platform)
 
@@ -1029,6 +1042,7 @@ function autobuild(dir::AbstractString,
 
         # Compress log files
         compress_dir(logdir(dest_prefix; subdir=src_name); verbose)
+        end  # @timeit Cleaning up
 
         # Once we're built up, go ahead and package this dest_prefix out
         timer.begin_package = time()
@@ -1065,6 +1079,7 @@ function autobuild(dir::AbstractString,
 
         # Destroy the workspace, taking care to make sure that we don't run into any
         # permissions errors while we do so.
+        @timeit BBB_TIMER "Destroying workspace" begin
         Base.Filesystem.prepare_for_deletion(prefix.path)
         rm(prefix.path; recursive=true)
 
@@ -1074,7 +1089,9 @@ function autobuild(dir::AbstractString,
         if isempty(readdir(build_path))
             rm(build_path; recursive=true)
         end
+        end  # @timeit Destroying workspace
         verbose && @info "$(timer)"
+        end  # @timeit platform
     end
 
     # Return our product hashes
@@ -1226,7 +1243,7 @@ function filter_main_tarball(tarball_filename, platform)
     end
 end
 
-function rebuild_jll_package(name::String, build_version::VersionNumber, sources::Vector,
+@timeit BBB_TIMER function rebuild_jll_package(name::String, build_version::VersionNumber, sources::Vector,
                              platforms::Vector, products::Vector, dependencies::Vector,
                              download_dir::String, upload_prefix::String;
                              code_dir::String = codedir(name),
@@ -1316,7 +1333,7 @@ function rebuild_jll_package(name::String, build_version::VersionNumber, sources
                       kwargs...)
 end
 
-function build_jll_package(src_name::String,
+@timeit BBB_TIMER function build_jll_package(src_name::String,
                            build_version::VersionNumber,
                            sources::Vector,
                            code_dir::String,
@@ -1473,11 +1490,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 +1511,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 +1534,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 +1551,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 +1570,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,
@@ -1768,7 +1785,7 @@ function build_jll_package(src_name::String,
     end
 end
 
-function push_jll_package(name, build_version;
+@timeit BBB_TIMER function push_jll_package(name, build_version;
                           code_dir = codedir(name),
                           deploy_repo = "JuliaBinaryWrappers/$(namejll(name)).jl",
                           gh_auth = Wizard.github_auth(;allow_anonymous=false))