Files
2026-07-13 13:22:34 +08:00

456 lines
17 KiB
Python

import logging
import threading
from collections import defaultdict
from functools import wraps
from typing import Any
import dspy
from dspy.utils.callback import BaseCallback
import mlflow
from mlflow.dspy.constant import FLAVOR_NAME
from mlflow.dspy.util import (
log_dspy_lm_state,
log_dspy_module_params,
sanitize_params,
save_dspy_module_state,
)
from mlflow.entities import SpanStatusCode, SpanType
from mlflow.entities.run_status import RunStatus
from mlflow.entities.span_event import SpanEvent
from mlflow.exceptions import MlflowException
from mlflow.tracing.constant import SpanAttributeKey, TokenUsageKey
from mlflow.tracing.fluent import start_span_no_context
from mlflow.tracing.provider import detach_span_from_context, set_span_in_context
from mlflow.tracing.utils import maybe_set_prediction_context
from mlflow.tracing.utils.token import SpanWithToken
from mlflow.utils import _get_fully_qualified_class_name
from mlflow.utils.autologging_utils import (
get_autologging_config,
)
from mlflow.version import IS_TRACING_SDK_ONLY
_logger = logging.getLogger(__name__)
_lock = threading.Lock()
def skip_if_trace_disabled(func):
@wraps(func)
def wrapper(*args, **kwargs):
if get_autologging_config(FLAVOR_NAME, "log_traces"):
func(*args, **kwargs)
return wrapper
def _convert_signature(val):
# serialization of dspy.Signature is quite slow, so we should convert it to string
if isinstance(val, type) and issubclass(val, dspy.Signature):
return repr(val)
return val
class MlflowCallback(BaseCallback):
"""Callback for generating MLflow traces for DSPy components"""
def __init__(self, dependencies_schema: dict[str, Any] | None = None):
self._dependencies_schema = dependencies_schema
# call_id: (LiveSpan, OTel token)
self._call_id_to_span: dict[str, SpanWithToken] = {}
self._call_id_to_module: dict[str, Any] = {}
###### state management for optimization process ######
# The current callback logic assumes there is no optimization running in parallel.
# The state management may not work when multiple optimizations are running in parallel.
# optimizer_stack_level is used to determine if the callback is called within compile
# we cannot use boolean flag because the callback can be nested
self.optimizer_stack_level = 0
# call_id: (key, step)
self._call_id_to_metric_key: dict[str, tuple[str, int]] = {}
self._evaluation_counter = defaultdict(int)
self._disabled_eval_call_ids = set()
self._eval_runs_started: set[str] = set()
def set_dependencies_schema(self, dependencies_schema: dict[str, Any]):
if self._dependencies_schema:
raise MlflowException(
"Dependencies schema should be set only once to the callback.",
error_code=MlflowException.INVALID_PARAMETER_VALUE,
)
self._dependencies_schema = dependencies_schema
@skip_if_trace_disabled
def on_module_start(self, call_id: str, instance: Any, inputs: dict[str, Any]):
span_type = self._get_span_type_for_module(instance)
attributes = self._get_span_attribute_for_module(instance)
# The __call__ method of dspy.Module has a signature of (self, *args, **kwargs),
# while all built-in modules only accepts keyword arguments. To avoid recording
# empty "args" key in the inputs, we remove it if it's empty.
if "args" in inputs and not inputs["args"]:
inputs.pop("args")
self._start_span(
call_id,
name=f"{instance.__class__.__name__}.forward",
span_type=span_type,
inputs=self._unpack_kwargs(inputs),
attributes=attributes,
)
self._call_id_to_module[call_id] = instance
@skip_if_trace_disabled
def on_module_end(self, call_id: str, outputs: Any | None, exception: Exception | None = None):
instance = self._call_id_to_module.pop(call_id)
attributes = {}
if _get_fully_qualified_class_name(instance) == "dspy.retrieve.databricks_rm.DatabricksRM":
from mlflow.entities.document import Document
if isinstance(outputs, dspy.Prediction):
# Convert outputs to MLflow document format to make it compatible with
# agent evaluation.
num_docs = len(outputs.doc_ids)
doc_uris = outputs.doc_uris if outputs.doc_uris is not None else [None] * num_docs
outputs = [
Document(
page_content=doc_content,
metadata={
"doc_id": doc_id,
"doc_uri": doc_uri,
}
| extra_column_dict,
id=doc_id,
).to_dict()
for doc_content, doc_id, doc_uri, extra_column_dict in zip(
outputs.docs,
outputs.doc_ids,
doc_uris,
outputs.extra_columns,
)
]
else:
# NB: DSPy's Prediction object is a customized dictionary-like object, but its repr
# is not easy to read on UI. Therefore, we unpack it to a dictionary.
# https://github.com/stanfordnlp/dspy/blob/6fe693528323c9c10c82d90cb26711a985e18b29/dspy/primitives/prediction.py#L21-L28
if isinstance(outputs, dspy.Prediction):
usage_by_model = (
outputs.get_lm_usage() if hasattr(outputs, "get_lm_usage") else None
)
outputs = outputs.toDict()
if usage_by_model:
usage_data = {
TokenUsageKey.INPUT_TOKENS: 0,
TokenUsageKey.OUTPUT_TOKENS: 0,
TokenUsageKey.TOTAL_TOKENS: 0,
}
for usage in usage_by_model.values():
usage_data[TokenUsageKey.INPUT_TOKENS] += usage.get("prompt_tokens", 0)
usage_data[TokenUsageKey.OUTPUT_TOKENS] += usage.get("completion_tokens", 0)
usage_data[TokenUsageKey.TOTAL_TOKENS] += usage.get("total_tokens", 0)
attributes[SpanAttributeKey.CHAT_USAGE] = usage_data
# TODO: the span may not contain model name so we cannot calculate cost
self._end_span(call_id, outputs, exception, attributes)
@skip_if_trace_disabled
def on_lm_start(self, call_id: str, instance: Any, inputs: dict[str, Any]):
span_type = (
SpanType.CHAT_MODEL if getattr(instance, "model_type", None) == "chat" else SpanType.LLM
)
filtered_kwargs = sanitize_params(instance.kwargs)
attributes = {
**filtered_kwargs,
"model": instance.model,
"model_type": instance.model_type,
"cache": instance.cache,
SpanAttributeKey.MESSAGE_FORMAT: "dspy",
SpanAttributeKey.MODEL: instance.model,
}
match instance.model.split("/", 1):
case [provider, _]:
attributes[SpanAttributeKey.MODEL_PROVIDER] = provider
inputs = self._unpack_kwargs(inputs)
self._start_span(
call_id,
name=f"{instance.__class__.__name__}.__call__",
span_type=span_type,
inputs=inputs,
attributes=attributes,
)
@skip_if_trace_disabled
def on_lm_end(self, call_id: str, outputs: Any | None, exception: Exception | None = None):
self._end_span(call_id, outputs, exception)
@skip_if_trace_disabled
def on_adapter_format_start(self, call_id: str, instance: Any, inputs: dict[str, Any]):
self._start_span(
call_id,
name=f"{instance.__class__.__name__}.format",
span_type=SpanType.PARSER,
inputs=self._unpack_kwargs(inputs),
attributes={},
)
@skip_if_trace_disabled
def on_adapter_format_end(
self, call_id: str, outputs: Any | None, exception: Exception | None = None
):
self._end_span(call_id, outputs, exception)
@skip_if_trace_disabled
def on_adapter_parse_start(self, call_id: str, instance: Any, inputs: dict[str, Any]):
self._start_span(
call_id,
name=f"{instance.__class__.__name__}.parse",
span_type=SpanType.PARSER,
inputs=self._unpack_kwargs(inputs),
attributes={},
)
@skip_if_trace_disabled
def on_adapter_parse_end(
self, call_id: str, outputs: Any | None, exception: Exception | None = None
):
self._end_span(call_id, outputs, exception)
@skip_if_trace_disabled
def on_tool_start(self, call_id: str, instance: Any, inputs: dict[str, Any]):
# DSPy uses the special "finish" tool to signal the end of the agent.
if instance.name == "finish":
return
inputs = self._unpack_kwargs(inputs)
# Tools are always called with keyword arguments only.
inputs.pop("args", None)
self._start_span(
call_id,
name=f"Tool.{instance.name}",
span_type=SpanType.TOOL,
inputs=inputs,
attributes={
"name": instance.name,
"description": instance.desc,
"args": instance.args,
},
)
@skip_if_trace_disabled
def on_tool_end(self, call_id: str, outputs: Any | None, exception: Exception | None = None):
if call_id in self._call_id_to_span:
self._end_span(call_id, outputs, exception)
def on_evaluate_start(self, call_id: str, instance: Any, inputs: dict[str, Any]):
"""
Callback handler at the beginning of evaluation call. Available with DSPy>=2.6.9.
This callback starts a nested run for each evaluation call inside optimization.
If called outside optimization and no active run exists, it creates a new run.
"""
if not get_autologging_config(FLAVOR_NAME, "log_evals"):
return
key = "eval"
if callback_metadata := inputs.get("callback_metadata"):
if "metric_key" in callback_metadata:
key = callback_metadata["metric_key"]
if callback_metadata.get("disable_logging"):
self._disabled_eval_call_ids.add(call_id)
return
started_run = False
if self.optimizer_stack_level > 0:
with _lock:
# we may want to include optimizer_stack_level in the key
# to handle nested optimization
step = self._evaluation_counter[key]
self._evaluation_counter[key] += 1
self._call_id_to_metric_key[call_id] = (key, step)
mlflow.start_run(run_name=f"{key}_{step}", nested=True)
started_run = True
elif mlflow.active_run() is None:
mlflow.start_run(run_name=key, nested=True)
started_run = True
if started_run:
self._eval_runs_started.add(call_id)
if program := inputs.get("program"):
save_dspy_module_state(program, "model.json")
log_dspy_module_params(program)
# Log the current DSPy LM state
log_dspy_lm_state()
def on_evaluate_end(
self,
call_id: str,
outputs: Any,
exception: Exception | None = None,
):
"""
Callback handler at the end of evaluation call. Available with DSPy>=2.6.9.
This callback logs the evaluation score to the individual run
and add eval metric to the parent run if called inside optimization.
"""
if not get_autologging_config(FLAVOR_NAME, "log_evals"):
return
if call_id in self._disabled_eval_call_ids:
self._disabled_eval_call_ids.discard(call_id)
return
run_started = call_id in self._eval_runs_started
if exception:
if run_started:
mlflow.end_run(status=RunStatus.to_string(RunStatus.FAILED))
self._eval_runs_started.discard(call_id)
return
score = None
if isinstance(outputs, float):
score = outputs
elif isinstance(outputs, tuple):
score = outputs[0]
elif isinstance(outputs, dspy.Prediction):
score = float(outputs)
try:
mlflow.log_table(self._generate_result_table(outputs.results), "result_table.json")
except Exception:
_logger.debug("Failed to log result table.", exc_info=True)
if score is not None:
mlflow.log_metric("eval", score)
if run_started:
mlflow.end_run()
self._eval_runs_started.discard(call_id)
# Log the evaluation score to the parent run if called inside optimization
if self.optimizer_stack_level > 0 and mlflow.active_run() is not None:
if call_id not in self._call_id_to_metric_key:
return
key, step = self._call_id_to_metric_key.pop(call_id)
if score is not None:
mlflow.log_metric(
key,
score,
step=step,
)
def reset(self):
self._call_id_to_metric_key: dict[str, tuple[str, int]] = {}
self._evaluation_counter = defaultdict(int)
self._eval_runs_started = set()
def _start_span(
self,
call_id: str,
name: str,
span_type: SpanType,
inputs: dict[str, Any],
attributes: dict[str, Any],
):
if not IS_TRACING_SDK_ONLY:
from mlflow.pyfunc.context import get_prediction_context
prediction_context = get_prediction_context()
if prediction_context and self._dependencies_schema:
prediction_context.update(**self._dependencies_schema)
else:
prediction_context = None
with maybe_set_prediction_context(prediction_context):
span = start_span_no_context(
name=name,
span_type=span_type,
parent_span=mlflow.get_current_active_span(),
inputs=inputs,
attributes=attributes,
)
token = set_span_in_context(span)
self._call_id_to_span[call_id] = SpanWithToken(span, token)
return span
def _end_span(
self,
call_id: str,
outputs: Any | None,
exception: Exception | None = None,
attributes: dict[str, Any] | None = None,
):
st = self._call_id_to_span.pop(call_id, None)
if not st.span:
_logger.warning(f"Failed to end a span. Span not found for call_id: {call_id}")
return
status = SpanStatusCode.OK if exception is None else SpanStatusCode.ERROR
if exception:
st.span.add_event(SpanEvent.from_exception(exception))
if attributes:
st.span.set_attributes(attributes)
try:
st.span.end(outputs=outputs, status=status)
finally:
detach_span_from_context(st.token)
def _get_span_type_for_module(self, instance):
if isinstance(instance, dspy.Retrieve):
return SpanType.RETRIEVER
elif isinstance(instance, dspy.ReAct):
return SpanType.AGENT
elif isinstance(instance, dspy.Predict):
return SpanType.LLM
elif isinstance(instance, dspy.Adapter):
return SpanType.PARSER
else:
return SpanType.CHAIN
def _get_span_attribute_for_module(self, instance):
if isinstance(instance, dspy.Predict):
return {"signature": instance.signature.signature}
elif isinstance(instance, dspy.ChainOfThought):
if hasattr(instance, "signature"):
signature = instance.signature.signature
else:
signature = instance.predict.signature.signature
attributes = {"signature": signature}
if hasattr(instance, "extended_signature"):
attributes["extended_signature"] = instance.extended_signature.signature
return attributes
return {}
def _unpack_kwargs(self, inputs: dict[str, Any]) -> dict[str, Any]:
"""Unpacks the kwargs from the inputs dictionary"""
# NB: Not using pop() to avoid modifying the original inputs dictionary
kwargs = inputs.get("kwargs", {})
inputs_wo_kwargs = {k: v for k, v in inputs.items() if k != "kwargs"}
merged = inputs_wo_kwargs | kwargs
return {k: _convert_signature(v) for k, v in merged.items()}
def _generate_result_table(
self, outputs: list[tuple[dspy.Example, dspy.Prediction, Any]]
) -> dict[str, list[Any]]:
result = {"score": []}
for i, (example, prediction, score) in enumerate(outputs):
for k, v in example.items():
if f"example_{k}" not in result:
result[f"example_{k}"] = [None] * i
result[f"example_{k}"].append(v)
for k, v in prediction.items():
if f"pred_{k}" not in result:
result[f"pred_{k}"] = [None] * i
result[f"pred_{k}"].append(v)
result["score"].append(score)
for k, v in result.items():
if len(v) != i + 1:
result[k].append(None)
return result