Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -164,6 +164,12 @@ def _get_monitoring_credentials(
return credentials


# Cloud Monitoring rejects points written more often than the metric's sample
# period (60s for Bigtable client metrics). Exports that come sooner than half of
# that after the previous write (e.g. the final export on shutdown) are skipped
_MIN_EXPORT_INTERVAL_SECONDS = 30

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

30 seems like a magic number, why 30? should this be 60?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Using 30 (half the 60s interval) gives plenty of headroom so normal 60s periodic ticks are never skipped due to latency/jitter

See analysis from Gemini below

Why we can't use 60 on the client: _last_export_time is recorded after the create_service_time_series RPC finishes. If periodic export 1 takes 0.4s over the network (finishing at t = 60.4s) and periodic export 2 fires on schedule at t = 120.0s, the elapsed time between them is 59.6s. If our threshold were 60, 59.6 < 60 would be true and every second periodic export would be skipped.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Following up on #18630 (comment) and #18630 (comment):

When a process exits shortly after a 60s periodic export, teardown triggers a final flush that Cloud Monitoring rejects with 400 (The same issue seen in #18576).

We have 2 potential solutions here:

  1. shutdown hook (marking the exporter as shutting down, still sending the final RPC, and catching the error with a warning)

or

  1. the 30s timer check in export() (skipping the RPC if the last export was < 30s ago)

  1. Shutdown hook Lets partial writes and other projects go through on exit, since create_service_time_series still writes any new time series in the batch even when returning 400 for points exported too recently. However, export() already catches errors and logs a warning today, so we'd still make a rejected 400 RPC and log a warning on exit—or if we suppress warnings on shutdown, we'd hide real errors for short-lived scripts (< 60s) where teardown is the only export. Also, since MeterProvider's built-in atexit hook calls exporter.export() before exporter.shutdown(), we'd have to pass shutdown_on_exit=False to MeterProvider and register our own atexit hook so the shutdown flag is set before MeterProvider.shutdown() runs.

  2. 30s timer check in export() Avoids the 400 RPC and warning log noise on normal exit, and works without the extra shutdown hook plumbing that is needed for 1.. It skips the final < 30s of points on exit for a project that just exported, though if we change _last_export_time to a per-project dict (dict[str, float]), other projects will still go through.

I'm leaning toward keeping the 30s timer check (updated to track _last_export_time per project) to avoid the warning noise, failed RPC on exit, and atexit plumbing, unless we think preserving the final < 30s of partial time series is worth those trade-offs. Thoughts?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the detailed write up, both of you. I went with the 30 second check and made it per project in 3209ffa: each project keeps its own last write time, so a project that just exported skips the final flush on exit while other projects still go through, and after a partial failure only the failed project is written again. Happy to switch to the shutdown hook instead if you'd rather keep the final partial series.



class GoogleCloudMetricsHandler(OpenTelemetryMetricsHandler):
"""
Maintains an internal set of OpenTelemetry metrics for the Bigtable client library,
Expand Down Expand Up @@ -228,6 +234,9 @@ def __init__(self, *client_args, **client_kwargs):
# Once disabled, exports are skipped instead of failing (and logging)
# on every export interval
self._disabled = False
# time.monotonic() of the last successful write to Cloud Monitoring, per
# project, so a recent write to one project doesn't hold back the others
self._last_export_times: dict[str, float] = {}

def export(
self, metrics_data: MetricsData, timeout_millis: float = 10_000, **kwargs
Expand Down Expand Up @@ -285,12 +294,28 @@ def export(
# send all metrics to Cloud Monitoring
try:
for project_id, series_list in series_by_project.items():
last_export_time = self._last_export_times.get(project_id)
if (
last_export_time is not None
and time.monotonic() - last_export_time
< _MIN_EXPORT_INTERVAL_SECONDS
):
# writing again this soon would be rejected by Cloud Monitoring.
# Metrics are cumulative, so the next export still includes this data
_LOGGER.debug(
"Skipping metrics export for project %s: previous export "
"was less than %d seconds ago",
project_id,
_MIN_EXPORT_INTERVAL_SECONDS,
)
continue
_LOGGER.debug(
"Exporting %d time series to Cloud Monitoring for project %s",
len(series_list),
project_id,
)
self._batch_write(project_id, series_list, deadline)
self._last_export_times[project_id] = time.monotonic()
return MetricExportResult.SUCCESS
Comment thread
parthea marked this conversation as resolved.
except (Unauthenticated, PermissionDenied) as e:
# authentication/authorization failures won't resolve on their own.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -129,6 +129,35 @@ def test_close(self):
GoogleCloudMetricsHandler.close(mock_instance)
assert mock_instance.meter_provider.shutdown.call_count == 1

def test_close_soon_after_export(self):
"""
Closing the handler right after a periodic export should not write
to Cloud Monitoring again, since the write would be rejected for being
more frequent than the metric's sample period

https://github.com/googleapis/google-cloud-python/issues/18576
"""
with mock.patch("google.auth.default", return_value=(mock.Mock(), "project")):
exporter = BigtableMetricsExporter()
exporter.client = mock.Mock()
handler = self._make_one(exporter)
try:
counter = handler.meter_provider.get_meter("test").create_counter(
"retry_count"
)
attributes = {
"resource_project": "project",
"resource_instance": "instance",
}
counter.add(1, attributes)
# periodic export
assert handler.meter_provider.force_flush()
assert exporter.client.create_service_time_series.call_count == 1
counter.add(1, attributes)
finally:
handler.close()
assert exporter.client.create_service_time_series.call_count == 1


BIGTABLE_DATA_SCOPE = "https://www.googleapis.com/auth/bigtable.data"
BIGTABLE_ADMIN_SCOPE = "https://www.googleapis.com/auth/bigtable.admin"
Expand Down Expand Up @@ -676,3 +705,93 @@ def test_export_when_disabled(self):
assert result == MetricExportResult.FAILURE
to_point_mock.assert_not_called()
instance._batch_write.assert_not_called()

def test_export_skipped_if_previous_export_too_recent(self):
"""
Cloud Monitoring rejects points written more often than the sample period.
Exports within 30 seconds of the last successful write should be skipped
"""
instance = self._make_one()
instance.client = mock.Mock()
write_mock = instance.client.create_service_time_series
with mock.patch("time.monotonic", return_value=1000.0):
assert instance.export(self._make_metrics_data()) == (
MetricExportResult.SUCCESS
)
assert write_mock.call_count == 1
# too soon: skipped without writing or failing
with mock.patch("time.monotonic", return_value=1029.0):
assert instance.export(self._make_metrics_data()) == (
MetricExportResult.SUCCESS
)
assert write_mock.call_count == 1
# enough time has passed: written again
with mock.patch("time.monotonic", return_value=1030.0):
assert instance.export(self._make_metrics_data()) == (
MetricExportResult.SUCCESS
)
assert write_mock.call_count == 2

def test_export_not_skipped_after_failed_export(self):
"""a failed write doesn't count as a recent export"""
instance = self._make_one()
instance.client = mock.Mock()
write_mock = instance.client.create_service_time_series
write_mock.side_effect = [api_exceptions.ServiceUnavailable("test"), None]
assert instance.export(self._make_metrics_data()) == (
MetricExportResult.FAILURE
)
assert instance.export(self._make_metrics_data()) == (
MetricExportResult.SUCCESS
)
assert write_mock.call_count == 2

def test_export_retries_only_failed_project_after_partial_failure(self):
"""
After a partial failure across projects, only the project that failed is
written again right away; the one that succeeded is too recent to rewrite
"""
instance = self._make_one()
instance.client = mock.Mock()
write_mock = instance.client.create_service_time_series
write_mock.side_effect = [
None,
api_exceptions.ServiceUnavailable("test"),
None,
]

metrics_data = self._make_metrics_data(project_id="project1")
metrics_data_2 = self._make_metrics_data(project_id="project2")
metrics_data.resource_metrics.extend(metrics_data_2.resource_metrics)

with mock.patch("time.monotonic", return_value=1000.0):
assert instance.export(metrics_data) == MetricExportResult.FAILURE
# Immediate retry (< 30s): project1 was just written, project2 failed
with mock.patch("time.monotonic", return_value=1010.0):
assert instance.export(metrics_data) == MetricExportResult.SUCCESS
assert write_mock.call_count == 3
written = [c.args[0].name for c in write_mock.call_args_list]
assert written == [
"projects/project1",
"projects/project2",
"projects/project2",
]

def test_recent_export_to_one_project_does_not_skip_another(self):
"""the 30 second check is per project"""
instance = self._make_one()
instance.client = mock.Mock()
write_mock = instance.client.create_service_time_series

with mock.patch("time.monotonic", return_value=1000.0):
assert instance.export(self._make_metrics_data(project_id="project1")) == (
MetricExportResult.SUCCESS
)
metrics_data = self._make_metrics_data(project_id="project1")
metrics_data_2 = self._make_metrics_data(project_id="project2")
metrics_data.resource_metrics.extend(metrics_data_2.resource_metrics)
# 10 seconds later: project1 is skipped, project2 is still written
with mock.patch("time.monotonic", return_value=1010.0):
assert instance.export(metrics_data) == MetricExportResult.SUCCESS
written = [c.args[0].name for c in write_mock.call_args_list]
assert written == ["projects/project1", "projects/project2"]
Loading