Need to generate telemetry for Expand, Resultify, ARAX_query

At today's performances and testing call it was noted that there are still substantial gaps in the ARAX telemetry.
For example, xDTD is now instrumented and we get lots of telemetry for each one of its SQLite calls, but then when xDTD is done, there is silence for the rest of the processing, where presumably it is doing a lookup call to Retriever, then merging the results of xDTD and Retriever and then doing NGD lookups and then scoring, and then transmitting back to ARS. None of that seems to be intrumented and thus there is no visibility in Jaeger. Consensus is that it should be.

@chunyuma

Thanks for bringing this to my attention. I'm also going to tentatively co-assign this to @chunyuma since it involves (in part) xDTD. I think @bazarkua can look into the non-xDTD telemetry parts of ARAX. Maybe it is turned off, globally? (For a while, we had it turned off by default in ARAX).

@edeutsch

@edeutsch I have a clarifying question. The reports that you got from the Performance and Testing call, did they say which ARAX service/maturity was not transmitting OTel data? Was it ITRB CI? Or ITRB Test? Or ITRB Prod?

@saramsey

@saramsey @bazarkua, please let me know what I can help with this issue.

@saramsey

@saramsey These reports are related to the CI maturity (although I strongly suspect that they are equally applicable to TEST and PROD but not examined there)

Therefore fixes for this can go in as PRs against master

@saramsey

@saramsey I looked into this on CI. Telemetry is not turned off. ARAX is sending spans to Jaeger and they show up there. The gap is that ARAX itself creates almost no spans of its own. Everything we see in Jaeger comes from automatic instrumentation of libraries: every SQLite call, every incoming Flask request, and every outgoing HTTP call made with requests or aiohttp (for example to NodeNorm and Retriever). The only spans written into ARAX code by hand are the two Pathfinder ones added in #2919.

That is why xDTD looks well instrumented. It makes thousands of SQLite calls, and each one becomes a span automatically. The steps after xDTD (merging the xDTD and Retriever results, NGD lookups, scoring, building the response) have no spans of their own. Where a step reads SQLite, like the NGD lookups, we only see anonymous SELECT spans, and nothing says which step is running or how long it took. For example, in one xDTD query on CI the request took 21.9 s, and the last span ended at 20.6 s, so the final 1.3 s has nothing in it.

I also checked why Expand's call to Retriever was missing from those traces. I sent one lookup query to arax.ci.transltr.io with bypass_cache, so Expand had to call Retriever. Its trace has the aiohttp span for the POST to retriever.ci.transltr.io, and Retriever's and Gandalf's own spans are in the same trace. So the aiohttp instrumentation works. In the earlier traces the call was missing because no HTTP call was made, which is what happens when the answer comes from ARAX's KP cache. Right now a cache hit is invisible in Jaeger.

Commands and output

Where ARAX spans come from on CI (last 48 h):

$ curl -s "https://translator-otel.ci.transltr.io/api/traces?service=ARAX&lookback=48h&limit=200" | jq -r '.data[] as $t | $t.spans[] | select($t.processes[.processID].serviceName=="ARAX") | .tags[] | select(.key=="otel.scope.name") | .value' | sort | uniq -c | sort -rn
9548 opentelemetry.instrumentation.sqlite3
  47 opentelemetry.instrumentation.flask
  33 opentelemetry.instrumentation.requests

Spans written by hand in ARAX code:

$ git grep -n "start_as_current_span" origin/master -- code/ARAX
origin/master:code/ARAX/ARAXQuery/ARAX_connect.py:484:            with tracer.start_as_current_span(
origin/master:code/ARAX/ARAXQuery/ARAX_connect.py:515:        with tracer.start_as_current_span("ARAX_connect.convert_to_trapi"):

The xDTD query example:

$ curl -s "https://translator-otel.ci.transltr.io/api/traces/75e4cacfba5d587859aed01b6a828494" | jq '.data[0].spans as $s | ($s[] | select(.operationName=="POST /api/arax/v1.4/query")) as $r | {request_s: ($r.duration/1e6), last_other_span_ends_at_s: ((([$s[] | select(.spanID != $r.spanID) | .startTime + .duration] | max) - $r.startTime)/1e6)}'
{
  "request_s": 21.925678,
  "last_other_span_ends_at_s": 20.618815
}

Lookup query with the cache bypassed, so Expand must call Retriever:

$ curl -s -X POST "https://arax.ci.transltr.io/api/arax/v1.4/query" -H "Content-Type: application/json" -d '{"message":{"query_graph":{"nodes":{"n0":{"ids":["CHEBI:46195"]},"n1":{"categories":["biolink:Protein"]}},"edges":{"e0":{"subject":"n0","object":"n1","predicates":["biolink:interacts_with"]}}}},"query_options":{"bypass_cache":true},"submitter":"bazarkua_otel_check_2923"}' | jq -c '{status, results: (.message.results | length), retriever: .query_options.query_plan.qedge_keys.e0["infores:retriever"].description}'
{"status":"Success","results":58,"retriever":"Returned 80 edges in 0.16 seconds"}

Its trace in Jaeger, spans by service and instrumentation:

$ curl -s "https://translator-otel.ci.transltr.io/api/traces/56aa3e7ce5cb85c8bcf1f5185d5cd1e4" | jq -r '.data[0] as $t | $t.spans[] | [$t.processes[.processID].serviceName, .operationName, ((.tags[] | select(.key=="otel.scope.name") | .value) // "-")] | @tsv' | sort | uniq -c | sort -rn
  59 NodeNorm	msearch	elasticsearch-api
   8 ARAX	PRAGMA	opentelemetry.instrumentation.sqlite3
   6 NodeNorm	POST /get_normalized_nodes?	opentelemetry.instrumentation.tornado
   6 ARAX	POST	opentelemetry.instrumentation.requests
   4 ARAX	SELECT	opentelemetry.instrumentation.sqlite3
   1 retriever	tier0_execute	lookup.execution.tracer
   1 retriever	operation_plan	lookup.execution.tracer
   1 retriever	POST /query	opentelemetry.instrumentation.fastapi
   1 retriever	POST	opentelemetry.instrumentation.httpx
   1 gandalf	gandalf.queue_wait	gandalf
   1 gandalf	gandalf.job	gandalf
   1 gandalf	gandalf.execute	gandalf
   1 gandalf	gandalf.deliver	gandalf
   1 gandalf	POST /query	opentelemetry.instrumentation.fastapi
   1 ARAX	POST /api/arax/v1.4/query	opentelemetry.instrumentation.flask
   1 ARAX	POST	opentelemetry.instrumentation.aiohttp_client
   1 ARAX	INSERT	opentelemetry.instrumentation.sqlite3

$ curl -s "https://translator-otel.ci.transltr.io/api/traces/56aa3e7ce5cb85c8bcf1f5185d5cd1e4" | jq -r '.data[0].spans[] | select(any(.tags[]; .key=="otel.scope.name" and .value=="opentelemetry.instrumentation.aiohttp_client")) | [.operationName, (.duration/1e6|tostring)+"s", (.tags[] | select(.key=="http.url" or .key=="url.full") | .value)] | @tsv'
POST	0.111302s	https://retriever.ci.transltr.io/query

To get tracing for the rest of the processing, we can add a span around each ARAXi action in the main processing loop here (expand, overlay, resultify, rank_results, and so on), plus the result transformer and saving the response, and a span for each KP call in Expand with the KP name, cache hit or miss, and number of results. That should cover all the gaps listed above.

RTX/code/ARAX/ARAXQuery/ARAX_query.py

Lines 757 to 762 in b2ce180

    
           for action in actions: 
        
               # Note: This logging message is keyed off to provide progress updates to the RTX front-end. 
        
               response.info(f"Processing action '{action['command']}' with parameters {action['parameters']}") 
        
               # Catch a crash 
        
               try:

@edeutsch I'll open a PR with the fix against master.

@chunyuma

@chunyuma just to clarify, there is no problem in xDTD itself. xDTD looks the most detailed in Jaeger because the SQLite auto-instrumentation turns every SQLite query it runs into a span.

One optional idea for xDTD, only if you think it is useful: a single span around the xDTD call, for example with the number of predicted drugs and paths. Then in Jaeger it is easy to see where xDTD starts and ends, instead of only a long list of SELECT spans (about 9,500 in one query on CI). (just a suggestion)

@chunyuma

Thank you so much for your suggestions @chunyuma. We have actually resolved the issue of thousands of SQLite calls in xDTD in #2894 (by using batch query, which reduces thousands of calls to only 3-4). However, it seems like this PR is still under tests by @hodgesf. So, I would like to get an idea from Frankie to see whether it is ready to be merged.

Navigation Menu

Repository navigation

Need to generate telemetry for Expand, Resultify, ARAX_query #2923

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	for action in actions:
	# Note: This logging message is keyed off to provide progress updates to the RTX front-end.
	response.info(f"Processing action '{action['command']}' with parameters {action['parameters']}")

	# Catch a crash
	try:

Need to generate telemetry for Expand, Resultify, ARAX_query #2923

Description

Activity

saramsey commented on Oct 20, 2026

saramsey commented on Oct 20, 2026

chunyuma commented on Oct 20, 2026

edeutsch commented on Oct 20, 2026

bazarkua commented on Oct 21, 2026

bazarkua commented on Oct 21, 2026

chunyuma commented on Oct 21, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions