PostgreSQL 使用 RETURNING 缓慢插入单行（在生产中花费 500 毫秒）

Question

有点难住这里。我有一个名为 request_to_print 的小表。这是表结构。

它有一个主键 request_internal_id。

该表中有 747 行。

当插入发生时，我注意到它需要 500ms+，这似乎过分了。大多数插入是在 1 毫秒内完成的，而且在更大的表上。

2020-10-06T10:38:29.284+11:00   Executed DbCommand (566ms) [Parameters=[@p0='', @p1='94ac21e6-bdd5-409c-90f6-4e014d1de763', @p2=NULL (DbType = DateTime), @p3='2020-10-05T23:38:28' (Nullable = true) (DbType = DateTime), @p4='E001'], CommandType='Text', CommandTimeout='30']
2020-10-06T10:38:29.284+11:00   INSERT INTO request_to_print (card_number, customer_internal_id, request_sent_date, requested_date, requesting_store)
2020-10-06T10:38:29.284+11:00   VALUES (@p0, @p1, @p2, @p3, @p4)
2020-10-06T10:38:29.284+11:00   RETURNING request_internal_id;

我已经在类似条件下在我们的测试环境中运行了这个命令。因为它是一个插入，所以没有很多东西需要分析/解释。我的意思是，它只是放入一行数据。这是我从跟踪插入中得到的：

[
  {
    "Plan": {
      "Node Type": "ModifyTable",
      "Operation": "Insert",
      "Parallel Aware": false,
      "Relation Name": "request_to_print",
      "Schema": "public",
      "Alias": "request_to_print",
      "Startup Cost": 0,
      "Total Cost": 0.02,
      "Plan Rows": 1,
      "Plan Width": 304,
      "Actual Startup Time": 0.087,
      "Actual Total Time": 0.088,
      "Actual Rows": 1,
      "Actual Loops": 1,
      "Output": [
        "request_internal_id"
      ],
      "Shared Hit Blocks": 2,
      "Shared Read Blocks": 0,
      "Shared Dirtied Blocks": 0,
      "Shared Written Blocks": 0,
      "Local Hit Blocks": 0,
      "Local Read Blocks": 0,
      "Local Dirtied Blocks": 0,
      "Local Written Blocks": 0,
      "Temp Read Blocks": 0,
      "Temp Written Blocks": 0,
      "I/O Read Time": 0,
      "I/O Write Time": 0,
      "Plans": [
        {
          "Node Type": "Result",
          "Parent Relationship": "Member",
          "Parallel Aware": false,
          "Startup Cost": 0,
          "Total Cost": 0.02,
          "Plan Rows": 1,
          "Plan Width": 304,
          "Actual Startup Time": 0.03,
          "Actual Total Time": 0.031,
          "Actual Rows": 1,
          "Actual Loops": 1,
          "Output": [
            "uuid_generate_v4()",
            "'2705000000835'::character varying(100)",
            "'aaaaaaaa-d0c9-46bc-b83e-cec6a22d6e82'::uuid",
            "now()",
            "'E001'::character varying(10)",
            "NULL::timestamp without time zone"
          ],
          "Shared Hit Blocks": 0,
          "Shared Read Blocks": 0,
          "Shared Dirtied Blocks": 0,
          "Shared Written Blocks": 0,
          "Local Hit Blocks": 0,
          "Local Read Blocks": 0,
          "Local Dirtied Blocks": 0,
          "Local Written Blocks": 0,
          "Temp Read Blocks": 0,
          "Temp Written Blocks": 0,
          "I/O Read Time": 0,
          "I/O Write Time": 0
        }
      ]
    },
    "Planning Time": 0.03,
    "Triggers": [],
    "Execution Time": 0.107
  }
]

任何人都可以帮助解释为什么在一张小桌子上这样一个看似无辜的插入需要这么长时间？对于上下文，我使用 Entity Framework Core 3.1 和 .NET Core 应用程序来执行插入（通过 NPGSQL 库）。

Answer 1

执行计划说0.1ms完成操作；我想这并不是执行缓慢的原因。

以下是对此进行调查的一些想法：

• 用于auto_explain记录缓慢执行的计划。如果您能负担得起大量的开销，请制定auto_explain.analyze计划，auto_explain.buffers以便on计划告诉您时间花在哪里。

• 暂时减小deadlock_timeout到 0.1 并设置log_lock_waits为on。然后您将在日志中看到该语句是否被锁阻止。

• 使用操作系统工具来确定 I/O 系统是否完全过载。

• 阅读日志文件以了解异常情况。