From 1f4a1f6f10c23b69dd46159ecafa268bbd0d9712 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Thu, 8 Feb 2024 14:55:50 +0100 Subject: [PATCH 1/9] using `Suppressor` to silence tests --- Project.toml | 3 ++- test/runtests_runner.jl | 29 ++++++++++++++++++++++++++++- 2 files changed, 30 insertions(+), 2 deletions(-) diff --git a/Project.toml b/Project.toml index 01ac694ce2..dd768ada2d 100644 --- a/Project.toml +++ b/Project.toml @@ -143,6 +143,7 @@ Logging = "56ddb016-857b-54e1-b83d-db4d58db5568" Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80" QuadGK = "1fd47b50-473d-5c70-9696-f719f8f3bcdc" Random = "9a3f8284-a2c9-5f02-9a11-845980a1fd5c" +Suppressor = "fd094767-a336-5f1f-9728-57cf17d0bbfb" Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40" TestItemRunner = "f8b46487-2199-4994-9208-9a1283c18c0a" Wannier = "2b19380a-1f7e-4d7d-b1b8-8aa60b3321c9" @@ -150,4 +151,4 @@ WriteVTK = "64499a7a-5c06-52f2-abe2-ccb03c286192" wannier90_jll = "c5400fa0-8d08-52c2-913f-1e3f656c1ce9" [targets] -test = ["Test", "TestItemRunner", "ASEconvert", "Aqua", "AtomsIO", "AtomsIOPython", "CUDA", "CUDA_Runtime_jll", "ComponentArrays", "DoubleFloats", "FiniteDiff", "FiniteDifferences", "GenericLinearAlgebra", "IntervalArithmetic", "JLD2", "JSON3", "Logging", "Plots", "QuadGK", "Random", "KrylovKit", "Wannier", "WriteVTK", "wannier90_jll"] +test = ["Test", "TestItemRunner", "ASEconvert", "Aqua", "AtomsIO", "AtomsIOPython", "CUDA", "CUDA_Runtime_jll", "ComponentArrays", "DoubleFloats", "FiniteDiff", "FiniteDifferences", "GenericLinearAlgebra", "IntervalArithmetic", "JLD2", "JSON3", "KrylovKit", "Logging", "Plots", "QuadGK", "Random", "Suppressor", "Wannier", "WriteVTK", "wannier90_jll"] diff --git a/test/runtests_runner.jl b/test/runtests_runner.jl index 7616bd8741..ca742a2eca 100644 --- a/test/runtests_runner.jl +++ b/test/runtests_runner.jl @@ -2,6 +2,7 @@ # This is needed to play nicely with MPI parallelised tests # using TestItemRunner +using Suppressor include("runtests_parser.jl") (; base_tag, excluded, included) = parse_test_args() @@ -29,4 +30,30 @@ function dftk_testfilter(ti) return false end end -@run_package_tests filter=dftk_testfilter verbose=true + +function run_tests() + output = @capture_out try + @run_package_tests filter=dftk_testfilter verbose=true + catch err + Base.showerror(stderr, err, Base.catch_backtrace()) + end + + lines = split(output, "\n") + # Print failed tests. + println() + for id in findall(occursin.("Test Failed", lines)) + id_context = id + while !isempty(lines[id_context]) + println(lines[id_context]) + id_context += 1 + end + println() + end + # Print the summary. + idx = findfirst(occursin.(r"^Test Summary:", lines)) + if !isnothing(idx) + println(join(lines[idx:end], "\n")) + end +end + +run_tests() From 3be58fd6809af280fda43e59deb6a36201ebd19a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Fri, 9 Feb 2024 01:23:31 +0100 Subject: [PATCH 2/9] replacing with Logging --- Project.toml | 5 ++--- src/DFTK.jl | 1 + src/common/logging.jl | 1 + src/eigen/lobpcg_hyper_impl.jl | 18 +++++++----------- src/scf/scf_callbacks.jl | 12 ++++++------ src/workarounds/forwarddiff_rules.jl | 2 +- test/runtests_runner.jl | 28 +++------------------------- 7 files changed, 21 insertions(+), 46 deletions(-) create mode 100644 src/common/logging.jl diff --git a/Project.toml b/Project.toml index dd768ada2d..3bed14e04e 100644 --- a/Project.toml +++ b/Project.toml @@ -24,6 +24,7 @@ Libxc = "66e17ffc-8502-11e9-23b5-c9248d0eb96d" LineSearches = "d3d80556-e9d4-5f37-9878-2ab0fcc64255" LinearAlgebra = "37e2e46d-f89d-539d-b4ee-838fcccc9c8e" LinearMaps = "7a12625a-238d-50fd-b39a-03d52299707e" +Logging = "56ddb016-857b-54e1-b83d-db4d58db5568" LoopVectorization = "bdcacae8-1622-11e9-2a5c-532679323890" MPI = "da04e1cc-30fd-572f-bb4f-1f8673147195" Markdown = "d6f4376e-aef5-505a-96c1-9c027394607a" @@ -139,11 +140,9 @@ IntervalArithmetic = "d1acc4aa-44c8-5952-acd4-ba5d80a2a253" JLD2 = "033835bb-8acc-5ee8-8aae-3f567f8a3819" JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1" KrylovKit = "0b1a1467-8014-51b9-945f-bf0ae24f4b77" -Logging = "56ddb016-857b-54e1-b83d-db4d58db5568" Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80" QuadGK = "1fd47b50-473d-5c70-9696-f719f8f3bcdc" Random = "9a3f8284-a2c9-5f02-9a11-845980a1fd5c" -Suppressor = "fd094767-a336-5f1f-9728-57cf17d0bbfb" Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40" TestItemRunner = "f8b46487-2199-4994-9208-9a1283c18c0a" Wannier = "2b19380a-1f7e-4d7d-b1b8-8aa60b3321c9" @@ -151,4 +150,4 @@ WriteVTK = "64499a7a-5c06-52f2-abe2-ccb03c286192" wannier90_jll = "c5400fa0-8d08-52c2-913f-1e3f656c1ce9" [targets] -test = ["Test", "TestItemRunner", "ASEconvert", "Aqua", "AtomsIO", "AtomsIOPython", "CUDA", "CUDA_Runtime_jll", "ComponentArrays", "DoubleFloats", "FiniteDiff", "FiniteDifferences", "GenericLinearAlgebra", "IntervalArithmetic", "JLD2", "JSON3", "KrylovKit", "Logging", "Plots", "QuadGK", "Random", "Suppressor", "Wannier", "WriteVTK", "wannier90_jll"] +test = ["Test", "TestItemRunner", "ASEconvert", "Aqua", "AtomsIO", "AtomsIOPython", "CUDA", "CUDA_Runtime_jll", "ComponentArrays", "DoubleFloats", "FiniteDiff", "FiniteDifferences", "GenericLinearAlgebra", "IntervalArithmetic", "JLD2", "JSON3", "KrylovKit", "Plots", "QuadGK", "Random", "Wannier", "WriteVTK", "wannier90_jll"] diff --git a/src/DFTK.jl b/src/DFTK.jl index b95f3bf2ee..52b64a5f1c 100644 --- a/src/DFTK.jl +++ b/src/DFTK.jl @@ -26,6 +26,7 @@ export Mat3 export mpi_nprocs export mpi_master export setup_threading, disable_threading +include("common/logging.jl") include("common/timer.jl") include("common/constants.jl") include("common/ortho.jl") diff --git a/src/common/logging.jl b/src/common/logging.jl new file mode 100644 index 0000000000..9701044d0f --- /dev/null +++ b/src/common/logging.jl @@ -0,0 +1 @@ +using Logging diff --git a/src/eigen/lobpcg_hyper_impl.jl b/src/eigen/lobpcg_hyper_impl.jl index 5c6fd1145b..68e5b22e6b 100644 --- a/src/eigen/lobpcg_hyper_impl.jl +++ b/src/eigen/lobpcg_hyper_impl.jl @@ -39,10 +39,6 @@ ## TODO it seems there is a lack of orthogonalization immediately after locking, maybe investigate this to save on some choleskys ## TODO debug orthogonalizations when A=I -# TODO Use @debug for this -# vprintln(args...) = println(args...) # Uncomment for output -vprintln(args...) = nothing - using LinearAlgebra import LinearAlgebra: BlasFloat import Base: * @@ -180,7 +176,7 @@ normest(M) = maximum(abs.(diag(M))) + norm(M - Diagonal(diag(M))) success = true catch err @assert isa(err, PosDefException) - vprintln("fail") + @debug "fail" # see https://arxiv.org/pdf/1809.11085.pdf for a nice analysis # We are not being very clever here; but this should very rarely happen # so it should be OK @@ -220,7 +216,7 @@ normest(M) = maximum(abs.(diag(M))) + norm(M - Diagonal(diag(M))) # condR = 1/LAPACK.trcon!('I', 'U', 'N', Array(R)) condR = normest(R)*norminvR # in practice this seems to be an OK estimate - vprintln("Ortho(X) success? $success ", eps(real(T))*condR^2, " < $tol") + @debug "Ortho(X) success? $success ", eps(real(T))*condR^2, " < $tol" # a good a posteriori error is that X'X - I is eps()*κ(R)^2; # in practice this seems to be sometimes very overconservative @@ -289,7 +285,7 @@ end niter > 10 && error("Ortho(X,Y) is failing badly, this should never happen") niter += 1 end - vprintln("ortho choleskys: ", ninners) # get how many Choleskys are performed + @debug "ortho choleskys: ", ninners # get how many Choleskys are performed # @assert (norm(BY'X)) < tol # @assert (norm(X'X-I)) < tol @@ -411,7 +407,7 @@ end resid_history[i + nlocked, niter+1] = norm(new_R[:, i]) end end - vprintln(niter, " ", resid_history[:, niter+1]) + @debug niter, " ", resid_history[:, niter+1] # it is actually a good question of knowing when to # precondition. Here seems sensible, but it could plausibly be @@ -429,7 +425,7 @@ end for i=nlocked+1:M if resid_history[i, niter+1] < tol nlocked += 1 - vprintln("locked $nlocked") + @debug "locked $nlocked" else # We lock in order, assuming that the lowest # eigenvectors converge first; might be tricky otherwise @@ -439,8 +435,8 @@ end end if display_progress - println("Iter $niter, converged $(nlocked)/$(n_conv_check), resid ", - norm(resid_history[1:n_conv_check, niter+1])) + @info "Iter $niter, converged $(nlocked)/$(n_conv_check), resid " * + "$(norm(resid_history[1:n_conv_check, niter+1]))" end if nlocked >= n_conv_check # Converged! diff --git a/src/scf/scf_callbacks.jl b/src/scf/scf_callbacks.jl index 2edabba3fc..936b11b0c9 100644 --- a/src/scf/scf_callbacks.jl +++ b/src/scf/scf_callbacks.jl @@ -67,10 +67,10 @@ function (cb::ScfDefaultCallback)(info) label_damp = show_damp ? (" α ", " ----") : ("", "") label_diag = show_diag ? (" Diag", " ----") : ("", "") label_time = show_time ? (" Δtime", " ------") : ("", "") - @printf "n Energy log10(ΔE) log10(Δρ)" - println(label_magn[1], label_damp[1], label_diag[1], label_time[1]) - @printf "--- --------------- --------- ---------" - println(label_magn[2], label_damp[2], label_diag[2], label_time[2]) + @info "n Energy log10(ΔE) log10(Δρ)" * + "$(label_magn[1]) $(label_damp[1]) $(label_diag[1]) $(label_time[1])" + @info "--- --------------- --------- ---------" * + "$(label_magn[2]) $(label_damp[2]) $(label_diag[2]) $(label_time[2])" end E = isnothing(info.energies) ? Inf : info.energies.total magn = sum(spin_density(info.ρout)) * info.basis.dvol @@ -97,8 +97,8 @@ function (cb::ScfDefaultCallback)(info) αstr = "" show_damp && (αstr = isnan(info.α) ? " " : @sprintf " % 4.2f" info.α) - @printf "% 3d %s %s %s" info.n_iter Estr ΔE Δρstr - println(Mstr, αstr, diagstr, tstr) + line = @sprintf "% 3d %s %s %s" info.n_iter Estr ΔE Δρstr + @info line * "$Mstr $αstr $diagstr $tstr" flush(stdout) info diff --git a/src/workarounds/forwarddiff_rules.jl b/src/workarounds/forwarddiff_rules.jl index 2d7eb582a9..e220771476 100644 --- a/src/workarounds/forwarddiff_rules.jl +++ b/src/workarounds/forwarddiff_rules.jl @@ -209,7 +209,7 @@ function self_consistent_field(basis_dual::PlaneWaveBasis{T}; end ## Implicit differentiation - response.verbose && println("Solving response problem") + response.verbose && @info "Solving response problem" δresults = ntuple(ForwardDiff.npartials(T)) do α δHextψ = [ForwardDiff.partials.(δHextψk, α) for δHextψk in Hψ_dual] solve_ΩplusK_split(scfres, -δHextψ; tol=last(scfres.history_Δρ), response.verbose) diff --git a/test/runtests_runner.jl b/test/runtests_runner.jl index ca742a2eca..46cc413786 100644 --- a/test/runtests_runner.jl +++ b/test/runtests_runner.jl @@ -2,7 +2,6 @@ # This is needed to play nicely with MPI parallelised tests # using TestItemRunner -using Suppressor include("runtests_parser.jl") (; base_tag, excluded, included) = parse_test_args() @@ -31,29 +30,8 @@ function dftk_testfilter(ti) end end -function run_tests() - output = @capture_out try - @run_package_tests filter=dftk_testfilter verbose=true - catch err - Base.showerror(stderr, err, Base.catch_backtrace()) - end +using Logging - lines = split(output, "\n") - # Print failed tests. - println() - for id in findall(occursin.("Test Failed", lines)) - id_context = id - while !isempty(lines[id_context]) - println(lines[id_context]) - id_context += 1 - end - println() - end - # Print the summary. - idx = findfirst(occursin.(r"^Test Summary:", lines)) - if !isnothing(idx) - println(join(lines[idx:end], "\n")) - end +with_logger(ConsoleLogger(stdout, LogLevel(1))) do + @run_package_tests filter=dftk_testfilter verbose=true end - -run_tests() From 3de393e4484b53fa63add3588748906b6e4104ed Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Fri, 9 Feb 2024 02:39:26 +0100 Subject: [PATCH 3/9] devnull for test printing --- test/printing.jl | 22 ++++++++++++++-------- 1 file changed, 14 insertions(+), 8 deletions(-) diff --git a/test/printing.jl b/test/printing.jl index 6f9e778f99..a96f094522 100644 --- a/test/printing.jl +++ b/test/printing.jl @@ -3,6 +3,8 @@ # rather to ensure that the code does not randomly stop working. @testitem "Test printing" setup=[TestCases] begin using DFTK + using Logging + magnesium = TestCases.magnesium function test_basis_printing(; modelargs=(; temperature=1e-3), @@ -11,14 +13,16 @@ disable_electrostatics_check=true, modelargs...) basis = PlaneWaveBasis(model; basisargs...) - println(model) - show(stdout, "text/plain", model) + io = current_logger().min_level > Info ? devnull : stdout + + @info model + show(io, "text/plain", model) - println(basis) - show(stdout, "text/plain", basis) + @info basis + show(io, "text/plain", basis) - println(basis.kpoints[1]) - show(stdout, "text/plain", basis.kpoints[1]) + @info basis.kpoints[1] + show(io, "text/plain", basis.kpoints[1]) basis end @@ -28,8 +32,10 @@ scfres = self_consistent_field(basis; nbandsalg=FixedBands(; n_bands_converge=6), tol=1e-3) - println(scfres.energies) - show(stdout, "text/plain", scfres.energies) + io = current_logger().min_level > Info ? devnull : stdout + + @info scfres.energies + show(io, "text/plain", scfres.energies) end test_scfres_printing() From 8ddb5511e80a6791b244a3b52c66a189a517fab7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Fri, 9 Feb 2024 03:10:30 +0100 Subject: [PATCH 4/9] reducing `@info` verbosity still `[` in `boxstr` --- src/common/logging.jl | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/common/logging.jl b/src/common/logging.jl index 9701044d0f..8b55545420 100644 --- a/src/common/logging.jl +++ b/src/common/logging.jl @@ -1 +1,8 @@ using Logging + +function meta_formatter(level::LogLevel, args...) + color = Logging.default_logcolor(level) + Info == level && return color, "", "" + Logging.default_metafmt(level, args...) +end +global_logger(ConsoleLogger(stdout, Info; meta_formatter)) From 038beade6a8f937e5f80e61d0594906d66955399 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Fri, 9 Feb 2024 03:49:01 +0100 Subject: [PATCH 5/9] removing `boxstr` --- Project.toml | 1 + src/DFTK.jl | 7 +++++++ src/common/logging.jl | 16 +++++++++++++++- src/common/threading.jl | 2 +- test/runtests_runner.jl | 3 ++- 5 files changed, 26 insertions(+), 3 deletions(-) diff --git a/Project.toml b/Project.toml index 3bed14e04e..c6fdeab0ed 100644 --- a/Project.toml +++ b/Project.toml @@ -96,6 +96,7 @@ Libxc = "0.3.17" LineSearches = "7" LinearAlgebra = "1" LinearMaps = "3" +Logging = "1" LoopVectorization = "0.12" MPI = "0.20.13" Markdown = "1" diff --git a/src/DFTK.jl b/src/DFTK.jl index 52b64a5f1c..b563c9026a 100644 --- a/src/DFTK.jl +++ b/src/DFTK.jl @@ -231,6 +231,13 @@ include("workarounds/dummy_inplace_fft.jl") include("workarounds/forwarddiff_rules.jl") include("workarounds/gpu_arrays.jl") +function __init__() + # We need to wait to have access to stdout. + # But now local to the REPL… + default_logger = DFTKLogger(; io=Base.stdout) + global_logger(default_logger) +end + # Precompilation block with a basic workflow @setup_workload begin # very artificial silicon ground state example diff --git a/src/common/logging.jl b/src/common/logging.jl index 8b55545420..a9a252394c 100644 --- a/src/common/logging.jl +++ b/src/common/logging.jl @@ -1,8 +1,22 @@ using Logging +# Removing most of format for `@info` in default logger. function meta_formatter(level::LogLevel, args...) color = Logging.default_logcolor(level) Info == level && return color, "", "" Logging.default_metafmt(level, args...) end -global_logger(ConsoleLogger(stdout, Info; meta_formatter)) + +# Bypasses everything to ConsoleLogger but Info which just shows message without any +# formatting. +Base.@kwdef struct DFTKLogger <: AbstractLogger + io::IO + min_level::LogLevel = Info + fallback = ConsoleLogger(io, min_level; meta_formatter) +end +function Logging.handle_message(logger::DFTKLogger, level, msg, args...; kwargs...) + level == Info && return level < logger.min_level ? nothing : println(logger.io, msg) + Logging.handle_message(logger.fallback, level, msg, args...; kwargs...) +end +Logging.min_enabled_level(logger::DFTKLogger) = logger.min_level +Logging.shouldlog(::DFTKLogger, args...) = true diff --git a/src/common/threading.jl b/src/common/threading.jl index 268688a6b5..91fb8baec4 100644 --- a/src/common/threading.jl +++ b/src/common/threading.jl @@ -19,7 +19,7 @@ function disable_threading() "JULIA_NUM_THREADS is unset and julia does not get the `-t` flag passed." ) @assert n_julia == 1 # To exit in non-master MPI nodes - setup_threading(;n_fft=1, n_blas=1) + setup_threading(; n_fft=1, n_blas=1) end # Parallelization loop breaking range into chunks. diff --git a/test/runtests_runner.jl b/test/runtests_runner.jl index 46cc413786..6c16487b4f 100644 --- a/test/runtests_runner.jl +++ b/test/runtests_runner.jl @@ -32,6 +32,7 @@ end using Logging -with_logger(ConsoleLogger(stdout, LogLevel(1))) do +# Don't print anything below or equal to warning level. +with_logger(ConsoleLogger(stdout, LogLevel(1001))) do @run_package_tests filter=dftk_testfilter verbose=true end From 28ba3d019f9e99025aa4850f76edd42e60b3f4a0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Fri, 9 Feb 2024 05:58:24 +0100 Subject: [PATCH 6/9] need to wrap everything --- src/DFTK.jl | 7 ------- src/common/logging.jl | 14 ++++++-------- src/eigen/diag_lobpcg_hyper.jl | 4 +++- src/scf/self_consistent_field.jl | 8 ++++++-- test/forwarddiff.jl | 17 +++++++++++------ test/printing.jl | 4 ++-- test/runtests_runner.jl | 7 +++++-- 7 files changed, 33 insertions(+), 28 deletions(-) diff --git a/src/DFTK.jl b/src/DFTK.jl index b563c9026a..52b64a5f1c 100644 --- a/src/DFTK.jl +++ b/src/DFTK.jl @@ -231,13 +231,6 @@ include("workarounds/dummy_inplace_fft.jl") include("workarounds/forwarddiff_rules.jl") include("workarounds/gpu_arrays.jl") -function __init__() - # We need to wait to have access to stdout. - # But now local to the REPL… - default_logger = DFTKLogger(; io=Base.stdout) - global_logger(default_logger) -end - # Precompilation block with a basic workflow @setup_workload begin # very artificial silicon ground state example diff --git a/src/common/logging.jl b/src/common/logging.jl index a9a252394c..42b3655ea5 100644 --- a/src/common/logging.jl +++ b/src/common/logging.jl @@ -1,18 +1,12 @@ using Logging - -# Removing most of format for `@info` in default logger. -function meta_formatter(level::LogLevel, args...) - color = Logging.default_logcolor(level) - Info == level && return color, "", "" - Logging.default_metafmt(level, args...) -end +#using Preferences # Bypasses everything to ConsoleLogger but Info which just shows message without any # formatting. Base.@kwdef struct DFTKLogger <: AbstractLogger io::IO min_level::LogLevel = Info - fallback = ConsoleLogger(io, min_level; meta_formatter) + fallback = ConsoleLogger(io, min_level) end function Logging.handle_message(logger::DFTKLogger, level, msg, args...; kwargs...) level == Info && return level < logger.min_level ? nothing : println(logger.io, msg) @@ -20,3 +14,7 @@ function Logging.handle_message(logger::DFTKLogger, level, msg, args...; kwargs. end Logging.min_enabled_level(logger::DFTKLogger) = logger.min_level Logging.shouldlog(::DFTKLogger, args...) = true + +# Minimum log level is read from LocalPreferences.toml; defaults to Info. +#min_level = @load_preference("min_log_level"; default="0") +default_logger() = DFTKLogger(; io=stdout) diff --git a/src/eigen/diag_lobpcg_hyper.jl b/src/eigen/diag_lobpcg_hyper.jl index 93992fe13e..3e05b8934c 100644 --- a/src/eigen/diag_lobpcg_hyper.jl +++ b/src/eigen/diag_lobpcg_hyper.jl @@ -6,7 +6,9 @@ function lobpcg_hyper(A, X0; maxiter=100, prec=nothing, prec === nothing && (prec = I) @assert !largest "Only seeking the smallest eigenpairs is implemented." - result = LOBPCG(A, X0, I, prec, tol, maxiter; n_conv_check, kwargs...) + result = with_logger(default_logger()) do + LOBPCG(A, X0, I, prec, tol, maxiter; n_conv_check, kwargs...) + end n_conv_check === nothing && (n_conv_check = size(X0, 2)) converged = maximum(result.residual_norms[1:n_conv_check]) < tol diff --git a/src/scf/self_consistent_field.jl b/src/scf/self_consistent_field.jl index 3575a6f6d8..3abd98ebb3 100644 --- a/src/scf/self_consistent_field.jl +++ b/src/scf/self_consistent_field.jl @@ -199,7 +199,9 @@ Overview of parameters: converged = is_converged(info) converged = MPI.bcast(converged, 0, MPI.COMM_WORLD) # Ensure same converged - callback(merge(info, (; converged))) + with_logger(default_logger()) do + callback(merge(info, (; converged))) + end ρin + T(damping) .* mix_density(mixing, basis, Δρ; info...) end @@ -218,6 +220,8 @@ Overview of parameters: ρ=ρout, α=damping, eigenvalues, occupation, εF, info.n_bands_converge, n_iter, ψ, info.diagonalization, stage=:finalize, history_Δρ, history_Etot, runtime_ns=time_ns() - start_ns, algorithm="SCF") - callback(info) + with_logger(default_logger()) do + callback(info) + end info end diff --git a/test/forwarddiff.jl b/test/forwarddiff.jl index fe0f3268f6..6f4209a9c7 100644 --- a/test/forwarddiff.jl +++ b/test/forwarddiff.jl @@ -3,6 +3,7 @@ using DFTK using ForwardDiff using LinearAlgebra + using Logging silicon = TestCases.silicon function compute_force(ε1, ε2; metal=false, tol=1e-10) @@ -17,7 +18,7 @@ end basis = PlaneWaveBasis(model; Ecut=5, kgrid=[2, 2, 2], kshift=[0, 0, 0]) - response = ResponseOptions(; verbose=true) + response = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info) is_converged = DFTK.ScfConvergenceForce(tol) scfres = self_consistent_field(basis; is_converged, response) compute_forces_cart(scfres) @@ -61,6 +62,7 @@ end using ForwardDiff using LinearAlgebra using ComponentArrays + using Logging aluminium = TestCases.aluminium function compute_band_energies(ε::T) where {T} @@ -76,9 +78,10 @@ end basis = PlaneWaveBasis(model; Ecut=5, kgrid=[2, 2, 2], kshift=[0, 0, 0]) is_converged = DFTK.ScfConvergenceDensity(1e-10) + response = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info) scfres = self_consistent_field(basis; is_converged, mixing=KerkerMixing(), nbandsalg=FixedBands(; n_bands_converge=10), - damping=0.6, response=ResponseOptions(; verbose=true)) + damping=0.6, response) ComponentArray( eigenvalues=stack([ev[1:10] for ev in scfres.eigenvalues]), @@ -103,6 +106,7 @@ end using LinearAlgebra using ComponentArrays using DftFunctionals + using Logging silicon = TestCases.silicon function compute_force(ε1::T) where {T} @@ -115,8 +119,8 @@ end basis = PlaneWaveBasis(model; Ecut=5, kgrid=[2, 2, 2], kshift=[0, 0, 0]) is_converged = DFTK.ScfConvergenceDensity(1e-10) - scfres = self_consistent_field(basis; is_converged, - response=ResponseOptions(; verbose=true)) + response = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info) + scfres = self_consistent_field(basis; is_converged, response) compute_forces_cart(scfres) end @@ -146,6 +150,7 @@ end using DFTK using ForwardDiff using LinearAlgebra + using Logging function compute_force(ε::T) where {T} # solve the 1D Gross-Pitaevskii equation with ElementGaussian potential @@ -160,8 +165,8 @@ end basis = PlaneWaveBasis(model; Ecut=500, kgrid=(1, 1, 1)) ρ = zeros(Float64, basis.fft_size..., 1) is_converged = DFTK.ScfConvergenceDensity(1e-10) - scfres = self_consistent_field(basis; ρ, is_converged, - response=ResponseOptions(; verbose=true)) + response = ResponseOptions(; verbose=DFTK.default_logger().min_level ≤ Info) + scfres = self_consistent_field(basis; ρ, is_converged, response) compute_forces_cart(scfres) end derivative_ε = let ε = 1e-5 diff --git a/test/printing.jl b/test/printing.jl index a96f094522..bb1fd4784a 100644 --- a/test/printing.jl +++ b/test/printing.jl @@ -13,7 +13,7 @@ disable_electrostatics_check=true, modelargs...) basis = PlaneWaveBasis(model; basisargs...) - io = current_logger().min_level > Info ? devnull : stdout + io = DFTK.default_logger().min_level > Info ? devnull : stdout @info model show(io, "text/plain", model) @@ -32,7 +32,7 @@ scfres = self_consistent_field(basis; nbandsalg=FixedBands(; n_bands_converge=6), tol=1e-3) - io = current_logger().min_level > Info ? devnull : stdout + io = DFTK.default_logger().min_level > Info ? devnull : stdout @info scfres.energies show(io, "text/plain", scfres.energies) diff --git a/test/runtests_runner.jl b/test/runtests_runner.jl index 6c16487b4f..08e83a50f9 100644 --- a/test/runtests_runner.jl +++ b/test/runtests_runner.jl @@ -31,8 +31,11 @@ function dftk_testfilter(ti) end using Logging +using DFTK -# Don't print anything below or equal to warning level. -with_logger(ConsoleLogger(stdout, LogLevel(1001))) do +# Don't print anything below warning level. +DFTK.default_logger() = DFTK.DFTKLogger(; io=stdout, min_level=Warn) +#@set_preferences!("min_log_level" => "1001"; export_prefs=false) +with_logger(DFTK.default_logger()) do @run_package_tests filter=dftk_testfilter verbose=true end From 83bd5a8240a667c47bbc3603022a0930ba2674cf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Fri, 9 Feb 2024 15:17:30 +0100 Subject: [PATCH 7/9] logger more locallised --- src/eigen/diag_lobpcg_hyper.jl | 4 +--- src/eigen/lobpcg_hyper_impl.jl | 2 ++ src/scf/scf_callbacks.jl | 2 ++ src/scf/self_consistent_field.jl | 8 ++------ test/runtests_runner.jl | 4 ++-- 5 files changed, 9 insertions(+), 11 deletions(-) diff --git a/src/eigen/diag_lobpcg_hyper.jl b/src/eigen/diag_lobpcg_hyper.jl index 3e05b8934c..93992fe13e 100644 --- a/src/eigen/diag_lobpcg_hyper.jl +++ b/src/eigen/diag_lobpcg_hyper.jl @@ -6,9 +6,7 @@ function lobpcg_hyper(A, X0; maxiter=100, prec=nothing, prec === nothing && (prec = I) @assert !largest "Only seeking the smallest eigenpairs is implemented." - result = with_logger(default_logger()) do - LOBPCG(A, X0, I, prec, tol, maxiter; n_conv_check, kwargs...) - end + result = LOBPCG(A, X0, I, prec, tol, maxiter; n_conv_check, kwargs...) n_conv_check === nothing && (n_conv_check = size(X0, 2)) converged = maximum(result.residual_norms[1:n_conv_check]) < tol diff --git a/src/eigen/lobpcg_hyper_impl.jl b/src/eigen/lobpcg_hyper_impl.jl index 68e5b22e6b..334929a036 100644 --- a/src/eigen/lobpcg_hyper_impl.jl +++ b/src/eigen/lobpcg_hyper_impl.jl @@ -321,6 +321,7 @@ end @timing function LOBPCG(A, X, B=I, precon=I, tol=1e-10, maxiter=100; miniter=1, ortho_tol=2eps(real(eltype(X))), n_conv_check=nothing, display_progress=false) + old_logger = global_logger(default_logger()) N, M = size(X) # If N is too small, we will likely get in trouble @@ -530,6 +531,7 @@ end niter < maxiter || break niter = niter + 1 end + global_logger(old_logger) final_retval(full_X, full_AX, full_BX, resid_history, maxiter, n_matvec) end diff --git a/src/scf/scf_callbacks.jl b/src/scf/scf_callbacks.jl index 936b11b0c9..5513f3c42b 100644 --- a/src/scf/scf_callbacks.jl +++ b/src/scf/scf_callbacks.jl @@ -38,6 +38,7 @@ function ScfDefaultCallback(; show_damping=true, show_time=true) ScfDefaultCallback(show_damping, show_time, Ref(0)) end function (cb::ScfDefaultCallback)(info) + old_logger = global_logger(default_logger()) # If first iteration clear a potentially cached previous time info.n_iter ≤ 1 && (cb.prev_time[] = 0) @@ -99,6 +100,7 @@ function (cb::ScfDefaultCallback)(info) line = @sprintf "% 3d %s %s %s" info.n_iter Estr ΔE Δρstr @info line * "$Mstr $αstr $diagstr $tstr" + global_logger(old_logger) flush(stdout) info diff --git a/src/scf/self_consistent_field.jl b/src/scf/self_consistent_field.jl index 3abd98ebb3..3575a6f6d8 100644 --- a/src/scf/self_consistent_field.jl +++ b/src/scf/self_consistent_field.jl @@ -199,9 +199,7 @@ Overview of parameters: converged = is_converged(info) converged = MPI.bcast(converged, 0, MPI.COMM_WORLD) # Ensure same converged - with_logger(default_logger()) do - callback(merge(info, (; converged))) - end + callback(merge(info, (; converged))) ρin + T(damping) .* mix_density(mixing, basis, Δρ; info...) end @@ -220,8 +218,6 @@ Overview of parameters: ρ=ρout, α=damping, eigenvalues, occupation, εF, info.n_bands_converge, n_iter, ψ, info.diagonalization, stage=:finalize, history_Δρ, history_Etot, runtime_ns=time_ns() - start_ns, algorithm="SCF") - with_logger(default_logger()) do - callback(info) - end + callback(info) info end diff --git a/test/runtests_runner.jl b/test/runtests_runner.jl index 08e83a50f9..e28cb3631d 100644 --- a/test/runtests_runner.jl +++ b/test/runtests_runner.jl @@ -33,8 +33,8 @@ end using Logging using DFTK -# Don't print anything below warning level. -DFTK.default_logger() = DFTK.DFTKLogger(; io=stdout, min_level=Warn) +# Don't print anything below or at warning level. +DFTK.default_logger() = DFTK.DFTKLogger(; io=stdout, min_level=LogLevel(1001)) #@set_preferences!("min_log_level" => "1001"; export_prefs=false) with_logger(DFTK.default_logger()) do @run_package_tests filter=dftk_testfilter verbose=true From da11eb9f5729ba082fa3a8e6ce7a73cc6ed12bd2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Mon, 12 Feb 2024 11:22:00 +0100 Subject: [PATCH 8/9] no gate around `@run_package_tests` --- test/runtests_runner.jl | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/test/runtests_runner.jl b/test/runtests_runner.jl index e28cb3631d..8849fda237 100644 --- a/test/runtests_runner.jl +++ b/test/runtests_runner.jl @@ -36,6 +36,4 @@ using DFTK # Don't print anything below or at warning level. DFTK.default_logger() = DFTK.DFTKLogger(; io=stdout, min_level=LogLevel(1001)) #@set_preferences!("min_log_level" => "1001"; export_prefs=false) -with_logger(DFTK.default_logger()) do - @run_package_tests filter=dftk_testfilter verbose=true -end +@run_package_tests filter=dftk_testfilter verbose=true From d84c2f34cc2ddf10951020c41deb05a7313fd840 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=89tienne=20Polack?= Date: Mon, 19 Feb 2024 14:50:00 +0100 Subject: [PATCH 9/9] stdout closed during doc compilation --- src/common/logging.jl | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/common/logging.jl b/src/common/logging.jl index 42b3655ea5..2b48d32844 100644 --- a/src/common/logging.jl +++ b/src/common/logging.jl @@ -9,7 +9,8 @@ Base.@kwdef struct DFTKLogger <: AbstractLogger fallback = ConsoleLogger(io, min_level) end function Logging.handle_message(logger::DFTKLogger, level, msg, args...; kwargs...) - level == Info && return level < logger.min_level ? nothing : println(logger.io, msg) + io = isopen(logger.io) ? logger.io : stdout # not sure what happens when docs are run + level == Info && return level < logger.min_level ? nothing : println(io, msg) Logging.handle_message(logger.fallback, level, msg, args...; kwargs...) end Logging.min_enabled_level(logger::DFTKLogger) = logger.min_level