basic tracing #5757

c-cube · 2023-12-08T15:50:28Z

This is WIP.

I'm adding tracing to find why opam is so slow on my machine. It gives excellent insights on where time is spent (e.g after opam upd, all 30k files are read one by one, to update the cache).

I've been instrumenting things as I explore but it needs to be more principled in general I think.

The overhead when tracing is not active (ie TRACE_FILE is not set) should be fairly low.

kit-ty-kate · 2023-12-08T20:06:27Z

Thanks a lot for this! I have a couple of questions:

I’m not familiar with this tracing format. Is it used by a visualisation tool? If so which one?
If not, what are the advantages compared to --debug-level=3?
Is the dependency on mtime necessary or could we use something that already exists for --debug-level=3 for example?

c-cube · 2023-12-08T20:38:20Z

the tracing format is the classic JSON file for chrome://tracing, which can also be read by https://ui.perfetto.dev/
(see also past example of this 1). So you can easily visualize it.

It can look like this:
I think we could use Unix.gettimeofday() instead, I think, we don't need that high precision in general. I got a bit over enthusiastic.

kit-ty-kate

LGTM on first glance

kit-ty-kate · 2024-01-02T19:37:06Z

We’re trying to get 2.2.0 out the door asap and i’d prefer to merge this after the release to avoid unnecessary time spent in extra maintenance and CI work (don’t worry the CI failure is unrelated to you changes).
Is that ok for you?

c-cube · 2024-01-02T19:42:13Z

Of course, no worries! This is really a tool to debug/improve opam itself, not something end users urgently need, I think.

…ebase

this cuts the time spent on parsing `pacman -Si` significantly down

kit-ty-kate

I've squashed the PR and cleaned a couple trailing whitespaces. It looks good overall but there are a couple of things to split off into their own PRs I think

kit-ty-kate · 2024-08-13T12:42:27Z

src/client/opamAuxCommands.ml

@@ -395,6 +395,7 @@ let simulate_local_pinnings ?quiet ?(for_view=false) st to_pin =

 let simulate_autopin st ?quiet ?(for_view=false) ?locked ?recurse ?subpath
    atom_or_local_list =
+  OpamTrace.with_span "AuxCommands.simulate_autopin" @@ fun () ->


I think it's better to give the full name of the module even if the Opam prefix is repetitive

Suggested change

OpamTrace.with_span "AuxCommands.simulate_autopin" @@ fun () ->

OpamTrace.with_span "OpamAuxCommands.simulate_autopin" @@ fun () ->

kit-ty-kate · 2024-08-13T12:45:30Z

src/core/opamTrace.ml

+(* ## setup ## *)
+
+let setup ~trace_file () : unit =
+  match trace_file, Sys.getenv_opt "TRACE_FILE" with


I think this should be OPAMTRACEFILE instead and be added through OpamCoreConfig and OpamArg like the rest of the environment variables

kit-ty-kate · 2024-08-13T12:50:02Z

src/core/opamStd.ml

-    (* old compat version (Re 1.2.0)
-       {[Re_str.split (Re_str.regexp (Printf.sprintf "[%c]+" c)) s]} *)
-    Re.(split (compile (rep1 (char c)))) s
+    let acc = ref [] in
+    let in_run = ref false in
+    let slice_start = ref 0 in
+
+    for i=0 to String.length s-1 do
+      if String.get s i = c then (
+        if not !in_run then (
+          if i > !slice_start then
+            acc := String.sub s !slice_start (i - !slice_start) :: !acc;
+          in_run := true;
+        )
+      ) else (
+        if !in_run then (
+          in_run := false;
+          slice_start := i;
+        )
+      )
+    done;
+    if not !in_run && !slice_start < String.length s then
+      acc := String.sub s !slice_start (String.length s - !slice_start) :: !acc;
+    List.rev !acc


I think this change should be in its own PR

kit-ty-kate · 2024-08-13T12:54:31Z

src/core/opamConsole.ml

 let print_message =
  if Sys.win32 then
-    fun ch fmt ->
-      flush (if ch = `stdout then stderr else stdout);
+    fun ~force_flush ch fmt ->


is this for performance improvement or does the tracing itself need it? If it's the former, i think this should be in its own PR

kit-ty-kate · 2024-08-13T12:57:52Z

src/core/opamTrace.mli

@@ -0,0 +1,9 @@
+(** Tracing *)


Suggested change

(** Tracing *)

(**************************************************************************)

(* *)

(* Copyright 2023 Simon Cruanes *)

(* *)

(* All rights reserved. This file is distributed under the terms of the *)

(* GNU Lesser General Public License version 2.1, with the special *)

(* exception on linking described in the file LICENSE. *)

(* *)

(**************************************************************************)

(** Tracing *)

kit-ty-kate · 2024-08-13T12:58:04Z

src/core/opamTrace.ml

@@ -0,0 +1,110 @@
+module Json = OpamJson


Suggested change

module Json = OpamJson

(**************************************************************************)

(* *)

(* Copyright 2023 Simon Cruanes *)

(* *)

(* All rights reserved. This file is distributed under the terms of the *)

(* GNU Lesser General Public License version 2.1, with the special *)

(* exception on linking described in the file LICENSE. *)

(* *)

(**************************************************************************)

module Json = OpamJson

c-cube marked this pull request as ready for review December 13, 2023 16:25

kit-ty-kate reviewed Jan 2, 2024

View reviewed changes

c-cube force-pushed the wip-basic-tracing branch from 6ed05e0 to c7b6f5e Compare January 8, 2024 17:18

c-cube added 2 commits August 13, 2024 13:39

Add a new OpamTrace module and instrument known slow parts of the cod…

6678053

…ebase

perf: optimize OpamString.split

c64b484

this cuts the time spent on parsing `pacman -Si` significantly down

kit-ty-kate force-pushed the wip-basic-tracing branch from c7b6f5e to c64b484 Compare August 13, 2024 12:40

kit-ty-kate reviewed Aug 13, 2024

View reviewed changes

kit-ty-kate added this to the 2.3.0~alpha milestone Aug 13, 2024

kit-ty-kate added the AREA: PERFORMANCE label Aug 13, 2024

kit-ty-kate modified the milestones: 2.3.0~alpha, 2.4.0~alpha1 Sep 3, 2024

kit-ty-kate mentioned this pull request Sep 25, 2024

perf: optimize OpamString.split #6210

Draft

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

basic tracing #5757

basic tracing #5757

c-cube commented Dec 8, 2023

kit-ty-kate commented Dec 8, 2023

c-cube commented Dec 8, 2023 •

edited

Loading

kit-ty-kate left a comment

kit-ty-kate commented Jan 2, 2024

c-cube commented Jan 2, 2024

kit-ty-kate left a comment

kit-ty-kate Aug 13, 2024

kit-ty-kate Aug 13, 2024

kit-ty-kate Aug 13, 2024

kit-ty-kate Aug 13, 2024

kit-ty-kate Aug 13, 2024

kit-ty-kate Aug 13, 2024

	OpamTrace.with_span "AuxCommands.simulate_autopin" @@ fun () ->
	OpamTrace.with_span "OpamAuxCommands.simulate_autopin" @@ fun () ->

-(** Tracing *)
+(**************************************************************************)
+(*                                                                        *)
+(*    Copyright 2023  Simon Cruanes                                       *)
+(*                                                                        *)
+(*  All rights reserved. This file is distributed under the terms of the  *)
+(*  GNU Lesser General Public License version 2.1, with the special       *)
+(*  exception on linking described in the file LICENSE.                   *)
+(*                                                                        *)
+(**************************************************************************)
+(** Tracing *)

basic tracing #5757

Are you sure you want to change the base?

basic tracing #5757

Conversation

c-cube commented Dec 8, 2023

kit-ty-kate commented Dec 8, 2023

c-cube commented Dec 8, 2023 • edited Loading

kit-ty-kate left a comment

Choose a reason for hiding this comment

kit-ty-kate commented Jan 2, 2024

c-cube commented Jan 2, 2024

kit-ty-kate left a comment

Choose a reason for hiding this comment

kit-ty-kate Aug 13, 2024

Choose a reason for hiding this comment

kit-ty-kate Aug 13, 2024

Choose a reason for hiding this comment

kit-ty-kate Aug 13, 2024

Choose a reason for hiding this comment

kit-ty-kate Aug 13, 2024

Choose a reason for hiding this comment

kit-ty-kate Aug 13, 2024

Choose a reason for hiding this comment

kit-ty-kate Aug 13, 2024

Choose a reason for hiding this comment

c-cube commented Dec 8, 2023 •

edited

Loading