From 526b121bd2b2a12cad76e99406122ba7f5118852 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Tue, 1 Jun 2021 13:46:44 +0100 Subject: [PATCH 1/6] opentracing: add tracing for individual database statements --- synapse/storage/database.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/synapse/storage/database.py b/synapse/storage/database.py index a761ad603bbb..e1fe43454ec1 100644 --- a/synapse/storage/database.py +++ b/synapse/storage/database.py @@ -40,6 +40,7 @@ from synapse.api.errors import StoreError from synapse.config.database import DatabaseConnectionConfig +from synapse.logging import opentracing from synapse.logging.context import ( LoggingContext, current_context, @@ -313,7 +314,14 @@ def _do_execute(self, func: Callable[..., R], sql: str, *args: Any) -> R: start = time.time() try: - return func(sql, *args) + with opentracing.start_active_span( + "db.query", + tags={ + opentracing.tags.DATABASE_TYPE: "sql", + opentracing.tags.DATABASE_STATEMENT: sql, + }, + ): + return func(sql, *args) except Exception as e: sql_logger.debug("[SQL FAIL] {%s} %s", self.name, e) raise From c503b32a3744eec4e0b05d162b12821c1035a93b Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Tue, 1 Jun 2021 13:47:44 +0100 Subject: [PATCH 2/6] opentracing: add tracing for database transactions --- synapse/logging/opentracing.py | 6 ++++++ synapse/storage/database.py | 13 ++++++++++--- 2 files changed, 16 insertions(+), 3 deletions(-) diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index f64845b80cc0..68f0c00151d5 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -271,6 +271,12 @@ class SynapseTags: # HTTP request tag (used to distinguish full vs incremental syncs, etc) REQUEST_TAG = "request_tag" + # Text description of a database transaction + DB_TXN_DESC = "db.txn_desc" + + # Uniqueish ID of a database transaction + DB_TXN_ID = "db.txn_id" + # Block everything by default # A regex which matches the server_names to expose traces for. diff --git a/synapse/storage/database.py b/synapse/storage/database.py index e1fe43454ec1..8086db527417 100644 --- a/synapse/storage/database.py +++ b/synapse/storage/database.py @@ -533,9 +533,16 @@ def new_transaction( exception_callbacks=exception_callbacks, ) try: - r = func(cursor, *args, **kwargs) - conn.commit() - return r + with opentracing.start_active_span( + "db.txn", + tags={ + opentracing.SynapseTags.DB_TXN_DESC: desc, + opentracing.SynapseTags.DB_TXN_ID: name, + }, + ): + r = func(cursor, *args, **kwargs) + conn.commit() + return r except self.engine.module.OperationalError as e: # This can happen if the database disappears mid # transaction. From 171fd3155361c85191b9af5f4a6026d0677ec3a5 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 2 Jun 2021 16:27:46 +0100 Subject: [PATCH 3/6] oepntracing: add opentracing spans while we hold a db connection --- synapse/storage/database.py | 42 ++++++++++++++++++++----------------- 1 file changed, 23 insertions(+), 19 deletions(-) diff --git a/synapse/storage/database.py b/synapse/storage/database.py index 8086db527417..2a1b895962c0 100644 --- a/synapse/storage/database.py +++ b/synapse/storage/database.py @@ -733,25 +733,29 @@ def inner_func(conn, *args, **kwargs): with LoggingContext( str(curr_context), parent_context=parent_context ) as context: - sched_duration_sec = monotonic_time() - start_time - sql_scheduling_timer.observe(sched_duration_sec) - context.add_database_scheduled(sched_duration_sec) - - if self.engine.is_connection_closed(conn): - logger.debug("Reconnecting closed database connection") - conn.reconnect() - - try: - if db_autocommit: - self.engine.attempt_to_set_autocommit(conn, True) - - db_conn = LoggingDatabaseConnection( - conn, self.engine, "runWithConnection" - ) - return func(db_conn, *args, **kwargs) - finally: - if db_autocommit: - self.engine.attempt_to_set_autocommit(conn, False) + with opentracing.start_active_span( + operation_name="db.connection", + ): + sched_duration_sec = monotonic_time() - start_time + sql_scheduling_timer.observe(sched_duration_sec) + context.add_database_scheduled(sched_duration_sec) + + if self.engine.is_connection_closed(conn): + logger.debug("Reconnecting closed database connection") + conn.reconnect() + opentracing.log_kv({"message", "reconnected"}) + + try: + if db_autocommit: + self.engine.attempt_to_set_autocommit(conn, True) + + db_conn = LoggingDatabaseConnection( + conn, self.engine, "runWithConnection" + ) + return func(db_conn, *args, **kwargs) + finally: + if db_autocommit: + self.engine.attempt_to_set_autocommit(conn, False) return await make_deferred_yieldable( self._db_pool.runWithConnection(inner_func, *args, **kwargs) From 336e5019f98c55e8387db4ead9aea411315076b9 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Tue, 1 Jun 2021 13:50:07 +0100 Subject: [PATCH 4/6] opentracing: add tracing for each database "interaction" These are the things that we tend to call "transactions" in Synapse-land, but can actually end up being multiple transactions as seen by the database (particularly if we get a locking error, in which case we will retry the transaction). --- synapse/storage/database.py | 21 +++++++++++---------- 1 file changed, 11 insertions(+), 10 deletions(-) diff --git a/synapse/storage/database.py b/synapse/storage/database.py index 2a1b895962c0..71fa88743555 100644 --- a/synapse/storage/database.py +++ b/synapse/storage/database.py @@ -668,16 +668,17 @@ async def runInteraction( logger.warning("Starting db txn '%s' from sentinel context", desc) try: - result = await self.runWithConnection( - self.new_transaction, - desc, - after_callbacks, - exception_callbacks, - func, - *args, - db_autocommit=db_autocommit, - **kwargs, - ) + with opentracing.start_active_span(f"db.{desc}"): + result = await self.runWithConnection( + self.new_transaction, + desc, + after_callbacks, + exception_callbacks, + func, + *args, + db_autocommit=db_autocommit, + **kwargs, + ) for after_callback, after_args, after_kwargs in after_callbacks: after_callback(*after_args, **after_kwargs) From 3ba69714d06468c969e1808f45c064c3b99ed95f Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 2 Jun 2021 17:01:41 +0100 Subject: [PATCH 5/6] changelog --- changelog.d/10113.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/10113.feature diff --git a/changelog.d/10113.feature b/changelog.d/10113.feature new file mode 100644 index 000000000000..2658ab891882 --- /dev/null +++ b/changelog.d/10113.feature @@ -0,0 +1 @@ +Report OpenTracing spans for database activity. From c19053986fa3caa9e08af72f5aba864e346b8e90 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Thu, 3 Jun 2021 16:01:59 +0100 Subject: [PATCH 6/6] Update synapse/storage/database.py Co-authored-by: Erik Johnston --- synapse/storage/database.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/storage/database.py b/synapse/storage/database.py index 71fa88743555..974703d13ae2 100644 --- a/synapse/storage/database.py +++ b/synapse/storage/database.py @@ -744,7 +744,7 @@ def inner_func(conn, *args, **kwargs): if self.engine.is_connection_closed(conn): logger.debug("Reconnecting closed database connection") conn.reconnect() - opentracing.log_kv({"message", "reconnected"}) + opentracing.log_kv({"message": "reconnected"}) try: if db_autocommit: