1818import time
1919import re
2020import logging
21- import uuid
2221import contextvars
2322
2423from enum import Enum
4241
4342# default values for zone and cluster data, if not captured
4443DEFAULT_ZONE = "global"
45- DEFAULT_CLUSTER_ID = "unspecified"
44+ DEFAULT_CLUSTER_ID = "< unspecified> "
4645
4746# keys for parsing metadata blobs
48- BIGTABLE_METADATA_KEY = "x-goog-ext-425905942-bin"
47+ BIGTABLE_LOCATION_METADATA_KEY = "x-goog-ext-425905942-bin"
4948SERVER_TIMING_METADATA_KEY = "server-timing"
5049SERVER_TIMING_REGEX = re .compile (r".*gfet4t7;\s*dur=(\d+\.?\d*).*" )
5150
@@ -64,7 +63,23 @@ class OperationType(Enum):
6463
6564
6665class OperationState (Enum ):
67- """Enum for the state of the active operation."""
66+ """Enum for the state of the active operation.
67+
68+ ┌───────────┐
69+ │ CREATED │────────┐
70+ └─────┬─────┘ │
71+ │ │
72+ ▼ │
73+ ┌▶ ACTIVE_ATTEMPT ───┐│
74+ │ │ ││
75+ │ ▼ ││
76+ └─ BETWEEN_ATTEMPTS ││
77+ │ ││
78+ ▼ ││
79+ ┌───────────┐ ││
80+ │ COMPLETED │ ◀─────┘│
81+ └───────────┘ ◀──────┘
82+ """
6883
6984 CREATED = 0
7085 ACTIVE_ATTEMPT = 1
@@ -87,7 +102,6 @@ class CompletedAttemptMetric:
87102 gfe_latency_ns : int | None = None
88103 application_blocking_time_ns : int = 0
89104 backoff_before_attempt_ns : int = 0
90- grpc_throttling_time_ns : int = 0
91105
92106
93107@dataclass (frozen = True )
@@ -101,7 +115,6 @@ class CompletedOperationMetric:
101115 """
102116
103117 op_type : OperationType
104- uuid : str
105118 duration_ns : int
106119 completed_attempts : list [CompletedAttemptMetric ]
107120 final_status : StatusCode
@@ -128,9 +141,6 @@ class ActiveAttemptMetric:
128141 application_blocking_time_ns : int = 0
129142 # backoff time is added to application_blocking_time_ns
130143 backoff_before_attempt_ns : int = 0
131- # time waiting on grpc channel, in nanoseconds
132- # TODO: capture grpc_throttling_time
133- grpc_throttling_time_ns : int = 0
134144
135145
136146@dataclass
@@ -141,7 +151,7 @@ class ActiveOperationMetric:
141151 """
142152
143153 op_type : OperationType
144- uuid : str = field ( default_factory = lambda : str ( uuid . uuid4 ()))
154+ state : OperationState = OperationState . CREATED
145155 # create a default backoff generator, initialized with standard default backoff values
146156 backoff_generator : TrackedBackoffGenerator = field (
147157 default_factory = lambda : TrackedBackoffGenerator (
@@ -155,7 +165,6 @@ class ActiveOperationMetric:
155165 zone : str | None = None
156166 completed_attempts : list [CompletedAttemptMetric ] = field (default_factory = list )
157167 is_streaming : bool = False # only True for read_rows operations
158- was_completed : bool = False
159168 handlers : list [MetricsHandler ] = field (default_factory = list )
160169 # the time it takes to recieve the first response from the server, in nanoseconds
161170 # attached by interceptor
@@ -190,18 +199,6 @@ def from_context(cls) -> ActiveOperationMetric | None:
190199 return None
191200 return op
192201
193- @property
194- def state (self ) -> OperationState :
195- if self .was_completed :
196- return OperationState .COMPLETED
197- elif self .active_attempt is None :
198- if self .completed_attempts :
199- return OperationState .BETWEEN_ATTEMPTS
200- else :
201- return OperationState .CREATED
202- else :
203- return OperationState .ACTIVE_ATTEMPT
204-
205202 def __post_init__ (self ):
206203 """
207204 Save new instances to contextvars on init
@@ -213,7 +210,8 @@ def start(self) -> None:
213210 Optionally called to mark the start of the operation. If not called,
214211 the operation will be started at initialization.
215212
216- Assumes operation is in CREATED state.
213+ StartState: CREATED
214+ EndState: CREATED
217215 """
218216 if self .state != OperationState .CREATED :
219217 return self ._handle_error (INVALID_STATE_ERROR .format ("start" , self .state ))
@@ -225,7 +223,8 @@ def start_attempt(self) -> ActiveAttemptMetric | None:
225223 """
226224 Called to initiate a new attempt for the operation.
227225
228- Assumes operation is in either CREATED or BETWEEN_ATTEMPTS states
226+ StartState: CREATED | BETWEEN_ATTEMPTS
227+ EndState: ACTIVE_ATTEMPT
229228 """
230229 if (
231230 self .state != OperationState .BETWEEN_ATTEMPTS
@@ -248,6 +247,7 @@ def start_attempt(self) -> ActiveAttemptMetric | None:
248247 backoff_ns = 0
249248
250249 self .active_attempt = ActiveAttemptMetric (backoff_before_attempt_ns = backoff_ns )
250+ self .state = OperationState .ACTIVE_ATTEMPT
251251 return self .active_attempt
252252
253253 def add_response_metadata (self , metadata : dict [str , bytes | str ]) -> None :
@@ -256,7 +256,8 @@ def add_response_metadata(self, metadata: dict[str, bytes | str]) -> None:
256256
257257 If not called, default values for the metadata will be used.
258258
259- Assumes operation is in ACTIVE_ATTEMPT state.
259+ StartState: ACTIVE_ATTEMPT
260+ EndState: ACTIVE_ATTEMPT
260261
261262 Args:
262263 - metadata: the metadata as extracted from the grpc call
@@ -266,8 +267,8 @@ def add_response_metadata(self, metadata: dict[str, bytes | str]) -> None:
266267 INVALID_STATE_ERROR .format ("add_response_metadata" , self .state )
267268 )
268269 if self .cluster_id is None or self .zone is None :
269- # BIGTABLE_METADATA_KEY should give a binary-encoded ResponseParams proto
270- blob = cast (bytes , metadata .get (BIGTABLE_METADATA_KEY ))
270+ # BIGTABLE_LOCATION_METADATA_KEY should give a binary-encoded ResponseParams proto
271+ blob = cast (bytes , metadata .get (BIGTABLE_LOCATION_METADATA_KEY ))
271272 if blob :
272273 parse_result = self ._parse_response_metadata_blob (blob )
273274 if parse_result is not None :
@@ -278,7 +279,7 @@ def add_response_metadata(self, metadata: dict[str, bytes | str]) -> None:
278279 self .zone = zone
279280 else :
280281 self ._handle_error (
281- f"Failed to decode { BIGTABLE_METADATA_KEY } metadata: { blob !r} "
282+ f"Failed to decode { BIGTABLE_LOCATION_METADATA_KEY } metadata: { blob !r} "
282283 )
283284 # SERVER_TIMING_METADATA_KEY should give a string with the server-latency headers
284285 timing_header = cast (str , metadata .get (SERVER_TIMING_METADATA_KEY ))
@@ -316,7 +317,8 @@ def end_attempt_with_status(self, status: StatusCode | BaseException) -> None:
316317 be attempted, `end_with_status` or `end_with_success` should be used
317318 to finalize the operation along with the attempt.
318319
319- Assumes operation is in ACTIVE_ATTEMPT state.
320+ StartState: ACTIVE_ATTEMPT
321+ EndState: BETWEEN_ATTEMPTS
320322
321323 Args:
322324 - status: The status of the attempt.
@@ -327,16 +329,19 @@ def end_attempt_with_status(self, status: StatusCode | BaseException) -> None:
327329 )
328330 if isinstance (status , BaseException ):
329331 status = self ._exc_to_status (status )
332+ duration_ns = self ._ensure_positive (
333+ time .monotonic_ns () - self .active_attempt .start_time_ns , "duration"
334+ )
330335 complete_attempt = CompletedAttemptMetric (
331- duration_ns = time . monotonic_ns () - self . active_attempt . start_time_ns ,
336+ duration_ns = duration_ns ,
332337 end_status = status ,
333338 gfe_latency_ns = self .active_attempt .gfe_latency_ns ,
334339 application_blocking_time_ns = self .active_attempt .application_blocking_time_ns ,
335340 backoff_before_attempt_ns = self .active_attempt .backoff_before_attempt_ns ,
336- grpc_throttling_time_ns = self .active_attempt .grpc_throttling_time_ns ,
337341 )
338342 self .completed_attempts .append (complete_attempt )
339343 self .active_attempt = None
344+ self .state = OperationState .BETWEEN_ATTEMPTS
340345 for handler in self .handlers :
341346 handler .on_attempt_complete (complete_attempt , self )
342347
@@ -345,7 +350,8 @@ def end_with_status(self, status: StatusCode | BaseException) -> None:
345350 Called to mark the end of the operation. If there is an active attempt,
346351 end_attempt_with_status will be called with the same status.
347352
348- Assumes operation is not already in COMPLETED state.
353+ StartState: CREATED | ACTIVE_ATTEMPT | BETWEEN_ATTEMPTS
354+ EndState: COMPLETED
349355
350356 Causes on_operation_completed to be called for each registered handler.
351357
@@ -361,27 +367,30 @@ def end_with_status(self, status: StatusCode | BaseException) -> None:
361367 )
362368 if self .state == OperationState .ACTIVE_ATTEMPT :
363369 self .end_attempt_with_status (final_status )
364- self .was_completed = True
370+ duration_ns = self ._ensure_positive (
371+ time .monotonic_ns () - self .start_time_ns , "duration"
372+ )
365373 finalized = CompletedOperationMetric (
366374 op_type = self .op_type ,
367- uuid = self .uuid ,
368375 completed_attempts = self .completed_attempts ,
369- duration_ns = time . monotonic_ns () - self . start_time_ns ,
376+ duration_ns = duration_ns ,
370377 final_status = final_status ,
371378 cluster_id = self .cluster_id or DEFAULT_CLUSTER_ID ,
372379 zone = self .zone or DEFAULT_ZONE ,
373380 is_streaming = self .is_streaming ,
374381 first_response_latency_ns = self .first_response_latency_ns ,
375382 flow_throttling_time_ns = self .flow_throttling_time_ns ,
376383 )
384+ self .state = OperationState .COMPLETED
377385 for handler in self .handlers :
378386 handler .on_operation_complete (finalized )
379387
380388 def end_with_success (self ):
381389 """
382390 Called to mark the end of the operation with a successful status.
383391
384- Assumes operation is not already in COMPLETED state.
392+ StartState: CREATED | ACTIVE_ATTEMPT | BETWEEN_ATTEMPTS
393+ EndState: COMPLETED
385394
386395 Causes on_operation_completed to be called for each registered handler.
387396 """
@@ -425,6 +434,15 @@ def _handle_error(message: str) -> None:
425434 full_message = f"Error in Bigtable Metrics: { message } "
426435 LOGGER .warning (full_message )
427436
437+ def _ensure_positive (self , value : int , field_name : str ) -> int :
438+ """
439+ Helper to replace negative value with 0, and record an error
440+ """
441+ if value < 0 :
442+ self ._handle_error (f"received negative value for { field_name } : { value } " )
443+ return 0
444+ return value
445+
428446 def __enter__ (self ):
429447 """
430448 Implements the async manager protocol
0 commit comments