# `Arcana.Telemetry`
[🔗](https://github.com/georgeguimaraes/arcana/blob/main/lib/arcana/telemetry.ex#L1)

Telemetry events emitted by Arcana.

Arcana uses the standard `:telemetry` library to emit events for observability.
You can attach handlers to these events for logging, metrics, or tracing.

## Events

All events are emitted using `:telemetry.span/3`, which automatically generates
`:start`, `:stop`, and `:exception` events.

### Ingest Events

* `[:arcana, :ingest, :start]` - Emitted when document ingestion begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{text: String.t(), repo: module(), collection: String.t()}`

* `[:arcana, :ingest, :stop]` - Emitted when document ingestion completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{document: Document.t(), chunk_count: integer}`

* `[:arcana, :ingest, :exception]` - Emitted when document ingestion fails.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

### Search Events

* `[:arcana, :search, :start]` - Emitted when a search query begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{query: String.t(), repo: module(), mode: atom(), limit: integer}`

* `[:arcana, :search, :stop]` - Emitted when a search query completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{results: list(), result_count: integer}`

* `[:arcana, :search, :exception]` - Emitted when a search query fails.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

### Ask Events (RAG)

* `[:arcana, :ask, :start]` - Emitted when a RAG question begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{question: String.t(), repo: module()}`

* `[:arcana, :ask, :stop]` - Emitted when a RAG question completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{answer: String.t(), context_count: integer}`

* `[:arcana, :ask, :exception]` - Emitted when a RAG question fails.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

### Embed Events

* `[:arcana, :embed, :start]` - Emitted when embedding generation begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{text: String.t()}`

* `[:arcana, :embed, :stop]` - Emitted when embedding generation completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{dimensions: integer}`

* `[:arcana, :embed, :exception]` - Emitted when embedding generation fails.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

### LLM Events

* `[:arcana, :llm, :complete, :start]` - Emitted when an LLM call begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{model: String.t(), prompt_length: integer, context_count: integer}`

* `[:arcana, :llm, :complete, :stop]` - Emitted when an LLM call completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{success: boolean, response_length: integer}` or `%{success: false, error: String.t()}`

* `[:arcana, :llm, :complete, :exception]` - Emitted when an LLM call fails.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

### Agent Pipeline Events

Each step in the Agent pipeline emits `:start`, `:stop`, and `:exception` events:

* `[:arcana, :agent, :rewrite, :*]` - Query rewriting step.
  * Stop metadata: `%{query: String.t()}`

* `[:arcana, :agent, :select, :*]` - Collection selection step.
  * Stop metadata: `%{selected: [String.t()]}`

* `[:arcana, :agent, :expand, :*]` - Query expansion step.
  * Stop metadata: `%{expanded_query: String.t()}`

* `[:arcana, :agent, :decompose, :*]` - Question decomposition step.
  * Stop metadata: `%{sub_question_count: integer}`

* `[:arcana, :agent, :search, :*]` - Vector search step.
  * Stop metadata: `%{total_chunks: integer}`

* `[:arcana, :agent, :rerank, :*]` - Chunk reranking step.
  * Stop metadata: `%{kept: integer, original: integer}`

* `[:arcana, :agent, :answer, :*]` - Answer generation step.
  * Stop metadata: `%{}`

* `[:arcana, :agent, :self_correct, :*]` - Self-correction iteration.
  * Stop metadata: `%{attempt: integer}`

### GraphRAG Events

When using GraphRAG features (`graph: true`), these events are emitted:

* `[:arcana, :graph, :build, :start]` - Emitted when graph building begins during ingest.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{chunk_count: integer, collection: String.t()}`

* `[:arcana, :graph, :build, :stop]` - Emitted when graph building completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{entity_count: integer, relationship_count: integer}`

* `[:arcana, :graph, :build, :exception]` - Emitted when graph building fails.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

* `[:arcana, :graph, :search, :start]` - Emitted when graph-enhanced search begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{query: String.t(), entity_count: integer}`

* `[:arcana, :graph, :search, :stop]` - Emitted when graph-enhanced search completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{graph_result_count: integer, combined_count: integer}`

* `[:arcana, :graph, :search, :exception]` - Emitted when graph-enhanced search fails.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

* `[:arcana, :graph, :ner, :start]` - Emitted when NER entity extraction begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{text: String.t()}`

* `[:arcana, :graph, :ner, :stop]` - Emitted when NER entity extraction completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{entity_count: integer}`

* `[:arcana, :graph, :relationship_extraction, :start]` - Emitted when relationship extraction begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{text: String.t()}`

* `[:arcana, :graph, :relationship_extraction, :stop]` - Emitted when relationship extraction completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{relationship_count: integer}`

* `[:arcana, :graph, :community_detection, :start]` - Emitted when community detection begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{entity_count: integer}`

* `[:arcana, :graph, :community_detection, :stop]` - Emitted when community detection completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{community_count: integer}`

* `[:arcana, :graph, :community_summary, :start]` - Emitted when community summarization begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{entity_count: integer}`

* `[:arcana, :graph, :community_summary, :stop]` - Emitted when community summarization completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{summary_length: integer}`

### VectorStore Events

* `[:arcana, :vector_store, :store, :start]` - Emitted when storing a vector.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{collection: String.t(), id: String.t()}`

* `[:arcana, :vector_store, :store, :stop]` - Emitted when vector storage completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

* `[:arcana, :vector_store, :search, :start]` - Emitted when vector search begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{collection: String.t(), limit: integer}`

* `[:arcana, :vector_store, :search, :stop]` - Emitted when vector search completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom(), result_count: integer}`

* `[:arcana, :vector_store, :search_text, :start]` - Emitted when fulltext search begins.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{collection: String.t(), query: String.t(), limit: integer}`

* `[:arcana, :vector_store, :search_text, :stop]` - Emitted when fulltext search completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom(), result_count: integer}`

* `[:arcana, :vector_store, :delete, :start]` - Emitted when deleting a vector.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{collection: String.t(), id: String.t()}`

* `[:arcana, :vector_store, :delete, :stop]` - Emitted when vector deletion completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

* `[:arcana, :vector_store, :clear, :start]` - Emitted when clearing a collection.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{collection: String.t()}`

* `[:arcana, :vector_store, :clear, :stop]` - Emitted when collection clearing completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

### GraphStore Events

* `[:arcana, :graph_store, :persist_entities, :start]` - Emitted when persisting entities.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{collection_id: String.t(), entity_count: integer}`

* `[:arcana, :graph_store, :persist_entities, :stop]` - Emitted when entity persistence completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

* `[:arcana, :graph_store, :persist_relationships, :start]` - Emitted when persisting relationships.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{relationship_count: integer}`

* `[:arcana, :graph_store, :persist_relationships, :stop]` - Emitted when relationship persistence completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

* `[:arcana, :graph_store, :persist_mentions, :start]` - Emitted when persisting mentions.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{mention_count: integer}`

* `[:arcana, :graph_store, :persist_mentions, :stop]` - Emitted when mention persistence completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

* `[:arcana, :graph_store, :search, :start]` - Emitted when searching graph store.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{entity_count: integer}`

* `[:arcana, :graph_store, :search, :stop]` - Emitted when graph search completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom(), result_count: integer}`

* `[:arcana, :graph_store, :delete_by_chunks, :start]` - Emitted when deleting by chunks.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{chunk_count: integer}`

* `[:arcana, :graph_store, :delete_by_chunks, :stop]` - Emitted when chunk deletion completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

* `[:arcana, :graph_store, :delete_by_collection, :start]` - Emitted when deleting by collection.
  * Measurement: `%{system_time: integer}`
  * Metadata: `%{collection_id: String.t()}`

* `[:arcana, :graph_store, :delete_by_collection, :stop]` - Emitted when collection deletion completes.
  * Measurement: `%{duration: integer}`
  * Metadata: `%{backend: atom()}`

## Quick Start with Built-in Logger

For quick setup, use the built-in logger:

    # In your application's start/2
    Arcana.Telemetry.Logger.attach()

This logs all events with timing info. See `Arcana.Telemetry.Logger` for options.

## Custom Handler

For custom handling, attach your own handler:

    defmodule MyApp.ArcanaLogger do
      require Logger

      def setup do
        events = [
          [:arcana, :ingest, :stop],
          [:arcana, :search, :stop],
          [:arcana, :ask, :stop],
          [:arcana, :embed, :stop]
        ]

        :telemetry.attach_many("arcana-logger", events, &handle_event/4, nil)
      end

      def handle_event([:arcana, :ingest, :stop], measurements, metadata, _config) do
        Logger.info("Ingested document #{metadata.document.id} with #{metadata.chunk_count} chunks in #{format_duration(measurements.duration)}")
      end

      def handle_event([:arcana, :search, :stop], measurements, metadata, _config) do
        Logger.info("Search returned #{metadata.result_count} results in #{format_duration(measurements.duration)}")
      end

      def handle_event([:arcana, :ask, :stop], measurements, metadata, _config) do
        Logger.info("RAG answered with #{metadata.context_count} context chunks in #{format_duration(measurements.duration)}")
      end

      def handle_event([:arcana, :embed, :stop], measurements, _metadata, _config) do
        Logger.debug("Generated embedding in #{format_duration(measurements.duration)}")
      end

      defp format_duration(duration) do
        duration
        |> System.convert_time_unit(:native, :millisecond)
        |> then(&"#{&1}ms")
      end
    end

Then call `MyApp.ArcanaLogger.setup()` in your application startup.

## Integration with Metrics Libraries

These telemetry events work with metrics libraries like:

* `telemetry_metrics` - Define metrics based on these events
* `telemetry_poller` - Periodically report metrics
* `prom_ex` - Export to Prometheus

Example with `telemetry_metrics`:

    defmodule MyApp.Metrics do
      import Telemetry.Metrics

      def metrics do
        [
          counter("arcana.ingest.stop.duration", unit: {:native, :millisecond}),
          counter("arcana.search.stop.duration", unit: {:native, :millisecond}),
          summary("arcana.search.stop.result_count"),
          distribution("arcana.embed.stop.duration", unit: {:native, :millisecond})
        ]
      end
    end

# `span`

Wraps a function call with telemetry span events.

This is a convenience function used internally by Arcana to emit
consistent telemetry events.

# `span_with_metadata`

Wraps a function call with telemetry span events, allowing custom stop metadata.

The function should return `{result, stop_metadata}` where `stop_metadata`
is a map of additional metadata to include in the stop event.

---

*Consult [api-reference.md](api-reference.md) for complete listing*