Abnormally slow loop (25x) under OCaml 5 / macOS / arm64

[fpottier]

Hello,

I am using macOS Ventura 13.6.7 with an Apple M2 Max processor.

A loop that writes values into an integer array is about 20x slower with OCaml 5 than with OCaml 4.

Using Array.set versus Array.unsafe_set does not make much difference.

If the loop is manually unrolled (5 times) then this surprising slowness disappears.

To reproduce the problem:

git clone git@github.com:fpottier/array_set_loop.git
cd array_set_loop
make test

On OCaml 4.14.2, I get the following (normal) results:

main $ make test
Benchmark 1: _build/default/main.exe
  Time (mean ± σ):      10.6 ms ±   0.1 ms    [User: 9.8 ms, System: 0.6 ms]
  Range (min … max):    10.2 ms …  10.9 ms    281 runs
 
Benchmark 2: _build/default/main.exe --unsafe
  Time (mean ± σ):       8.4 ms ±   0.1 ms    [User: 7.6 ms, System: 0.6 ms]
  Range (min … max):     8.1 ms …   9.1 ms    357 runs
 
Benchmark 3: _build/default/main.exe --unrolled
  Time (mean ± σ):       9.1 ms ±   0.1 ms    [User: 8.3 ms, System: 0.6 ms]
  Range (min … max):     8.9 ms …   9.3 ms    328 runs
 
Benchmark 4: _build/default/main.exe --unsafe --unrolled
  Time (mean ± σ):       7.7 ms ±   0.1 ms    [User: 6.9 ms, System: 0.6 ms]
  Range (min … max):     7.5 ms …   8.2 ms    381 runs
 
Summary
  _build/default/main.exe --unsafe --unrolled ran
    1.09 ± 0.02 times faster than _build/default/main.exe --unsafe
    1.18 ± 0.02 times faster than _build/default/main.exe --unrolled
    1.38 ± 0.02 times faster than _build/default/main.exe

On OCaml 5.x, I get the following abnormal results:

main $ make test
Benchmark 1: _build/default/main.exe
  Time (mean ± σ):     187.3 ms ±  10.9 ms    [User: 184.2 ms, System: 2.8 ms]
  Range (min … max):   155.3 ms … 206.4 ms    30 runs
 
Benchmark 2: _build/default/main.exe --unsafe
  Time (mean ± σ):     191.2 ms ±  11.8 ms    [User: 188.1 ms, System: 2.8 ms]
  Range (min … max):   156.4 ms … 210.7 ms    30 runs
 
Benchmark 3: _build/default/main.exe --unrolled
  Time (mean ± σ):       7.6 ms ±   0.1 ms    [User: 6.8 ms, System: 0.6 ms]
  Range (min … max):     7.4 ms …   8.0 ms    391 runs
 
Benchmark 4: _build/default/main.exe --unsafe --unrolled
  Time (mean ± σ):       7.6 ms ±   0.1 ms    [User: 6.7 ms, System: 0.6 ms]
  Range (min … max):     7.4 ms …   7.9 ms    388 runs
 
Summary
  _build/default/main.exe --unsafe --unrolled ran
    1.01 ± 0.02 times faster than _build/default/main.exe --unrolled
   24.70 ± 1.47 times faster than _build/default/main.exe
   25.22 ± 1.58 times faster than _build/default/main.exe --unsafe

I have tried OCaml 5.0, 5.1, and 5.2, and get similar results.

In the unrolled loop, the safe point (_caml_call_gc) is executed only once every 5 iterations. So, my (uninformed) guess is that somehow, if _caml_call_gc is called too often, it becomes very slow (?).

[gasche]

I cannot reproduce on my Linux (amd64) machine with OCaml 5.1:

Summary
  _build/default/main.exe --unsafe --unrolled ran
    1.18 ± 0.03 times faster than _build/default/main.exe --unsafe
    1.22 ± 0.02 times faster than _build/default/main.exe --unrolled
    1.55 ± 0.04 times faster than _build/default/main.exe

(Note: I bumped the iteration count from 100_000 to 1_000_000, as your choice gives runtimes of 7-12ms, which I think is too short at least on my system where there typically are system-related overheads of the order of 2-3ms.)

[gasche]

I wonder if code-alignment effects could play a role here. Do you observe the same results if you swap the order of the functions in your source file?

Note: unless I am missing something, poll points perform a young-ptr check before calling caml_call_gc, and your benchmark does not actually allocate (or receive stop-the-world events or thread ticks, etc.) so caml_call_gc should in fact never be called in any of your versions. To me this suggests that the surprisingly slowdown may come from microarchitectural effects.

[fpottier]

Yes, the problem is fairly reproducible (stable). If I swap the order of the functions, the problem is the same. In fact, this is a simplified version of a problem that I initially observed while benchmarking vectors (not arrays). The code of the vector library is quite different (more complex) but the weird slowness is there, too.

[fpottier]

Regarding allocation, you are correct, this benchmark does not allocate any memory.

So, I guess you are right: _caml_call_gc is never called. Weird.

[dustanddreams]

Confirmed on a non-mac arm64 system, with the test compiled with trunk being always about 3 times slower than the test compiled with 4.14.1. I'll investigate a bit.

[dustanddreams]

Note that, similarly to @gasche's results, there is no significant difference between the standard and unrolled versions on trunk:

4.14.1

Benchmark 1: _build/default/main.exe
  Time (mean ± σ):      35.1 ms ±   1.3 ms    [User: 29.6 ms, System: 5.0 ms]
  Range (min … max):    32.8 ms …  38.4 ms    82 runs
 
Benchmark 2: _build/default/main.exe --unsafe
  Time (mean ± σ):      31.9 ms ±   1.5 ms    [User: 26.0 ms, System: 5.4 ms]
  Range (min … max):    29.1 ms …  34.7 ms    96 runs
 
Benchmark 3: _build/default/main.exe --unrolled
  Time (mean ± σ):      26.7 ms ±   1.4 ms    [User: 20.9 ms, System: 5.3 ms]
  Range (min … max):    24.4 ms …  29.8 ms    111 runs
 
Benchmark 4: _build/default/main.exe --unsafe --unrolled
  Time (mean ± σ):      23.7 ms ±   1.2 ms    [User: 18.0 ms, System: 5.1 ms]
  Range (min … max):    21.0 ms …  27.6 ms    131 runs
 
Summary
  _build/default/main.exe --unsafe --unrolled ran
    1.13 ± 0.08 times faster than _build/default/main.exe --unrolled
    1.35 ± 0.09 times faster than _build/default/main.exe --unsafe
    1.48 ± 0.09 times faster than _build/default/main.exe

5.3.0+trunk

Benchmark 1: _build/default/main.exe
  Time (mean ± σ):      92.2 ms ±   1.6 ms    [User: 84.5 ms, System: 7.0 ms]
  Range (min … max):    89.4 ms …  95.8 ms    33 runs
 
Benchmark 2: _build/default/main.exe --unsafe
  Time (mean ± σ):      93.1 ms ±   1.5 ms    [User: 86.4 ms, System: 6.0 ms]
  Range (min … max):    90.6 ms …  95.7 ms    32 runs
 
Benchmark 3: _build/default/main.exe --unrolled
  Time (mean ± σ):      92.7 ms ±   1.7 ms    [User: 85.6 ms, System: 6.4 ms]
  Range (min … max):    89.3 ms …  96.0 ms    31 runs
 
Benchmark 4: _build/default/main.exe --unsafe --unrolled
  Time (mean ± σ):      92.8 ms ±   1.7 ms    [User: 85.3 ms, System: 6.7 ms]
  Range (min … max):    89.8 ms …  96.3 ms    32 runs
 
Summary
  _build/default/main.exe ran
    1.01 ± 0.03 times faster than _build/default/main.exe --unrolled
    1.01 ± 0.02 times faster than _build/default/main.exe --unsafe --unrolled
    1.01 ± 0.02 times faster than _build/default/main.exe --unsafe

[gasche]

@dustanddreams so you observe a performance difference between 5.2 and trunk?

There is a large absolute difference between your 4.14 and trunk numbers (~30ms on 4.14, ~90ms on trunk), is the benchmark 3x slower on trunk or are you using different parameters?

[dustanddreams]

Yes, there is a 3x slowdown between 4.14 and trunk (of a few days ago). I didn't tune anything.

[gasche]

On my (Linux, amd64) system there is no such difference between 4.14 and 5.1.

Summary
  5.1 unsafe, unrolled ran
    1.06 ± 0.03 times faster than 4.14 unsafe, unrolled
    1.25 ± 0.04 times faster than 5.1 unsafe
    1.26 ± 0.04 times faster than 4.14 unsafe
    1.30 ± 0.03 times faster than 4.14 unrolled
    1.32 ± 0.04 times faster than 5.1 unrolled
    1.63 ± 0.04 times faster than 4.14
    1.66 ± 0.04 times faster than 5.1

(My version of the benchmark is at https://github.com/gasche/array_set_loop ; I use dune-workspace to easily compare across two OCaml versions, but the specific opam switches I am using are set in stone so it probably requires some search-and-replace to adapt for you. Oh and @fpottier, witness the glorious -n / --command-name option to give a name to the benchmark that is more pleasant than the command-line itself: hyperfine $CMD1 -n name1 $CMD2 -n name2 ....)

[dustanddreams]

Comparing the 4.14 generated code to the 5.x generated code, the changes I see are:

• explicit stack usage checking at the beginning of every function call in 5.x (since 5.x can not rely upon the operating system to grow the stack automagically as it expands). This sounds like an easy culprit, but removing these checks does not create a significant difference.
• some of the variables being accessed are marked as atomic in 5.x, which causes synchronisation barriers (dsb instructions) to be added. Removing them does not create a significant difference.
• initialization of the array (Array.make) is done with caml_make_vect in 4.x and caml_array_make in 5.x in function init, but that's only a name change, the code is unchanged otherwise.
• a bunch of explicit calls to caml_initialize at the beginning of the program.

The code is a bit larger, which can of course hurt wrt cache usage, but there doesn't seem to be something responsible for a 3x slowdown.

[dustanddreams]

Regarding allocation, you are correct, this benchmark does not allocate any memory.

So, I guess you are right: _caml_call_gc is never called. Weird.

This is wrong - on 4.14, it never gets called, in 5.x. it gets called once before the first output:

#0  0x0000aaaaaabbec70 in caml_call_gc ()
#1  0x0000aaaaaab7600c in camlStdlib__Printf.kfprintf_322 () at printf.ml:20
#2  0x0000aaaaaab31048 in camlDune__exe__Main.chrono_320 ()
#3  0x0000aaaaaab31230 in camlDune__exe__Main.benchmark_set_599 ()
#4  0x0000aaaaaab319ac in camlDune__exe__Main.entry ()

[gasche]

I think that "a constant number of time" and "never" are similar for performance analysis. For example I wondered if it could be the case that some active security system would somehow notice unexpected behavior around the caml_call_gc call (stack switching that it would consider suspicious activity or what not), and slow down the program due to this reason, but here nothing like this should be at play that is provoked by caml_call_gc.

[dustanddreams]

You're right. I've timed that single caml_call_gc and it does not account for the 60msec difference.

[fpottier]

I have experimented with another loop, a small blit loop. It exhibits a similar phenomenon.

This example is interesting, because

• in OCaml 5, adding a type annotation makes the code 34 times slower (monomorphic blit is 34 times slower than polymorphic blit).
• the code of monomorphic blit is the same in OCaml 4 and in OCaml 5, except for the memory barrier.
• in OCaml 5, unrolling the loop 5 times removes the slowness.

The code is here:

  git clone git@github.com:fpottier/array_blit.git
  cd array_blit
  make test

With OCaml 4.14.2, I get the following (normal) results:

main $ make test
Benchmark 1: polymorphic array blit
  Time (mean ± σ):      56.3 ms ±   1.7 ms    [User: 54.4 ms, System: 1.6 ms]
  Range (min … max):    54.2 ms …  58.8 ms    54 runs

Benchmark 2: monomorphic array blit
  Time (mean ± σ):      14.2 ms ±   0.1 ms    [User: 13.2 ms, System: 0.8 ms]
  Range (min … max):    14.0 ms …  15.1 ms    208 runs

Summary
  monomorphic array blit ran
    3.95 ± 0.13 times faster than polymorphic array blit

With OCaml 5.2, I get the following abnormal results:

main $ make test
Benchmark 1: polymorphic array blit
  Time (mean ± σ):      55.0 ms ±   0.2 ms    [User: 53.2 ms, System: 1.5 ms]
  Range (min … max):    54.5 ms …  55.3 ms    54 runs

Benchmark 2: monomorphic array blit
  Time (mean ± σ):     485.9 ms ±  83.8 ms    [User: 473.7 ms, System: 11.7 ms]
  Range (min … max):   374.1 ms … 663.2 ms    30 runs

Summary
  polymorphic array blit ran
    8.84 ± 1.52 times faster than monomorphic array blit

In short, the monomorphic blit is 34 times slower in OCaml 5 than it was in OCaml 4.

Now, the interesting thing is, the code produced by OCaml 4 and by OCaml 5 is exactly the same, except OCaml 5 inserts a memory barrier instruction dmb ishld before the store instruction. Here is the code produced by OCaml 5:

	.globl	_camlDune__exe__Main.blit_mono_605
_camlDune__exe__Main.blit_mono_605:
	.cfi_startproc
	sub	sp, sp, #16
	.cfi_adjust_cfa_offset	16
	.cfi_offset 30, -8
	str	x30, [sp, #8]
L142:
	ldr	x2, [x0, #-8]
	lsr	x3, x2, #9
	orr	x4, x3, #1
	orr	x5, xzr, #1
L141:
	cmp	x5, x4
	b.ge	L140
	add	x7, x1, x5, lsl #2
	add	x8, x0, x5, lsl #2
	ldr	x9, [x8, #-4]
	dmb	ishld
	str	x9, [x7, #-4]
	add	x5, x5, #2
	ldr	x16, [x28, #0]
	cmp	x27, x16
	b.hi	L141
	b	L144
L140:
	orr	x0, xzr, #1
	ldr	x30, [sp, #8]
	add	sp, sp, #16
	.cfi_adjust_cfa_offset	-16
	ret
	.cfi_adjust_cfa_offset	16
L144:	bl	_caml_call_gc
L143:	b	L141
	.cfi_endproc

If the loop in blit_mono is unrolled 2 or 4 times, then (with OCaml 5) it is still abnormally slow. However, if it is unrolled 5 times, then it becomes fast again.

[dustanddreams]

I have been doing about the same experiments.

It turns out that, when I said disabling the dmb instruction did not produce any significant change, I had only disabled the load barrier, not the store barrier. With it correctly disabled (asmcomp/arm64/emit.mlp line 827), the 5.x performance gets very close to 4.x:

Benchmark 1: _build/default/main.exe
  Time (mean ± σ):      36.9 ms ±   1.3 ms    [User: 30.5 ms, System: 5.8 ms]
  Range (min … max):    35.2 ms …  40.5 ms    84 runs
 
Benchmark 2: _build/default/main.exe --unsafe
  Time (mean ± σ):      32.5 ms ±   1.5 ms    [User: 25.3 ms, System: 6.7 ms]
  Range (min … max):    29.7 ms …  35.1 ms    95 runs
 
Benchmark 3: _build/default/main.exe --unrolled
  Time (mean ± σ):      29.0 ms ±   1.3 ms    [User: 21.8 ms, System: 6.7 ms]
  Range (min … max):    26.6 ms …  32.2 ms    109 runs
 
Benchmark 4: _build/default/main.exe --unsafe --unrolled
  Time (mean ± σ):      23.7 ms ±   1.1 ms    [User: 16.3 ms, System: 7.0 ms]
  Range (min … max):    21.7 ms …  29.1 ms    128 runs
 
Summary
  _build/default/main.exe --unsafe --unrolled ran
    1.22 ± 0.08 times faster than _build/default/main.exe --unrolled
    1.37 ± 0.09 times faster than _build/default/main.exe --unsafe
    1.55 ± 0.09 times faster than _build/default/main.exe