opentelemetry-ecto: Creating spans after-the-fact causes misattributed child spans (e.g. opentelemetry-sqlcommenter IDs)

[ivucica]

Describe the bug

In opentelemetry-ecto:

Because Ecto emits telemetry events only after queries have finished, OpentelemetryEcto estimates the start time of the span by subtracting the reported total duration from the current timestamp.

opentelemetry-sqlcommenter attaches SQLCommenter-style annotations to generated queries, resembling this:

SELECT 
  f0."id", f0."user_id", f0."filter_id", f0."hide", f0."whole_word", f0."phrase", f0."context",
  f0."expires_at", f0."inserted_at", f0."updated_at" 
FROM 
  "filters" AS f0
WHERE 
  ((f0."expires_at" IS NULL) OR (f0."expires_at" > $1)) AND (f0."hide")
  AND
  (f0."user_id" = $2)
ORDER BY
  f0."id" DESC/*traceparent='00-adcd837ab305e206fc7bf5fc3395ca95-d503af1be7dc8fbc-01'*/

Per opentelemetry-sqlcommenter's instructions, it's hooked into a Ecto in lib/pleroma/repo.ex inside defmodule Pleroma.Repo do ... end block as follows:

defdelegate prepare_query(operation, query, opts), to: OpentelemetrySqlcommenter

prepare_query (or prepare_query_sampled) set comment: comment, but also prepare: :unnamed, the latter seemingly a trick to disable prepared statements, so that the preparation will happen every time, resulting in the delegate being called.

Neat trick, but it has a flaw: it happens while Ecto is making the query, meaning when the delegated prepare_query invokes OpenTelemetry.Tracer.current_span_ctx(), it's receiving the parent context -- or frequently none at all. (I'm not an Elixir or Erlang developer, so this is a lot of tapping in the dark. Please correct me if I am wrong.)

This seems to be the cause of queries sent by pg_tracing being detached from spans created by opentelemetry-ecto (sometimes with no parent span -- with pg_tracing just using part of the trace ID instead -- and sometimes with parent-of-ecto-span as parent).

I previously thought it was a pg_tracing bug: DataDog/pg_tracing#84 but I think the issues I saw there are all coming from opentelemetry-ecto faking the start event.

opentelemetry-sqlcommenter seems to be doing the right thing: getting the span context, and using it to build the comment, so the issue with the wrong parent seems to be elsewhere.

(Possibly related: #425)

Expected behavior
Correct span ID should be known at the time the query is being executed, so the correct parent span ID can be sent into the database.

Some thoughts?

1. Would Ecto / ecto-sql itself have to be patched to correctly start and end spans? Or can the fix live fully outside of that core?
2. Am I setting things up incorrectly or missing something? Should I be using something else to create the spans?
3. Would some integration between the opentelemetry-sqlcommenter's hack and opentelemetry-ecto make sense, e.g. starting the span during query prep (giving up on "end time, minus telemetry-observed total duration" trick to compute an accurate start_time) make sense (with fallback to that kind of start_time if need be)?
4. If it does make sense, what would be the best way in Elixir to store the fact that a span has already been started? A thread-local variable, presumably? (A global variable with mutex guarding it is, I expect, not a very Erlang-like approach.)

Additional context
I do not actually know Elixir or Erlang, neither the languages nor the wider ecosystem. I am not familiar with Ecto, ecto-sql, or OpenTelemetry implementation in Elixir or Erlang. I am very unfamiliar with how threading or global vars (such as a tracing context) work in Erlang and Elixir.

Honestly, I was mainly trying to figure out the causes of performance issues I have with Pleroma (a fediverse server, implementing a federated social network over HTTP) and with queries it's sending into PostgreSQL.

In my setup, for each request I propagate a single trace:

1. starting in nginx (creates trace ID and a span),
2. getting into Pleroma in Phoenix (receives the trace ID and parent span ID, creates a span) which
3. during the handling of a route causes many Ecto queries to PostgreSQL
4. these get annotated with traceparent comment as an SQLCommenter-style comment
5. this is used by the pg_tracing extension installed into PostgreSQL
6. both Pleroma and PostgreSQL have been configured to talk to local otelcol-contrib, which currently forwards this to Google Cloud Trace

I haven't set up Oban telemetry or anything else I might be missing. Some processing happens without HTTP requests as well.

I'm also running this on top of whatever's in my Debian-based install -- apparently, "Elixir 1.14.0 (compiled with Erlang/OTP 24)". This is mostly Pleroma v2.9.1 with these OpenTelemetry-related changes installed.

[tsloughter]

My understanding, without yet actually digging into Ecto is that it has to be patched.

I believe it simply emits a single event, it does not wrap the query in a span. Until it does there will be this issue.

[ivucica]

@tsloughter As mentioned earlier, I am very unfamiliar with Ecto (and lack time right now to become deeply familiar with it -- I don't even know how it gets invoked by software like Pleroma) as well as the general Erlang/Elixir ecosystem. Apologies for some possibly nonsensical questions:

1. Is Ecto used for much more than queries to relational databases? Would Ecto "events" (whatever is covered by a span) typically contain a query? Do they contain more than one query?

2. Do you know if it would be fair to expect that hijacking the 'prepare' statement could deal with this? That is, as I suggested in point 3, do something like what opentelemetry-sqlcommenter does, to initiate the start of the span?

   If a query doesn't kick in by the end, inspecting the ctx for whether it contains the current invocation's span -- e.g. by checking the attributes -- could still end up indicating that a span hasn't been started, and follow the old path. And similarly, if there's already a span covering Ecto when a query is happening, could that be

3. Do you know if a lot happens before the query and would, therefore, starting the span together with the query via the defdelegate "hack" be the wrong thing to do? That is: would it shift the time too much? Should / could the 'start time' be adjusted just before span end is invoked?

4. Is defdelegate approach even a hack or is that one of expected ways to do things like this? (I am familiar with 'delegates' in Objective-C frameworks on various platforms, but I'm not sure of the exact meaning of the keyword here.)

---

For clarity, here's a direct link to the "hack"'s delegate implementation (the prepare_query implementation):

https://github.com/dkuku/opentelemetry_sqlcommenter/blob/75ff69d1ca3625b944ab80e8f3f844d07a1526d9/lib/opentelemetry_sqlcommenter.ex#L165-L173

And an example of setting it up, which worked for me:

https://github.com/dkuku/opentelemetry_sqlcommenter/blob/master/lib/opentelemetry_sqlcommenter.ex#L144-L150

[tsloughter]

Actually, I looked closer at this, having made too many assumptions that may have been wrong. The children that are detached have a parent span id that doesn't exist, right? Isn't the only way that can happen if a span doesn't get sent (or doesn't get sampled and thus not sent)? As in, the child span you need would appear to be being created thanks to how sqlcommenter is implemented and invoked but never exported for whatever reason?

[tsloughter]

As for 3 and 4. I'm not that familiar with Ecto either (my experience is Erlang with limited Elixir), I had forgotten it did this defmodule MyApp.Repo definition which then is used for querying the repo. If I had realized this defdelegate potential I'd have been pushing for that to be used for wrap things in spans from the beginning :). I don't know that I'd have won that argument, but at least now it can be had.

It would be optional since people will want prepared queries and unlike with sqlcommenter it isn't absolutely necessary, but it is a nice way around some other potential issues I think. Like people might be able to just add into their Repo module a case statement to not start a span if the query statement is BEGIN, COMMIT or ROLLBACK which seems better to me than having to do a sampler that runs for every single span in the system.

[bryannaegele]

This is a list of relevant info. The numbers don't correlate to anything else in the issue.

1. Ecto does not only work with relational databases, that's just its primary use
2. sqlcommenter only works with postgres and is intended as a debug tool since it will break query planning and caching. It's not intended for production use. You can leverage it for Datadog, but it's not something we'd introduce to otel ecto.
3. Ecto produces a single telemetry event at the same time it emits logs. It does not have separate lifecycle events.
4. sqlcommenter is going to set whatever the current ctx is which will not be an ecto span because it hasn't been created because of Ecto's limited telemetry events.
5. Ecto does not directly interact with the database, it leverages adaptors to technology-specific libraries such as postgrex, which in turn use libraries such as db_connection to manage the actual connections. None of those libraries emit telemetry which would be the desired points for database instrumentation.
6. opentelemetry_ecto uses opentelemetry_process_propagator to attempt to find a context in the current process or ancestors to a defined depth. If none is found, it would not have a parent and thus start a new trace.
7. Queries from preloads are always orphaned because they are created using Task which propagates ancestors on a different pdict key. We cannot search both for performance reasons. In user code, the Opentelemetry.ProcessPropagator.Task module addresses that issue.
8. In the case of 1:1 ecto query to database operation, an additional parent span would at least group those together.

Until the libraries emit more information, we are pretty much stuck in this position.

[tsloughter]

@bryannaegele but this has a missing span, its not a new trace, so its like a parent could be there and is just missing?

[bryannaegele]

Nah. If it had a parent it would be part of the trace. It's a span like any other. If no parent is found, a new trace would be started. If that were to get sampled, it would appear as an orphan.

This could be anything and not necessarily ecto related. Since that's a sqlcommenter initiated DD span. The parent wasn't likely ecto but whatever was invoking it. Someplace between nginx and those sql calls, at least one span didn't propagate with the usual suspects: parent span never closed, long-running process, etc. I would expect the ecto spans to appear as siblings to the SELECT statement spans due to the same parent.

[tsloughter]

You say 'nah' but then say the same thing, so I think we are talking past each other :). I agree its not necessarily Ecto related, I was thinking the parent was never ended and that was the issue. Something under /chats is creating a span and never ending it and that is what sqlcommenter is a child of.

[bryannaegele]

I think we are talking past each other

Highly likely given my mental capacity these days.

[ivucica]

The children that are detached have a parent span id that doesn't exist, right?

Something under /chats is creating a span and never ending it and that is what sqlcommenter is a child of

pg_tracing is, seemingly intentionally, inventing a span ID when one is invalid, by cropping the trace ID. Relevant snippets are quoted in DataDog/pg_tracing#84

I can't tell where it would even be possible for trace ID to be picked up, but span to remain zero:

https://github.com/DataDog/pg_tracing/blob/c343277660011200212c4e0833eea0c6b1ee8fa2/src/pg_tracing_query_process.c#L77-L117

but it seems to somehow fill trace ID and leave parent span ID empty, because I think it's hitting this codepath:

https://github.com/DataDog/pg_tracing/blob/c343277660011200212c4e0833eea0c6b1ee8fa2/src/pg_tracing_span.c#L16-L42

The second snippet shows how they're creating the span ID. I was rather confused about this: I thought I'm seeing random span IDs until by accident I noticed that bytes seem to match the end of the trace ID.

However, inventing a span ID doesn't happen always because sometimes opentracing-sqlcommenter gets a valid span ID from opentelemetry-phoenix. Query spans submitted by pg_tracing should always be children of opentelemetry-ecto spans (because that ID should be propagated by sqlcommenter, but it can't be), however we end up with parent span ID being either a fake, nonexistent span ID derived from trace ID (trace ID itself is typically¹ created by nginx), or the span ID from opentelemetry-phoenix (with trace ID from nginx, parent span ID from nginx).

Nah. If it had a parent it would be part of the trace.

Spans do not always get transmitted (as you two already discussed above), but this is especially going to be true for the fake one invented by pg_tracing inside PostgreSQL won't ever be transmitted.

---

Thanks for this follow-up @bryannaegele, some thoughts:

1. Ecto does not only work with relational databases, that's just its primary use

Got it, thanks!

2. sqlcommenter only works with postgres

Well, that's the situation right now. (Looking at performance_schema tables in MySQL / MariaDB, it looks like even without a tightly-integrated plugin, they could perhaps be leveraged to generate spans every N seconds.)

and is intended as a debug tool

Tracing in general is mostly useful as a debug tool, anyway.

since it will break query planning and caching. It's not intended for production use.

pg_tracing itself is generating loads of spans, simply that one by itself definitely doesn't feel like it should be in production, certainly not at anywhere near the 100% rate. But in this particular situation I am just trying to chase what's even happening without doing printf-debugging (which I would have a hard time doing in an unfamiliar language, anyway) :-)

Re: planning and caching, sure, it breaks preparation seemingly by design. I suppose that can break pre-planning which can happen as part of preparation (I did assume Postgres is doing that), but I doubt it should break data caching -- that shouldn't be there in the first place since there's no guarantees about data not changing under application's hood. (Other instance of the app or even the admin are perfectly free to mess with the stored data.)

All performance in the world in the frontend or backend is for nothing if the queries themselves don't scale. (For example: thousands of subqueries calling into Postgres's regex match function. I don't have the full query available because I don't have them logged yet, but that's what I saw in the spans.)

You can leverage it for Datadog,

For the record, I'm not specifically using Datadog, just using their pg_tracing extension.

but it's not something we'd introduce to otel ecto.

It'd be ideal if Ecto itself would allow a per-request override whether a "full" execution should happen, which otel-ecto could control using the "sampled" flag in traceparent. If, say, 1% of queries were sampled automatically (controllable by a flag, disabled by default), it'd likely be no problem in production: take the cost of un-prepared statement in favor of more closely debugging those particular requests.

3. Ecto produces a single telemetry event at the same time it emits logs. It does not have separate lifecycle events.
4. sqlcommenter is going to set whatever the current ctx is which will not be an ecto span because it hasn't been created because of Ecto's limited telemetry events.
5. Ecto does not directly interact with the database, it leverages adaptors to technology-specific libraries such as postgrex, which in turn use libraries such as db_connection to manage the actual connections. None of those libraries emit telemetry which would be the desired points for database instrumentation.

Honestly, it still sounds like Ecto itself would be a fine place to plug things in, if it did have a 'start' event. I don't need postgrex et al to do more than propagate the context down the network pipe (which sqlcommenter has successfully been hacked to do). Adaptors, maybe (if they are the ones responsible when to do prepare + cache the prepared statement). In case of 100% sample rate, "report start and end at the same time" would be completely acceptable (though I don't know how to report the query text: right now I get the query text from pg_tracing which is a big reason why I'd like them to be linked).

6. opentelemetry_ecto uses opentelemetry_process_propagator to attempt to find a context in the current process or ancestors to a defined depth. If none is found, it would not have a parent and thus start a new trace.
7. Queries from preloads are always orphaned because they are created using Task which propagates ancestors on a different pdict key. We cannot search both for performance reasons. In user code, the Opentelemetry.ProcessPropagator.Task module addresses that issue.
8. In the case of 1:1 ecto query to database operation, an additional parent span would at least group those together.

I mostly did not manage to follow these last two replies, but for e.g. 'cannot search both for performance reasons': I would be willing to take a performance hit most of the time, given the low traffic in my particular situation: the load is coming from the complex queries going into Postgres, and I really would like to have a clear understanding of those.

Production deployments may be willing to take a hit on a certain percentage of frontend traffic (i.e. lower sample rate).

But it is understandable if it's not doable, complexities in these situations are not obvious to a casual passerby like I happen to be.

Until the libraries emit more information, we are pretty much stuck in this position.

Based on your experience with maintainers of the other libraries, do you think it makes sense to file issues with them to see if they're willing to add more telemetry events, or not really? They may not be aware of the use cases.

---

If I do get wild enough to modify my local opentelemetry-sqlcommenter and opentelemetry-ecto to begin a span when something resembling start-of-processing happens, I'll post an update here. I'm mostly concerned about not being sure² where to store information that I've begun a span, and enough info to invoke End on it.

Whatever I do, I'd be happy with even the "not-production-worthy hack" label, just to get a nicer overview of what's even going on with some of these pageloads, API calls and regular check operations.

Footnotes

1. I'm saying typically because Pleroma has background tasks as well that also spawn ecto events. I haven't even begun looking at how to deal with those. ↩

2. I'd have some starting ideas about what to do in Go, C, Python even if I didn't have ctx propagation. For example, perhaps modify the 'query' object to have the span ID as an additional attribute, perhaps, and when 'telemetry' layer fires, I'd read it at that point. But: if you have some advice on how to approach this in a locally-modified piece of Elixir code, I'd appreciate that. ↩

[tsloughter]

Something under /chats is creating a span and never ending it and that is what sqlcommenter is a child of

pg_tracing is, seemingly intentionally, inventing a span ID when one is invalid, by cropping the trace ID.

This code is extracting the parent span id from a traceparent propagated string value version-traceid-parentid-sampled. So it is using what should be the parent span id, but I don't know where it is getting that propagated string.

[tsloughter]

Oh, that is what otel-sqlcommenter sends. So again, it seems to me that the spanid in the traceparent propagated by otel-sqlcommenter does not exist on the backend. Meaning something is not getting ended.

It may be also that due to when otel-ecto creates its span the tree of spans won't be correct, but it still seems to me there is first a missing span.

[tsloughter]

If I do get wild enough to modify my local opentelemetry-sqlcommenter and opentelemetry-ecto to begin a span when something resembling start-of-processing happens

You would have to modify Ecto itself to do this or modify Pleroma to add a defdelegate function, as you mention, to its Repo that sends a start event.