事务统计信息

Cloud Spanner 提供内置表，表中存储关于事务的统计信息。您可以使用 SQL 语句从这些 SPANNER_SYS.TXN_STATS* 表中检索统计信息。

何时使用事务统计信息

在调查性能问题时，事务统计信息非常有用。例如，您可以检查是否存在任何可能影响数据库性能或每秒查询次数 (QPS) 的运行缓慢的事务。另一种情况是，您的客户端应用出现较高的事务执行延迟。分析事务统计信息可能有助于发现潜在的瓶颈，例如可能影响延迟时间的特定列的大量更新。

可用情况

SPANNER_SYS 数据只能通过 SQL 接口获得；例如：

  • Google Cloud 控制台中数据库的 Spanner Studio 页面

  • gcloud spanner databases execute-sql 命令

  • 事务数据分析信息中心

  • executeQuery API

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 (Fingerprint) 对统计信息进行分组。如果存在交易代码，则 FPRINT 是该代码的哈希值。否则，系统会根据事务中涉及的操作计算哈希值。

  • 由于统计信息是根据 FPRINT 进行分组的，因此如果在同一时间间隔内多次执行同一事务，我们仍会在这些表中看到该事务的一个条目。

  • 每行包含 Spanner 在指定的时间间隔内捕获特定事务的统计信息的所有执行统计信息。

如果 Spanner 无法存储这些表内在相应时间间隔内运行的所有事务的统计信息，系统会优先处理在指定的时间间隔内延迟时间最长、提交尝试次数和写入字节数最高的事务。

表架构

列名 类型 说明
INTERVAL_END TIMESTAMP 所含事务执行发生的时间段结束。
TRANSACTION_TAG STRING 此交易操作的可选交易代码。如需详细了解如何使用代码，请参阅使用交易代码进行问题排查。具有相同代码字符串的多笔交易的统计信息会归在一行中，并且“TRANSACTION_TAG”与此代码字符串相匹配。
FPRINT INT64 TRANSACTION_TAG 的哈希值（如果存在）；否则，系统会根据事务涉及的操作计算哈希值。INTERVAL_END 和 FPRINT 共同充当这些表的唯一键。
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 个百分位数。n如需查看相关示例，请参阅查找事务的第 99 百分位延迟时间。

如需了解详情，请参阅百分位和分布值指标。
OPERATIONS_BY_TABLE ARRAY<STRUCT>

事务中的 INSERT 或 UPDATE 操作对每个表的影响。这由受影响的行数和写入的字节数指示。

此列有助于直观呈现表的负载，并可让您深入了解事务写入表的速率。

按如下方式指定数组：
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

1 _exists 是一个内部字段，用于检查特定行是否存在。

示例查询

本部分提供了几个可检索事务统计信息的示例 SQL 语句。您可以使用客户端库、gcloud 命令行工具或 Google 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 个百分位数。n如需查看示例，请参阅查找事务的第 99 百分位延迟时间。

如需了解详情，请参阅百分位和分布值指标。
OPERATIONS_BY_TABLE ARRAY<STRUCT>

按表计算所有事务对 INSERT 或 UPDATE 操作的影响。这由受影响的行数和写入的字节数指示。

此列有助于直观呈现表的负载，并可让您深入了解事务写入表的速率。

按如下方式指定数组：
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

示例查询

本部分提供了几个可检索事务统计信息的示例 SQL 语句。您可以使用客户端库、gcloud 命令行工具或 Google 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_MINUTE 和 SPANNER_SYS.TXN_STATS_TOTAL_MINUTE：前 6 个小时中的时间段。

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE 和 SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE：前 4 天中的时间段。

  • SPANNER_SYS.TXN_STATS_TOP_HOUR 和 SPANNER_SYS.TXN_STATS_TOTAL_HOUR：前 30 天中的时间段。

Spanner 中的事务统计信息可让您深入了解应用如何使用数据库，并且有助于调查性能问题。例如，您可以检查是否有任何运行缓慢的事务可能导致争用，或者确定潜在的高负载来源，例如特定列有大量更新。通过以下步骤，我们将展示如何使用事务统计信息来调查数据库中的争用。

了解事务和提交计数

Spanner 事务可能必须尝试多次才能提交。发生这种情况的最常见情况是两个事务尝试同时处理同一数据，并且需要中止其中一个事务才能保留事务的隔离属性。也可能会导致中止事务的一些其他暂时性事件包括：

  • 暂时性网络问题。

  • 事务提交过程中应用数据库架构更改。

  • Spanner 实例不具备处理其收到的所有请求的容量。

在这种情况下，客户端应该重试已取消的事务，直至其成功提交或超时。对于官方 Spanner 客户端库的用户，每个库都实现了自动重试机制。如果您使用的是自定义版本的客户端代码，请将事务提交封装在重试循环中。

Spanner 事务也可能因不可重试的错误（例如事务超时、权限问题或表/列名称无效）而被取消。无需重试此类事务，Spanner 客户端库会立即返回错误。

下表举例说明了在不同情况下如何记录 COMMIT_ATTEMPT_COUNT、COMMIT_ABORT_COUNT 和 COMMIT_RETRY_COUNT。

情况 COMMIT_ATTEMPT_COUNT COMMIT_ABORT_COUNT COMMIT_RETRY_COUNT
事务在首次尝试就成功提交。 1 0 0
由于超时错误，交易已取消。 1 1 0
事务因暂时性网络问题而被取消，并在重试一次后成功提交。 2 1 1
具有相同 FPRINT 的 5 个事务将按 10 分钟间隔执行。其中 3 个事务在首次尝试时就成功提交，同时 2 个事务被取消，然后在首次重试时成功提交。 7 2 2

transactions-stats 表中的数据是某个时间间隔的汇总数据。对于特定间隔，事务可能会取消并跨边界重试，并归入不同的存储分区。因此，在特定时间间隔，取消和重试可能并不相等。

这些统计信息旨在用于问题排查和自省，并且不能保证 100% 准确。统计信息会先在内存中汇总，然后再存储在 Cloud Spanner 表中。在升级或其他维护活动期间，Cloud Spanner 服务器可能会重启，从而影响数字的准确性。

使用事务统计信息排查数据库争用问题

您可以使用 SQL 代码或事务数据分析信息中心来查看数据库中可能由于锁争用而导致延迟时间较长的事务。

以下主题介绍如何使用 SQL 代码调查此类事务。

选择要调查的时间段

可以在使用 Spanner 的应用中找到该编号。

在本练习中，假设问题于 2020 年 5 月 17 日下午 5:20 左右开始出现。

您可以使用事务标记识别事务来源，并在事务统计信息表和锁定统计信息表之间建立关联，以便有效地排查锁争用问题。有关详情，请参阅使用交易代码进行问题排查。

收集所选时间段内的交易统计信息

在开始调查之前，我们将查询问题开始时间前后的 TXN_STATS_TOTAL_10MINUTE 表。此查询的结果将展示该时间段内延迟时间和其他事务统计信息的变化。

例如，以下查询返回从 4:30 pm 到 7: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_columns、write_constructive_columns 和 write_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 latency 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_count、commit_abort_count 和 commit_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

我们可以看到，具有 fprint 1557557373282541312 的事务被取消 44232 次，但从未重试。这看起来很可疑，因为取消计数很高，且每次取消都不可能是由不可重试错误导致。另一方面，对于具有 fprint 5776062322886969344 的事务，不可信，因为总取消次数并不高。

以下查询返回有关具有 fprint 1557557373282541312 的事务的更多详细信息，包括 read_columns、write_constructive_columns 和 write_delete_tables。此信息有助于识别客户端代码中的事务，其中可以审核此场景的重试逻辑。

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.FirstName 和 Singer.LastName 列。此信息有助于确定自定义客户端库中实现的事务重试机制是否按预期运行。

后续步骤