observability: annotate Session+SessionPool events #1207

odeke-em · 2024-09-19T03:48:09Z

This change adds annotations for session and session pool events to aid customers in debugging latency issues with session pool malevolence and also for maintainers to figure out which session pool type is the most appropriate.

Updates #1170

odeke-em · 2024-09-19T07:41:52Z

Exhibit

On running examples/grpc_instrumentation_enabled.py we get back these traces

odeke-em · 2024-09-19T07:42:08Z

cc @harshachinta

This change adds annotations for session and session pool events to aid customers in debugging latency issues with session pool malevolence and also for maintainers to figure out which session pool type is the most appropriate. Updates googleapis#1170

This allows us to avoid the flakes with OpenTelemetry's inMemorySpanExporter that might not have received the exported spans yet.

odeke-em · 2024-09-20T22:10:24Z

Kindly cc-ing you @harshachinta.

google/cloud/spanner_v1/pool.py

google/cloud/spanner_v1/_opentelemetry_tracing.py

google/cloud/spanner_v1/pool.py

harshachinta · 2024-09-30T11:22:42Z

google/cloud/spanner_v1/pool.py

+        start_time = time.time()
+        current_span = get_current_span()
+        current_span.add_event(
+            "Waiting for a session to become available", {"kind": "pinging_pool"}


Why is this not "Acquiring a session"? Lets maintain span consistency across all the pools.

Because really it is waiting for a session to become available per

python-spanner/google/cloud/spanner_v1/pool.py

Lines 218 to 238 in b2e6762

def get(self, timeout=None):

"""Check a session out from the pool.

:type timeout: int

:param timeout: seconds to block waiting for an available session

:rtype: :class:`~google.cloud.spanner_v1.session.Session`

:returns: an existing session from the pool, or a newly-created

session.

:raises: :exc:`queue.Empty` if the queue is empty.

"""

if timeout is None:

timeout = self.default_timeout

session = self._sessions.get(block=True, timeout=timeout)

if not session.exists():

session = self._database.session()

session.create()

return session

and in our document requirements there is a clear need to add that case

google/cloud/spanner_v1/session.py

odeke-em · 2024-10-07T02:37:26Z

Kindly please take another look @harshachinta, feedback addressed, thank you for the code review!

harshachinta · 2024-10-09T12:44:42Z

google/cloud/spanner_v1/_opentelemetry_tracing.py

            raise
        else:
            span.set_status(Status(StatusCode.OK))
+
+
+def set_span_error_and_record_exception(span, exc):


Since this is not used anywhere else, we can revert it back as it was.

harshachinta · 2024-10-09T12:44:47Z

google/cloud/spanner_v1/pool.py

-            resp = api.batch_create_sessions(
-                request=request,
-                metadata=metadata,
+        with trace_call("CloudSpanner.BatchCreateSessions", self) as span:


looks like trace_call is not imported here.

from google.cloud.spanner_v1._opentelemetry_tracing import trace_call

harshachinta · 2024-10-09T12:45:11Z

google/cloud/spanner_v1/pool.py

+            )
+
+            if requested_session_count > 0:
+                current_span.add_event(


current_span is not initialized.

Sheesh, sorry I had a bunch of benchmarks running locally and they interrupted my nox -s unit-3.8 tests so didn't see those but all fixed now.

harshachinta · 2024-10-10T11:21:45Z

google/cloud/spanner_v1/_opentelemetry_tracing.py

+
+
+def get_current_span():
+    return trace.get_current_span()


I am afraid what happens here if opentelemetry is not installed.
trace will be None right? then all the places where this function will get invoked will get Null pointer exception.

harshachinta · 2024-10-10T11:21:58Z

google/cloud/spanner_v1/pool.py

+            )
+
+            if requested_session_count > 0:
+                span.add_event(


Clearly span here could be None if opentelemetry is not installed (see

python-spanner/google/cloud/spanner_v1/_opentelemetry_tracing.py

Line 56 in b2e6762

# Empty context manager. Users will have to check if the generated value is None or a span

).

In that case it can throw AttributeError: 'NoneType' object has no attribute 'add_event'

harshachinta · 2024-10-10T11:22:10Z

google/cloud/spanner_v1/pool.py

            session = self._database.session()
            session.create()
+            span_event_attributes["id"] = self._session_id


Here _session_id is not a propery of pool.
Test cases are already failing for this

Looks like this should be session.session_id

harshachinta · 2024-10-10T11:52:21Z

google/cloud/spanner_v1/pool.py

        session = self._sessions.get(block=True, timeout=timeout)
+        span_event_attributes["session.id"] = session.session_id


Here session.session_id can be empty, if session does not exist. Move this attribute addignment to after the if block below, as it ensures that session will be available.

harshachinta · 2024-10-10T11:53:24Z

google/cloud/spanner_v1/pool.py

            session = self._database.session()
            session.create()
+            span_event_attributes["id"] = self._session_id


What is the attribute we are using for session id?
In some place above it was session.id, but here it is id. Can we follow the attribure naming consistently?

harshachinta · 2024-10-10T12:06:57Z

google/cloud/spanner_v1/pool.py


+        span_event_attributes["time.elapsed"] = time.time() - start_time
+        current_span.add_event("Acquired session", span_event_attributes)


It makes more sense to have "Acquired Session" and then "Using Session".

Also I feel "Acquired Session" event should exist when a session lies in pool. If there is no session in pool then we are creating session and in that case "Acquired Session" does not make sense.

So the span event hierachy would something be like this.

If session exists in the pool, then

Acquiring Session

Waiting for a session to become available

Acquired Session

Using Session

If no session in the pool

Acquiring Session

Waiting for a session to become available

No session available

Creating Session

CloudSpanner.CreateSession span

Using Session

Does that sound good?
@surbhigarg92 Do you have any comments on this structure?

harshachinta · 2024-10-10T12:16:52Z

google/cloud/spanner_v1/pool.py

@@ -422,6 +480,18 @@ def bind(self, database):
            session_template=Session(creator_role=self.database_role),
        )

+        requested_session_count = request.session_count


Have you not followed the BatchCreateSession span here as commented earlier somewhere above?

harshachinta · 2024-10-10T12:19:50Z

google/cloud/spanner_v1/session.py

-            raise ValueError("No session ID set by back-end")
+            err_message = "No session ID set by back-end"
+            current_span = get_current_span()
+            current_span.add_event(err_message)


Will this error not get captured by parent span? Do we need to add it as event here?

harshachinta · 2024-10-10T12:21:00Z

google/cloud/spanner_v1/session.py

        if self._session_id is not None:
-            raise ValueError("Session ID already set by back-end")
+            err_message = "Session ID already set by back-end"
+            current_span.add_event(err_message)


Same here also, will this not be captured by current_span?

harshachinta · 2024-10-10T12:23:05Z

tests/unit/test_session.py

@@ -174,6 +175,43 @@ def test_create_w_database_role(self):
            "CloudSpanner.CreateSession", attributes=TestSession.BASE_ATTRIBUTES
        )

+    def test_create_session_span_annotations(self):


Can we add unit tests to verify spans for different pool class similar to what is done for create_session?

odeke-em requested review from a team as code owners September 19, 2024 03:48

product-auto-label bot added the size: m Pull request size is medium. label Sep 19, 2024

blunderbuss-gcf bot assigned manu2 Sep 19, 2024

product-auto-label bot added the api: spanner Issues related to the googleapis/python-spanner API. label Sep 19, 2024

odeke-em force-pushed the trace-annotation-SessionPools branch 3 times, most recently from 8d6f2b7 to 4bc937e Compare September 19, 2024 07:37

odeke-em force-pushed the trace-annotation-SessionPools branch from 4bc937e to 0d5bf26 Compare September 19, 2024 07:45

harshachinta added the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 19, 2024

yoshi-kokoro removed the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 19, 2024

odeke-em force-pushed the trace-annotation-SessionPools branch from 0d5bf26 to 3617921 Compare September 19, 2024 13:43

harshachinta added the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 19, 2024

yoshi-kokoro removed the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 19, 2024

odeke-em force-pushed the trace-annotation-SessionPools branch 2 times, most recently from f71d05c to eb9dd5a Compare September 20, 2024 01:27

harshachinta added the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 20, 2024

yoshi-kokoro removed the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 20, 2024

odeke-em added 2 commits September 20, 2024 11:49

tests/unit/*tracing: pass current span into assertions

ab23f09

This allows us to avoid the flakes with OpenTelemetry's inMemorySpanExporter that might not have received the exported spans yet.

odeke-em force-pushed the trace-annotation-SessionPools branch from b1ea772 to ab23f09 Compare September 20, 2024 22:09

harshachinta added the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 23, 2024

yoshi-kokoro removed the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Sep 23, 2024

harshachinta requested changes Oct 1, 2024

View reviewed changes

odeke-em added 2 commits October 5, 2024 23:53

observability: address review feedback

0ce415b

Add BatchCreateSessions

aadb961

odeke-em requested a review from harshachinta October 7, 2024 02:36

harshachinta reviewed Oct 9, 2024

View reviewed changes

Address code review feedback

7cbbb0f

odeke-em force-pushed the trace-annotation-SessionPools branch from 3c0c421 to 7cbbb0f Compare October 9, 2024 13:46

harshachinta added the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Oct 10, 2024

yoshi-kokoro removed the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Oct 10, 2024

harshachinta reviewed Oct 10, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

observability: annotate Session+SessionPool events #1207

observability: annotate Session+SessionPool events #1207

odeke-em commented Sep 19, 2024

odeke-em commented Sep 19, 2024

odeke-em commented Sep 19, 2024

odeke-em commented Sep 20, 2024

harshachinta Sep 30, 2024

odeke-em Oct 6, 2024

odeke-em commented Oct 7, 2024

harshachinta Oct 9, 2024

harshachinta Oct 9, 2024

harshachinta Oct 9, 2024

odeke-em Oct 9, 2024

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024 •

edited

Loading

harshachinta Oct 10, 2024 •

edited

Loading

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024

harshachinta Oct 10, 2024

	def get(self, timeout=None):
	"""Check a session out from the pool.

	:type timeout: int
	:param timeout: seconds to block waiting for an available session

	:rtype: :class:`~google.cloud.spanner_v1.session.Session`
	:returns: an existing session from the pool, or a newly-created
	session.
	:raises: :exc:`queue.Empty` if the queue is empty.
	"""
	if timeout is None:
	timeout = self.default_timeout

	session = self._sessions.get(block=True, timeout=timeout)

	if not session.exists():
	session = self._database.session()
	session.create()

	return session

		session = self._sessions.get(block=True, timeout=timeout)
		span_event_attributes["session.id"] = session.session_id


		span_event_attributes["time.elapsed"] = time.time() - start_time
		current_span.add_event("Acquired session", span_event_attributes)

observability: annotate Session+SessionPool events #1207

Are you sure you want to change the base?

observability: annotate Session+SessionPool events #1207

Conversation

odeke-em commented Sep 19, 2024

odeke-em commented Sep 19, 2024

Exhibit

odeke-em commented Sep 19, 2024

odeke-em commented Sep 20, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

odeke-em commented Oct 7, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

harshachinta Oct 10, 2024 • edited Loading

Choose a reason for hiding this comment

harshachinta Oct 10, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

harshachinta Oct 10, 2024 •

edited

Loading

harshachinta Oct 10, 2024 •

edited

Loading