Remove BLAS timing and make logging more efficient

Based on review feedback:

1. Removed all BLAS timing functionality
   - Removed time_blas_operation function
   - Removed blas_timing verbosity setting
   - Removed timing from documentation and tests

2. Made get_blas_operation_info conditional on logging
   - Only calls get_blas_operation_info when logging is actually enabled
   - Avoids unnecessary computation when logging is disabled

3. Made condition number computation optional
   - Added compute_condition parameter (default: false)
   - Only computes condition number when explicitly requested
   - Avoids expensive computation for large matrices

4. Updated BLISLUFactorization extension
   - Removed timing calls
   - Only gathers operation info when needed for logging
   - More efficient checking of verbosity levels

5. Updated documentation
   - Removed all references to timing functionality
   - Documented optional condition number computation

6. Updated tests
   - Removed timing tests
   - Added tests for optional condition number computation

These changes make the logging more efficient by avoiding
unnecessary computations when logging is disabled.

🤖 Generated with [Claude Code](https://claude.ai/code)

Co-Authored-By: Claude <[email protected]>

Author: claude

docs/src/basics/common_solver_opts.md

@@ -111,7 +111,6 @@ sol = solve(prob; verbose=verbose)
 - blas_invalid_args: Controls messages when BLAS/LAPACK receives invalid arguments (default: Error)
 ##### Performance Settings
 - no_right_preconditioning: Controls messages when right preconditioning is not used (default: Warn)
-- blas_timing: Controls performance timing messages for BLAS/LAPACK operations (default: None)
 ##### Numerical Settings
 - using_IterativeSolvers: Controls messages when using the IterativeSolvers.jl package (default: Warn)
 - IterativeSolvers_iterations: Controls messages about iteration counts from IterativeSolvers.jl (default: Warn)
@@ -145,7 +144,6 @@ using LinearSolve
 # Enable detailed BLAS error logging
 verbose = LinearVerbosity(
     blas_errors = Verbosity.Info(),  # Show detailed error interpretations
-    blas_timing = Verbosity.Info(),  # Show performance metrics
     blas_info = Verbosity.Info()     # Show all BLAS operation details
 )
 
@@ -163,7 +161,7 @@ sol = solve(prob, LUFactorization(); verbose=verbose)
 ```
 
 The enhanced logging also provides:
-- Matrix properties (size, type, condition number when feasible)
+- Matrix properties (size, type, element type)
 - Memory usage estimates
-- Performance timing for BLAS operations (when blas_timing is enabled)
-- Detailed context for debugging numerical issues
+- Detailed context for debugging numerical issues
+- Optional condition number computation (can be enabled via compute_condition parameter)

ext/LinearSolveBLISExt.jl

@@ -11,7 +11,7 @@ using LinearAlgebra.LAPACK: require_one_based_indexing, chkfinite, chkstride1,
                             @blasfunc, chkargsok
 using LinearSolve: ArrayInterface, BLISLUFactorization, @get_cacheval, LinearCache, SciMLBase,
                    interpret_blas_code, log_blas_info, get_blas_operation_info, 
-                   time_blas_operation, check_and_log_lapack_result, LinearVerbosity
+                   check_and_log_lapack_result, LinearVerbosity
 using SciMLBase: ReturnCode
 using SciMLLogging: Verbosity
 
@@ -228,22 +228,23 @@ function SciMLBase.solve!(cache::LinearCache, alg::BLISLUFactorization;
     if cache.isfresh
         cacheval = @get_cacheval(cache, :BLISLUFactorization)
 
-        # Get additional operation info for logging
-        op_info = get_blas_operation_info(:dgetrf, A, cache.b)
-        
-        # Time the BLAS operation if verbosity requires it
-        res = time_blas_operation(:dgetrf, verbose) do
-            getrf!(A; ipiv = cacheval[1].ipiv, info = cacheval[2])
-        end
+        # Perform the factorization
+        res = getrf!(A; ipiv = cacheval[1].ipiv, info = cacheval[2])
 
         fact = LU(res[1:3]...), res[4]
         cache.cacheval = fact
 
-        # Log BLAS return code with detailed interpretation
+        # Log BLAS return code with detailed interpretation if logging is enabled
         info_value = res[3]
         if info_value != 0
-            log_blas_info(:dgetrf, info_value, verbose; extra_context=op_info)
-        elseif isa(verbose.numerical.blas_success, Verbosity.Info)
+            # Only get operation info if we need to log
+            if !(verbose.numerical.blas_errors isa Verbosity.None)
+                op_info = get_blas_operation_info(:dgetrf, A, cache.b)
+                log_blas_info(:dgetrf, info_value, verbose; extra_context=op_info)
+            end
+        elseif !(verbose.numerical.blas_success isa Verbosity.None)
+            # Only get operation info if we need to log success
+            op_info = get_blas_operation_info(:dgetrf, A, cache.b)
             @info "BLAS LU factorization (dgetrf) completed successfully" op_info
         end
 
@@ -258,20 +259,18 @@ function SciMLBase.solve!(cache::LinearCache, alg::BLISLUFactorization;
     require_one_based_indexing(cache.u, cache.b)
     m, n = size(A, 1), size(A, 2)
 
-    # Time the solve operation
-    solve_result = time_blas_operation(:dgetrs, verbose) do
-        if m > n
-            Bc = copy(cache.b)
-            getrs!('N', A.factors, A.ipiv, Bc; info)
-            copyto!(cache.u, 1, Bc, 1, n)
-        else
-            copyto!(cache.u, cache.b)
-            getrs!('N', A.factors, A.ipiv, cache.u; info)
-        end
+    # Perform the solve
+    if m > n
+        Bc = copy(cache.b)
+        getrs!('N', A.factors, A.ipiv, Bc; info)
+        copyto!(cache.u, 1, Bc, 1, n)
+    else
+        copyto!(cache.u, cache.b)
+        getrs!('N', A.factors, A.ipiv, cache.u; info)
     end
 
     # Log solve operation result if there was an error
-    if info[] != 0
+    if info[] != 0 && !(verbose.numerical.blas_errors isa Verbosity.None)
         log_blas_info(:dgetrs, info[], verbose)
     end
 

src/blas_logging.jl

@@ -190,20 +190,21 @@ end
 
 # Extended information for specific BLAS operations
 """
-    get_blas_operation_info(func::Symbol, A, b=nothing)
+    get_blas_operation_info(func::Symbol, A, b=nothing; compute_condition=false)
 
 Get additional information about a BLAS operation for enhanced logging.
+Set compute_condition=true to include condition number computation (may be expensive).
 """
-function get_blas_operation_info(func::Symbol, A, b=nothing)
+function get_blas_operation_info(func::Symbol, A, b=nothing; compute_condition=false)
     info = Dict{Symbol,Any}()
 
     # Matrix properties
     info[:matrix_size] = size(A)
     info[:matrix_type] = typeof(A)
     info[:element_type] = eltype(A)
 
-    # Condition number (if not too expensive)
-    if size(A, 1) <= 1000 && size(A, 1) == size(A, 2)
+    # Condition number (only if explicitly requested)
+    if compute_condition && size(A, 1) == size(A, 2)
         try
             info[:condition_number] = cond(A)
         catch
@@ -224,44 +225,3 @@ function get_blas_operation_info(func::Symbol, A, b=nothing)
     return info
 end
 
-# Performance timing for BLAS operations
-mutable struct BLASTimingInfo
-    operation::Symbol
-    start_time::Float64
-    end_time::Float64
-    allocated_bytes::Int
-    gc_time::Float64
-end
-
-"""
-    time_blas_operation(f::Function, func::Symbol, verbose::LinearVerbosity)
-
-Time a BLAS operation and log performance information based on verbosity.
-"""
-function time_blas_operation(f::Function, func::Symbol, verbose::LinearVerbosity)
-    if verbose.performance.blas_timing isa Verbosity.None
-        return f()
-    end
-    
-    # Measure performance
-    stats = @timed f()
-    result = stats.value
-    
-    # Log timing information
-    if verbose.performance.blas_timing isa Verbosity.Info ||
-       verbose.performance.blas_timing isa Verbosity.Warn
-        timing_msg = format_timing_message(func, stats)
-        log_with_verbosity(verbose.performance.blas_timing, timing_msg, :performance)
-    end
-    
-    return result
-end
-
-function format_timing_message(func::Symbol, stats)
-    parts = String[]
-    push!(parts, "BLAS/LAPACK $func performance:")
-    push!(parts, "  Time: $(round(stats.time, sigdigits=3)) seconds")
-    push!(parts, "  Allocations: $(round(stats.bytes / 1024^2, digits=2)) MB")
-    push!(parts, "  GC time: $(round(stats.gctime, sigdigits=3)) seconds")
-    return join(parts, "\n")
-end

src/verbosity.jl

@@ -13,8 +13,7 @@ const linear_defaults = Dict{Symbol, Verbosity.Type}(
     :blas_errors => Verbosity.Warn(),
     :blas_info => Verbosity.None(),
     :blas_success => Verbosity.None(),
-    :blas_invalid_args => Verbosity.Error(),
-    :blas_timing => Verbosity.None()
+    :blas_invalid_args => Verbosity.Error()
 )
 mutable struct LinearErrorControlVerbosity
     default_lu_fallback::Verbosity.Type
@@ -51,12 +50,10 @@ end
 
 mutable struct LinearPerformanceVerbosity
     no_right_preconditioning::Verbosity.Type
-    blas_timing::Verbosity.Type
 
     function LinearPerformanceVerbosity(;
-            no_right_preconditioning = linear_defaults[:no_right_preconditioning],
-            blas_timing = linear_defaults[:blas_timing])
-        new(no_right_preconditioning, blas_timing)
+            no_right_preconditioning = linear_defaults[:no_right_preconditioning])
+        new(no_right_preconditioning)
     end
 
     function LinearPerformanceVerbosity(verbose::Verbosity.Type)

test/test_blas_logging.jl

@@ -33,15 +33,19 @@ using SciMLLogging: Verbosity
     end
 
     @testset "BLAS Operation Info" begin
-        # Test getting operation info
+        # Test getting operation info without condition number
         A = rand(10, 10)
         b = rand(10)
         info = LinearSolve.get_blas_operation_info(:dgetrf, A, b)
 
         @test info[:matrix_size] == (10, 10)
         @test info[:element_type] == Float64
-        @test haskey(info, :condition_number)
+        @test !haskey(info, :condition_number)  # Should not compute by default
         @test info[:memory_usage_MB] >= 0  # Memory can be 0 for very small matrices
+        
+        # Test with condition number computation enabled
+        info_with_cond = LinearSolve.get_blas_operation_info(:dgetrf, A, b; compute_condition=true)
+        @test haskey(info_with_cond, :condition_number)
     end
 
     @testset "Verbosity Integration" begin
@@ -64,7 +68,6 @@ using SciMLLogging: Verbosity
         # Test with all logging enabled
         verbose_all = LinearVerbosity(
             blas_errors = Verbosity.Info(),
-            blas_timing = Verbosity.Info(),
             blas_info = Verbosity.Info()
         )
 
@@ -98,17 +101,3 @@ using SciMLLogging: Verbosity
     end
 end
 
-@testset "BLAS Timing" begin
-    # Simple test of timing functionality
-    A = rand(100, 100)
-    b = rand(100)
-    
-    verbose = LinearVerbosity(
-        blas_timing = Verbosity.Info()
-    )
-    
-    # Test that timing doesn't break the solve
-    prob = LinearProblem(A, b)
-    sol = solve(prob, LUFactorization(); verbose=verbose)
-    @test sol.retcode == ReturnCode.Success
-end