very basic timer logger

src/Xranklin.jl

@@ -76,35 +76,17 @@ const FRANKLIN_ENV = Dict{Symbol, Any}(
     :output_site_folder  => "__site",
     :output_pdf_folder   => "__pdf",
     :output_cache_folder => "__cache",
+    # see logging.jl
+    :log_times           => false,
 )
 env(s::Symbol)        = FRANKLIN_ENV[s]
 setenv!(s::Symbol, v) = (FRANKLIN_ENV[s] = v; nothing)
 
-const TIMER  = Dict{Float64,Pair{String, Float64}}()
-const TIMERN = Ref(0)
-
-nest()  = (TIMERN[] += 1)
-dnest() = (TIMERN[] -= 1)
-
-tic() = begin
-    nest()
-    t0 = time()
-    TIMER[t0] = "" => 0.0
-    return t0
-end
-toc(t0, s) = begin
-    depth = dnest()
-    δt = time() - t0
-    s  = "."^depth * " (d:$depth) $s $(time_fmt(δt))" => δt
-    @info s.first
-    TIMER[t0] = s
-    return
-end
-
 # ------------------------------------------------------------------------
 
 include("misc_utils.jl")
 include("html_utils.jl")
+include("logging/timer.jl")
 
 # ------------------------------------------------------------------------
 

src/build/full_pass.jl

@@ -88,13 +88,16 @@ function full_pass(
         # if so, discard the hash of pages which would depend upon those
         # to guarantee that they're process_file_from_triggered and consider
         # the latest dependent file.
+        __t = tic()
         for rp in have_changed_deps(gc.deps_map)
             pgh = path(gc, :cache) / noext(rp) / "pg.hash"
             rm(pgh, force=true)
         end
+        toc(__t, "fullpass / init check")
     end
 
     if utils_changed || config_changed
+        __t = tic()
         # save code blocks marked as independent from context to avoid
         # having to reload them
         bk_indep_code  = Dict{String,Dict{String,CodeRepr}}()
@@ -136,9 +139,11 @@ function full_pass(
         end
         # Now *all* pages will now be built from a resetted code and
         # vars module with the latest utils.
+        toc(__t, "fullpass / utils or config changed")
     end
 
     # now we can skip utils/config (will happen in full_pass_other)
+    __t = tic()
     append!(skip_files, [
         path(gc, :folder) => "config.md",
         path(gc, :folder) => "config.jl",
@@ -161,6 +166,7 @@ function full_pass(
             """
         )
     end
+    toc(__t, "fullpass / misc")
 
     # ---------------------------------------------
     start = time()
@@ -169,22 +175,26 @@ function full_pass(
         """
     # ---------------------------------------------
 
+    __t = tic()
     full_pass_markdown(gc,
         watched_files[:md];
         skip_files,
         allow_init_skip,
         final
-    )
+    ); toc(__t, "fullpass / markdown")
+    __t = tic()
     full_pass_html(gc,
         watched_files[:html];
         skip_files,
         final
-    )
+    ); toc(__t, "fullpass / html")
+    __t = tic()
     full_pass_other(gc,
         merge(watched_files[:other], watched_files[:infra]);
         skip_files
-    )
+    ); toc(__t, "fullpass / other")
 
+    __t = tic()
     # HACK: attached-but-ignored
     # flatten watched files rpath
     watched_rpaths = String[]
@@ -203,13 +213,13 @@ function full_pass(
         fp = folder => rp
         watched_files[:other][fp] = mtime(joinpath(fp...))
     end
-
-
+    toc(__t, "fullpass / attached but ignored")
 
     #
     # RSS, Sitemap, Robots generation
     #
     if final
+        __t = tic()
         gen_rss     = getvar(gc, :generate_rss, false)
         gen_sitemap = getvar(gc, :generate_sitemap, false)
         gen_robots  = getvar(gc, :generate_robots, false)
@@ -232,6 +242,7 @@ function full_pass(
         gen_rss     && generate_rss_feeds(gc)
         gen_sitemap && generate_sitemap(gc)
         gen_robots  && generate_robots_txt(gc)
+        toc(__t, "fullpass / final aux")
     end
 
     # ---------------------------------------------------------
@@ -332,7 +343,9 @@ function _md_loop_1(gc, fp, skip_dict=nothing, allow_init_skip=false; reproc=fal
 
     reproc && reset_both_notebooks!(lc; leave_indep=true)
 
+    __t = tic()
     skip = process_md_file_pass_1(lc, fpath; allow_init_skip)
+    toc(__t, "mdp1 ($(lc.rpath))")
     isnothing(skip_dict) || (skip_dict[fp] = skip)
 
     return skip
@@ -382,7 +395,9 @@ function full_pass_markdown(
 
     n_watched   = length(watched)
     iszero(n_watched) && return
+    __t = tic()
     allocate_children_contexts(gc, watched)
+    toc(__t, "fpmd / allocate children")
 
     # keep track of files to skip (either because marked as such
     # or because their hash hasn't changed) so that they can also
@@ -402,17 +417,22 @@ function full_pass_markdown(
 
     # ----------------------------------------------------------------------
     @info "> Full Pass [MD/1]"
+    __t = tic()
     rp(fp) = get_rpath(gc, joinpath(fp...))
     msg(fp, n="1️⃣") = " $n ⟨$(hl(str_fmt(rp(fp))))⟩"
     for (fp, _) in watched
         @info msg(fp)
+        __ti = tic()
         skip = _md_loop_1(gc, fp, skip_dict, allow_init_skip)
+        toc(__ti, "fdmp / md1 : $(rp(fp))")
         skip && @info " ... ($(hl("skipped '$(rp(fp))'", :yellow)))"
     end
+    toc(__t, "fdmp / md1")
 
     # ----------------------------------------------------------------------
     # Some pages may have been skipped from cache but should in fact be
     # done anyway because they depend upon a page that changed
+    __t = tic()
     all_to_trigger = Set{String}()
     for (_, lci) in gc.children_contexts
         union!(all_to_trigger, lci.to_trigger)
@@ -440,16 +460,21 @@ function full_pass_markdown(
             skip_dict[fp] = false
         end
     end
+    toc(__t, "fdmp / md1-retrig")
     # ----------------------------------------------------------------------
 
     @info "> Full Pass [MD/I] (sequential)"
+    __t = tic()
     _md_loop_i(gc)
+    toc(__t, "fdmp / mdi")
 
     @info "> Full Pass [MD/2]"
+    __t = tic()
     for (fp, _) in watched
         @info msg(fp, "2️⃣")
         _md_loop_2(gc, fp, skip_dict, final)
     end
+    toc(__t, "fdmp / md2")
 
     return
 end

src/build/serve.jl

@@ -87,6 +87,8 @@ function serve(
             launch::Bool = true,
         )::Nothing
 
+    reset_timer()
+
     if debug
         Logging.disable_logging(Logging.Debug - 100)
         ENV["JULIA_DEBUG"] = "all"
@@ -101,6 +103,7 @@ function serve(
     # notebooks which each have their module. The first creation of a module
     # will also create the overall `parent_module` in which all modules (for
     # both the global and the local contexts) will live.
+    __t = tic()
     gc     = DefaultGlobalContext()
     folder = ifelse(isempty(folder), pwd(), dir)
 
@@ -125,6 +128,9 @@ function serve(
     utils_unchanged = !any(isfile, (cached_utils, current_utils)) ||
                       utilscmp(cached_utils, current_utils)
 
+    toc(__t, "serve / init")
+    __t = tic()
+
     # same for config except the cached version may be from a .jl or .md
     config_unchanged = false
     for case in ("config.jl", "config.md")
@@ -134,9 +140,12 @@ function serve(
                            filecmp(cached_config, current_config)
         config_unchanged || break
     end
+
+    toc(__t, "serve / cmp config+utils")
 
     deserialized_gc_success = false
     if !clear && isfile(gc_cache_path())
+        __t   = tic()
         start = time()
         # try to load previously-serialised contexts if any, the process config
         # and process_utils happen within the deserialise so that children
@@ -156,9 +165,12 @@ function serve(
 
         # check if layout files have changed, if they have --> clear
         clear = clear || changed_layout_hashes(gc)
+
+        toc(__t, "serve / cache loading")
     end
 
     if clear || !utils_unchanged
+        __t = tic()
         # if there was a successfully deserialised gc, we discard it
         # if there wasn't, then the gc is currently a fresh one
         if deserialized_gc_success
@@ -173,8 +185,13 @@ function serve(
         end
 
         @debug "clear: $clear / utils: $utils_unchanged; reprocess config/utils"
+        __t1 = tic()
         process_config(gc)
+        toc(__t1, "process config")
+        __t2 = tic()
         process_utils(gc)
+        toc(__t2, "process utils")
+        toc(__t, "serve / scratch init")
     end
 
     # useful to check if changes to utils are relevant or not, see
@@ -188,8 +205,11 @@ function serve(
     # scrape the folder to collect all files that should be watched for
     # changes; this set will be updated in the loop if new files get
     # added that should be watched
+    __t = tic()
     wf = find_files_to_watch(gc)
+    toc(__t, "serve / fill watcher")
 
+    __t = tic()
     gc = full_pass(
         gc, wf;
         initial_pass    = true,
@@ -198,6 +218,7 @@ function serve(
         final,
         allow_no_index
     )
+    toc(__t, "serve / fullpass")
 
     # ---------------------------------------------------------------
     # Start the build loop unless we're in single pass mode (single)
@@ -216,6 +237,7 @@ function serve(
 
     # ---------------------------------------------------------------
     # Finalise by caching notebooks etc
+    __t = tic()
     with_parser_error = String[]
     with_failed_block = String[]
     for (rp, lc) in gc.children_contexts
@@ -267,6 +289,8 @@ function serve(
     # cache
     serialize_contexts(gc)
 
+    toc(__t, "serve / finalise + serialise")
+
     # ---------------------------------------------------------------
     # Cleanup:
     # > wipe parent module (make all children modules inaccessible
@@ -276,6 +300,7 @@ function serve(
         start = time()
         @info "🗑️ cleaning up all objects..."
         parent_module(wipe=true)
+        save_timer()
         setenv!(:cur_global_ctx, nothing)
         setenv!(:cur_local_ctx,  nothing)
         δt = time() - start; @info """

src/context/code/notebook.jl

@@ -6,6 +6,11 @@ Base.length(nb::Notebook)    = length(nb.code_pairs)
 increment!(nb::Notebook)     = (nb.cntr_ref[] += 1)
 reset_counter!(nb::Notebook) = (nb.cntr_ref[] = 1)
 
+reset_notebook_counters!(lc::LocalContext) = begin
+    reset_counter!(lc.nb_vars)
+    is_dummy(lc.nb_code) || reset_counter!(lc.nb_code)
+end
+
 """
     reset_notebook!(nb)
 
@@ -34,11 +39,12 @@ function reset_notebook!(
 end
 
 function reset_both_notebooks!(
-            c::Context;
+            lc::LocalContext;
             leave_indep::Bool=false
         )
-    reset_notebook!(c.nb_code; leave_indep)
-    reset_notebook!(c.nb_vars)
+
+    is_dummy(lc.nb_code) || reset_notebook!(lc.nb_code; leave_indep)
+    reset_notebook!(lc.nb_vars)
     return
 end
 
@@ -79,6 +85,7 @@ This can happen if an indep code block gets modified.
 See process/md/process_md_file_io!
 """
 function refresh_indep_code!(lc::LocalContext)
+    is_dummy(lc.nb_code) && return
     actual_code_on_page = Set([cp.code for cp in lc.nb_code.code_pairs])
     keys_to_remove = Set{String}()
     for k in keys(lc.nb_code.indep_code)

src/context/code/notebook_vars.jl

@@ -16,6 +16,8 @@ function eval_vars_cell!(
         )::Nothing
     isempty(cell_code) && return
 
+    __t = tic()
+
     if ctx isa LocalContext && ctx !== cur_lc()
         set_current_local_context(ctx)
     end
@@ -72,10 +74,16 @@ function eval_vars_cell!(
         deleteat!(nb.code_pairs, cntr:lnb)
     end
 
+    toc(__t, "varcell / init")
+    __t = tic()
+
     # eval cell and recover the names of the variables assigned
     vpairs   = _eval_vars_cell(nb.mdl, code)
     vnames   = [vp.var for vp in vpairs]
 
+    toc(__t, "varcell / eval")
+    __t = tic()
+
     # list of all variables that either have just been assigned
     # or were removed/reset through the existing_assignments phase
     all_vars = union!(existing_assignments, vnames)
@@ -104,7 +112,11 @@ function eval_vars_cell!(
     end
 
     # finalise
-    return finish_cell_eval!(nb, VarsCodePair((code, vpairs)))
+    finish_cell_eval!(nb, VarsCodePair((code, vpairs)))
+
+    toc(__t, "varcell / finalise")
+
+    return
 end