Merge pull request #17879 from MinaProtocol/georgeee/add-sw-internal-trace-logs

Add additional SW internal trace logging

Author: georgeee

src/lib/transaction_witness/transaction_witness.ml

@@ -171,7 +171,7 @@ type t =
   ; status : Mina_base.Transaction_status.t
   ; block_global_slot : Mina_numbers.Global_slot_since_genesis.t
   }
-[@@deriving sexp_of, to_yojson]
+[@@deriving fields, sexp_of, to_yojson]
 
 let read_all_proofs_from_disk
     { transaction

src/lib/transaction_witness/transaction_witness.mli

@@ -108,7 +108,7 @@ type t =
   ; status : Mina_base.Transaction_status.t
   ; block_global_slot : Mina_numbers.Global_slot_since_genesis.t
   }
-[@@deriving sexp_of, to_yojson]
+[@@deriving fields, sexp_of, to_yojson]
 
 val read_all_proofs_from_disk : t -> Stable.Latest.t
 

src/lib/work_selector/inputs.ml

@@ -2,10 +2,21 @@ open Core_kernel
 open Currency
 
 module Test_inputs = struct
-  module Transaction_witness = Int
+  module Transaction_witness = struct
+    type t = Int.t
+
+    let transaction = Fn.id
+  end
+
   module Ledger_hash = Int
   module Sparse_ledger = Int
-  module Transaction = Int
+
+  module Transaction = struct
+    type t = Int.t
+
+    let yojson_summary t = `Int t
+  end
+
   module Ledger_proof_statement = Fee
 
   module Transaction_protocol_state = struct

src/lib/work_selector/intf.ml

@@ -20,10 +20,14 @@ module type Inputs_intf = sig
 
   module Transaction : sig
     type t
+
+    val yojson_summary : t -> Yojson.Safe.t
   end
 
   module Transaction_witness : sig
     type t
+
+    val transaction : t -> Transaction.t
   end
 
   module Ledger_proof : sig
@@ -117,7 +121,8 @@ module type Lib_intf = sig
 
     (** [mark_scheduled t work] Mark [work] as scheduled in [t] *)
     val mark_scheduled :
-         t
+         logger:Logger.t
+      -> t
       -> ( Transaction_witness.t
          , Ledger_proof.Cached.t )
          Snark_work_lib.Work.Single.Spec.t

src/lib/work_selector/random.ml

@@ -1,14 +1,14 @@
 open Core_kernel
 
 module Make (Lib : Intf.Lib_intf) = struct
-  let work ~snark_pool ~fee ~logger:_ (state : Lib.State.t) =
+  let work ~snark_pool ~fee ~logger (state : Lib.State.t) =
     match Lib.State.all_unscheduled_expensive_works ~snark_pool ~fee state with
     | [] ->
         None
     | expensive_work ->
         let i = Random.int (List.length expensive_work) in
         let x = List.nth_exn expensive_work i in
-        Lib.State.mark_scheduled state x ;
+        Lib.State.mark_scheduled ~logger state x ;
         Some x
 end
 

src/lib/work_selector/random_offset.ml

@@ -42,14 +42,14 @@ module Make (Lib : Intf.Lib_intf) = struct
         List.nth_exn expensive_work !offset
   end
 
-  let work ~snark_pool ~fee ~logger:_ (state : Lib.State.t) =
+  let work ~snark_pool ~fee ~logger (state : Lib.State.t) =
     match Lib.State.all_unscheduled_expensive_works ~snark_pool ~fee state with
     | [] ->
         None
     | expensive_work ->
         Offset.update ~new_length:(List.length expensive_work) ;
         let x = Offset.get_nth expensive_work in
-        Lib.State.mark_scheduled state x ;
+        Lib.State.mark_scheduled ~logger state x ;
         Some x
 end
 

src/lib/work_selector/sequence.ml

@@ -1,10 +1,10 @@
 module Make (Lib : Intf.Lib_intf) = struct
-  let work ~snark_pool ~fee ~logger:_ (state : Lib.State.t) =
+  let work ~snark_pool ~fee ~logger (state : Lib.State.t) =
     match Lib.State.all_unscheduled_expensive_works ~snark_pool ~fee state with
     | [] ->
         None
     | x :: _ ->
-        Lib.State.mark_scheduled state x ;
+        Lib.State.mark_scheduled ~logger state x ;
         Some x
 end
 

src/lib/work_selector/work_lib.ml

@@ -6,6 +6,16 @@ module Make (Inputs : Intf.Inputs_intf) = struct
   module Inputs = Inputs
   module Work_spec = Snark_work_lib.Work.Single.Spec
 
+  let yojson_summary t =
+    let f = function
+      | Work_spec.Merge _ ->
+          `String "merge"
+      | Transition (_, witness) ->
+          Inputs.Transaction.yojson_summary
+            (Inputs.Transaction_witness.transaction witness)
+    in
+    `List (One_or_two.map ~f t |> One_or_two.to_list)
+
   module State = struct
     module Job_key = struct
       module T = struct
@@ -71,11 +81,44 @@ module Make (Inputs : Intf.Inputs_intf) = struct
                                 ( Time.diff end_time start_time
                                 |> Time.Span.to_ms ) )
                           ] ;
+                      let old_available_jobs = t.available_jobs in
+                      let old_job_keys =
+                        List.map ~f:Job_key.of_job old_available_jobs
+                        |> Job_key.Set.of_list
+                      in
                       t.available_jobs <- new_available_jobs ;
                       let new_job_keys =
-                        List.map ~f:Job_key.of_job t.available_jobs
+                        List.map ~f:Job_key.of_job new_available_jobs
                         |> Job_key.Set.of_list
                       in
+                      let removed_job_keys =
+                        Job_key.Set.diff old_job_keys new_job_keys
+                      in
+                      let added_job_keys =
+                        Job_key.Set.diff new_job_keys old_job_keys
+                      in
+                      List.iter old_available_jobs ~f:(fun job ->
+                          if
+                            Job_key.Set.mem removed_job_keys
+                              (Job_key.of_job job)
+                          then
+                            [%log internal] "Snark_work_removed"
+                              ~metadata:
+                                [ ( "work_ids"
+                                  , Transaction_snark_work.Statement
+                                    .compact_json @@ Job_key.of_job job )
+                                ; ("txs", yojson_summary job)
+                                ] ) ;
+                      List.iter new_available_jobs ~f:(fun job ->
+                          if Job_key.Set.mem added_job_keys (Job_key.of_job job)
+                          then
+                            [%log internal] "Snark_work_added"
+                              ~metadata:
+                                [ ( "work_ids"
+                                  , Transaction_snark_work.Statement
+                                    .compact_json @@ Job_key.of_job job )
+                                ; ("txs", yojson_summary job)
+                                ] ) ;
                       t.jobs_scheduled <-
                         Job_key.Set.inter t.jobs_scheduled new_job_keys ) ;
                   Deferred.unit )
@@ -84,10 +127,15 @@ module Make (Inputs : Intf.Inputs_intf) = struct
       |> Deferred.don't_wait_for ;
       t
 
-    let mark_scheduled t x =
-      t.jobs_scheduled <-
-        Job_key.Set.add t.jobs_scheduled
-          (One_or_two.map ~f:Work_spec.statement x)
+    let mark_scheduled ~logger t job =
+      let statement = One_or_two.map ~f:Work_spec.statement job in
+      (* Log to internal trace all of the newly available jobs. *)
+      [%log internal] "Snark_work_scheduled"
+        ~metadata:
+          [ ("work_ids", Transaction_snark_work.Statement.compact_json statement)
+          ; ("txs", yojson_summary job)
+          ] ;
+      t.jobs_scheduled <- Job_key.Set.add t.jobs_scheduled statement
 
     let does_not_have_better_fee ~snark_pool ~fee
         (statements : Inputs.Transaction_snark_work.Statement.t) : bool =