Exception when inserting multiple rows into the same table on SQL Server #29502
Assignees
Labels
area-save-changes
area-sqlserver
closed-fixed
The issue has been fixed and is/will be included in the release indicated by the issue milestone.
customer-reported
regression
Servicing-approved
type-bug
Milestone
Comments
|
@joakimriedel I'm not able to reproduce this--see my code below. Please attach a small, runnable project or post a small, runnable code listing that reproduces what you are seeing so that we can investigate. #nullable enable
public static class Your
{
public static string ConnectionString = @"Data Source=(LocalDb)\MSSQLLocalDB;Database=AllTogetherNow";
}
public class Product
{
public int Id { get; set; }
}
public class User
{
public int Id { get; set; }
}
public class DailyDigest
{
public int Id { get; set; }
public User User { get; set; }
public DateTime TimeCreatedUtc { get; set; }
}
public class SomeDbContext : DbContext
{
protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
=> optionsBuilder
.UseSqlServer(Your.ConnectionString)
.LogTo(Console.WriteLine, LogLevel.Information)
.EnableSensitiveDataLogging();
public DbSet<User> Users { get; set; }
public DbSet<DailyDigest> DailyDigests { get; set; }
}
public class Program
{
public static async Task Main()
{
using (var context = new SomeDbContext())
{
context.Database.EnsureDeleted();
context.Database.EnsureCreated();
context.Add(new DailyDigest { User = new() });
context.SaveChanges();
}
using (var context = new SomeDbContext())
{
var utcNow = DateTime.UtcNow;
var digests = await context.Users
.Select(u => new DailyDigest
{
User = u,
TimeCreatedUtc = utcNow,
})
.ToListAsync();
foreach (var digest in digests)
{
// next line is necessary in 7.0 rc2, was not necessary in 6.0 and below (down to 1.0 ?)
// digest.Id = default;
context.DailyDigests.Add(digest);
}
await context.SaveChangesAsync();
}
}
} |
|
@ajcvickers I'm terribly sorry for posting a bad issue without repro. The real project is a huge codebase, five years old and iterated on since the very first version of EF Core, which makes it quite challenging to break parts out in a smaller project and still reproduce. This issue was the only thing (except how hard it was to regenerate compiled model) that I had after migrating from 6.0.10 to 7.0-rc2 (which in itself is amazing! 🙌). I've now spent the last hours trying to reproduce in a smaller project, but without success. It really bugs me because there is absolutely nothing I can think of in the code that might set or alter Note that your sample has one issue, since it projects from // old: context.Add(new DailyDigest { User = new() });
context.Add(new User());What I've applied from real project so far that I thought might help reproduce;
var digests = await context.Users
.TagWith(tag: nameof(DailyDigest))
// lots of conditions
.Where(conditions...)
.OrderBy(u => u.TimeCreatedUtc)
.Take(maxCount)
.Select(u => new
{
User = u,
// lots of other calculated properties from navigation properties..
})
.Select(source => new DailyDigest
{
User = source.User,
TimeCreatedUtc = utcNow,
// lots of other properties...
})
.ToListAsync(cancellationToken);What I haven't tried so far, but might affect results;
I'd appreciate any tips or hints on what was changed in 7.0 that you think might affect migrating from 6.0. |
|
@joakimriedel Have you tried with 7.0 GA? |
|
@ajcvickers Just installed 7.0 GA but this bug still reproduces in real project. I think there's something really fishy going on, perhaps memory corruption or bad caching somewhere? Look at the following verbose logs; Verbose logThis line is especially troubling since Id 82485 has already been set earlier, why does it change into 82460? Looks like it is when this entity is about to switch from Added to Unchanged that this exception is thrown. The DailyDigests will be generated in batches, default batch size is 50. If I change batch size to 1 the bug does not reproduce. It seems only as if I can reproduce this if SaveChangesAsync is called for a large number of items saved to db at once. |
|
@ajcvickers while on the topic of logs, I noted that the following log message seems to have reversed property and class name in output string? Should be |
|
@roji Looks like this could be a batching issue related to #28654 and #29356. @joakimriedel Can you post the SQL generated for the SaveChanges that is being executed when the exception is thrown? |
|
@ajcvickers Sure, this is the full log produced when executing the SaveChangesAsync call. It does indeed look related to batching. I save 50 items here, but somehow it was decided to split into 42 in one batch and 8 in second, and the error seems to occur with the id of the item on the boundary between the two batches. Full log output |
|
@ajcvickers Spent the day trying to get the repro project as similar to the real project as possible, adding generic host, connection pooling and enable multiple active result sets in connection string. It still only reproduces in the real project but I have at least managed to get a debug log output which is identical to the real project log output, down to a few lines which may or may not have something to do with this bug. See the diff below, in real project when it fails a db reader is closed during detect changes phase. Related or red herring? You decide.
edit: full diff here |
|
@ajcvickers @roji I think I managed to find something interesting today. I experimented with maxCount (the Then I tried reproducing with 32 items after adding the following workaround to the table configuration; This works! 🤯 But the SQL query will be a bit different; Without HasTrigger With HasTrigger Could this difference (missing sort) be the cause of this exception? I hope you could have a look at this because at this moment I feel not safe about pushing EF7/NET7 to production without resolving this issue. |
joakimriedel
changed the title
|
@joakimriedel the difference in SQL between the trigger and non-trigger cases - including the missing sort - are very much by-design, and are a performance optimization introduced in EF Core 7.0 (see this blog post for more information). However, I don't doubt that there's a bug here; are you now able to submit a reprocible code sample, similar to what @ajcvickers attempted above? |
|
@roji I've now spent ~16 hours trying to reproduce this outside of the real project. I've imported almost every aspect that I can think of that might affect the results from the real project into the repro project unsuccessfully. The only thing missing now is the real data, which would be the next step to import into repro project. As I wrote above, the debug output from repro and real are the same, but it only fails in real project. In real project it is 100% reproducible. 31 items => no exception, 32 items => exception. 32 items w/ HasTrigger => no exception. 32 items where Id is set explicitly to default int => no exception. 32 items in version 6.0.10 => no exception. As the bug is hard to reproduce in repro project I'm starting to think there is some kind of memory corruption, caching or timing issue that only occurs when full project is loaded and the entity graph is more saturated with data. |
|
@joakimriedel any memory corruption here is very unlikely... Using actual (or similar) data in your repro is definitely a good step forward, otherwise it's good practice to start from your real project and progressively strip it down until you get a minimal repro. In any case, I did do various work in this area for 7.0, so it makes sense for there to be a bug here. |
|
From the logs, this looks suspicious: It looks like the foreign key Two theories:
@joakimriedel Can you post the code for the |
|
@ajcvickers as you see earlier in the log, 82485 has already been set from temporary to database value.
I'm currently working on minimizing the real project down until it doesn't reproduce anymore as suggested by @roji will keep you posted soon. Notification is the abstract base class for DailyDigest. |
|
@ajcvickers @roji just a quick update, it is definitely related to the specific data and how it is loaded. I have managed to minimize the entire code in the real project (with real data) down to only the following lines and it still reproduces: Now for the fun part. The following two modifications to the code will prevent the exception:
What kind of sorcery is this?? 🤔 |
|
@joakimriedel we're going to need the data here as well, as well as preferably a fully runnable console program (see @ajcvickers's repro above), in order to see the error happening on our side; once that's done, we can investigate and get to the root cause. If the data is private, you can also send the stuff to my email (on my github profile), or invite me to a private github repo with the code and data. |
|
@roji The User object above is quite big (28 columns) so my plan right now is to try bringing the data to a minimal db that I can provide for you (fingers crossed it still reproduces...) I'll keep you posted. |
|
@ajcvickers @roji 🎉 I finally managed to create a repro: https://github.com/joakimriedel/efcore-issue-29502/tree/repro Run the Then run the solution. It will throw exception on Edit: Just found out that in this minimal repro, it throws exception on exactly 23 items, 22 and less works fine. Could there be anything in the seed data that makes it crash at row 23 ordered by time? 🤔 |
joakimriedel
changed the title
|
@ajcvickers @roji reduced repro complexity a bit in recent push, to make it as minimal as possible. Some findings; CREATE TABLE [dbo].[Users](
[Id] [nvarchar](450) NOT NULL,
[AccessFailedCount] [int] NOT NULL,
[ConcurrencyStamp] [nvarchar](max) NULL,
[Email] [nvarchar](256) NULL,
[EmailConfirmed] [bit] NOT NULL,
[LockoutEnabled] [bit] NOT NULL,
[LockoutEnd] [datetimeoffset](7) NULL,
[NormalizedEmail] [nvarchar](256) NULL,
[NormalizedUserName] [nvarchar](256) NULL,
[PasswordHash] [nvarchar](max) NULL,
[PhoneNumber] [nvarchar](max) NULL,
[PhoneNumberConfirmed] [bit] NOT NULL,
[SecurityStamp] [nvarchar](max) NULL,
[TwoFactorEnabled] [bit] NOT NULL,
[UserName] [nvarchar](256) NULL,
[TimeCreatedUtc] [datetime2](7) NOT NULL,
CONSTRAINT [PK_Users] PRIMARY KEY CLUSTERED
(
[Id] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]
GOThe columns from IdentityUser matters somehow, guessing it affects the order of items inserted later in the script. If I change the table columns to only CREATE TABLE [dbo].[Users](
[Id] [nvarchar](450) NOT NULL,
[TimeCreatedUtc] [datetime2](7) NOT NULL,
CONSTRAINT [PK_Users] PRIMARY KEY CLUSTERED
(
[Id] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]
GOand then insert the data, it will not reproduce anymore. But! If I run the script, and THEN delete the IdentityUser columns from database, it still reproduces. I guess the order of the rows does not change internally in SQL server when columns are deleted like that. And if I script the database without the IdentityUser columns and then create from that script - it doesn't reproduce anymore. So, this bug must have something to do with the physical order of the columns within SQL Server. It's by far one of the deepest rabbit holes I've been into with Entity Framework Core so far... 🐰 Do you have any ideas on what we are looking at here? |
|
Thanks for the dedicated work on this and for the repro - much appreciated. I'll dive into this in the coming days to get to the root cause, will post back here when I figure out what's going on. |
roji
added a commit
to roji/efcore
that referenced
this issue
Nov 16, 2022
|
@roji, ahh, I missed that stored procedure condition in AddCommand, thanks. Is a HasResultRow flag really equivalent to !NoResults? I don't see HasResultRow ever being set anywhere, and only used as a conditional check in AffectedCountModificationCommandBatch.Consume[Async]. |
|
@ewbi HasResultRow is a bit that's also included in LastInResultSet/NotLastInResultSet (see source), so when you set the latter you get the former too. I know it's a bit complex, but hopefully not too much. |
roji
added a commit
to roji/efcore
that referenced
this issue
Nov 16, 2022
Fixes dotnet#29502 (cherry picked from commit a066241)
roji
changed the title
|
@roji, oh dang, I hadn't even considered the enum's values or noticed that they might overlap - that really is a spicy enum! :) Thanks for the second look and hard work. I'll stop bugging you guys and let you get on with the v7 patching. I'm looking forward to turning that trigger workaround off and seeing what this new logic will do for our insert performance. Cheers. |
ajcvickers
added
the
closed-fixed
|
I am using EF Core 7.0.1 and I can confirm inserting 30 records is the maximum I can bulk save. When I bump it to 31, I get the error: counter++; |
|
@randalltomes please give the latest daily build a try - a fix has already been merged there. That would allow us to confirm that there isn't an additional bug we're not aware of. |
|
@roji I am on .Net 6. Followed the instructions on the daily build link but could not get the latest daily to show up in my Nuget Packages manager. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Include your code
Beginning with EF Core 7.0 rc2 when a database entity is generated through a projection and then saved as a new entity, EF Core will throw exception due to "temporary value" of
Idproperty.Workaround: set
Idto default before saving.Pre-7.0 this was not necessary. If this is expected, it would be nice to add to https://learn.microsoft.com/en-us/ef/core/what-is-new/ef-core-7.0/breaking-changes
Include stack traces
Include provider and version information
EF Core version: 7.0 rc2
Database provider: Microsoft.EntityFrameworkCore.SqlServer
Target framework: 7.0 rc2
Operating system: Win11
IDE: Visual Studio 2022 17.4
The text was updated successfully, but these errors were encountered: