[Caml-list] gc overhead

[Caml-list] gc overhead

[Julia Lawall]

Hello,

Is there any reasonable way to reduce the amount of garbage collection
activity in an OCaml program?  I see various knobs in the control
structure, but I don't know what the impact of changing the values would
be.

thanks,
juli

Re: [Caml-list] gc overhead

[Yawar Amin]

[-- Attachment #1: Type: text/plain, Size: 904 bytes --]

Hi Juli, you can take a look at
https://realworldocaml.org/v1/en/html/understanding-the-garbage-collector.html
for some explanations of the various knobs. Specifically, the in-text note
sections (marked with the icon of two pages) give some helpful hints. The
first one on the page is 'Setting the Size of the Minor Heap'.

Regards,

Yawar

On Tue, Nov 28, 2017 at 1:11 PM, Julia Lawall <julia.lawall@lip6.fr> wrote:

> Hello,
>
> Is there any reasonable way to reduce the amount of garbage collection
> activity in an OCaml program?  I see various knobs in the control
> structure, but I don't know what the impact of changing the values would
> be.
>
> thanks,
> juli
>
> --
> Caml-list mailing list.  Subscription management and archives:
> https://sympa.inria.fr/sympa/arc/caml-list
> Beginner's list: http://groups.yahoo.com/group/ocaml_beginners
> Bug reports: http://caml.inria.fr/bin/caml-bugs
>

[-- Attachment #2: Type: text/html, Size: 1742 bytes --]

Re: [Caml-list] gc overhead

[Julia Lawall]

[-- Attachment #1: Type: text/plain, Size: 1069 bytes --]



On Tue, 28 Nov 2017, Yawar Amin wrote:

> Hi Juli, you can take a look at https://realworldocaml.org/v1/en/html/understanding-the-garbage-collector.html for some explanations of the various knobs. Specifically, the in-text note sections (marked with the icon of two pages) give some helpful
> hints. The first one on the page is 'Setting the Size of the Minor Heap'.

Thanks for the pointer.

julia

> Regards,
>
> Yawar
>
> On Tue, Nov 28, 2017 at 1:11 PM, Julia Lawall <julia.lawall@lip6.fr> wrote:
>       Hello,
>
>       Is there any reasonable way to reduce the amount of garbage collection
>       activity in an OCaml program?  I see various knobs in the control
>       structure, but I don't know what the impact of changing the values would
>       be.
>
>       thanks,
>       juli
>
>       --
>       Caml-list mailing list.  Subscription management and archives:
>       https://sympa.inria.fr/sympa/arc/caml-list
>       Beginner's list: http://groups.yahoo.com/group/ocaml_beginners
>       Bug reports: http://caml.inria.fr/bin/caml-bugs
>
>
>
>

Re: [Caml-list] gc overhead

[Julia Lawall]

[-- Attachment #1: Type: text/plain, Size: 1279 bytes --]



On Tue, 28 Nov 2017, Yawar Amin wrote:

> Hi Juli, you can take a lookat https://realworldocaml.org/v1/en/html/understanding-the-garbage-collecto
> r.html for some explanations of the various knobs. Specifically, the in-text
> note sections (marked with the icon of two pages) give some helpful hints.
> The first one on the page is 'Setting the Size of the Minor Heap'.

Is it possible to know when a major GC starts, to be able to measure the
time spent?  I saw the verbose flag in the control structure, but that
just prints a message.  I don't see how to get the time.

thanks,
julia

> Regards,
>
> Yawar
>
> On Tue, Nov 28, 2017 at 1:11 PM, Julia Lawall <julia.lawall@lip6.fr> wrote:
>       Hello,
>
>       Is there any reasonable way to reduce the amount of garbage
>       collection
>       activity in an OCaml program?  I see various knobs in the
>       control
>       structure, but I don't know what the impact of changing the
>       values would
>       be.
>
>       thanks,
>       juli
>
>       --
>       Caml-list mailing list.  Subscription management and archives:
>       https://sympa.inria.fr/sympa/arc/caml-list
>       Beginner's list: http://groups.yahoo.com/group/ocaml_beginners
>       Bug reports: http://caml.inria.fr/bin/caml-bugs
>
>
>
>

Re: [Caml-list] gc overhead

[Gabriel Scherer]

[-- Attachment #1: Type: text/plain, Size: 2260 bytes --]

There is an instrumentation mode for the OCaml GC whose usage I have
described in a blog post and on the caml-list:


http://prl.ccs.neu.edu/blog/2016/05/24/measuring-gc-latencies-in-haskell-ocaml-racket/
  https://sympa.inria.fr/sympa/arc/caml-list/2016-05/msg00219.html

(I am realizing that the simple change I proposed, of building the
instrumented runtime by default, was forgotten, and will submit a pull
request shortly -- hopefully it will be present in 4.07... In the meantime,
people have to build the compiler with the -with-instrumented-runtime flag
explicitly set.)

On Mon, Dec 11, 2017 at 7:53 PM, Julia Lawall <julia.lawall@lip6.fr> wrote:

>
>
> On Tue, 28 Nov 2017, Yawar Amin wrote:
>
> > Hi Juli, you can take a lookat https://realworldocaml.
> org/v1/en/html/understanding-the-garbage-collecto
> > r.html for some explanations of the various knobs. Specifically, the
> in-text
> > note sections (marked with the icon of two pages) give some helpful
> hints.
> > The first one on the page is 'Setting the Size of the Minor Heap'.
>
> Is it possible to know when a major GC starts, to be able to measure the
> time spent?  I saw the verbose flag in the control structure, but that
> just prints a message.  I don't see how to get the time.
>
> thanks,
> julia
>
> > Regards,
> >
> > Yawar
> >
> > On Tue, Nov 28, 2017 at 1:11 PM, Julia Lawall <julia.lawall@lip6.fr>
> wrote:
> >       Hello,
> >
> >       Is there any reasonable way to reduce the amount of garbage
> >       collection
> >       activity in an OCaml program?  I see various knobs in the
> >       control
> >       structure, but I don't know what the impact of changing the
> >       values would
> >       be.
> >
> >       thanks,
> >       juli
> >
> >       --
> >       Caml-list mailing list.  Subscription management and archives:
> >       https://sympa.inria.fr/sympa/arc/caml-list
> >       Beginner's list: http://groups.yahoo.com/group/ocaml_beginners
> >       Bug reports: http://caml.inria.fr/bin/caml-bugs
> >
> >
> >
> >
>
> --
> Caml-list mailing list.  Subscription management and archives:
> https://sympa.inria.fr/sympa/arc/caml-list
> Beginner's list: http://groups.yahoo.com/group/ocaml_beginners
> Bug reports: http://caml.inria.fr/bin/caml-bugs
>

[-- Attachment #2: Type: text/html, Size: 3918 bytes --]

Re: [Caml-list] gc overhead

[Julia Lawall]

[-- Attachment #1: Type: text/plain, Size: 2603 bytes --]



On Mon, 11 Dec 2017, Gabriel Scherer wrote:

> There is an instrumentation mode for the OCaml GC whose usage I have described in a blog post and on the caml-list:
>
>   http://prl.ccs.neu.edu/blog/2016/05/24/measuring-gc-latencies-in-haskell-ocaml-racket/
>   https://sympa.inria.fr/sympa/arc/caml-list/2016-05/msg00219.html
>
> (I am realizing that the simple change I proposed, of building the instrumented runtime by default, was forgotten, and will submit a pull request shortly -- hopefully it will be present in 4.07... In the meantime, people have to
> build the compiler with the -with-instrumented-runtime flag explicitly set.)

Thanks for the pointer.

julia

>
> On Mon, Dec 11, 2017 at 7:53 PM, Julia Lawall <julia.lawall@lip6.fr> wrote:
>
>
>       On Tue, 28 Nov 2017, Yawar Amin wrote:
>
>       > Hi Juli, you can take a lookat https://realworldocaml.org/v1/en/html/understanding-the-garbage-collecto
>       > r.html for some explanations of the various knobs. Specifically, the in-text
>       > note sections (marked with the icon of two pages) give some helpful hints.
>       > The first one on the page is 'Setting the Size of the Minor Heap'.
>
>       Is it possible to know when a major GC starts, to be able to measure the
>       time spent?  I saw the verbose flag in the control structure, but that
>       just prints a message.  I don't see how to get the time.
>
>       thanks,
>       julia
>
>       > Regards,
>       >
>       > Yawar
>       >
>       > On Tue, Nov 28, 2017 at 1:11 PM, Julia Lawall <julia.lawall@lip6.fr> wrote:
>       >       Hello,
>       >
>       >       Is there any reasonable way to reduce the amount of garbage
>       >       collection
>       >       activity in an OCaml program?  I see various knobs in the
>       >       control
>       >       structure, but I don't know what the impact of changing the
>       >       values would
>       >       be.
>       >
>       >       thanks,
>       >       juli
>       >
>       >       --
>       >       Caml-list mailing list.  Subscription management and archives:
>       >       https://sympa.inria.fr/sympa/arc/caml-list
>       >       Beginner's list: http://groups.yahoo.com/group/ocaml_beginners
>       >       Bug reports: http://caml.inria.fr/bin/caml-bugs
>       >
>       >
>       >
>       >
>
>       --
>       Caml-list mailing list.  Subscription management and archives:
>       https://sympa.inria.fr/sympa/arc/caml-list
>       Beginner's list: http://groups.yahoo.com/group/ocaml_beginners
>       Bug reports: http://caml.inria.fr/bin/caml-bugs
>
>
>
>

Re: [Caml-list] gc overhead

[Goswin von Brederlow]

Warren Harris <warrensomebody@gmail.com> writes:

> I would like to determine what percentage of my application's cpu time
> is spent in the garbage collector (for tuning purposes, but also just
> to monitor the overhead). Is there any way to obtain this information
> short of using gprof? Additional information provided by Gc.stat would
> be ideal, or perhaps a Gc.alarm that was called at the beginning of
> the gc cycle, but neither of these seem to exist.
>
> Warren

In my code I have a cache structure that implements a last-recently-used
ordering of cached objects. As objects are used the list grows an every
now and then I have to shrink it. It would be real nice if I could
shrink it exactly before evrey GC major cycle or compaction.

I also saw that Gc.alarm is called AFTER each GC cycle. But maybe that
doesn't matter as after a cycle is before a cycle. With the major cycle
being done in increments the next cycle probably starts right after the
last one finished compared to the time the cycle takes overall.

MfG
        Goswin

Re: [Caml-list] gc overhead

[Olivier Andrieu]

[-- Attachment #1: Type: text/plain, Size: 1011 bytes --]

On Mon, Mar 1, 2010 at 01:16, Warren Harris <warrensomebody@gmail.com> wrote:
> I would like to determine what percentage of my application's cpu time is
> spent in the garbage collector (for tuning purposes, but also just to
> monitor the overhead). Is there any way to obtain this information short of
> using gprof? Additional information provided by Gc.stat would be ideal, or
> perhaps a Gc.alarm that was called at the beginning of the gc cycle, but
> neither of these seem to exist.

Here's what I use to measure GC overhead in my programs.
There's a small modification to the runtime, so as to track the time
spent in caml_minor_collection, and a helper ml module. It tracks and
prints the time spent between calls to the start() and stop() function
of the helper module, as well the number of collections, number of
bytes allocated, etc.

It is rather coarse-grained of course. I use it to profile the
different parts of a compiler: parsing, typing, optimizations, code
generation, etc.

-- 
  Olivier

[-- Attachment #2: ocaml-timing.patch --]
[-- Type: text/x-patch, Size: 3058 bytes --]

diff -up ./byterun/sys.h.orig ./byterun/sys.h
--- ./byterun/sys.h.orig	2007-02-25 13:38:36.000000000 +0100
+++ ./byterun/sys.h	2007-10-03 15:42:18.000000000 +0200
@@ -27,4 +27,6 @@ CAMLextern value caml_sys_exit (value);
 
 extern char * caml_exe_name;
 
+double caml_tick (void);
+
 #endif /* CAML_SYS_H */
diff -up ./byterun/minor_gc.c.orig ./byterun/minor_gc.c
--- ./byterun/minor_gc.c.orig	2005-09-22 16:21:50.000000000 +0200
+++ ./byterun/minor_gc.c	2007-10-03 15:42:18.000000000 +0200
@@ -27,6 +27,9 @@
 #include "roots.h"
 #include "signals.h"
 
+#include "alloc.h"
+#include "sys.h"
+
 asize_t caml_minor_heap_size;
 CAMLexport char *caml_young_start = NULL, *caml_young_end = NULL;
 CAMLexport char *caml_young_ptr = NULL, *caml_young_limit = NULL;
@@ -35,6 +38,20 @@ CAMLexport value **caml_ref_table_ptr = 
 static asize_t ref_table_size, ref_table_reserve;
 int caml_in_minor_collection = 0;
 
+static int caml_gc_timing;
+double caml_gc_time = 0.;
+
+CAMLprim value caml_get_gc_time (value unit)
+{
+  return caml_copy_double (caml_gc_time);
+}
+
+CAMLprim value caml_set_gc_timing (value v)
+{
+  caml_gc_timing = Bool_val (v);
+  return Val_unit;
+}
+
 void caml_set_minor_heap_size (asize_t size)
 {
   char *new_heap;
@@ -217,8 +234,13 @@ void caml_empty_minor_heap (void)
 */
 CAMLexport void caml_minor_collection (void)
 {
+  double t_start, t_end;
+
   intnat prev_alloc_words = caml_allocated_words;
 
+  if (caml_gc_timing)
+    t_start = caml_tick ();
+
   caml_empty_minor_heap ();
 
   caml_stat_promoted_words += caml_allocated_words - prev_alloc_words;
@@ -229,6 +251,12 @@ CAMLexport void caml_minor_collection (v
   caml_final_do_calls ();
 
   caml_empty_minor_heap ();
+
+  if (caml_gc_timing) 
+    {
+      t_end = caml_tick ();
+      caml_gc_time += t_end - t_start;
+    }
 }
 
 CAMLexport value caml_check_urgent_gc (value extra_root)
diff -up ./byterun/sys.c.orig ./byterun/sys.c
--- ./byterun/sys.c.orig	2007-03-01 14:37:39.000000000 +0100
+++ ./byterun/sys.c	2007-10-03 15:42:18.000000000 +0200
@@ -344,3 +344,54 @@ CAMLprim value caml_sys_read_directory(v
   caml_ext_table_free(&tbl, 1);
   CAMLreturn(result);
 }
+
+
+#include <math.h>
+static long dumb_gettime (clockid_t i, struct timespec *ts)
+{
+  double t = clock () / (double) CLOCKS_PER_SEC;
+  ts->tv_sec  = t;
+  ts->tv_nsec = (t - floor(t)) * 1e9;
+  return 0;
+}
+
+static long (* gettime)(clockid_t, struct timespec *);
+
+#include <dlfcn.h>
+static void init_gettime ()
+{
+  void *h;
+  h = dlopen ("librt.so", RTLD_LAZY);
+  if (! h)
+    goto fail;
+  dlerror ();
+  *(void **)(&gettime) = dlsym (h, "clock_gettime");
+  if (dlerror () != NULL)
+    {
+      dlclose (h);
+      goto fail;
+    }
+  return;
+
+ fail:
+  gettime = dumb_gettime;
+}
+
+
+double caml_tick ()
+{
+  struct timespec tp;
+
+  if (! gettime)
+    init_gettime();
+
+  if (gettime (CLOCK_PROCESS_CPUTIME_ID, &tp))
+    abort();
+
+  return tp.tv_sec + (1.e-9) * tp.tv_nsec;
+}
+
+CAMLprim value caml_get_tick (value unit)
+{
+  return caml_copy_double (caml_tick ());
+}

[-- Attachment #3: ocaml-timing.ml --]
[-- Type: text/x-ocaml, Size: 3984 bytes --]

let do_timing = 
  try ignore (Sys.getenv "TIMING") ; true
  with Not_found -> false

external set_gc_timing : bool -> unit  = "caml_set_gc_timing" "noalloc"
external get_gc_time   : unit -> float = "caml_get_gc_time"
external get_tick      : unit -> float = "caml_get_tick"

let bpw = float_of_int (Sys.word_size / 8)

let gc_alloc_mem () =
  let s = Gc.quick_stat () in
  let mi = s.Gc.minor_words
  and pr = s.Gc.promoted_words
  and ma = s.Gc.major_words in
  (mi -. pr +. ma) *. bpw,
  s.Gc.heap_words,
  s.Gc.minor_collections, s.Gc.major_collections, s.Gc.compactions







type chrono = {
    mutable tick         : float ;
    mutable gc_tick      : float ;
    mutable gc_alloc     : float ;
    mutable gc_heap      : int ;
    mutable gc_collec_mi : int ;
    mutable gc_collec_ma : int ;
    mutable gc_collec_co : int ;
  }

let make_chrono () = {
  tick         = 0. ;
  gc_tick      = 0. ;
  gc_alloc     = 0. ;
  gc_heap      = 0 ;
  gc_collec_mi = 0 ;
  gc_collec_ma = 0 ;
  gc_collec_co = 0 ;
}


let chrono_start c =
  if do_timing then begin
    c.tick    <- get_tick () ;
    c.gc_tick <- get_gc_time () ;
    let mem, _, mi, ma, co = gc_alloc_mem () in
    c.gc_alloc     <- mem ;
    c.gc_collec_mi <- mi ;
    c.gc_collec_ma <- ma ;
    c.gc_collec_co <- co
  end

let chrono_stop c =
  if do_timing then begin
    c.tick    <- get_tick () -. c.tick ;
    c.gc_tick <- get_gc_time () -. c.gc_tick ;
    let n_mem, h, n_mi, n_ma, n_co = gc_alloc_mem () in
    c.gc_alloc     <- n_mem -. c.gc_alloc ;
    c.gc_heap      <- h ;
    c.gc_collec_mi <- n_mi - c.gc_collec_mi ;
    c.gc_collec_ma <- n_ma - c.gc_collec_ma ;  
    c.gc_collec_co <- n_co - c.gc_collec_co ;
  end

let chrono_accum c1 c2 =
  c1.tick         <- c1.tick +. c2.tick ;
  c1.gc_tick      <- c1.gc_tick +. c2.gc_tick ;
  c1.gc_alloc     <- c1.gc_alloc +. c2.gc_alloc ;
  c1.gc_heap      <- max c1.gc_heap c2.gc_heap ;
  c1.gc_collec_mi <- c1.gc_collec_mi + c2.gc_collec_mi ;
  c1.gc_collec_ma <- c1.gc_collec_ma + c2.gc_collec_ma ;
  c1.gc_collec_co <- c1.gc_collec_co + c2.gc_collec_co






let string_of_time t =
  if t = 0.        then
    "0ms"
  else if t < 1e-3 then
    "<1ms"
  else if t < 1.   then
    Printf.sprintf "%.3fs" t
  else let m = floor (t /. 60.) in
  if m < 1.        then 
    Printf.sprintf "%.2fs" t
  else let s = t -. m *. 60. in
  Printf.sprintf "%.0fm %.2fs" m s

let string_of_mem b =
  let b = int_of_float b in
  let g, b = 
    let v = b / (1 lsl 30) in
    if v > 0 
    then string_of_int v ^ "G ", b - v * (1 lsl 30)
    else "", b in
  let m, b =
    let v = b / (1 lsl 20) in
    if v > 0 
    then g ^ string_of_int v ^ "M ", b - v * (1 lsl 20)
    else g, b in
  let k, b =
    let v = b / (1 lsl 10) in
    if v > 0 
    then m ^ string_of_int v ^ "K ", b - v * (1 lsl 10)
    else m, b in
  let b = 
    if b > 0
    then k ^ string_of_int b 
    else k in
  b

let string_of_memw w =
  string_of_mem (float_of_int w *. bpw)

let string_of_coll c =
  let mi = c.gc_collec_mi
  and ma = c.gc_collec_ma
  and co = c.gc_collec_co in
  let mi = if mi > 0 then string_of_int mi ^ "m " else "" in
  let ma = if ma > 0 then string_of_int ma ^ "M " else "" in
  let co = if co > 0 then string_of_int co ^ "C"  else "" in
  mi ^ ma ^ co


let pp_chrono msg c =
  let tp  = c.tick -. c.gc_tick 
  and tg  = c.gc_tick
  and mem = c.gc_alloc in
  Printf.sprintf
    "%-15s: %8s (GC %-9s, alloc %-20s, heap %-15s, collec %s)"
    msg
    (string_of_time tp) (string_of_time tg)
    (string_of_mem mem) (string_of_memw c.gc_heap)
    (string_of_coll c)

let pp_time msg c =
  if do_timing 
  then prerr_endline (pp_chrono msg c)



let main = 
  make_chrono ()

let start () = 
  chrono_start main

let stop msg =
  chrono_stop main ;
  pp_time msg main


let _ = 
  set_gc_timing do_timing ;
  if do_timing
  then
    at_exit (fun () ->
      let s = Gc.quick_stat () in
      prerr_endline
        ("top_heap_words = " ^ string_of_memw s.Gc.top_heap_words))

[-- Attachment #4: ocaml-timing.mli --]
[-- Type: text/x-ocaml, Size: 257 bytes --]

type chrono
val make_chrono  : unit -> chrono
val chrono_start : chrono -> unit
val chrono_stop  : chrono -> unit
val chrono_accum : chrono -> chrono -> unit
val pp_chrono    : string -> chrono -> string

val start : unit -> unit
val stop  : string -> unit

Re: [Caml-list] gc overhead

[David MENTRE]

Hello Warren,

2010/3/3 Warren Harris <warrensomebody@gmail.com>:
> Thanks, this is excellent info. I've been using both gprof and shark and
> understand the tradeoffs. I really was looking for a way to just provide a
> simple live "gc overhead" number that we could graph along with a bunch of
> other server health stats for our zenoss monitors.

So simply enable gprof on OCaml binaries and look at the total
fraction of time spent in OCaml GC functions!

 http://caml.inria.fr/pub/ml-archives/caml-list/2003/01/e8ee9d44073ff9cb7d257fef86bc8f53.en.html

Best regards,
david

Re: [Caml-list] gc overhead

[Warren Harris]

Peter,

Thanks, this is excellent info. I've been using both gprof and shark  
and understand the tradeoffs. I really was looking for a way to just  
provide a simple live "gc overhead" number that we could graph along  
with a bunch of other server health stats for our zenoss monitors.  
Looks like I'd need to hack my runtime a bit to get this though.

Warren

On Mar 2, 2010, at 4:55 PM, Peter Hawkins wrote:

> Hi...
>
> On Tue, Mar 2, 2010 at 3:08 PM, Warren Harris <warrensomebody@gmail.com 
> > wrote:
>>
>> Peter - gprof with ocaml works quite well:
>> http://caml.inria.fr/pub/docs/manual-ocaml/manual031.html
>
> I'm fully aware of gprof and ocaml's support of profiling.
>
> OCaml's profiling support works by adding calls to the _mcount library
> function at the entry point to every compiled function, which takes
> approximately 10 instructions on x86 (pushes and pops to save
> registers, and a call instruction). The _mcount function records
> function call counts, and is also responsible for producing the call
> graph. Separately, the profile library samples the program counter at
> some frequency, which lets us work out in which functions the program
> is spending its time.
>
> Using OCaml's profiling support has three problems:
> 1) programs compiled with profiling are slower, and
> 2) the profiling instrumentation itself distorts the resulting  
> profile, and
> 3) the call graph accounting is inaccurate.
>
> Let's discuss each of these in turn:
>
> Problem (1) is simply that your program has extra overhead from all of
> those _mcount calls, which occur on every function invocation. You
> can't turn them off, and you can't make them happen less frequently.
> It's an all-or-nothing proposition. It would be unusual to include
> profiling instrumentation in a production system.
>
> Problem (2) is a little more subtle. Recall that the profiling
> instrumentation adds ~10 instructions to the start of each function,
> regardless of its size. For a large function, this may be a negligible
> overhead. For a small function, say one that was only 5 or 10
> instructions in size to begin with, that is a substantial overhead.
> Since we determine how much time is spent in each function by sampling
> the program counter, small and frequently called functions will appear
> to take relatively longer than larger functions in the resulting
> profile. Small functions are common in OCaml code so we should see an
> appreciable amount of distortion.
>
> Problem (3) is a criticism of the _mcount mechanism in general. For
> each function f(), the profiler knows (a) how long we spent executing
> f() in total, and (b) how many times each of f()'s callers invoked
> f(). We do not know how much time f() spent executing on behalf of any
> given caller. If we assume that all of f()'s invocations took
> approximately the same amount of time, then we can use the caller
> counts to approximate the time spent executing f() on behalf of each
> caller. However, the assumption that f() always takes approximately
> the same amount of time is not necessarily a good one. I think it's an
> especially bad assumption in a functional program.
>
> These problems are avoided by using a sampling profiler like oprofile
> or shark, which samples an _uninstrumented_ binary at  a particular
> frequency. Because the binary is unmodified, we can turn profiling on
> and off on a running system, avoiding point (1); furthermore we can
> adjust the sampling rate so profiling overhead is low enough to be
> tolerable. Since there is no instrumentation added to the program, the
> resulting profile does not suffer from the distortion of point (2).
> Some profilers (e.g. shark on Mac OS X) can deal with point (3) as
> well --- all we need to do is record a complete stack trace at
> sampling time.
>
> My point was that oprofile or one of its cousins (e.g. shark) is
> probably adequate for your needs. You can set the sampling rate low
> enough that your service can run more or less as normal. To determine
> GC overhead, you simply need to look at the total amount of time spent
> in the various GC functions of the runtime.
>
> Peter

Re: [Caml-list] gc overhead

[Peter Hawkins]

Hi...

On Tue, Mar 2, 2010 at 3:08 PM, Warren Harris <warrensomebody@gmail.com> wrote:
>
> Peter - gprof with ocaml works quite well:
> http://caml.inria.fr/pub/docs/manual-ocaml/manual031.html

I'm fully aware of gprof and ocaml's support of profiling.

OCaml's profiling support works by adding calls to the _mcount library
function at the entry point to every compiled function, which takes
approximately 10 instructions on x86 (pushes and pops to save
registers, and a call instruction). The _mcount function records
function call counts, and is also responsible for producing the call
graph. Separately, the profile library samples the program counter at
some frequency, which lets us work out in which functions the program
is spending its time.

Using OCaml's profiling support has three problems:
1) programs compiled with profiling are slower, and
2) the profiling instrumentation itself distorts the resulting profile, and
3) the call graph accounting is inaccurate.

Let's discuss each of these in turn:

Problem (1) is simply that your program has extra overhead from all of
those _mcount calls, which occur on every function invocation. You
can't turn them off, and you can't make them happen less frequently.
It's an all-or-nothing proposition. It would be unusual to include
profiling instrumentation in a production system.

Problem (2) is a little more subtle. Recall that the profiling
instrumentation adds ~10 instructions to the start of each function,
regardless of its size. For a large function, this may be a negligible
overhead. For a small function, say one that was only 5 or 10
instructions in size to begin with, that is a substantial overhead.
Since we determine how much time is spent in each function by sampling
the program counter, small and frequently called functions will appear
to take relatively longer than larger functions in the resulting
profile. Small functions are common in OCaml code so we should see an
appreciable amount of distortion.

Problem (3) is a criticism of the _mcount mechanism in general. For
each function f(), the profiler knows (a) how long we spent executing
f() in total, and (b) how many times each of f()'s callers invoked
f(). We do not know how much time f() spent executing on behalf of any
given caller. If we assume that all of f()'s invocations took
approximately the same amount of time, then we can use the caller
counts to approximate the time spent executing f() on behalf of each
caller. However, the assumption that f() always takes approximately
the same amount of time is not necessarily a good one. I think it's an
especially bad assumption in a functional program.

These problems are avoided by using a sampling profiler like oprofile
or shark, which samples an _uninstrumented_ binary at  a particular
frequency. Because the binary is unmodified, we can turn profiling on
and off on a running system, avoiding point (1); furthermore we can
adjust the sampling rate so profiling overhead is low enough to be
tolerable. Since there is no instrumentation added to the program, the
resulting profile does not suffer from the distortion of point (2).
Some profilers (e.g. shark on Mac OS X) can deal with point (3) as
well --- all we need to do is record a complete stack trace at
sampling time.

My point was that oprofile or one of its cousins (e.g. shark) is
probably adequate for your needs. You can set the sampling rate low
enough that your service can run more or less as normal. To determine
GC overhead, you simply need to look at the total amount of time spent
in the various GC functions of the runtime.

Peter

Re: [Caml-list] gc overhead

[Warren Harris]

On Mar 2, 2010, at 1:01 PM, Peter Hawkins wrote:

>
> I would have recommended using oprofile on linux, which I greatly
> prefer to GCC's built-in profiling support for profiling C programs.
> It has a low and tunable overhead, and because it's a sampling
> profiler it doesn't perturb the results anywhere near as much as
> standard profiling instrumentation.
>
> Unfortunately last time I checked it had poor OCaml support (no
> support for unwinding the OCaml call stack, so no context-sensitivity
> in the profiles). That said, you probably don't need
> context-sensitivity to determine the fraction of execution time spent
> in the GC.

Peter - gprof with ocaml works quite well: http://caml.inria.fr/pub/docs/manual-ocaml/manual031.html

Warren

Re: [Caml-list] gc overhead

[Peter Hawkins]

Hi...

On Tue, Mar 2, 2010 at 12:11 PM, Warren Harris <warrensomebody@gmail.com> wrote:
>
> On Mar 1, 2010, at 12:54 AM, Richard Jones wrote:
>
>> On Sun, Feb 28, 2010 at 04:16:03PM -0800, Warren Harris wrote:
>>>
>>> I would like to determine what percentage of my application's cpu time
>>> is spent in the garbage collector (for tuning purposes, but also just
>>> to monitor the overhead). Is there any way to obtain this information
>>> short of using gprof? Additional information provided by Gc.stat would
>>> be ideal, or perhaps a Gc.alarm that was called at the beginning of
>>> the gc cycle, but neither of these seem to exist.
>>
>> I would have to say what's wrong with using gprof?
>
> What's wrong with it is that it provides no way to monitor gc overhead in an
> active service.

I would have recommended using oprofile on linux, which I greatly
prefer to GCC's built-in profiling support for profiling C programs.
It has a low and tunable overhead, and because it's a sampling
profiler it doesn't perturb the results anywhere near as much as
standard profiling instrumentation.

Unfortunately last time I checked it had poor OCaml support (no
support for unwinding the OCaml call stack, so no context-sensitivity
in the profiles). That said, you probably don't need
context-sensitivity to determine the fraction of execution time spent
in the GC.

It might be worth a try...

Peter

Re: [Caml-list] gc overhead

[Warren Harris]

On Mar 1, 2010, at 12:54 AM, Richard Jones wrote:

> On Sun, Feb 28, 2010 at 04:16:03PM -0800, Warren Harris wrote:
>> I would like to determine what percentage of my application's cpu  
>> time
>> is spent in the garbage collector (for tuning purposes, but also just
>> to monitor the overhead). Is there any way to obtain this information
>> short of using gprof? Additional information provided by Gc.stat  
>> would
>> be ideal, or perhaps a Gc.alarm that was called at the beginning of
>> the gc cycle, but neither of these seem to exist.
>
> I would have to say what's wrong with using gprof?

What's wrong with it is that it provides no way to monitor gc overhead  
in an active service.

>
> On a related topic: Has anyone tried using SystemTap with userspace
> DTrace-compatible probes to measure anything about total kernel +
> userspace usage of OCaml programs?  ie, this sort of thing:
>
> http://sourceware.org/systemtap/wiki/AddingUserSpaceProbingToApps
>
> but with OCaml programs.
>
> Rich.
>
> -- 
> Richard Jones
> Red Hat

Re: [Caml-list] gc overhead

[Richard Jones]

On Sun, Feb 28, 2010 at 04:16:03PM -0800, Warren Harris wrote:
> I would like to determine what percentage of my application's cpu time  
> is spent in the garbage collector (for tuning purposes, but also just  
> to monitor the overhead). Is there any way to obtain this information  
> short of using gprof? Additional information provided by Gc.stat would  
> be ideal, or perhaps a Gc.alarm that was called at the beginning of  
> the gc cycle, but neither of these seem to exist.

I would have to say what's wrong with using gprof?

On a related topic: Has anyone tried using SystemTap with userspace
DTrace-compatible probes to measure anything about total kernel +
userspace usage of OCaml programs?  ie, this sort of thing:

http://sourceware.org/systemtap/wiki/AddingUserSpaceProbingToApps

but with OCaml programs.

Rich.

-- 
Richard Jones
Red Hat