交易統計資料

Spanner 提供內建資料表,可儲存交易統計資料。您可以使用 SQL 陳述式,從這些 SPANNER_SYS.TXN_STATS* 資料表擷取統計資料。

交易統計資料的使用時機

交易統計資料有助於調查效能問題。舉例來說,您可以檢查是否有任何執行緩慢的交易,可能影響資料庫的效能或每秒查詢次數 (QPS)。另一種情況是,用戶端應用程式的交易執行延遲時間過長。分析交易統計資料有助於找出潛在的效能瓶頸,例如特定資料欄的大量更新,這可能會影響延遲時間。

存取交易統計資料

Spanner 會在 SPANNER_SYS 結構定義中提供資料表交易統計資料。您可以透過下列方式存取 SPANNER_SYS 資料:

  • Google Cloud 控制台中的資料庫 Spanner Studio 頁面。

  • gcloud spanner databases execute-sql 指令。

  • 「交易深入分析」資訊主頁。

  • executeSqlexecuteStreamingSql 方法。

Spanner 提供的下列單一讀取方法不支援 SPANNER_SYS

  • 從資料表中的單一資料列或多個資料列執行強式讀取。
  • 從資料表中的單一資料列或多個資料列執行過時讀取。
  • 從次要索引中的單一資料列或多個資料列讀取。

按照交易分組的延遲統計資料

下表會追蹤特定時間範圍內,TOP 資源耗用交易的統計資料。

  • SPANNER_SYS.TXN_STATS_TOP_MINUTE:每隔 1 分鐘彙整的交易統計資料。

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE:每 10 分鐘間隔匯總的交易統計資料。

  • SPANNER_SYS.TXN_STATS_TOP_HOUR:以 1 小時間隔匯總的交易統計資料。

這些資料表具備下列屬性:

  • 每個資料表都包含資料表名稱所指定的非重疊時間間隔長度的資料。

  • 間隔是基於時鐘時間。1 分鐘間隔的結束時間是目前這一分鐘、10 分鐘間隔的結束時間是目前這個小時的每 10 分鐘,而 1 小時間隔的結束時間是目前這個小時。

    舉例來說,在上午 11:59:30,SQL 查詢的最近可用間隔如下:

    • 1 分鐘:上午 11:58:00–11:58:59
    • 10 分鐘:上午 11:40:00–11:49:59
    • 1 小時:上午 10:00:00–10:59:59
  • Spanner 會依交易的 FPRINT (指紋) 將統計資料分組。如有交易標記,FPRINT 就是標記的雜湊值。否則,就是根據交易涉及的作業計算出的雜湊。

  • 由於統計資料是根據 FPRINT 分組,因此如果同一筆交易在任何時間間隔內執行多次,這些表格中仍只會顯示該筆交易的一筆項目。

  • 每個資料列都包含特定交易所有執行作業的統計資料,Spanner 會在指定間隔期間擷取這些統計資料。

  • 如果 Spanner 無法在這些資料表中儲存間隔期間執行的所有交易統計資料,系統會優先處理在指定間隔期間延遲時間最長、嘗試提交次數最多,以及寫入位元組數最多的交易。

  • 資料表中的所有資料欄都可為空值。

資料表結構定義

資料欄名稱 類型 說明
INTERVAL_END TIMESTAMP 包含的交易執行作業發生時的時間間隔結束時間。
TRANSACTION_TAG STRING 這項交易作業的選用交易標記。如要進一步瞭解如何使用標記,請參閱「使用交易標記排解問題」。如果多筆交易具有相同的代碼字串,系統會將這些交易的統計資料歸入同一列,並以符合該代碼字串的 `TRANSACTION_TAG` 顯示。
FPRINT INT64 如果存在 TRANSACTION_TAG,則為該項目的雜湊值;否則,系統會根據交易涉及的作業計算雜湊值。INTERVAL_ENDFPRINT 共同做為這些資料表的專屬鍵。
READ_COLUMNS ARRAY<STRING> 交易讀取的欄集。
WRITE_CONSTRUCTIVE_COLUMNS ARRAY<STRING> 交易建構式寫入的資料欄集 (即指派給新值的資料欄)。

如果是變更串流,且交易涉及寫入變更串流監看的資料欄和資料表,WRITE_CONSTRUCTIVE_COLUMNS 會包含兩個資料欄 - .data._exists 1,並以變更串流名稱做為前置字元。
WRITE_DELETE_TABLES ARRAY<STRING> 交易刪除或取代資料列的資料表集。
ATTEMPT_COUNT INT64 交易嘗試的總次數,包括在呼叫 `commit` 前中止的嘗試。
COMMIT_ATTEMPT_COUNT INT64 交易提交嘗試總數。這必須與交易的 commit 方法呼叫次數相符。
COMMIT_ABORT_COUNT INT64 遭中止的交易嘗試總數,包括在呼叫交易的 commit 方法前中止的交易。
COMMIT_RETRY_COUNT INT64 先前中止的嘗試重試總次數。由於鎖定爭用或暫時事件,Spanner 交易可能會在修訂前嘗試多次。如果重試次數相較於提交嘗試次數偏高,可能表示有值得調查的問題。詳情請參閱本頁面的「瞭解交易和提交次數」。
COMMIT_FAILED_PRECONDITION_COUNT INT64 傳回失敗前提條件錯誤的交易提交嘗試總數,例如UNIQUE索引違規、資料列已存在、找不到資料列等。
AVG_PARTICIPANTS FLOAT64 每次提交嘗試的平均參與者人數。如要進一步瞭解參與者,請參閱「Cloud Spanner 的讀取與寫入」。
AVG_TOTAL_LATENCY_SECONDS FLOAT64 從交易的第一項作業到提交/中止作業的平均秒數。
AVG_COMMIT_LATENCY_SECONDS FLOAT64 執行提交作業的平均秒數。
AVG_BYTES FLOAT64 交易寫入的平均位元組數。
TOTAL_LATENCY_DISTRIBUTION ARRAY<STRUCT>

所有交易嘗試的總提交延遲時間直方圖,也就是從第一個交易作業開始時間到提交或中止時間之間的時間。

如果交易多次中止,然後成功提交,系統會測量每次嘗試的延遲時間,直到最終成功提交為止。這些值以秒為單位。

陣列包含單一元素,且具有下列類型:
ARRAY<STRUCT<
  COUNT INT64,
  MEAN FLOAT64,
  SUM_OF_SQUARED_DEVIATION FLOAT64,
  NUM_FINITE_BUCKETS INT64,
  GROWTH_FACTOR FLOAT64,
  SCALE FLOAT64,
  BUCKET_COUNTS ARRAY<INT64>>>

如要進一步瞭解值,請參閱「分布」。

如要從分配計算所需百分位數延遲時間,請使用 SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64) 函式,該函式會傳回估計的第 n 個百分位數。如需相關範例,請參閱「找出交易的第 99 個百分位數延遲時間」。

詳情請參閱「百分位數和分佈值指標」。

OPERATIONS_BY_TABLE ARRAY<STRUCT>

以表格為單位,交易對 INSERTUPDATE 作業的影響。這項指標會顯示受影響的資料列次數和寫入的位元組數。

這個資料欄有助於呈現資料表負載的視覺化效果,並深入瞭解交易寫入資料表的速率。

指定陣列,如下所示:
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

1 _exists 是用來檢查特定資料列是否存在的內部欄位。

查詢範例

本節包含多個擷取交易統計資料的範例 SQL 陳述式。您可以使用用戶端程式庫gcloud spannerGoogle Cloud 主控台執行這些 SQL 陳述式。

列出特定時間範圍內每筆交易的基本統計資料

下列查詢會傳回前一分鐘中,前幾名交易的原始資料。

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds,
       avg_commit_latency_seconds,
       operations_by_table,
       avg_bytes
FROM spanner_sys.txn_stats_top_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_top_minute);
查詢輸出
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds avg_commit_latency_seconds operations_by_table avg_bytes
40015598317 [] ["Routes.name", "Cars.model"] ["Users"] 0.006578737 0.006547737 [["Cars",1107,30996],["Routes",560,26880]] 25286
20524969030 ["id", "no"] [] [] 0.001732442 0.000247442 [] 0
77848338483 [] [] ["Cars", "Routes"] 0.033467418 0.000251418 [] 0

列出平均提交延遲時間最長的交易

下列查詢會傳回前一小時中平均提交延遲時間較長的交易,並依平均提交延遲時間從長到短排序。

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds,
       avg_commit_latency_seconds,
       avg_bytes
FROM spanner_sys.txn_stats_top_hour
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_top_hour)
ORDER BY avg_commit_latency_seconds DESC;
查詢輸出
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds avg_commit_latency_seconds avg_bytes
40015598317 [] ["Routes.name", "Cars.model"] ["Users"] 0.006578737 0.006547737 25286
77848338483 [] [] ["Cars", "Routes"] 0.033467418 0.000251418 0
20524969030 ["id", "no"] [] [] 0.001732442 0.000247442 0

找出讀取特定資料欄的交易平均延遲時間

下列查詢會傳回從 1 小時統計資料讀取 ADDRESS 欄的交易平均延遲時間資訊:

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds
FROM spanner_sys.txn_stats_top_hour
WHERE 'ADDRESS' IN UNNEST(read_columns)
ORDER BY avg_total_latency_seconds DESC;
查詢輸出
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds
77848338483 ["ID", "ADDRESS"] [] ["Cars", "Routes"] 0.033467418
40015598317 ["ID", "NAME", "ADDRESS"] [] ["Users"] 0.006578737

依修改的平均位元組數列出交易

下列查詢會傳回過去一小時內取樣的交易,並依交易修改的平均位元組數排序。

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_bytes
FROM spanner_sys.txn_stats_top_hour
ORDER BY avg_bytes DESC;
查詢輸出
fprint read_columns write_constructive_columns write_delete_tables avg_bytes
40015598317 [] [] ["Users"] 25286
77848338483 [] [] ["Cars", "Routes"] 12005
20524969030 ["ID", "ADDRESS"] [] ["Users"] 10923

匯總統計資料

SPANNER_SYS 也包含資料表,可儲存 Spanner 在特定時間範圍內擷取統計資料的所有交易匯總資料:

  • SPANNER_SYS.TXN_STATS_TOTAL_MINUTE:每 1 分鐘間隔內所有交易的匯總統計資料
  • SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE:10 分鐘間隔期間內所有交易的匯總統計資料
  • SPANNER_SYS.TXN_STATS_TOTAL_HOUR:1 小時間隔期間內所有交易的匯總統計資料

匯總統計資料表具有下列屬性:

  • 每個資料表都包含資料表名稱所指定的非重疊時間間隔長度的資料。

  • 間隔是基於時鐘時間。1 分鐘間隔的結束時間是目前這一分鐘、10 分鐘間隔的結束時間是目前這個小時的每 10 分鐘,而 1 小時間隔的結束時間是目前這個小時。

    舉例來說,在上午 11:59:30,SQL 查詢的最近可用間隔如下:

    • 1 分鐘:上午 11:58:00–11:58:59
    • 10 分鐘:上午 11:40:00–11:49:59
    • 1 小時:上午 10:00:00–10:59:59
  • 每個資料列都會包含指定間隔期間,資料庫上執行的所有交易的統計資料的匯總。每個時間間隔只有一個資料列。

  • SPANNER_SYS.TXN_STATS_TOTAL_* 資料表中擷取的統計資料可能包含 Spanner 未在 SPANNER_SYS.TXN_STATS_TOP_* 資料表中擷取的交易。

  • 這些表格中的部分資料欄會以 Cloud Monitoring 指標的形式顯示。 公開的指標如下:

    • 提交嘗試次數
    • 提交重試次數
    • 交易參與者
    • 交易延遲
    • 寫入的位元組

    詳情請參閱「Spanner 指標」。

資料表結構定義

資料欄名稱 類型 說明
INTERVAL_END TIMESTAMP 擷取這項統計資料的時間間隔結束時間。
ATTEMPT_COUNT INT64 交易嘗試的總次數,包括在呼叫 `commit` 前中止的嘗試。
COMMIT_ATTEMPT_COUNT INT64 交易提交嘗試總數。這必須與交易的 commit 方法呼叫次數相符。
COMMIT_ABORT_COUNT INT64 遭中止的交易嘗試總次數,包括在呼叫交易的 commit 方法前中止的交易。
COMMIT_RETRY_COUNT INT64 先前中止的嘗試重試次數。由於鎖定爭用或暫時事件,Spanner 交易可能會在修訂之前進行多次嘗試。如果重試次數相較於提交嘗試次數偏高,可能表示有值得調查的問題。詳情請參閱本頁面的「瞭解交易和提交次數」。
COMMIT_FAILED_PRECONDITION_COUNT INT64 傳回失敗前提條件錯誤的交易提交嘗試總數,例如UNIQUE索引違規、資料列已存在、找不到資料列等。
AVG_PARTICIPANTS FLOAT64 每次提交嘗試的平均參與者人數。如要進一步瞭解參與者,請參閱「Cloud Spanner 的讀取與寫入」。
AVG_TOTAL_LATENCY_SECONDS FLOAT64 從交易的第一項作業到提交/中止作業的平均秒數。
AVG_COMMIT_LATENCY_SECONDS FLOAT64 執行提交作業的平均秒數。
AVG_BYTES FLOAT64 交易寫入的平均位元組數。
TOTAL_LATENCY_DISTRIBUTION ARRAY<STRUCT>

總提交延遲時間的直方圖,也就是所有交易嘗試從第一個交易作業開始時間到提交或中止時間之間的時間。

如果交易多次中止,然後成功提交,系統會測量每次嘗試的延遲時間,直到最終成功提交為止。這些值以秒為單位。

陣列包含單一元素,且具有下列類型:
ARRAY<STRUCT<
  COUNT INT64,
  MEAN FLOAT64,
  SUM_OF_SQUARED_DEVIATION FLOAT64,
  NUM_FINITE_BUCKETS INT64,
  GROWTH_FACTOR FLOAT64,
  SCALE FLOAT64,
  BUCKET_COUNTS ARRAY<INT64>>>

如要進一步瞭解值,請參閱「分布」。

如要從分配計算所需百分位數延遲時間,請使用 SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64) 函式,該函式會傳回估計的第 n 個百分位數。如需範例,請參閱找出交易的第 99 個百分位數延遲時間

詳情請參閱「百分位數和分佈值指標」。

OPERATIONS_BY_TABLE ARRAY<STRUCT>

以表格為單位,顯示所有交易的 INSERTUPDATE 作業影響。這項指標會顯示受影響的資料列次數和寫入的位元組數。

這個資料欄有助於以視覺化方式呈現資料表負載,並深入瞭解交易寫入資料表的速率。

指定陣列,如下所示:
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

查詢範例

本節包含多個擷取交易統計資料的範例 SQL 陳述式。您可以使用用戶端程式庫gcloud spannerGoogle Cloud 主控台執行這些 SQL 陳述式。

找出所有交易的認可嘗試總數

下列查詢會傳回最近完成的 1 分間隔內,所有交易的提交嘗試總數:

SELECT interval_end,
       commit_attempt_count
FROM spanner_sys.txn_stats_total_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_minute)
ORDER BY interval_end;
查詢輸出
interval_end commit_attempt_count
2020-01-17 11:46:00-08:00 21

請注意,結果中只有一個資料列,因為任何時間長度的匯總統計資料,每個 interval_end 都只有一個項目。

找出所有交易的總提交延遲時間

下列查詢會傳回過去 10 分鐘內所有交易的總提交延遲時間:

SELECT (avg_commit_latency_seconds * commit_attempt_count / 60 / 60)
  AS total_commit_latency_hours
FROM spanner_sys.txn_stats_total_10minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_10minute);
查詢輸出
total_commit_latency_hours
0.8967

請注意,結果中只有一個資料列,因為任何時間長度的匯總統計資料,每個 interval_end 都只有一個項目。

找出交易的第 99 個百分位數延遲時間

下列查詢會傳回過去 10 分鐘內執行的交易,其延遲時間的第 99 個百分位數:

SELECT interval_end, avg_total_latency_seconds,
       SPANNER_SYS.DISTRIBUTION_PERCENTILE(total_latency_distribution[OFFSET(0)], 99.0)
  AS percentile_latency
FROM spanner_sys.txn_stats_total_10minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_10minute)
ORDER BY interval_end;

查詢輸出
interval_end avg_total_latency_seconds percentile_latency
2022-08-17 11:46:00-08:00 0.34576998305986395 9.00296190476190476

請注意,平均延遲時間和第 99 個百分位數延遲時間之間有很大的差異。 第 99 個百分位數的延遲時間有助於找出可能延遲時間較長,而成為離群值的交易。

由於匯總統計資料在任何時間長度內,每個 interval_end 都只有一個項目,因此結果中只有一個資料列。

資料保留

Spanner 至少會在下列時間範圍保留每個資料表的資料:

  • SPANNER_SYS.TXN_STATS_TOP_MINUTESPANNER_SYS.TXN_STATS_TOTAL_MINUTE:涵蓋前 6 個小時的間隔。

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTESPANNER_SYS.TXN_STATS_TOTAL_10MINUTE:涵蓋前 4 天的間隔。

  • SPANNER_SYS.TXN_STATS_TOP_HOURSPANNER_SYS.TXN_STATS_TOTAL_HOUR:涵蓋前 30 天的間隔。

Spanner 中的交易統計資料可深入瞭解應用程式使用資料庫的方式,有助於調查效能問題。舉例來說,您可以檢查是否有任何執行緩慢的交易可能導致爭用,或是找出高負載的潛在來源,例如對特定資料欄的大量更新。我們將透過下列步驟,說明如何使用交易統計資料調查資料庫中的爭用情形。

瞭解交易和提交次數

Spanner 交易可能會在修訂之前進行多次嘗試。最常見的情況是兩個交易嘗試同時處理相同資料,且其中一個交易必須中止,才能保留交易的隔離屬性。其他可能導致交易中止的暫時性事件包括:

  • 暫時性網路問題。

  • 交易正在提交時,資料庫結構定義發生變更。

  • Spanner 執行個體沒有足夠的容量來處理收到的所有要求。

在這種情況下,用戶端應重試已中止的交易,直到交易成功提交或逾時為止。如果使用官方 Spanner 用戶端程式庫,每個程式庫都已實作自動重試機制。如果您使用自訂版本的用戶端程式碼,請將交易提交作業包裝在重試迴圈中。

如果發生無法重試的錯誤 (例如交易逾時、權限問題或無效的資料表/欄名稱),Spanner 交易也可能會中止。這類交易不需要重試,Spanner 用戶端程式庫會立即傳回錯誤。

下表列出一些範例,說明在不同情境下如何記錄 COMMIT_ATTEMPT_COUNTCOMMIT_ABORT_COUNTCOMMIT_RETRY_COUNT

情境 COMMIT_ATTEMPT_COUNT COMMIT_ABORT_COUNT COMMIT_RETRY_COUNT
首次嘗試即成功修訂交易。 1 0 0
交易因逾時錯誤而中止。 1 1 0
交易因暫時性網路問題而中止,但經過一次重試後已成功提交。 2 1 1
在 10 分鐘間隔內執行 5 筆具有相同 FPRINT 的交易。3 筆交易在第一次嘗試時成功提交, 而 2 筆交易則遭到中止,然後在第一次重試時成功提交。 7 2 2

交易統計資料表中的資料是特定時間間隔的匯總資料。在特定間隔中,交易可能會在界線附近中止並重試,因此歸入不同的儲存區。因此,在特定時間間隔內,中止和重試次數可能不相等。

這些統計資料適用於排解問題和自我檢查,但不保證 100% 準確。統計資料會在儲存至 Spanner 資料表前,先在記憶體中匯總。升級或其他維護活動期間,Spanner 伺服器可能會重新啟動,影響數字的準確度。

使用交易統計資料排解資料庫爭用問題

您可以使用 SQL 程式碼或「交易洞察」資訊主頁,查看資料庫中可能因鎖定爭用而導致高延遲的交易。

下列主題說明如何使用 SQL 程式碼調查這類交易。

選取要調查的時間範圍

您可以在使用 Spanner 的應用程式中找到這個值。

在本練習中,假設問題是從 2020 年 5 月 17 日下午 5 點 20 分左右開始發生。

您可以使用交易標記識別交易來源,並在交易統計資料表和鎖定統計資料表之間建立關聯,有效排解鎖定爭用問題。詳情請參閱「使用交易代碼排解問題」。

收集所選時間範圍的交易統計資料

為展開調查,我們會查詢問題發生時間前後的 TXN_STATS_TOTAL_10MINUTE 表格。這項查詢的結果會顯示該段時間內延遲和其他交易統計資料的變化。

舉例來說,下列查詢會傳回 4:30 pm7:40 pm (含) 的匯總交易統計資料。

SELECT
  interval_end,
  ROUND(avg_total_latency_seconds,4) as avg_total_latency_seconds,
  commit_attempt_count,
  commit_abort_count
FROM SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE
WHERE
  interval_end >= "2020-05-17T16:40:00"
  AND interval_end <= "2020-05-17T19:40:00"
ORDER BY interval_end;

下表列出查詢傳回的範例資料。

interval_end avg_total_latency_seconds commit_attempt_count commit_abort_count
2020-05-17 16:40:00-07:00 0.0284 315691 5170
2020-05-17 16:50:00-07:00 0.0250 302124 3828
2020-05-17 17:00:00-07:00 0.0460 346087 11382
2020-05-17 17:10:00-07:00 0.0864 379964 33826
2020-05-17 17:20:00-07:00 0.1291 390343 52549
2020-05-17 17:30:00-07:00 0.1314 456455 76392
2020-05-17 17:40:00-07:00 0.1598 507774 121458
2020-05-17 17:50:00-07:00 0.1641 516587 115875
2020-05-17 18:00:00-07:00 0.1578 552711 122626
2020-05-17 18:10:00-07:00 0.1750 569460 154205
2020-05-17 18:20:00-07:00 0.1727 613571 160772
2020-05-17 18:30:00-07:00 0.1588 601994 143044
2020-05-17 18:40:00-07:00 0.2025 604211 170019
2020-05-17 18:50:00-07:00 0.1615 601622 135601
2020-05-17 19:00:00-07:00 0.1653 596804 129511
2020-05-17 19:10:00-07:00 0.1414 560023 112247
2020-05-17 19:20:00-07:00 0.1367 570864 100596
2020-05-17 19:30:00-07:00 0.0894 539729 65316
2020-05-17 19:40:00-07:00 0.0820 479151 40398

從這裡可以看出,醒目顯示的期間內,匯總延遲和中止次數較高。我們可以選擇任何 10 分鐘間隔,其中匯總延遲和/或中止計數偏高。請選擇以 2020-05-17T18:40:00 結尾的時間間隔,並在下一個步驟中用來找出導致高延遲和中止次數的交易。

找出延遲時間偏高的交易

現在,請查詢 TXN_STATS_TOP_10MINUTE 資料表,找出上一個步驟中選取的時間間隔。根據這項資料,我們可以開始找出延遲時間較長和/或中止次數較多的交易。

執行下列查詢,即可取得範例間隔 (結束時間為 2020-05-17T18:40:00) 中,總延遲時間最長的前幾項交易。

SELECT
  interval_end,
  fprint,
  ROUND(avg_total_latency_seconds,4) as avg_total_latency_seconds,
  ROUND(avg_commit_latency_seconds,4) as avg_commit_latency_seconds,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end = "2020-05-17T18:40:00"
ORDER BY avg_total_latency_seconds DESC;
interval_end fprint avg_total_latency_seconds avg_commit_latency_seconds commit_attempt_count commit_abort_count commit_retry_count
2020-05-17 18:40:00-07:00 15185072816865185658 0.3508 0.0139 278802 142205 129884
2020-05-17 18:40:00-07:00 15435530087434255496 0.1633 0.0142 129012 27177 24559
2020-05-17 18:40:00-07:00 14175643543447671202 0.1423 0.0133 5357 636 433
2020-05-17 18:40:00-07:00 898069986622520747 0.0198 0.0158 6 0 0
2020-05-17 18:40:00-07:00 10510121182038036893 0.0168 0.0125 7 0 0
2020-05-17 18:40:00-07:00 9287748709638024175 0.0159 0.0118 4269 1 0
2020-05-17 18:40:00-07:00 7129109266372596045 0.0142 0.0102 182227 0 0
2020-05-17 18:40:00-07:00 15630228555662391800 0.0120 0.0107 58 0 0
2020-05-17 18:40:00-07:00 7907238229716746451 0.0108 0.0097 65 0 0
2020-05-17 18:40:00-07:00 10158167220149989178 0.0095 0.0047 3454 0 0
2020-05-17 18:40:00-07:00 9353100217060788102 0.0093 0.0045 725 0 0
2020-05-17 18:40:00-07:00 9521689070912159706 0.0093 0.0045 164 0 0
2020-05-17 18:40:00-07:00 11079878968512225881 0.0064 0.0019 65 0 0

從上表 (醒目顯示) 中,我們清楚看到第一列顯示的交易因大量提交中止而發生高延遲。我們也可以看到大量重試提交作業,這表示系統隨後重試了已中止的提交作業。在下一個步驟中,我們會進一步調查,找出導致這個問題的原因。

找出交易延遲時間過長所涉及的資料欄

在這個步驟中,我們會擷取高中止次數交易的 read_columnswrite_constructive_columnswrite_delete_tables 資料,檢查高延遲交易是否在同一組資料欄上運作。FPRINT 值在下一個步驟中也會很有用。

SELECT
  fprint,
  read_columns,
  write_constructive_columns,
  write_delete_tables
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end = "2020-05-17T18:40:00"
ORDER BY avg_total_latency_seconds DESC LIMIT 3;
fprint read_columns write_constructive_columns write_delete_tables
15185072816865185658 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.score,globalTagAffinity.shares] [TestHigherLatency._exists,TestHigherLatency.shares,TestHigherLatency_lang_status_score_index.shares] []
15435530087434255496 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.likes,globalTagAffinity.score] [TestHigherLatency._exists,TestHigherLatency.likes,TestHigherLatency_lang_status_score_index.likes] []
14175643543447671202 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.score,globalTagAffinity.ugcCount] [TestHigherLatency._exists,TestHigherLatency.ugcCount,TestHigherLatency_lang_status_score_index.ugcCount] []

如上表輸出內容所示,平均總延遲時間最長的交易會讀取相同的資料欄。我們也可以觀察到一些寫入爭用,因為交易會寫入相同的資料欄,也就是 TestHigherLatency._exists

判斷交易成效的長期變化

我們可以查看與這項交易形狀相關的統計資料,瞭解一段時間內的變化。使用下列查詢,其中 $FPRINT 是上一個步驟中高延遲交易的指紋。

SELECT
  interval_end,
  ROUND(avg_total_latency_seconds, 3) AS latency,
  ROUND(avg_commit_latency_seconds, 3) AS commit_latency,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count,
  commit_failed_precondition_count,
  avg_bytes
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end >= "2020-05-17T16:40:00"
  AND interval_end <= "2020-05-17T19:40:00"
  AND fprint = $FPRINT
ORDER BY interval_end;
interval_end 延遲 commit_latency commit_attempt_count commit_abort_count commit_retry_count commit_failed_precondition_count avg_bytes
2020-05-17 16:40:00-07:00 0.095 0.010 53230 4752 4330 0 91
2020-05-17 16:50:00-07:00 0.069 0.009 61264 3589 3364 0 91
2020-05-17 17:00:00-07:00 0.150 0.010 75868 10557 9322 0 91
2020-05-17 17:10:00-07:00 0.248 0.013 103151 30220 28483 0 91
2020-05-17 17:20:00-07:00 0.310 0.012 130078 45655 41966 0 91
2020-05-17 17:30:00-07:00 0.294 0.012 160064 64930 59933 0 91
2020-05-17 17:40:00-07:00 0.315 0.013 209614 104949 96770 0 91
2020-05-17 17:50:00-07:00 0.322 0.012 215682 100408 95867 0 90
2020-05-17 18:00:00-07:00 0.310 0.012 230932 106728 99462 0 91
2020-05-17 18:10:00-07:00 0.309 0.012 259645 131049 125889 0 91
2020-05-17 18:20:00-07:00 0.315 0.013 272171 137910 129411 0 90
2020-05-17 18:30:00-07:00 0.292 0.013 258944 121475 115844 0 91
2020-05-17 18:40:00-07:00 0.350 0.013 278802 142205 134229 0 91
2020-05-17 18:50:00-07:00 0.302 0.013 256259 115626 109756 0 91
2020-05-17 19:00:00-07:00 0.315 0.014 250560 110662 100322 0 91
2020-05-17 19:10:00-07:00 0.271 0.014 238384 99025 90187 0 91
2020-05-17 19:20:00-07:00 0.273 0.014 219687 84019 79874 0 91
2020-05-17 19:30:00-07:00 0.198 0.013 195357 59370 55909 0 91
2020-05-17 19:40:00-07:00 0.181 0.013 167514 35705 32885 0 91

從上述輸出內容中,我們可以觀察到在醒目顯示的時間範圍內,總延遲時間較長。此外,只要總延遲時間較長,即使提交延遲時間 (commit_latency) 沒有太大變化,commit_attempt_countcommit_abort_countcommit_retry_count 也會較長。由於交易提交作業遭到中止的頻率較高,提交嘗試次數也因提交重試而增加。

結論

在本例中,我們發現高延遲的原因是大量交易中止。接下來,請查看應用程式收到的提交中止錯誤訊息,瞭解中止原因。檢查應用程式中的記錄後,我們發現應用程式在這段時間內確實變更了工作負載,也就是出現了其他具有高 attempts_per_second 的交易形狀,而該交易 (可能是夜間清除作業) 導致了額外的鎖定衝突。

找出未正確重試的交易

下列查詢會傳回過去十分鐘內,提交中止次數高但沒有重試的交易樣本。

SELECT
  *
FROM (
  SELECT
    fprint,
    SUM(commit_attempt_count) AS total_commit_attempt_count,
    SUM(commit_abort_count) AS total_commit_abort_count,
    SUM(commit_retry_count) AS total_commit_retry_count
  FROM
    SPANNER_SYS.TXN_STATS_TOP_10MINUTE
  GROUP BY
    fprint )
WHERE
  total_commit_retry_count = 0
  AND total_commit_abort_count > 0
ORDER BY
  total_commit_abort_count DESC;
fprint total_commit_attempt_count total_commit_abort_count total_commit_retry_count
1557557373282541312 3367894 44232 0
5776062322886969344 13566 14 0

我們發現交易 (指紋 1557557373282541312) 已中止 44232 次,但從未重試。這看起來很可疑,因為中止次數很高,而且不太可能每次中止都是由無法重試的錯誤所導致。另一方面,交易 fprint 5776062322886969344 的可疑程度較低,因為中止次數總計不高。

以下查詢會傳回交易的詳細資料,包括 read_columnswrite_constructive_columnswrite_delete_tables,以及 fprint 1557557373282541312。這項資訊有助於在用戶端程式碼中識別交易,以便針對這個情境檢查重試邏輯。

SELECT
  interval_end,
  fprint,
  read_columns,
  write_constructive_columns,
  write_delete_tables,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count
FROM
  SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  fprint = 1557557373282541312
ORDER BY
  interval_end DESC;
interval_end fprint read_columns write_constructive_columns write_delete_tables commit_attempt_count commit_abort_count commit_retry_count
2021-01-27T18:30:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 805228 1839 0
2021-01-27T18:20:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 1034429 38779 0
2021-01-27T18:10:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 833677 2266 0
2021-01-27T18:00:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 694560 1348 0

我們可以發現這項交易涉及讀取 Singers._exists 隱藏資料欄,以檢查資料列是否存在。交易也會寫入 Singers.FirstNameSinger.LastName 欄。這項資訊有助於判斷自訂用戶端程式庫中實作的交易重試機制是否正常運作。

後續步驟