Add binding invalidations to log (#58226)

Currently we log the invalidated backedges of a binding invalidation,
but the actual trigger of the invalidation is not logged. This is needed
to allow SnoopCompile to attribute a cause to those invalidations.

Author: timholy

base/invalidation.jl

@@ -67,20 +67,25 @@ function invalidate_method_for_globalref!(gr::GlobalRef, method::Method, invalid
     binding = convert(Core.Binding, gr)
     if isdefined(method, :source)
         src = _uncompressed_ir(method)
-        old_stmts = src.code
         invalidate_all = should_invalidate_code_for_globalref(gr, src)
     end
+    invalidated_any = false
     for mi in specializations(method)
         isdefined(mi, :cache) || continue
         ci = mi.cache
+        invalidated = false
         while true
             if ci.max_world > new_max_world && (invalidate_all || scan_edge_list(ci, binding))
                 ccall(:jl_invalidate_code_instance, Cvoid, (Any, UInt), ci, new_max_world)
+                invalidated = true
             end
             isdefined(ci, :next) || break
             ci = ci.next
         end
+        invalidated && ccall(:jl_maybe_log_binding_invalidation, Cvoid, (Any,), mi)
+        invalidated_any |= invalidated
     end
+    return invalidated_any
 end
 
 export_affecting_partition_flags(bpart::Core.BindingPartition) =
@@ -104,18 +109,21 @@ function invalidate_code_for_globalref!(b::Core.Binding, invalidated_bpart::Core
     need_to_invalidate_export = export_affecting_partition_flags(invalidated_bpart) !==
                                 export_affecting_partition_flags(new_bpart)
 
+    invalidated_any = false
+    queued_bindings = Tuple{Core.Binding, Core.BindingPartition, Core.BindingPartition}[]    # defer handling these to keep the logging coherent
     if need_to_invalidate_code
         if (b.flags & BINDING_FLAG_ANY_IMPLICIT_EDGES) != 0
             nmethods = ccall(:jl_module_scanned_methods_length, Csize_t, (Any,), gr.mod)
             for i = 1:nmethods
                 method = ccall(:jl_module_scanned_methods_getindex, Any, (Any, Csize_t), gr.mod, i)::Method
-                invalidate_method_for_globalref!(gr, method, invalidated_bpart, new_max_world)
+                invalidated_any |= invalidate_method_for_globalref!(gr, method, invalidated_bpart, new_max_world)
             end
         end
         if isdefined(b, :backedges)
             for edge in b.backedges
                 if isa(edge, CodeInstance)
                     ccall(:jl_invalidate_code_instance, Cvoid, (Any, UInt), edge, new_max_world)
+                    invalidated_any = true
                 elseif isa(edge, Core.Binding)
                     isdefined(edge, :partitions) || continue
                     latest_bpart = edge.partitions
@@ -124,9 +132,9 @@ function invalidate_code_for_globalref!(b::Core.Binding, invalidated_bpart::Core
                     if is_some_binding_imported(binding_kind(latest_bpart))
                         partition_restriction(latest_bpart) === b || continue
                     end
-                    invalidate_code_for_globalref!(edge, latest_bpart, latest_bpart, new_max_world)
+                    push!(queued_bindings, (edge, latest_bpart, latest_bpart))
                 else
-                    invalidate_method_for_globalref!(gr, edge::Method, invalidated_bpart, new_max_world)
+                    invalidated_any |= invalidate_method_for_globalref!(gr, edge::Method, invalidated_bpart, new_max_world)
                 end
             end
         end
@@ -148,11 +156,16 @@ function invalidate_code_for_globalref!(b::Core.Binding, invalidated_bpart::Core
                     ccall(:jl_maybe_reresolve_implicit, Any, (Any, Csize_t), user_binding, new_max_world) :
                     latest_bpart
                 if need_to_invalidate_code || new_bpart !== latest_bpart
-                    invalidate_code_for_globalref!(convert(Core.Binding, user_binding), latest_bpart, new_bpart, new_max_world)
+                    push!(queued_bindings, (convert(Core.Binding, user_binding), latest_bpart, new_bpart))
                 end
             end
         end
     end
+    invalidated_any && ccall(:jl_maybe_log_binding_invalidation, Cvoid, (Any,), invalidated_bpart)
+    for (edge, invalidated_bpart, new_bpart) in queued_bindings
+        invalidated_any |= invalidate_code_for_globalref!(edge, invalidated_bpart, new_bpart, new_max_world)
+    end
+    return invalidated_any
 end
 invalidate_code_for_globalref!(gr::GlobalRef, invalidated_bpart::Core.BindingPartition, new_bpart::Core.BindingPartition, new_max_world::UInt) =
     invalidate_code_for_globalref!(convert(Core.Binding, gr), invalidated_bpart, new_bpart, new_max_world)

src/gf.c

@@ -1891,6 +1891,19 @@ JL_DLLEXPORT void jl_invalidate_code_instance(jl_code_instance_t *replaced, size
     invalidate_code_instance(replaced, max_world, 1);
 }
 
+JL_DLLEXPORT void jl_maybe_log_binding_invalidation(jl_value_t *replaced)
+{
+    if (_jl_debug_method_invalidation) {
+        if (replaced) {
+            jl_array_ptr_1d_push(_jl_debug_method_invalidation, replaced);
+        }
+        jl_value_t *loctag = jl_cstr_to_string("jl_maybe_log_binding_invalidation");
+        JL_GC_PUSH1(&loctag);
+        jl_array_ptr_1d_push(_jl_debug_method_invalidation, loctag);
+        JL_GC_POP();
+    }
+}
+
 static void _invalidate_backedges(jl_method_instance_t *replaced_mi, jl_code_instance_t *replaced_ci, size_t max_world, int depth) {
     uint8_t recursion_flags = 0;
     jl_array_t *backedges = jl_mi_get_backedges_mutate(replaced_mi, &recursion_flags);

test/precompile.jl

@@ -967,6 +967,12 @@ precompile_test_harness("code caching") do dir
         const gib = makewib(1)
         fib() = gib.ib.x
 
+        struct LogBindingInvalidation
+            x::Int
+        end
+        const glbi = LogBindingInvalidation(1)
+        flbi() = @__MODULE__().glbi.x
+
         # force precompilation
         build_stale(37)
         stale('c')
@@ -991,10 +997,13 @@ precompile_test_harness("code caching") do dir
         useA() = $StaleA.stale("hello")
         useA2() = useA()
 
+        useflbi() = $StaleA.flbi()
+
         # force precompilation
         begin
             Base.Experimental.@force_compile
             useA2()
+            useflbi()
         end
         precompile($StaleA.fib, ())
 
@@ -1035,6 +1044,13 @@ precompile_test_harness("code caching") do dir
         end
         const gib = makewib(2.0)
     end)
+    # TODO: test a "method_globalref" invalidation also
+    Base.eval(MA, quote
+        struct LogBindingInvalidation # binding invalidations can't be done during precompilation
+            x::Float64
+        end
+        const glbi = LogBindingInvalidation(2.0)
+    end)
     @eval using $StaleC
     invalidations = Base.StaticData.debug_method_invalidation(true)
     @eval using $StaleB
@@ -1096,6 +1112,16 @@ precompile_test_harness("code caching") do dir
         @test !hasvalid(mi, world)
         @test any(x -> x isa Core.CodeInstance && x.def === mi, invalidations)
 
+        idxb = findfirst(x -> x isa Core.Binding, invalidations)
+        @test invalidations[idxb+1] == "insert_backedges_callee"
+        idxv = findnext(==("verify_methods"), invalidations, idxb)
+        if invalidations[idxv-1].def.def.name === :getproperty
+            idxv = findnext(==("verify_methods"), invalidations, idxv+1)
+        end
+        @test invalidations[idxv-1].def.def.name === :flbi
+        idxv = findnext(==("verify_methods"), invalidations, idxv+1)
+        @test invalidations[idxv-1].def.def.name === :useflbi
+
         m = only(methods(MB.map_nbits))
         @test !hasvalid(m.specializations::Core.MethodInstance, world+1) # insert_backedges invalidations also trigger their backedges
     end

test/worlds.jl

@@ -436,6 +436,34 @@ idxi = findfirst(==(m58080i), logmeths)
 @test logmeths[end-1] == m58080s
 @test logmeths[end] == "jl_method_table_insert"
 
+# logging binding invalidations
+struct LogBindingInvalidation
+    x::Int
+end
+makelbi(x) = LogBindingInvalidation(x)
+const glbi = makelbi(1)
+oLBI, oglbi = LogBindingInvalidation, glbi
+flbi() = @__MODULE__().glbi.x
+flbi()
+milbi1 = only(Base.specializations(only(methods(makelbi))))
+milbi2 = only(Base.specializations(only(methods(flbi))))
+logmeths = ccall(:jl_debug_method_invalidation, Any, (Cint,), 1)
+struct LogBindingInvalidation
+    x::Float64
+end
+const glbi = makelbi(2.0)
+@test flbi() === 2.0
+ccall(:jl_debug_method_invalidation, Any, (Cint,), 0)
+@test milbi1.cache.def ∈ logmeths
+@test milbi2.cache.next.def ∈ logmeths
+i = findfirst(x -> isa(x, Core.BindingPartition), logmeths)
+T = logmeths[i].restriction
+@test T === oLBI
+@test logmeths[i+1] == "jl_maybe_log_binding_invalidation"
+T = logmeths[end-1].restriction
+@test T === oglbi
+@test logmeths[end] == "jl_maybe_log_binding_invalidation"
+
 # issue #50091 -- missing invoke edge affecting nospecialized dispatch
 module ExceptionUnwrapping
 @nospecialize