DO_NOT_MERGE: add instrumentation

[gmaclennan]

This is a proof-of-concept for adding OpenTelemetry instrumentation to CoMapeo Core. The main reason for this is to get detailed traces for debugging and performance monitoring for the internal workings. The reason for defining instrumentation as a global variable, rather than mutating a global singleton, is so that we can eventually publish @comapeo/core-instrumentation as a separate module, so that by default the OpenTelemetry dependencies are not included in this module. This approach is largely copied from how Prisma implements instrumentation.

This is a first-step to setting up distributed tracing, which will give us insight into how different components are interacting with each other. For distributed tracing between the backend and frontend of apps, because the boundary between the components is in the app (not in this library), the context should be propagated in the RPC that we setup between the front-end and back-end in the app, and we can create a parent span in the backend of the mobile app. Distributed tracing of p2p RPC will need to be implemented here in core, and will require adding a trace_parent field to the RPC messages.

I have used OpenTelemetry here, rather than Sentry, which we use in the apps, to avoid creating a dependency on a specific vendor in this library. Sentry is OpenTelemetry under-the-hood, so the instrumentation here will "just work" with Sentry, as seen with the test-sentry.js example, the result of which can be seen here.

Adding spans for tracing is a little more verbose than I would like - for the first time I understand why the JS Decorators approach exists, which would make the syntax a lot neater.

We need to decide what we want to add traces to, and how we want to instrument it. We could instrument dependencies like better-sqlite3 and hypercore separately, like is done with opentelemetry-plugin-better-sqlite3, however in experimenting, wrapping methods with module hooks is tricky to get working, and possibly impossible with bundled code, and the better-sqlite3 plugin adds way too much information, including all SQL calls, which is too much noise for our needs. I think we will be better wrapping what we want to measure within this module, including spans around hypercore calls and indexing etc.

We need to think through semantic names and attributes for all these spans, following as much as possible Sentry's list of operations and the otel semantic conventions, which will help when filtering and viewing this info in a tool like Sentry.

For testing this approach locally, to see how spans are exported, you can run a local instance of Jaeger with:

docker run --rm --name jaeger -d -e COLLECTOR_OTLP_ENABLED=true -p 16686:16686 -p 4318:4318 jaegertracing/all-in-one:latest

Then run the file test-otel.js which will export to Jaeger without any additional config. You can then open the Jaeger UI and view the spans that are exported.

The next steps I think are:

• Review if this approach is the one we want to use
• Decide how we are going to name and structure the spans we collect, as an example see these Prisma docs
• Add spans to what we want to measure
• Set up distributed tracing for p2p RPC
• Publish @comapeo/core-instrumentation as a separate module
• Import and configure ComapeoCoreInstrumentation in mobile backend with Sentry

We may need some special code for spans for p2p connections. By default OpenTelemetry uses AsyncStorage to correctly pass context between parent and child spans within async functions, but if you are not in an async context, then child spans can get associated with the wrong parent. To solve that we probably need to manually manage inactive spans for p2p connections, and attach child spans for things like sync to the correct parent.

[awana-lockfile-bot]

package-lock.json changes

Summary

Status	Count
	89
	3

Click to toggle table visibility

Name	Status	Previous	Current
@grpc/grpc-js		-	1.13.4
@grpc/proto-loader		-	0.7.15
@js-sdsl/ordered-map		-	4.4.2
@opentelemetry/api-logs		-	0.202.0
@opentelemetry/api		-	1.9.0
@opentelemetry/context-async-hooks		-	2.0.1
@opentelemetry/core		-	2.0.1
@opentelemetry/exporter-logs-otlp-grpc		-	0.202.0
@opentelemetry/exporter-logs-otlp-http		-	0.202.0
@opentelemetry/exporter-logs-otlp-proto		-	0.202.0
@opentelemetry/exporter-metrics-otlp-grpc		-	0.202.0
@opentelemetry/exporter-metrics-otlp-http		-	0.202.0
@opentelemetry/exporter-metrics-otlp-proto		-	0.202.0
@opentelemetry/exporter-prometheus		-	0.202.0
@opentelemetry/exporter-trace-otlp-grpc		-	0.202.0
@opentelemetry/exporter-trace-otlp-http		-	0.202.0
@opentelemetry/exporter-trace-otlp-proto		-	0.202.0
@opentelemetry/exporter-zipkin		-	2.0.1
@opentelemetry/instrumentation-amqplib		-	0.46.1
@opentelemetry/instrumentation-connect		-	0.43.1
@opentelemetry/instrumentation-dataloader		-	0.16.1
@opentelemetry/instrumentation-express		-	0.47.1
@opentelemetry/instrumentation-fs		-	0.19.1
@opentelemetry/instrumentation-generic-pool		-	0.43.1
@opentelemetry/instrumentation-graphql		-	0.47.1
@opentelemetry/instrumentation-hapi		-	0.45.2
@opentelemetry/instrumentation-http		-	0.57.2
@opentelemetry/instrumentation-ioredis		-	0.47.1
@opentelemetry/instrumentation-kafkajs		-	0.7.1
@opentelemetry/instrumentation-knex		-	0.44.1
@opentelemetry/instrumentation-koa		-	0.47.1
@opentelemetry/instrumentation-lru-memoizer		-	0.44.1
@opentelemetry/instrumentation-mongodb		-	0.52.0
@opentelemetry/instrumentation-mongoose		-	0.46.1
@opentelemetry/instrumentation-mysql		-	0.45.1
@opentelemetry/instrumentation-mysql2		-	0.45.2
@opentelemetry/instrumentation-pg		-	0.51.1
@opentelemetry/instrumentation-redis-4		-	0.46.1
@opentelemetry/instrumentation-tedious		-	0.18.1
@opentelemetry/instrumentation-undici		-	0.10.1
@opentelemetry/instrumentation		-	0.202.0
@opentelemetry/otlp-exporter-base		-	0.202.0
@opentelemetry/otlp-grpc-exporter-base		-	0.202.0
@opentelemetry/otlp-transformer		-	0.202.0
@opentelemetry/propagator-b3		-	2.0.1
@opentelemetry/propagator-jaeger		-	2.0.1
@opentelemetry/redis-common		-	0.36.2
@opentelemetry/resources		-	2.0.1
@opentelemetry/sdk-logs		-	0.202.0
@opentelemetry/sdk-metrics		-	2.0.1
@opentelemetry/sdk-node		-	0.202.0
@opentelemetry/sdk-trace-base		-	2.0.1
@opentelemetry/sdk-trace-node		-	2.0.1
@opentelemetry/semantic-conventions		-	1.34.0
@opentelemetry/sql-common		-	0.40.1
@prisma/instrumentation		-	6.8.2
@sentry/core		-	9.29.0
@sentry/node		-	9.29.0
@types/connect		-	3.4.38
@types/mysql		-	2.15.26
@types/pg-pool		-	2.0.6
@types/pg		-	8.6.1
@types/shimmer		-	1.2.0
@types/tedious		-	4.0.14
acorn-import-attributes		-	1.9.5
acorn		8.11.3	8.15.0
cjs-module-lexer		-	1.4.3
cliui		-	8.0.1
escalade		-	3.2.0
forwarded-parse		-	2.1.2
get-caller-file		-	2.0.5
import-in-the-middle		-	1.14.2
is-core-module		2.11.0	2.16.1
lodash.camelcase		-	4.3.0
module-details-from-path		-	1.0.4
opentelemetry-plugin-better-sqlite3		-	1.9.0
pg-int8		-	1.0.1
pg-protocol		-	1.10.0
pg-types		-	2.2.0
postgres-array		-	2.0.0
postgres-bytea		-	1.0.0
postgres-date		-	1.0.7
postgres-interval		-	1.2.0
require-directory		-	2.1.1
require-in-the-middle		-	7.5.2
resolve		1.22.1	1.22.10
semver		-	7.7.2
shimmer		-	1.2.1
xtend		-	4.0.2
y18n		-	5.0.8
yargs-parser		-	21.1.1
yargs		-	17.7.2

[RangerMauve]

Looks good so far. I'm a little bit concerned about the overhead adding callbacks everywhere adds. We'd be allocating more to the heap and adding extra stuff to the scope chain for every single call which IMO will add up on hot code paths.

Is using the tracer span and adding the .end() inside a finally block out of the question?

[RangerMauve]

Suggested change

	global[GLOBAL_INSTRUMENTATION_ACCESSOR_KEY] = globalValue
	globalThis[GLOBAL_INSTRUMENTATION_ACCESSOR_KEY] = globalValue

I prefer globalThis to global since it's the standard and is more future proof

[gmaclennan]

Looks good so far. I'm a little bit concerned about the overhead adding callbacks everywhere adds. We'd be allocating more to the heap and adding extra stuff to the scope chain for every single call which IMO will add up on hot code paths.

Is using the tracer span and adding the .end() inside a finally block out of the question?

Yeah, I wonder what overhead that will add, even when the callback is a noop. There are very few places where we would add this though in loop where it is called multiple times, so given the overall time that the functions we call take, does this really add much overhead?

In terms of creating an inactive span and calling .end(), the issue is that child spans are not automatically associated. When you wrap in a callback, you propagate the context, so, for example, we wrap the frontend RPC call in a span, then wrap the backend RPC receive in a span, then we wrap createProject, and then, for example saveToProjectKeysTable(), then each would be a child of the other, and you will be able to see the entire trace. Without wrapping in callbacks, these would each appear as separate unrelated spans.

I think the bigger overhead is for actually capturing and sending these spans / instrumentation, because I think in any code path we would only have 1-5 wrapping callbacks, which I don't think relatively would have a big effect. The actual "non-noop" instrumentation overhead may well be significant though, and to reduce that impact we would use a tracesSampleRate to less than 1.0, which reduces the impact by only sampling a proportion of spans.

[RangerMauve]

In terms of creating an inactive span and calling .end(), the issue is that child spans are not automatically associated. When you wrap in a callback, you propagate the context

What mechanism do they use for this feature? I'd be surprised if we couldn't set this sort of chaining without needing callbacks.

There are very few places where we would add this though in loop where it is called multiple times, so given the overall time that the functions we call take, does this really add much overhead?

Yeah I guess we don't have the instrumentation to measure this in the first place. 😅 I just worry we could go to a "death by a thousand paper cuts" situation if we don't consider performance stuff from the get go. Especially if efforts like the new HTTP APIs in comapeo cloud need to scale more if they get heavy usage. Though maybe we can revisit this later once we can get some flame graphs and see what the memory usage / GC overhead is in normal situations.

[gmaclennan]

What mechanism do they use for this feature? I'd be surprised if we couldn't set this sort of chaining without needing callbacks.

Otel uses AsyncLocalStorage. If we don't do this within a callback, then there is no way of knowing when there is more than one async operation at the same time, which child belongs to which parent. We could pass spans around ourselves, but that would be a lot of work and maintenance, and require adding a span option to many method calls.

There are very few places where we would add this though in loop where it is called multiple times, so given the overall time that the functions we call take, does this really add much overhead?

Yeah I guess we don't have the instrumentation to measure this in the first place. 😅 I just worry we could go to a "death by a thousand paper cuts" situation if we don't consider performance stuff from the get go. Especially if efforts like the new HTTP APIs in comapeo cloud need to scale more if they get heavy usage. Though maybe we can revisit this later once we can get some flame graphs and see what the memory usage / GC overhead is in normal situations.

I think it will only really become an issue with comapeo cloud, rather than in the app, as long as we avoid adding it to "hot" code paths, e.g. avoid adding it to an operation which is carried out multiple times. However, also, as I understand it, the standard approach, which I believe a lot of production apps use, is to instrument every single DB transaction, which would have a lot more overhead than what we are planning (when I instrumented better-sqlite3 it generated 245 spans for the create project operation, which I think it too much for our needs).

I think observing bugs and debugging issues is a priority right now, so I think it makes sense to add this, and then analyse the impact and possibly remove it later. It is just frustrating that decorators aren't finalized yet, because if they were then we could implement most of this with decorators for methods we want to trace, which would be easy to remove. We could consider adding a build-step to transform decorators, but I don't like that. We could even get fancy and add decorators in comments, and add our own build-step to transform the comments, but I haven't seen prior examples of that. The other possibility is that we add some kind of constructor function that wraps class methods in spans, and only do that when we explicitly turn it on.

[RangerMauve]

I think observing bugs and debugging issues is a priority right now, so I think it makes sense to add this, and then analyse the impact and possibly remove it later.

Agreed

frustrating that decorators aren't finalized yet, because if they were then we could implement most of this with decorators for methods we want to trace, which would be easy to remove.

I think our API surface is small enough that adding the current approach won't be too bad. Worst case we could even run a transform over the AST to remove trace code if it's repetitive enough.

Another option might be to wrap objects in a Proxy which instruments all api calls. That might also have a performance hit but not sure if it's too much worse.

[gmaclennan]

Unfortunately using a Proxy as in 1a9793f is not going to work, because for correct behaviour it's necessary to pass the receiver (e.g. the object returned by new Proxy()) as the this argument in wrapped functions, because if we pass the target (e.g. the class instance), then any method calls within any instrumented function will be the originals on the class instance, not the proxied versions. This is just going to be confusing and lead to unexpected instrumentation bugs. However if we pass receiver as this, then any instrumented functions are unable to access private properties and methods, so the code doesn't work. In conclusion I don't think the approach is a good one, and if we're concerned about the overhead of wrapping code in callbacks, we now have the additional overhead of a proxy for all methods.

An alternative approach would be to mutate / override the original methods in the constructor, e.g.

const createProjectOrig = this.createProject
this.createProject = instrument(createProjectOrig)

However in the end I think it's clearer to just directly write the instrumentation in each method, as in the original commit dc83e6c - this has the disadvantage of a larger commit for the changes, because of the indentation within the callback, but this can be ignored when reviewing by selecting the "ignore white space" option in the github diff view and in git diff. That approach leaves it really clear which methods are wrapped and what the wrapping is doing.