LangChain Mastery

Course Content

LangChain Mastery

7 sections · 109 lessons

Implement a LangChain callback for logging execution time.

p95 milliseconds per step, found by a latency callback12041001800150123retrievererank, oneat a timemodelparseBatching the rerank calls took total p95 from 7 s to 3.2 s.
Timing the whole invoke showed only that it was slow; timing each run_id showed the model was not the problem.

What you need to know

Python
import time, loggingfrom langchain_core.callbacks import BaseCallbackHandlerclass LatencyLogger(BaseCallbackHandler):    def __init__(self):        self.starts = {}    def on_chain_start(self, serialized, inputs, *, run_id, **kw):        self.starts[run_id] = (time.perf_counter(), kw.get("name", "chain"))    def on_chat_model_start(self, serialized, messages, *, run_id, **kw):        name = kw.get("name") or (serialized or {}).get("name", "model")        self.starts[run_id] = (time.perf_counter(), name)    def on_chain_end(self, outputs, *, run_id, **kw):        self._done(run_id, "ok")    def on_llm_end(self, response, *, run_id, **kw):        self._done(run_id, "ok")    def on_chain_error(self, error, *, run_id, **kw):        self._done(run_id, "error")    def on_llm_error(self, error, *, run_id, **kw):        self._done(run_id, "error")    def _done(self, run_id, status):        t0, name = self.starts.pop(run_id, (None, None))        if t0 is not None:            ms = (time.perf_counter() - t0) * 1000            logging.info("%s %s %.0f ms", name, status, ms)chain.invoke(inputs, config={"callbacks": [LatencyLogger()]})

Running this on prompt | llm | parser logs one line per step and one for the whole sequence.

Details that matter

  • run_id keys: a batch call runs many steps at once, so a single "start time" variable would be overwritten. The dict keyed by run_id keeps them apart.
  • Chat models fire on_chat_model_start, not on_llm_start, but both finish with on_llm_end.
  • Error hooks: without on_chain_error, failed runs leave entries in self.starts forever, a slow memory leak.
  • Where to attach: config={"callbacks": [...]} applies to that call and every step inside it. Passing callbacks= to a model's constructor only covers that model.
  • Async code: use AsyncCallbackHandler if your handler does I/O, so it does not block the event loop.
  • Names: .with_config(run_name="retrieve_docs") gives a step a readable name in logs and traces.

A real-life example

A support bot over a telecom company's help-centre docs had a p95 latency of 7 seconds, and nobody knew why. The team added a latency handler that sent each step's duration to Prometheus, labelled by run_name. In one day the graphs showed the model took 1.8 seconds at p95, but a "rerank" step took 4.1 seconds because it called an external API one document at a time. Batching the rerank calls brought p95 down to 3.2 seconds. The handler stayed in production as a cheap metric feed, while LangSmith was used for looking at individual slow traces.

Follow-up questions to expect

  • "Why not just wrap invoke with a timer?" — That gives only the total. The callback gives per-step timings inside the chain, which is where the answer usually is.
  • "How would you log token usage too?" — In on_llm_end, read response.generations[0][0].message.usage_metadata and log the counts with the same run_id.
  • "LangSmith or a custom handler?" — LangSmith for debugging and trace inspection; a custom handler to send metrics to your own monitoring. Many teams use both.