Tracing for beginning of query for telemetry

[ksmithut]

I've been digging into instrumenting our project with opentelemetry, and the tracing you've provided works great for getting metrics for queries already run, but I wonder what your appetite would be for adding traces in right before a query is executed? I'd be happy to jump in and add it in if you're open to the feature. It's helpful in our trace visualization tool to see where and when a query starts and end to see how it affects application performance in relation to concurrently running code. Also knowing the best place to add it in would be helpful. I see that the current traces happen in the check_for_error function, which won't run if you don't get an {:ok, cmd, response} response from DBConnection.execute. I wonder if DBConnection.execute would be the best place to put that? Or perhaps in something that gets called everywhere before DBConnection.execute gets called?

[zookzook]

We can add the tracing stuff to the driver. I figure out where we can add it. Do you have a rough code example, what we need to do.

[ksmithut]

I think similar to what you've got here, but it could be something like:

:telemetry.execute([:mongodb_driver, :execution, :start], %{}, metadata)

Right now what I'm doing is hooking up the telemetry you've got already to open telemetry. But all my timings were instant because I didn't have a start time. I'm able to fake a start time by taking the current time and subtracting the execution, which is fine. But most libraries I interact with (like absinthe and finch) expose telemetry calls for the start and end of operations to get better timings.

[zookzook]

I guess you are using https://github.com/open-telemetry for tracing?!? I don't want to add a new dependency here, because it seems that the package is not documented very well (at least for me). I looked here to understand how it works: https://github.com/open-telemetry/opentelemetry-erlang-contrib/blob/main/instrumentation/opentelemetry_ecto/lib/opentelemetry_ecto.ex. Maybe I can add some hooks that are called if defined when encoding/decoding documents when the request is sent to the database and when the response is received.

[ksmithut]

You shouldn’t worry about adding any open-telemetry stuff into this project, just the :telemetry calls, and I can hook into those for my open telemetry integration. Maybe at one point I can publish what I’ve got as a hex package for others to use (once I’ve worked out all the kinks)

[zookzook]

Ah I understand it now. I will check it as soon I find some time to get into it.

[ksmithut]

No rush :) I've got something working that works for now.

[zookzook]

I added this before the command is sent to the database:

    metadata = %{
      type: :mongodb_driver,
      command: data,
      command_name: opts[:command_name] || command_name,
      database_name: db,
      request_id: state.request_id,
      operation_id: opts[:operation_id],
      connection_id: self(),
      options: Keyword.get(opts, :telemetry_options, [])
    }

    :telemetry.execute([:mongodb_driver, :start], %{}, metadata)

Here is an example:

%{command: [find: "global_configs", filter: [_id: #BSON.ObjectId<6283581e4ae06e6a9fbaef7c>], limit: 1, batchSize: 1, lsid: %{id: #BSON.UUID<c45ddab5-6757-4702-8c43-fb9f2f77e378>}, "$readPreference": %{mode: :primary}], command_name: :find, connection_id: #PID<0.1339.0>, database_name: "onsen", operation_id: nil, options: [], request_id: 1, type: :mongodb_driver}

Feel free to try the master branch

[zookzook]

Feel free to reopen the issue if you need more meta data.