C#、 Entity Framework 核心和 PostgreSql : inserting a single row takes 20+ seconds

Question

我正在使用 Entity Framework Core 和 nuget 包 Npgsql.EntityFrameworkCore.PostgreSQL。

我已经阅读了所有其他有关 Entity Framework Core 缓慢插入的答案，但都没有帮助。

using (var db = getNewContext())
{
     db.Table1.Add(Table1Object);
     db.SaveChanges();
}

这个单次插入大约需要 20 到 30 秒。表中的行数少于 100。我在 using 中放置了秒表启动和停止，以确保时间不是由于上下文初始化引起的。

这是我的表对象类(相关属性名称已更改):

public partial class Table1Object
{
    public long Id { get; set; }
    public Guid SessionId { get; set; }
    public DateTime Timestamp { get; set; }
    public long MyNumber1 { get; set; }
    public double MyNumber2 { get; set; }
    public double MyNumber3 { get; set; }
    public double MyNumber4 { get; set; }
    public long? ParentId { get; set; }
    public bool MyBool { get; set; }
}

SessionId 用于链接到另一个表(Session 表)，但我没有在任何地方为此明确定义外键或任何其他约束。 ParentId 也用于链接回同一表中的另一行，但我没有为此明确定义约束。

在不同的表上运行等效代码只需不到一秒的时间即可插入一行。 Table2 的列数较少，但我没想到行的大小如此不同会产生如此剧烈的影响:

public partial class Table2Object
{
    public int Id { get; set; }
    public DateTime Timestamp { get; set; }
    public string Name { get; set; }
    public double Value { get; set; }
}

使用 Serilog 和 Entity Framework Core 日志记录，您可以看到延迟发生在“提交事务”步骤中，大约需要 26 秒，插入本身只需要 6 毫秒(为简洁起见，日志语句的某些部分被缩减):

2021-04-08 11:20:36.874 [DBG] 'DataContext' generated a temporary value for the property 'Id.Table1'.
2021-04-08 11:20:36.879 [DBG] Context 'DataContext' started tracking 'Table1' entity.
2021-04-08 11:20:36.880 [DBG] SaveChanges starting for 'DataContext'.
2021-04-08 11:20:36.881 [DBG] DetectChanges starting for 'DataContext'.
2021-04-08 11:20:36.905 [DBG] DetectChanges completed for 'DataContext'.
2021-04-08 11:20:36.906 [DBG] Opening connection to database
2021-04-08 11:20:36.907 [DBG] Opened connection to database
2021-04-08 11:20:36.908 [DBG] Beginning transaction with isolation level 'Unspecified'.
2021-04-08 11:20:36.909 [DBG] Began transaction with isolation level 'ReadCommitted'.
2021-04-08 11:20:36.912 [DBG] Creating DbCommand for 'ExecuteReader'.
2021-04-08 11:20:36.913 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2021-04-08 11:20:36.914 [DBG] Executing DbCommand [Parameters= ...]
INSERT INTO "Table1" ("SessionId", "Timestamp" ...)
VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7)
RETURNING "Id";
2021-04-08 11:20:36.920 [INF] Executed DbCommand (6ms) Parameters=[...]
INSERT INTO "Table1" ("SessionId", "Timestamp" ...)
VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7)
RETURNING "Id";
2021-04-08 11:20:36.925 [DBG] The foreign key property 'Table1.Id' was detected as changed.
2021-04-08 11:20:36.930 [DBG] A data reader was disposed.
2021-04-08 11:20:36.931 [DBG] Committing transaction.
2021-04-08 11:21:02.729 [DBG] Committed transaction.
2021-04-08 11:21:02.730 [DBG] Closing connection to database

这是插入到 Table2 时的等效日志。插入需要 3 毫秒，提交需要 75 毫秒。这是应该的速度:

2021-04-08 11:20:36.459 [DBG] 'DataContext' generated a temporary value for the property 'Id.Table2'.
2021-04-08 11:20:36.460 [DBG] Context 'DataContext' started tracking 'Table2' entity.
2021-04-08 11:20:36.461 [DBG] SaveChanges starting for 'DataContext'.
2021-04-08 11:20:36.462 [DBG] DetectChanges starting for 'DataContext'.
2021-04-08 11:20:36.463 [DBG] DetectChanges completed for 'DataContext'.
2021-04-08 11:20:36.464 [DBG] Opening connection to database
2021-04-08 11:20:36.465 [DBG] Opened connection to database
2021-04-08 11:20:36.466 [DBG] Beginning transaction with isolation level 'Unspecified'.
2021-04-08 11:20:36.467 [DBG] Began transaction with isolation level 'ReadCommitted'.
2021-04-08 11:20:36.468 [DBG] Creating DbCommand for 'ExecuteReader'.
2021-04-08 11:20:36.469 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2021-04-08 11:20:36.470 [DBG] Executing DbCommand [Parameters=...]
INSERT INTO "Table2" ("Name", "Timestamp", "Value")
VALUES (@p0, @p1, @p2)
RETURNING "Id";
2021-04-08 11:20:36.472 [INF] Executed DbCommand (3ms) [Parameters=[...]
INSERT INTO "Table2" ("Name", "Timestamp", "Value")
VALUES (@p0, @p1, @p2)
RETURNING "Id";
2021-04-08 11:20:36.474 [DBG] The foreign key property 'Table2.Id' was detected as changed.
2021-04-08 11:20:36.475 [DBG] A data reader was disposed.
2021-04-08 11:20:36.476 [DBG] Committing transaction.
2021-04-08 11:20:36.551 [DBG] Committed transaction.
2021-04-08 11:20:36.552 [DBG] Closing connection to database

除了行大小稍大之外，我对表格之间的不同之处感到茫然。我删除并重新创建了该表，以防出现我不知道的任何约束、外键、触发器等。

插入的“解释”计划生成:

"Insert on ""Table1""  (cost=0.00..0.01 rows=1 width=81)"
"  ->  Result  (cost=0.00..0.01 rows=1 width=81)"

为 postgresql 启用“显示查询日志”会提供与 Entity Framework 日志记录相同数量的信息:

2021-04-09 12:05:06.559 BST [1979] user1@database LOG:  statement: BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED
2021-04-09 12:05:06.560 BST [1979] user1@database LOG:  execute <unnamed>: INSERT INTO "Table1" (...)
    VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
    RETURNING "Id"
2021-04-09 12:05:06.560 BST [1979] user1@database DETAIL:  parameters: $1 = '0.580484961751977', $2 = 'f', $3 = '0.205387434417341', $4 = '18', $5 = '148', $6 = '93c71fb5-836a-486a-8d82-e073743b41cd', $7 = '2021-04-09 11:04:58.123773', $8 = '1.15474773024298'
2021-04-09 12:05:06.565 BST [1979] user1@database LOG:  statement: COMMIT
2021-04-09 12:05:47.352 BST [1443] postgres@database LOG:  statement: /*pga4dash*/
    SELECT 'session_stats' AS chart_name, row_to_json(t) AS chart_data
    FROM ...
    UNION ALL
    SELECT 'tps_stats' AS chart_name, row_to_json(t) AS chart_data
    FROM ...
    UNION ALL
    SELECT 'ti_stats' AS chart_name, row_to_json(t) AS chart_data
    FROM ...
    UNION ALL
    SELECT 'to_stats' AS chart_name, row_to_json(t) AS chart_data
    FROM ...
    UNION ALL
    SELECT 'bio_stats' AS chart_name, row_to_json(t) AS chart_data
    FROM ...
    
2021-04-09 12:05:51.148 BST [1979] user1@database LOG:  statement: DISCARD ALL

您可以看到，在 COMMIT 语句之后，在下一个语句执行一些内部图表日志信息之前大约过了 41 秒。 41 秒仅用于提交单行插入!

与 Table2 的插入相比，提交只需要 100 毫秒!

2021-04-09 12:05:06.097 BST [1979] user1@database LOG:  statement: BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED
2021-04-09 12:05:06.097 BST [1979] user1@database LOG:  execute <unnamed>: INSERT INTO "Table2" ("Name", "Timestamp", "Value")
    VALUES ($1, $2, $3)
    RETURNING "Id"
2021-04-09 12:05:06.097 BST [1979] user1@database DETAIL:  parameters: $1 = 'Test', $2 = '2021-04-09 11:05:06.096182', $3 = '98'
2021-04-09 12:05:06.098 BST [1979] user1@database LOG:  statement: COMMIT
2021-04-09 12:05:06.189 BST [1979] user1@database LOG:  statement: DISCARD ALL

我直接在 PGAdmin 中运行以下语句，它告诉我它用了 323 毫秒:

BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED;
INSERT INTO "Table1" ("MyColumn1", "MyColumn2", "MyColumn3", "MyColumn4", "ParentId", "SessionId", "Timestamp", "MyColumn5")
    VALUES ('0.580484961751977','f' , '0.205387434417341','18',  '148',  '93c71fb5-836a-486a-8d82-e073743b41cd','2021-04-09 11:04:58.123773',  '1.15474773024298')
    RETURNING "Id";
COMMIT;

我还尝试使用带有以下 C# 代码的 NpgSql 直接运行该语句:

            _logger.Debug("Using connection");
            using (var conn = new NpgsqlConnection(StaticConfig.ConnectionString))
            {
                _logger.Debug("connection.open");
                conn.Open();
                _logger.Debug("Using command");
                // Insert some data
                using (var cmd = new NpgsqlCommand(
                    " BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED;" +
                    " INSERT INTO \"Table1\" (\"MyColumn1\", \"MyColumn2\", \"MyColumn3\", \"MyColumn4\", \"ParentId\", \"SessionId\", \"Timestamp\", \"MyColumn5\")" +
                    " VALUES ('0.580484961751977','f' , '0.205387434417341','18',  '148',  '93c71fb5-836a-486a-8d82-e073743b41cd','2021-04-09 11:04:58.123773',  '1.15474773024298')" +
                    " RETURNING \"Id\";" +
                    "COMMIT;"
                    , conn))
                {
                    _logger.Debug("command execute");
                    cmd.ExecuteNonQuery();
                }
            }
            _logger.Debug("Done");

该代码中的日志语句告诉我整个过程不到一秒钟:

[21:59:41 DBG] Using connection
[21:59:41 DBG] connection.open
[21:59:42 DBG] Using command
[21:59:42 DBG] command execute
[21:59:42 DBG] Done

我还删除了数据库，删除了 Entity Framework 中的所有迁移，并创建了一个新的 Initial create 迁移，所以一切都从头开始运行，插入 Table1 仍然需要大约 20 秒，但不到一秒插入 Table2。

将 Enlist=false 放在连接字符串中没有帮助。

我同意@Mark G 的评论，即“调查结果……表明问题要么出在 EF Core 的上游，要么出在提供程序中”，但我不确定如何进一步诊断问题。

从那以后，我更改了代码以使用 NpgSql 通过原始 sql 将行插入到此表中，这非常快，每次插入不到 100 毫秒。所以最有可能的候选人似乎是 Entity Framework Core 中的错误，但由于我不知 Prop 体问题是什么，所以很难向他们的团队提出错误报告。

Answer 1

经过大量测试，我最终发现问题根本不在 Entity Framework 或 NpgSql 中，但我看到的延迟是由写入缓存引起的。在向表 1 中插入一行之前，我总是写一个 30MB 的文件，我相信文件写入是在 File.WriteAllBytes 返回之后完成的，因此它不会影响任何 future 的计时语句。然而，在操作系统层，当插入语句运行时并没有真正完成写入磁盘，导致插入语句被人为延迟。

我用下面的代码证明了这一点:

Stopwatch sw1 = new Stopwatch();
sw1.Start();
File.WriteAllBytes(myBytes);
sw1.Stop();

Thread.Sleep(1000);

Stopwatch sw2 = new Stopwatch();
sw2.Start();
MethodThatInsertsIntoTable1();
sw2.Stop();

秒表 1 显示 File.WriteAllBytes 总是花费大约 500 毫秒，然后秒表 2 计时大约 20 到 30 秒。

如果我更改 MethodThatInsertsIntoTable1 以插入到不同的表中，那么无论表如何，它仍然需要 20 到 30 秒。

如果我将 Thread.Sleep(1000) 增加到 Thread.Sleep(30000)，则秒表 2 记录插入时间少于 10 毫秒。

这表明即使在 File.WriteAllBytes 将控制权返回给程序之后，实际上并没有真正完成将文件写入磁盘。

我运行的环境是树莓派上的linux。写入速度测试证实我对 SD 卡的写入速度刚刚超过 1MB/s，这与我看到的结果一致，写入 30MB 文件需要 20-30 秒，不可能在 500 毫秒内完成那个秒表 1 说是。

另一个用户似乎因此在 File.WriteAllBytes does not block 中遇到问题

在树莓派上加了一个外接的SSD USB HDD，改成在那里保存文件后，保存文件只需要0.5秒，问题就解决了。