Current section
Files
Jump to
Current section
Files
lib/mix/tasks/index_benchmark.ex
defmodule Mix.Tasks.TimelessLogs.IndexBenchmark do
@moduledoc "Benchmark pure ETS index operations in isolation (no disk I/O)"
use Mix.Task
@shortdoc "Benchmark index ETS operations with in-memory storage"
@block_count 2_000
@entries_per_block 100
@iterations 5
@destructive_iterations 3
@levels [:info, :info, :info, :debug, :debug, :warning, :error]
@modules ~w(Phoenix.Logger Ecto.Adapters.SQL MyApp.Scheduler MyApp.Health MyApp.Monitor)
@impl true
def run(_args) do
Application.put_env(:timeless_logs, :storage, :memory)
Application.put_env(:timeless_logs, :compaction_interval, 600_000)
Mix.Task.run("app.start")
total_entries = @block_count * @entries_per_block
IO.puts("=== TimelessLogs Index Benchmark ===\n")
IO.puts(
"Seeding #{fmt_number(@block_count)} blocks (#{fmt_number(total_entries)} log entries, ~200K term index entries)..."
)
{setup_us, _} = :timer.tc(fn -> seed_blocks() end)
IO.puts("Setup: #{fmt_ms(setup_us)}\n")
{:ok, stats} = TimelessLogs.Index.stats()
term_count = :ets.info(:timeless_logs_term_index, :size)
IO.puts("Total blocks: #{fmt_number(stats.total_blocks)}")
IO.puts("Total entries: #{fmt_number(stats.total_entries)}")
IO.puts("Total term index entries: #{fmt_number(term_count)}\n")
six_hours_ago = System.system_time(:second) - 6 * 3600
benchmarks = [
{"stats()", fn -> TimelessLogs.Index.stats() end},
{"raw_block_ids()", fn -> TimelessLogs.Index.raw_block_ids() end},
{"matching_block_ids (no filter)",
fn -> TimelessLogs.Index.matching_block_ids(limit: 1000) end},
{"matching_block_ids (term filter)",
fn -> TimelessLogs.Index.matching_block_ids(level: :error, limit: 1000) end},
{"matching_block_ids (time range)",
fn -> TimelessLogs.Index.matching_block_ids(since: six_hours_ago, limit: 1000) end},
{"matching_block_ids (term + time)",
fn ->
TimelessLogs.Index.matching_block_ids(
level: :error,
since: six_hours_ago,
limit: 1000
)
end}
]
IO.puts("--- Index Operations (#{@iterations} iterations) ---")
IO.puts(
String.pad_trailing("Operation", 38) <>
String.pad_leading("Median", 10) <>
String.pad_leading("Min", 10) <>
String.pad_leading("Max", 10)
)
IO.puts(String.duplicate("-", 68))
for {label, fun} <- benchmarks do
{median, min_l, max_l} = bench(fun)
IO.puts(
String.pad_trailing(label, 38) <>
String.pad_leading(fmt_ms(median), 10) <>
String.pad_leading(fmt_ms(min_l), 10) <>
String.pad_leading(fmt_ms(max_l), 10)
)
end
# Destructive operations — restart app + re-seed before each iteration
IO.puts(
"\n--- Destructive Operations (#{@destructive_iterations} iterations, re-seed each) ---"
)
IO.puts(
String.pad_trailing("Operation", 38) <>
String.pad_leading("Median", 10) <>
String.pad_leading("Min", 10) <>
String.pad_leading("Max", 10)
)
IO.puts(String.duplicate("-", 68))
destructive_ops = [
{"delete_blocks_over_size",
fn ->
{:ok, s} = TimelessLogs.Index.stats()
TimelessLogs.Index.delete_blocks_over_size(div(s.total_bytes, 2))
end},
{"delete_by_term_limit",
fn ->
half_terms = div(:ets.info(:timeless_logs_term_index, :size), 2)
TimelessLogs.Index.delete_oldest_blocks_until_term_limit(half_terms)
end}
]
for {label, fun} <- destructive_ops do
times =
for _ <- 1..@destructive_iterations do
reseed()
{us, _} = :timer.tc(fun)
us
end
sorted = Enum.sort(times)
median = Enum.at(sorted, div(@destructive_iterations, 2))
min_l = hd(sorted)
max_l = List.last(sorted)
IO.puts(
String.pad_trailing(label, 38) <>
String.pad_leading(fmt_ms(median), 10) <>
String.pad_leading(fmt_ms(min_l), 10) <>
String.pad_leading(fmt_ms(max_l), 10)
)
end
IO.puts("\n=== Summary ===")
IO.puts("Total term index entries: #{fmt_number(term_count)}")
IO.puts("Total blocks: #{fmt_number(stats.total_blocks)}")
IO.puts("Total entries: #{fmt_number(stats.total_entries)}")
Application.stop(:timeless_logs)
end
defp reseed do
Application.stop(:timeless_logs)
Application.ensure_all_started(:timeless_logs)
seed_blocks()
end
defp seed_blocks do
base_ts = System.system_time(:second) - 86_400
for i <- 1..@block_count do
chunk = generate_chunk(base_ts, i)
case TimelessLogs.Writer.write_block(chunk, :memory, :raw) do
{:ok, meta} ->
terms = TimelessLogs.Index.extract_terms(chunk)
TimelessLogs.Index.index_block(meta, chunk, terms)
end
end
end
defp generate_chunk(base_ts, block_idx) do
for j <- 1..@entries_per_block do
ts = base_ts + block_idx * @entries_per_block + j
level = Enum.at(@levels, rem(j, length(@levels)))
mod = Enum.at(@modules, rem(block_idx + j, length(@modules)))
%{
timestamp: ts,
level: level,
message: "Request processed in #{:rand.uniform(500)}ms",
metadata: %{
"module" => mod,
"request_id" => random_hex(16),
"status" => "#{Enum.random([200, 201, 400, 404, 500])}"
}
}
end
end
defp bench(fun) do
times = for _ <- 1..@iterations, do: elem(:timer.tc(fun), 0)
sorted = Enum.sort(times)
{Enum.at(sorted, div(@iterations, 2)), hd(sorted), List.last(sorted)}
end
defp random_hex(n), do: :crypto.strong_rand_bytes(n) |> Base.encode16(case: :lower)
defp fmt_number(n) when n >= 1_000_000,
do: "#{:erlang.float_to_binary(n / 1_000_000, decimals: 1)}M"
defp fmt_number(n) when n >= 1_000, do: "#{:erlang.float_to_binary(n / 1_000, decimals: 1)}K"
defp fmt_number(n), do: "#{n}"
defp fmt_ms(us) when us < 1_000, do: "#{us}us"
defp fmt_ms(us) when us < 1_000_000, do: "#{:erlang.float_to_binary(us / 1_000, decimals: 1)}ms"
defp fmt_ms(us), do: "#{:erlang.float_to_binary(us / 1_000_000, decimals: 2)}s"
end