Collect both DBM active sessions and blocking sessions which are sleeping

sqlserver/datadog_checks/sqlserver/activity.py

@@ -74,6 +74,39 @@
 """,
 ).strip()
 
+# Query to fetch idle blocking sessions
+# with only basic sess and conn info
+# not joining with sys.dm_exec_requests
+IDLE_BLOCKING_SESSIONS_QUERY = re.sub(
+    r'\s+',
+    ' ',
+    """\
+SELECT
+    CONVERT(
+        NVARCHAR, TODATETIMEOFFSET(CURRENT_TIMESTAMP, DATEPART(TZOFFSET, SYSDATETIMEOFFSET())), 126
+    ) as now,
+    sess.login_name as user_name,
+    sess.last_request_start_time as last_request_start_time,
+    sess.session_id as id,
+    DB_NAME(sess.database_id) as database_name,
+    sess.status as session_status,
+    lqt.text as statement_text,
+    SUBSTRING(lqt.text, 1, {proc_char_limit}) as text,
+    c.client_tcp_port as client_port,
+    c.client_net_address as client_address,
+    sess.host_name as host_name,
+    sess.program_name as program_name
+FROM sys.dm_exec_sessions sess
+    INNER JOIN sys.dm_exec_connections c
+        ON sess.session_id = c.session_id
+    CROSS APPLY sys.dm_exec_sql_text(c.most_recent_sql_handle) lqt
+WHERE sess.session_id != @@spid
+    AND sess.status = 'sleeping'
+    AND sess.session_id IN ({blocking_session_ids})
+    AND c.session_id IN ({blocking_session_ids})
+""",
+).strip()
+
 # enumeration of the columns we collect
 # from sys.dm_exec_requests
 DM_EXEC_REQUESTS_COLS = [
@@ -153,6 +186,19 @@ def _get_active_connections(self, cursor):
         self.log.debug("loaded sql server current connections len(rows)=%s", len(rows))
         return rows
 
+    @tracked_method(agent_check_getter=agent_check_getter, track_result_length=True)
+    def _get_idle_blocking_sessions(self, cursor, blocking_session_ids):
+        # The IDLE_BLOCKING_SESSIONS_QUERY contains minimum information on idle blocker
+        self.log.debug("collecting sql server idle blocking sessions")
+        query = IDLE_BLOCKING_SESSIONS_QUERY.format(
+            blocking_session_ids=",".join(map(str, blocking_session_ids)), proc_char_limit=PROC_CHAR_LIMIT
+        )
+        self.log.debug("Running query [%s]", query)
+        cursor.execute(query)
+        columns = [i[0] for i in cursor.description]
+        rows = [dict(zip(columns, row)) for row in cursor.fetchall()]
+        return rows
+
     @tracked_method(agent_check_getter=agent_check_getter, track_result_length=True)
     def _get_activity(self, cursor, exec_request_columns):
         self.log.debug("collecting sql server activity")
@@ -165,6 +211,12 @@ def _get_activity(self, cursor, exec_request_columns):
         columns = [i[0] for i in cursor.description]
         # construct row dicts manually as there's no DictCursor for pyodbc
         rows = [dict(zip(columns, row)) for row in cursor.fetchall()]
+        # construct set of blocking session ids
+        blocking_session_ids = {r['blocking_session_id'] for r in rows if r['blocking_session_id']}
+        if blocking_session_ids:
+            # if there are blocking sessions, fetch idle blocking sessions
+            idle_blocking_sessions = self._get_idle_blocking_sessions(cursor, blocking_session_ids)
+            rows.extend(idle_blocking_sessions)
         return rows
 
     def _normalize_queries_and_filter_rows(self, rows, max_bytes_limit):
@@ -211,7 +263,7 @@ def _get_available_requests_columns(self, cursor, all_expected_columns):
 
     @staticmethod
     def _get_sort_key(r):
-        return r.get("query_start") or datetime.datetime.now()
+        return r.get("query_start") or datetime.datetime.now().isoformat()
 
     def _obfuscate_and_sanitize_row(self, row):
         row = self._remove_null_vals(row)

sqlserver/tests/test_activity.py

@@ -9,6 +9,7 @@
 import json
 import os
 import re
+import threading
 import time
 from concurrent.futures.thread import ThreadPoolExecutor
 from copy import copy
@@ -145,10 +146,11 @@ def run_test_query(c, q):
     assert set(event['ddtags']) == expected_instance_tags, "wrong instance tags activity"
     assert type(event['collection_interval']) in (float, int), "invalid collection_interval"
 
-    assert len(event['sqlserver_activity']) == 1, "should have collected exactly one activity row"
+    assert len(event['sqlserver_activity']) == 2, "should have collected exactly two activity rows"
+    event['sqlserver_activity'].sort(key=lambda r: r.get('blocking_session_id', 0))
     # the second query should be fred's, which is currently blocked on
     # bob who is holding a table lock
-    blocked_row = event['sqlserver_activity'][0]
+    blocked_row = event['sqlserver_activity'][1]
     # assert the data that was collected is correct
     assert blocked_row['user_name'] == "fred", "incorrect user_name"
     assert blocked_row['session_status'] == "running", "incorrect session_status"
@@ -200,6 +202,121 @@ def run_test_query(c, q):
     )
 
 
+def test_activity_nested_blocking_transactions(
+    aggregator,
+    instance_docker,
+    dd_run_check,
+    dbm_instance,
+):
+    """
+    Test to ensure the check captures a scenario where a blocking idle transaction
+    is collected through activity. An open transaction which completes its current
+    request but has not committed can still hold a row-level lock preventing subsequent
+    sessions from updating. It is important that the Agent captures these cases to show
+    the complete picture and the last executed query responsible for the lock.
+    """
+
+    TABLE_NAME = "##LockTest{}".format(str(int(time.time() * 1000)))
+
+    QUERIES_SETUP = (
+        """
+        CREATE TABLE {}
+        (
+            id int,
+            name varchar(10),
+            city varchar(20)
+        )""".format(
+            TABLE_NAME
+        ),
+        "INSERT INTO {} VALUES (1001, 'tire', 'sfo')".format(TABLE_NAME),
+        "INSERT INTO {} VALUES (1002, 'wisth', 'nyc')".format(TABLE_NAME),
+        "INSERT INTO {} VALUES (1003, 'tire', 'aus')".format(TABLE_NAME),
+        "COMMIT",
+    )
+
+    QUERY1 = """UPDATE {} SET [name] = 'west' WHERE [id] = 1001""".format(TABLE_NAME)
+    QUERY2 = """UPDATE {} SET [name] = 'fast' WHERE [id] = 1001""".format(TABLE_NAME)
+    QUERY3 = """UPDATE {} SET [city] = 'blow' WHERE [id] = 1001""".format(TABLE_NAME)
+
+    check = SQLServer(CHECK_NAME, {}, [dbm_instance])
+    conn1 = _get_conn_for_user(instance_docker, "fred", _autocommit=False)
+    conn2 = _get_conn_for_user(instance_docker, "bob", _autocommit=False)
+    conn3 = _get_conn_for_user(instance_docker, "fred", _autocommit=False)
+
+    close_conns = threading.Event()
+
+    def run_queries(conn, queries):
+        cur = conn.cursor()
+        cur.execute("USE {}".format("datadog_test"))
+        cur.execute("BEGIN TRANSACTION")
+        for q in queries:
+            try:
+                cur.execute(q)
+            except pyodbc.OperationalError as err:
+                print(err)
+                # This is expected since the query (might be) blocked
+                print("Timeout on query: {}".format(q))
+        # Do not allow the conn to be garbage collected and closed until the global lock is released
+        while not close_conns.is_set():
+            time.sleep(0.1)
+        cur.execute("COMMIT")
+
+    # Setup
+    cur = conn1.cursor()
+    for q in QUERIES_SETUP:
+        cur.execute(q)
+
+    # Transaction 1
+    t1 = threading.Thread(target=run_queries, args=(conn1, [QUERY1]))
+    # Transaction 2
+    t2 = threading.Thread(target=run_queries, args=(conn2, [QUERY2]))
+    # Transaction 3
+    t3 = threading.Thread(target=run_queries, args=(conn3, [QUERY3]))
+
+    t1.start()
+    time.sleep(0.3)
+    t2.start()
+    time.sleep(0.3)
+    t3.start()
+
+    try:
+        dd_run_check(check)
+        dbm_activity = aggregator.get_event_platform_events("dbm-activity")
+    finally:
+        close_conns.set()  # Release the threads
+
+    # All 3 connections are expected
+    assert dbm_activity and 'sqlserver_activity' in dbm_activity[0]
+    assert len(dbm_activity[0]['sqlserver_activity']) == 3
+
+    activity = dbm_activity[0]['sqlserver_activity']
+    activity = sorted(activity, key=lambda a: a.get('blocking_session_id', 0))
+
+    root_blocker = activity[0]
+    tx2 = activity[1]
+    tx3 = activity[2]
+
+    # Expect to capture the root blocker, which would have a sleeping transaction but no
+    # associated sys.dm_exec_requests.
+    assert root_blocker["user_name"] == "fred"
+    assert root_blocker["session_status"] == "sleeping"
+    # Expect to capture the query signature for the root blocker
+    # query text is not captured from the req dmv
+    # but available in the connection dmv with most_recent_sql_handle
+    assert root_blocker["query_signature"]
+    # we do not capture requests for sleeping sessions
+    assert "blocking_session_id" not in root_blocker
+
+    # TX2 should be blocked by the root blocker TX1, TX3 should be blocked by TX2
+    assert tx2["blocking_session_id"] == root_blocker["id"]
+    assert tx3["blocking_session_id"] == tx2["id"]
+    assert tx2["session_status"] == "running"
+    assert tx3["session_status"] == "running"
+
+    for t in [t1, t2, t3]:
+        t.join()
+
+
 @pytest.mark.integration
 @pytest.mark.usefixtures('dd_environment')
 @pytest.mark.parametrize(
@@ -306,15 +423,15 @@ def test_activity_reported_hostname(
 
 
 def new_time():
-    return datetime.datetime(2021, 9, 23, 23, 21, 21, 669330)
+    return datetime.datetime(2021, 9, 23, 23, 21, 21, 669330).isoformat()
 
 
 def old_time():
-    return datetime.datetime(2021, 9, 22, 22, 21, 21, 669330)
+    return datetime.datetime(2021, 9, 22, 22, 21, 21, 669330).isoformat()
 
 
 def very_old_time():
-    return datetime.datetime(2021, 9, 20, 23, 21, 21, 669330)
+    return datetime.datetime(2021, 9, 20, 23, 21, 21, 669330).isoformat()
 
 
 @pytest.mark.parametrize(