diff --git a/Project.toml b/Project.toml index 01ac694ce2..c6fdeab0ed 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" @@ -95,6 +96,7 @@ Libxc = "0.3.17" LineSearches = "7" LinearAlgebra = "1" LinearMaps = "3" +Logging = "1" LoopVectorization = "0.12" MPI = "0.20.13" Markdown = "1" @@ -139,7 +141,6 @@ 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" @@ -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", "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..2b48d32844 --- /dev/null +++ b/src/common/logging.jl @@ -0,0 +1,21 @@ +using Logging +#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) +end +function Logging.handle_message(logger::DFTKLogger, level, msg, args...; kwargs...) + 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 +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/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/src/eigen/lobpcg_hyper_impl.jl b/src/eigen/lobpcg_hyper_impl.jl index 5c6fd1145b..334929a036 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 @@ -325,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 @@ -411,7 +408,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 +426,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 +436,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! @@ -534,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 2edabba3fc..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) @@ -67,10 +68,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 +98,9 @@ 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" + global_logger(old_logger) 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/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 6f9e778f99..bb1fd4784a 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 = DFTK.default_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 = DFTK.default_logger().min_level > Info ? devnull : stdout + + @info scfres.energies + show(io, "text/plain", scfres.energies) end test_scfres_printing() diff --git a/test/runtests_runner.jl b/test/runtests_runner.jl index 7616bd8741..8849fda237 100644 --- a/test/runtests_runner.jl +++ b/test/runtests_runner.jl @@ -29,4 +29,11 @@ function dftk_testfilter(ti) return false end end + +using Logging +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) @run_package_tests filter=dftk_testfilter verbose=true