Example in README cannot read the last entry in the append only log

[Exadra37]

First, thanks for this project :)

While playing with i found that I always fail to read the last entry in the log.

Running this code:

dir = Path.join(".examples", EventLog.Utils.random_string(16))

{:ok, log} = EventLog.start_link(dir)
{:ok, _} = EventLog.create_stream(log, "my_stream")

EventLog.append(log, "my_stream", "foo0")
EventLog.append(log, "my_stream", "foo1")
EventLog.append(log, "my_stream", "foo2")

# :timer.sleep(2000)

# read from beginning
{:ok, reader} = EventLog.get_reader(log, "my_stream")

EventLog.Reader.get_next(reader) |> IO.inspect
EventLog.Reader.get_next(reader) |> IO.inspect
EventLog.Reader.get_next(reader) |> IO.inspect

EventLog.Reader.get_next(reader) |> IO.inspect # no more entries

# read from offset=2
{:ok, reader} = EventLog.get_reader(log, "my_stream", 2)
EventLog.Reader.get_next(reader)

# read all entries
EventLog.Reader.get_batch(reader, 0, 3) |> IO.inspect

EventLog.close(log)

outputs this:

20:47:45.503 [info]  init, opts: [max_seg_size: 1073741824]

20:47:45.504 [debug] dir: .examples/V6KaYgoOKPEKxv1n/my_stream, opts: [max_seg_size: 1073741824]

20:47:45.511 [debug] {".examples/V6KaYgoOKPEKxv1n/my_stream/00000000000000000000.seg", -1, 0}
{:ok, {0, "foo0", 1608497265517, 0, 795769153}}
{:ok, {1, "foo1", 1608497265517, 0, 1483295191}}
{:ok, :eof}
{:ok, :eof}
[
  {0, "foo0", 1608497265517, 0, 795769153},
  {1, "foo1", 1608497265517, 0, 1483295191}
]

As we can see the foo2 doesn't exist in the append only log, instead we find the end of the file.

Now if we sleep for 2 seconds, :timer.sleep(2000)(line 10) we can read it:

20:51:17.327 [info]  init, opts: [max_seg_size: 1073741824]

20:51:17.329 [debug] dir: .examples/DJ5MMl_kCwfeWddQ/my_stream, opts: [max_seg_size: 1073741824]

20:51:17.336 [debug] {".examples/DJ5MMl_kCwfeWddQ/my_stream/00000000000000000000.seg", -1, 0}
{:ok, {0, "foo0", 1608497477342, 0, 795769153}}
{:ok, {1, "foo1", 1608497477342, 0, 1483295191}}
{:ok, {2, "foo2", 1608497477345, 0, 3244300397}}
{:ok, :eof}
[
  {0, "foo0", 1608497477342, 0, 795769153},
  {1, "foo1", 1608497477342, 0, 1483295191},
  {2, "foo2", 1608497477345, 0, 3244300397}
]

I think this to to the Linux write cache being enabled by default in the OS, therefore the writes are not flushed from the cache to the disk immediately.

Disabling the Linux write cache could resolve this as per this article:

Not all system's belong to the same "turn-on write-back caching" recommendation group as write-back caching caries a risk of data loss in the event such as power failure etc. In the event of power failure, data residing in the hard drive's cache do not get a chance to be stored and a lost. This fact is especially important for database system. In order to disable write-back caching set write-caching to 0:

# hdparm -W0 /dev/sda

/dev/sda:
setting drive write-caching to 0 (off)
write-caching =  0 (off)

I will later test this in a server, not in my Laptop and will update the issue.

[pbudzik]

Thank you Paulo. Would you create a Pull Request with a fix for this issue?

[Exadra37]

I found that the 2 seconds delay is due to this line of code:

eventlog/lib/event_log/appender.ex

Line 9 in 1db572f

@write_mode [:append, :binary, :delayed_write]

The delayed_write defaults to 2 seconds, as per the Erlang docs for the function to open a file:

delayed_write

The same as {delayed_write, Size, Delay} with reasonable default values for Size and Delay (roughly some 64 KB, 2 seconds).

Changing this value for less then 2 seconds may have an impact in throughput, depending if the delayed write is triggered by exceeding the size or the time for the delay.

You can play with different values with this module:

defmodule FileIO do
  
  @moduledoc """
  iex> fd = FileIO.open! "test.txt"                             
  #PID<0.292.0>
  iex> FileIO.append!(fd, "test it") && FileIO.read!("test.txt")
  "test it\n"
  iex> FileIO.close fd                                          
  :ok
  """

  @write_mode [:append, :binary]
  # @write_mode [:append, :binary, :delayed_write]
  # @write_mode [:append, :binary, {:delayed_write, 1, 1}]

  def open!(path, write_mode \\ @write_mode) do
    File.open!(path, write_mode)
  end

  def close(file_descriptor) do
    File.close(file_descriptor)
  end

  def append!(file_descriptor, data) do
    {:ok, start_position} = :file.position(file_descriptor, :cur)

    :ok = IO.binwrite(file_descriptor, "#{data}\n")

    {:ok, end_position} = :file.position(file_descriptor, :cur)

    %{
      file_descriptor: file_descriptor,
      start_position: start_position,
      end_position: end_position,
      size: byte_size(data)
    }
  end

  def read!(path) do
    {:ok, data} = :file.read_file(path)
    data
  end
end

I would recommend to make it configurable [:append, :binary, {:delayed_write, 1, 1}].

For example we could change in appender.ex the start_link/2 to:

  def start_link(dir, opts \\ [max_seg_size: @max_seg_size, write_mode: @write_mode]) do
    GenServer.start_link(__MODULE__, [dir, opts])
  end

   def init([dir, opts]) do
     ...
      fd = File.open!(seg_path, opts[:write_mode])
     ...
   end

So, how would you like to proceed?