我已经阅读了所有有关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的“显示查询日志”功能提供的信息与实体框架日志记录相当。
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中删除了所有的迁移,并创建了一个新的初始创建迁移,所以一切都是从头开始运行,插入到Table1仍然需要大约20秒的时间,但插入到Table2只需要不到1秒钟。
在连接字符串中加入Enlist=false也没有帮助。
我同意@Mark G的评论:“结果……表明问题要么在EF Core上游,要么在提供程序中”,但我不知道如何进一步诊断问题。
我现在已将代码更改为使用NpgSql通过原始SQL插入行到此表格,速度非常快,每个插入少于100毫秒。因此,最有可能的候选人似乎是Entity Framework Core中的一个bug,但由于我不知道具体的问题是什么,所以很难向他们的团队提出错误报告。
npgsql
。同时尝试在连接字符串中使用Enlist=false
。 - Mark G