diff --git a/.formatter.exs b/.formatter.exs new file mode 100644 index 0000000..d2cda26 --- /dev/null +++ b/.formatter.exs @@ -0,0 +1,4 @@ +# Used by "mix format" +[ + inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"] +] diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml new file mode 100644 index 0000000..82ed752 --- /dev/null +++ b/.github/workflows/ci.yml @@ -0,0 +1,48 @@ +name: CI + +on: + pull_request: + push: + branches: + - main + +jobs: + test: + runs-on: ubuntu-20.04 + env: + MIX_ENV: test + strategy: + fail-fast: false + matrix: + include: + - pair: + elixir: 1.15.0 + otp: 26.0.1 + lint: lint + steps: + - uses: actions/checkout@v2 + + - uses: erlef/setup-beam@v1 + with: + otp-version: ${{matrix.pair.otp}} + elixir-version: ${{matrix.pair.elixir}} + + - name: Install Dependencies + run: mix deps.get --only test + + - run: mix format --check-formatted + if: ${{ matrix.lint }} + + - run: mix deps.get && mix deps.unlock --check-unused + if: ${{ matrix.lint }} + + - run: mix deps.compile + + - run: mix compile --warnings-as-errors + if: ${{ matrix.lint }} + + - run: mix credo + + - run: mix test + + - run: mix dialyzer --unmatched_returns diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..b263cd1 --- /dev/null +++ b/.gitignore @@ -0,0 +1,10 @@ +/_build +/cover +/deps +/doc +/.fetch +erl_crash.dump +*.ez +*.beam +/config/*.secret.exs +.elixir_ls/ diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..942e911 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,7 @@ +# Changelog for Jop + + + +## v0.1.0 (2023-12-02) + + * First release. diff --git a/README.md b/README.md new file mode 100644 index 0000000..ae51114 --- /dev/null +++ b/README.md @@ -0,0 +1,117 @@ +# JOP: an in-memory key value logger +[![Test](https://github.com/bougueil/jop_ex/actions/workflows/ci.yml/badge.svg)](https://github.com/bougueil/jop_ex/actions/workflows/ci.yml) + +Logs in memory, spatially and temporally, key value events.
+These events, generated by multiple processes, are then flushed to disk for analysis (e.g. to detect locks). + + +## Installation + + +```elixir +def deps do + [ + {:jop_ex, git: "https://github.com/bougueil/jop_ex"} + ] +end +``` + +## Usage +``` + iex> "myjop" + ...> |> Jop.init() + ...> |> Jop.log("key_1", :any_term_112) + ...> |> Jop.log("key_2", :any_term_133) + ...> |> Jop.flush() +log stored in jop_myjop.2020_05_12_21.42.49_dates.gz +log stored in jop_myjop.2020_05_12_21.42.49_keys.gz +#Jop +``` + +## Performance +Excerpt from a run of the unit test : +``` +througput 1267456 logs/s. +``` + +## Basic example +``` +# prepare for logging and return a handle +myjop = Jop.init("myjop") + +# log with handle event "key_1", :any_term_112 +Jop.log myjop, "key_1", :any_term_112 +Process.sleep 12 + +# clear logs +Jop.clear myjop + +Jop.log myjop, "key_2", :any_term_113 +Process.sleep 12 + +Jop.log myjop, "key_1", :any_term_112 +Process.sleep 12 + +Jop.log myjop, "key_2", :any_term_113 +# flush to disk and erase the log +Jop.flush myjop + +log stored in jop_myjop.2020_05_12_21.42.49_dates.gz +log stored in jop_myjop.2020_05_12_21.42.49_keys.gz +#Jop +``` +will generate both a temporal (by date) and a spatial (by key) log files: + +### Temporal log file +``` +# list all operations by date +zcat jop_myjop.2020_05_12_21.42.49_dates.gz + +00:00:00_000.482 "key_2": :any_term_113 +00:00:00_014.674 "key_1": :any_term_112 +00:00:00_028.568 "key_2": :any_term_113 + +``` + +### Spatial (by key) log file +``` +# list all operations by key : +zcat jop_myjop.2020_05_12_21.42.49_keys.gz + +"key_1": 00:00:00_014.674 :any_term_112 +"key_2": 00:00:00_000.482 :any_term_113 +"key_2": 00:00:00_028.568 :any_term_113 +``` +## Real life: multiple processes logging +Processes log in myjop as follow: +``` +# Handle can be saved in process state +myjop = Jop.ref("myjop") + +# Log if logging is activated +Jop.log myjop, "key_1", :any_term_112 +``` +Console activate / deactivate the logging: +``` +# Activate the logging +# Starts the logging +myjop = Jop.init("myjop") + +# Do some queries while the logging is on +inspect myjop # see how many records +Enum.count mylog +Enum.member? mylog, "mykey" + ... + +# Flush the logs on disk, keep on logging +Jop.flush myjop, :nostop + +# Clear the logs, keep on logging +Jop.clear myjop # clear all entries and continue logging + +# Flush the logs on disk and deactivate the logging +Jop.flush myjop + +# Start logging again +Jop.init("myjop") +``` \ No newline at end of file diff --git a/config/config.exs b/config/config.exs new file mode 100644 index 0000000..dd82180 --- /dev/null +++ b/config/config.exs @@ -0,0 +1,7 @@ +import Config + +# https://spapas.github.io/2020/05/15/elixir-osmon-alerts/ +# config :os_mon, +# memsup_system_only: true, +# start_disk_sup: false, +# start_cpu_sup: false diff --git a/lib/common.ex b/lib/common.ex new file mode 100644 index 0000000..1bc1203 --- /dev/null +++ b/lib/common.ex @@ -0,0 +1,39 @@ +# See LICENSE for licensing information. + +defmodule JLValid do + @moduledoc false + + defmacro ets?(tab, clauses) do + valid_if(tab, clauses) + end + + defp valid_if(tab, do: do_clause) do + valid_if(tab, do: do_clause, else: nil) + end + + defp valid_if(tab, do: do_clause, else: else_clause) do + quote do + case :undefined != :ets.info(unquote(tab), :size) do + x when :"Elixir.Kernel".in(x, [false, nil]) -> unquote(else_clause) + _ -> unquote(do_clause) + end + end + end +end + +defmodule JLCommon do + @moduledoc false + + @date_format ".~p_~2.2.0w_~2.2.0w_~2.2.0w.~2.2.0w.~2.2.0w" + + def date_str do + hms = + List.flatten( + for e <- Tuple.to_list(:calendar.universal_time_to_local_time(:calendar.universal_time())) do + Tuple.to_list(e) + end + ) + + :io_lib.format(@date_format, hms) + end +end diff --git a/lib/jop_log.ex b/lib/jop_log.ex new file mode 100644 index 0000000..5be89e6 --- /dev/null +++ b/lib/jop_log.ex @@ -0,0 +1,180 @@ +# See LICENSE for licensing information. + +defmodule Jop do + require JLValid + @tag_start "jop_start" + + @moduledoc """ + Documentation for Jop an in memory log + + ## Example + + iex> "mylog" + ...> |> Jop.init() + ...> |> Jop.log("device_1", data: 112) + ...> |> Jop.log("device_2", data: 113) + ...> |> Jop.flush() + + """ + + defstruct [:ets] + @type t :: %__MODULE__{ets: atom()} + + @doc """ + Initialize Jop with a log name. + returns a handle %Joplog{} + """ + @spec init(log_name :: binary()) :: Jop.t() + def init(log_name) when is_binary(log_name) do + tab = String.to_atom(log_name) + + JLValid.ets? tab do + Jop.ref(log_name) + |> reset() + end + + _ = :ets.new(tab, [:bag, :named_table, :public]) + + joplog = Jop.ref(log_name) + + IO.puts("Jop now logging on memory joplog #{joplog.ets}.") + log(joplog, @tag_start, "#{JLCommon.date_str()}") + end + + @doc """ + returns a handle from a log name + does not require JOP doesn't require init/1 + """ + @spec ref(log_name :: String.t()) :: Jop.t() + def ref(log_name) when is_binary(log_name) do + tab = String.to_atom(log_name) + + %Jop{ets: tab} + end + + @doc """ + log with the handle jop a key and its value + returns the handle. + """ + @spec log(Jop.t(), any, any) :: Jop.t() + def log(%Jop{ets: tab} = jop, key, value) do + JLValid.ets?(tab, do: :ets.insert(tab, {key, value, now_μs()})) + jop + end + + @doc """ + write a joplog on disk from a handle. + 2 logs are generated : dates.gz and keys.gz + unless option :notstop is used, logging is stopped. + """ + @spec flush(Jop.t(), opt :: atom) :: Jop.t() + def flush(%Jop{ets: tab} = joplog, opt \\ nil) do + JLValid.ets? tab do + {logs, t0} = + case lookup_tag_start(tab) do + nil -> + {[], 0} + + t0 -> + {:ets.tab2list(tab), t0} + end + + if opt == :nostop do + IO.puts( + "Jop continue logging.\nflushing memory joplog #{tab} (#{Enum.count(joplog)} records) on files ..." + ) + + clear(joplog) + else + IO.puts( + "Jop logging stopped.\nflushing memory joplog #{tab} (#{Enum.count(joplog)} records) on files ..." + ) + + reset(joplog) + end + + JL.Writer.flush(tab, t0, logs) + end + + joplog + end + + defp reset(%Jop{ets: tab}), + do: JLValid.ets?(tab, do: :ets.delete(tab)) + + defp lookup_tag_start(tab) do + case :ets.lookup(tab, @tag_start) do + [{_, _, t0}] -> + t0 + + [] -> + nil + end + end + + @doc """ + erase all entries from the jop handle + """ + @spec clear(Jop.t()) :: Jop.t() + def clear(%Jop{ets: tab} = jop) do + JLValid.ets? tab do + t0 = lookup_tag_start(tab) + :ets.delete_all_objects(tab) + + if t0 do + :ets.insert(tab, {@tag_start, t0, now_μs()}) + end + end + + jop + end + + defp now_μs, do: System.monotonic_time(:microsecond) + + @doc """ + returns if the handle is initialized with an ets table + """ + def is_initialized(%Jop{ets: tab}), + do: JLValid.ets?(tab, do: true, else: false) + + defimpl Enumerable do + @doc """ + returns the size of the Jop log + """ + def count(%Jop{ets: tab}) do + {:ok, max(0, :ets.info(tab, :size) - 1)} + end + + @doc """ + returns if `key`is member of Jop + """ + @spec member?(Jop.t(), any) :: {:ok, boolean} + def member?(%Jop{ets: tab}, key) do + {:ok, :ets.member(tab, key)} + end + + def reduce(%Jop{ets: tab}, acc, fun) do + :ets.tab2list(tab) + |> List.keysort(2) + |> Enum.drop(1) + |> Enum.map(fn {k, v, _t} -> {k, v} end) + |> Enumerable.List.reduce(acc, fun) + end + + def slice(_id) do + {:error, __MODULE__} + end + end + + defimpl Inspect do + import Inspect.Algebra + + def inspect(%Jop{ets: tab} = jop, opts) do + JLValid.ets? tab do + concat(["#Jop<#{tab}:size(", to_doc(Enum.count(jop), opts), ")>"]) + else + concat(["#Jop<#{tab}:uninitialized>"]) + end + end + end +end diff --git a/lib/writer.ex b/lib/writer.ex new file mode 100644 index 0000000..cbd8d29 --- /dev/null +++ b/lib/writer.ex @@ -0,0 +1,49 @@ +# See LICENSE for licensing information. + +defmodule JL.Writer do + @moduledoc false + + @usecond_format "~2.2.0w:~2.2.0w:~2.2.0w_~3.3.0w.~3.3.0w" + + defp fname(tab, ext), do: ["jop_#{tab}", JLCommon.date_str(), "_", ext] + + defp fmt_duration_us(duration_us) do + sec = div(duration_us, 1_000_000) + rem_us = rem(duration_us, 1_000_000) + ms = div(rem_us, 1000) + us = rem(rem_us, 1000) + {_, {h, m, s}} = :calendar.gregorian_seconds_to_datetime(sec) + :io_lib.format(@usecond_format, [h, m, s, ms, us]) + end + + def flush(tab, t0, logs) do + names = for f <- ~w(dates keys), do: fname(tab, "#{f}.gz") + [fa, fb] = for name <- names, do: File.open!(name, [:write, :compressed, encoding: :unicode]) + + # factorize + # flush log to the 'temporal' log file + awaits = [ + {Task.async(fn -> + for {k, op, t} <- List.keysort(logs, 2) do + IO.puts(fa, "#{fmt_duration_us(t - t0)} #{inspect(k)}: #{inspect(op)}") + end + end), fa}, + # flush log to 'spatial' log file + {Task.async(fn -> + for {k, op, t} <- List.keysort(logs, 0) do + IO.puts(fb, "#{inspect(k)}: #{fmt_duration_us(t - t0)} #{inspect(op)}") + end + end), fb} + ] + + for {task, fd} <- awaits, + do: + ( + Task.await(task, :infinity) + _ = File.close(fd) + ) + + IO.puts("log stored in :") + for name <- names, do: IO.puts("- #{name}") + end +end diff --git a/mix.exs b/mix.exs new file mode 100644 index 0000000..d05a9e6 --- /dev/null +++ b/mix.exs @@ -0,0 +1,46 @@ +defmodule Jop.Mixfile do + use Mix.Project + + @version "0.1.0" + def project do + [ + app: :jop, + version: @version, + elixir: ">= 1.14.1", + package: package(), + start_permanent: Mix.env() == :prod, + deps: deps(), + docs: [ + main: "Superls", + source_ref: "v#{@version}", + source_url: "https://github.com/bougueil/superls" + ] + ] + end + + def application do + [ + extra_applications: [ + :logger + # , :os_mon + ] + ] + end + + # Run "mix help deps" to learn about dependencies. + defp deps do + [ + {:ex_doc, "~> 0.30", only: [:docs, :test], runtime: false}, + {:dialyxir, "~> 1.2", only: [:dev, :test], runtime: false}, + {:credo, "~> 1.6", only: [:dev, :test], runtime: false} + ] + end + + defp package do + %{ + licenses: ["Apache-2.0"], + maintainers: ["Renaud Mariana"], + links: %{"GitHub" => "https://github.com/bougueil/jop"} + } + end +end diff --git a/mix.lock b/mix.lock new file mode 100644 index 0000000..14fa243 --- /dev/null +++ b/mix.lock @@ -0,0 +1,14 @@ +%{ + "bunt": {:hex, :bunt, "0.2.1", "e2d4792f7bc0ced7583ab54922808919518d0e57ee162901a16a1b6664ef3b14", [:mix], [], "hexpm", "a330bfb4245239787b15005e66ae6845c9cd524a288f0d141c148b02603777a5"}, + "credo": {:hex, :credo, "1.7.1", "6e26bbcc9e22eefbff7e43188e69924e78818e2fe6282487d0703652bc20fd62", [:mix], [{:bunt, "~> 0.2.1", [hex: :bunt, repo: "hexpm", optional: false]}, {:file_system, "~> 0.2.8", [hex: :file_system, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: false]}], "hexpm", "e9871c6095a4c0381c89b6aa98bc6260a8ba6addccf7f6a53da8849c748a58a2"}, + "dialyxir": {:hex, :dialyxir, "1.4.2", "764a6e8e7a354f0ba95d58418178d486065ead1f69ad89782817c296d0d746a5", [:mix], [{:erlex, ">= 0.2.6", [hex: :erlex, repo: "hexpm", optional: false]}], "hexpm", "516603d8067b2fd585319e4b13d3674ad4f314a5902ba8130cd97dc902ce6bbd"}, + "earmark_parser": {:hex, :earmark_parser, "1.4.39", "424642f8335b05bb9eb611aa1564c148a8ee35c9c8a8bba6e129d51a3e3c6769", [:mix], [], "hexpm", "06553a88d1f1846da9ef066b87b57c6f605552cfbe40d20bd8d59cc6bde41944"}, + "erlex": {:hex, :erlex, "0.2.6", "c7987d15e899c7a2f34f5420d2a2ea0d659682c06ac607572df55a43753aa12e", [:mix], [], "hexpm", "2ed2e25711feb44d52b17d2780eabf998452f6efda104877a3881c2f8c0c0c75"}, + "ex_doc": {:hex, :ex_doc, "0.30.9", "d691453495c47434c0f2052b08dd91cc32bc4e1a218f86884563448ee2502dd2", [:mix], [{:earmark_parser, "~> 1.4.31", [hex: :earmark_parser, repo: "hexpm", optional: false]}, {:makeup_elixir, "~> 0.14", [hex: :makeup_elixir, repo: "hexpm", optional: false]}, {:makeup_erlang, "~> 0.1", [hex: :makeup_erlang, repo: "hexpm", optional: false]}], "hexpm", "d7aaaf21e95dc5cddabf89063327e96867d00013963eadf2c6ad135506a8bc10"}, + "file_system": {:hex, :file_system, "0.2.10", "fb082005a9cd1711c05b5248710f8826b02d7d1784e7c3451f9c1231d4fc162d", [:mix], [], "hexpm", "41195edbfb562a593726eda3b3e8b103a309b733ad25f3d642ba49696bf715dc"}, + "jason": {:hex, :jason, "1.4.1", "af1504e35f629ddcdd6addb3513c3853991f694921b1b9368b0bd32beb9f1b63", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "fbb01ecdfd565b56261302f7e1fcc27c4fb8f32d56eab74db621fc154604a7a1"}, + "makeup": {:hex, :makeup, "1.1.1", "fa0bc768698053b2b3869fa8a62616501ff9d11a562f3ce39580d60860c3a55e", [:mix], [{:nimble_parsec, "~> 1.2.2 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "5dc62fbdd0de44de194898b6710692490be74baa02d9d108bc29f007783b0b48"}, + "makeup_elixir": {:hex, :makeup_elixir, "0.16.1", "cc9e3ca312f1cfeccc572b37a09980287e243648108384b97ff2b76e505c3555", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.2.3 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "e127a341ad1b209bd80f7bd1620a15693a9908ed780c3b763bccf7d200c767c6"}, + "makeup_erlang": {:hex, :makeup_erlang, "0.1.2", "ad87296a092a46e03b7e9b0be7631ddcf64c790fa68a9ef5323b6cbb36affc72", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "f3f5a1ca93ce6e092d92b6d9c049bcda58a3b617a8d888f8e7231c85630e8108"}, + "nimble_parsec": {:hex, :nimble_parsec, "1.4.0", "51f9b613ea62cfa97b25ccc2c1b4216e81df970acd8e16e8d1bdc58fef21370d", [:mix], [], "hexpm", "9c565862810fb383e9838c1dd2d7d2c437b3d13b267414ba6af33e50d2d1cf28"}, +} diff --git a/test/jop_test.exs b/test/jop_test.exs new file mode 100644 index 0000000..c687ecc --- /dev/null +++ b/test/jop_test.exs @@ -0,0 +1,104 @@ +defmodule JopTest do + use ExUnit.Case + @jop_log "test_jop_log" + + # doctest Jop + + setup do + on_exit(fn -> clean_jop_files(@jop_log) end) + end + + test "ref from uninitialized" do + jop = Jop.ref(@jop_log) + refute Jop.is_initialized(jop) + end + + test "ref from initialized" do + joplog = Jop.init(@jop_log) + assert try do: Jop.ref(@jop_log), catch: (any -> false), else: (_ -> true) + assert is_struct(joplog, Jop) + end + + test "double init" do + joplog = Jop.init(@jop_log) + ^joplog = Jop.init(@jop_log) + assert is_struct(joplog, Jop) + assert Enum.empty?(joplog) + assert joplog == Jop.flush(joplog) + assert all_logs_are_present?(@jop_log) + end + + test "clear" do + joplog = Jop.init(@jop_log) + Jop.log(joplog, "key_1", :any_term_112) + Jop.clear(joplog) + assert Enum.empty?(joplog) + assert joplog == Jop.flush(joplog) + assert all_logs_are_present?(@jop_log) + end + + test "flush" do + joplog = Jop.init(@jop_log) + Jop.log(joplog, "key_1", :any_term_112) + Jop.flush(joplog) + refute Jop.is_initialized(joplog) + assert all_logs_are_present?(@jop_log) + end + + test "flush nostop" do + joplog = Jop.init(@jop_log) + Jop.log(joplog, "key_1", :any_term_112) + Jop.flush(joplog, :nostop) + assert joplog == Jop.log(joplog, "mykey2", {:vv, 113}) + assert Enum.count(joplog) == 1 + assert joplog == Jop.flush(joplog) + assert all_logs_are_present?(@jop_log) + end + + test "log_and_dump" do + joplog = Jop.init(@jop_log) + assert is_struct(joplog, Jop) + + assert joplog == Jop.log(joplog, "mykey1", {:vv, 112}) + :timer.sleep(12) + assert joplog == Jop.init(@jop_log) + + assert joplog == Jop.log(joplog, "mykey2", {:vv, 113}) + + :timer.sleep(12) + assert joplog = Jop.log(joplog, "mykey1", {:vv, 112}) + + :timer.sleep(12) + assert joplog == Jop.log(joplog, "mykey2", {:vv, 113}) + + assert Enum.count(joplog) == 3 + assert joplog == Jop.flush(joplog) + assert all_logs_are_present?(@jop_log) + end + + test "is_initialized" do + job_ref = Jop.ref(@jop_log) + joplog = Jop.init(@jop_log) + assert Jop.is_initialized(joplog) + assert joplog == Jop.flush(joplog) + assert all_logs_are_present?(@jop_log) + end + + test "enumerable" do + joplog = Jop.init(@jop_log) + assert is_struct(joplog, Jop) + assert joplog == Jop.log(joplog, "mykey", "myvalue") + assert joplog == Jop.log(joplog, "mykey", "myvalue777") + assert Enum.count(joplog) == 2 + assert Enum.member?(joplog, "mykey") + assert 10 == Enum.reduce(joplog, 0, fn {_k, val}, acc -> max(byte_size(val), acc) end) + end + + defp all_logs_are_present?(id), + do: 2 == length(Path.wildcard("jop_#{id}*.gz")) + + def clean_jop_files(id) do + for file <- Path.wildcard("jop_#{id}*.gz"), + do: File.rm!(file) + end +end diff --git a/test/perf_test.exs b/test/perf_test.exs new file mode 100644 index 0000000..faa48ec --- /dev/null +++ b/test/perf_test.exs @@ -0,0 +1,21 @@ +defmodule PerfTest do + use ExUnit.Case + @jop_log "test_jop_log" + + test "measure logging" do + joplog = Jop.init(@jop_log) + + n = 1_000_000 + + {tlog, _} = + fn -> + for i <- 1..n, + do: Jop.log(joplog, <>, {<<"data.", <>::binary>>}) + end + |> :timer.tc() + + througput = div(n * 1_000_000, tlog) + IO.puts("througput #{througput} logs/s.") + assert Enum.count(joplog) == n + end +end diff --git a/test/test_helper.exs b/test/test_helper.exs new file mode 100644 index 0000000..869559e --- /dev/null +++ b/test/test_helper.exs @@ -0,0 +1 @@ +ExUnit.start()