EF Core N+1: kod, który po cichu wysyła 51 zapytań

Ten raport wypisuje każdego klienta sklepu, liczbę jego zamówień i ich łączną wartość:

foreach (var customer in db.Customers.ToList())
{
    var total = customer.Orders.Sum(o => o.Total);
    lines.Add($"{customer.Name}: {customer.Orders.Count} zamówienia, razem {total} zł");
}

W bazie jest 50 klientów, każdy ma trzy zamówienia. Raport się kompiluje, nie rzuca wyjątku, a pierwsza linia wyniku wygląda dokładnie tak, jak powinna:

Klient 1: 3 zamówienia, razem 36.0 zł

Test, który porównuje te linie z oczekiwanymi, też przejdzie. Problem nie dotyczy wyniku.

Dotyczy tego, ile razy program zapytał bazę, żeby go policzyć. Odpowiedź brzmi: 51 razy. To jest problem EF Core N+1, i jest o tyle podstępny, że w żadnym miejscu kodu nie widać pętli wysyłającej zapytania.

Co EF Core wysłał do bazy

Model jest zwyczajny. Customer ma kolekcję Orders, a kontekst włącza leniwe ładowanie (lazy loading) przez pakiet Microsoft.EntityFrameworkCore.Proxies:

public class Customer
{
    public int Id { get; set; }
    public string Name { get; set; } = "";
    public virtual List<Order> Orders { get; set; } = new();
}

protected override void OnConfiguring(DbContextOptionsBuilder options)
{
    options.UseSqlite("Data Source=shop.db").UseLazyLoadingProxies();
}

Słowo virtual przy Orders i wywołanie UseLazyLoadingProxies() sprawiają, że EF Core tworzy w locie klasę pochodną od Customer. Jej właściwość Orders przy pierwszym odczycie sama wysyła zapytanie do bazy.

Żeby zobaczyć, co faktycznie trafia do SQLite, dołożyłem do kontekstu interceptor DbCommandInterceptor, który liczy wykonane polecenia, i włączyłem log LogTo dla zdarzenia RelationalEventId.CommandExecuted. Pierwsze trzy polecenia po uruchomieniu raportu:

-- zapytanie 1
SELECT "c"."Id", "c"."Name"
FROM "Customers" AS "c"

-- zapytanie 2
SELECT "o"."Id", "o"."CustomerId", "o"."Total"
FROM "Orders" AS "o"
WHERE "o"."CustomerId" = @p

-- zapytanie 3
SELECT "o"."Id", "o"."CustomerId", "o"."Total"
FROM "Orders" AS "o"
WHERE "o"."CustomerId" = @p

Licznik po zakończeniu raportu pokazał Zapytań do bazy: 51.

Jedno zapytanie pobiera listę klientów. To jest „1” w nazwie. Potem pętla dochodzi do customer.Orders i proxy, zamiast oddać pustą listę, wysyła osobny SELECT po zamówienia tego jednego klienta. Pięćdziesiąt razy, bo klientów jest pięćdziesięciu. To jest „N”.

W samym raporcie nie ma żadnego wywołania, które wyglądałoby jak zapytanie. customer.Orders.Sum(...) wygląda jak operacja na liście w pamięci, i od momentu, w którym proxy załaduje kolekcję, rzeczywiście nią jest. Zapytanie ukrywa się w odczycie właściwości.

Liczba zapytań rośnie razem z danymi, a baza deweloperska zwykle ma ich mało. Uruchomiłem ten sam raport na trzech rozmiarach bazy, za każdym razem z jednym przebiegiem na rozgrzewkę i dwudziestoma pomiarami. W tabeli jest mediana:

Klientów	Zapytań	Czas bez poprawki	Czas z Include
5	6	2,0 ms	0,9 ms
50	51	16–19 ms	około 8 ms
500	501	170–200 ms	20–32 ms

Środowisko: SQLite w pliku na tym samym komputerze, EF Core 10, .NET SDK 10.0.401. Zakres oznacza medianę z kilku serii, które różniły się między sobą bardziej, niż bym chciał; wiersz dla pięciu klientów to jedna seria. Rozrzut nie zmienia jednak obrazu, bo różnica między kolumnami jest wielokrotnie większa niż różnica między seriami.

Przy pięciu klientach różnica wynosi ułamek milisekundy i nikt jej nie poczuje, klikając po aplikacji. Pięciuset klientów zmienia sytuację: raport z poprawką jest wtedy od sześciu do ośmiu razy szybszy.

Kod się nie zmienił, zmieniła się tylko liczba wierszy w tabeli Customers, i dlatego EF Core N+1 tak często wychodzi dopiero po wdrożeniu, kiedy pierwszy większy klient zaimportuje swoje dane.

A to jest SQLite, który działa w tym samym procesie co aplikacja. Każde zapytanie omija sieć. Na serwerze bazy danych każde z tych dodatkowych zapytań to osobna podróż przez sieć, więc tabela powyżej pokazuje najłagodniejszy możliwy przypadek. Nie mierzyłem tego na zdalnym PostgreSQL ani SQL Server, więc nie podam liczb, ale kierunek jest jednoznaczny: im dalej baza, tym drożej kosztuje każde z N zapytań.

Include: jedno zapytanie zamiast 51

Najkrótsza poprawka to powiedzieć EF Core z góry, że zamówienia będą potrzebne:

foreach (var customer in db.Customers.Include(c => c.Orders).ToList())
{
    var total = customer.Orders.Sum(o => o.Total);
    lines.Add($"{customer.Name}: {customer.Orders.Count} zamówienia, razem {total} zł");
}

Zmieniła się jedna linia. Log pokazuje teraz jedno polecenie:

SELECT "c"."Id", "c"."Name", "o"."Id", "o"."CustomerId", "o"."Total"
FROM "Customers" AS "c"
LEFT JOIN "Orders" AS "o" ON "c"."Id" = "o"."CustomerId"
ORDER BY "c"."Id"

Licznik: Zapytań do bazy: 1. Wynik raportu jest identyczny co do znaku.

LEFT JOIN zwraca 150 wierszy, po jednym na zamówienie, a dane klienta powtarzają się w każdym z nich. EF Core składa je z powrotem w 50 obiektów Customer z wypełnionymi kolekcjami. Proxy dalej istnieją, ale kolekcja jest już załadowana, więc odczyt Orders niczego do bazy nie wysyła.

Jedna kolekcja oznacza tanie powtarzanie danych klienta. Kiedy dołączasz kilka kolekcji naraz, liczba wierszy JOIN-a mnoży się, i wtedy pomaga AsSplitQuery(). Dopisane po Include daje u mnie dokładnie dwa zapytania: jedno po klientów, drugie po wszystkie ich zamówienia przez INNER JOIN. Dwa zapytania to nie jest N+1. Liczba dalej nie zależy od tego, ilu klientów jest w bazie, a to jest właściwa miara. Dla 500 klientów wersja z AsSplitQuery() miała medianę od 16 do 19 ms, w tym samym przedziale co zwykłe Include.

Projekcja: tylko dane, których raport potrzebuje

Raport nie potrzebuje obiektów Order. Potrzebuje dwóch liczb na klienta. Można o nie poprosić wprost:

var rows = db.Customers
    .Select(c => new { c.Name, Count = c.Orders.Count, Total = c.Orders.Sum(o => o.Total) })
    .ToList();

EF Core tłumaczy tę projekcję na jedno zapytanie, w którym liczenie i sumowanie robi baza:

SELECT "c"."Name", (
    SELECT COUNT(*)
    FROM "Orders" AS "o"
    WHERE "c"."Id" = "o"."CustomerId") AS "Count", (
    SELECT COALESCE(ef_sum("o0"."Total"), '0.0')
    FROM "Orders" AS "o0"
    WHERE "c"."Id" = "o0"."CustomerId") AS "Total"
FROM "Customers" AS "c"

ef_sum to funkcja, którą dostawca SQLite rejestruje na potrzeby sumowania typu decimal, bo sam SQLite nie ma typu dziesiętnego.

Wynik: jedno zapytanie, 50 wierszy zamiast 150, żadnych encji do śledzenia. Mediana wyszła poniżej 1 ms we wszystkich seriach dla 50 klientów i 2,3 ms dla 500. To ta sama liczba zapytań co przy Include, a czas mniejszy mniej więcej dziesięciokrotnie. W wersji z Include większość czasu nie idzie na bazę, tylko na utworzenie 200 śledzonych encji razem z ich proxy. Projekcja nie tworzy żadnej.

Jest też wariant pośredni: Include z dopisanym AsNoTracking(). Encje dalej powstają, ale kontekst ich nie śledzi. W moich pomiarach mediana spadła mniej więcej o połowę względem zwykłego Include: z około 8 do nieco ponad 3 ms dla 50 klientów i z 32 do 16 ms dla 500 w tej samej serii. Projekcja i tak została najszybsza, bo nie tworzy w ogóle obiektów Order.

Wybór między nimi zależy od tego, co dalej dzieje się z danymi. Jeśli kod modyfikuje zamówienia i zapisuje je przez SaveChanges, potrzebujesz śledzonych encji i Include jest właściwe. Jeśli tylko je czytasz, żeby coś wyświetlić, projekcja wygrywa.

Ten sam problem w endpoincie API

Pętla z foreach jest łatwa do zauważenia w przeglądzie kodu. Trudniej, kiedy pętli w ogóle nie piszesz. Endpoint, który zwraca listę encji, oddaje ją do serializatora JSON, a serializator przechodzi po każdej właściwości każdego obiektu, także po Orders.

Sprawdziłem to na tym samym kontekście z proxy: pobrałem klientów bez Include i przekazałem listę do JsonSerializer.Serialize. Z domyślnymi opcjami serializacja kończy się wyjątkiem:

System.Text.Json.JsonException: A possible object cycle was detected. This can either be due to a cycle or if the object depth is larger than the maximum allowed depth of 64. Consider using ReferenceHandler.Preserve on JsonSerializerOptions to support cycles. Path: $.Orders.Customer.Orders.Customer.Orders...

Order ma właściwość Customer, a Customer ma Orders, więc serializator krąży między nimi, a proxy po drodze doładowuje kolejne kolekcje. Do momentu wyjątku licznik pokazał dwa zapytania.

Typowa reakcja na ten wyjątek to ustawienie ReferenceHandler.IgnoreCycles. Wyjątek znika, odpowiedź zaczyna się od [{"Id":1,"Name":"Klient 1","Orders":[{"Id":1,"Total":11.0,..., a licznik pokazuje 51 zapytań. Ten sam N+1 co w raporcie, tylko pętla jest teraz w kodzie System.Text.Json, którego nie czytasz.

Dlatego endpoint nie powinien zwracać encji, tylko obiekty utworzone projekcją Select, opisaną wyżej. Taki obiekt nie ma właściwości nawigacyjnych, więc serializator nie ma czego doładowywać.

Wyłączenie lazy loading to nie poprawka

Kuszące jest usunięcie UseLazyLoadingProxies() i uznanie sprawy za zamkniętą. Sprawdziłem, co wtedy robi oryginalna pętla bez Include. Jedno zapytanie, zero błędów i taki wynik:

Klient 1: 0 zamówienia, razem 0 zł

Bez leniwego ładowania niezaładowana kolekcja jest pusta, a raport liczy zera. Zamiast wolnego kodu dostajesz szybki kod, który podaje złe liczby. Gorsza wymiana. Problem N+1 nie znika razem z proxy. Zmienia się w inny błąd. Rozwiązaniem jest jawne powiedzenie, jakich danych potrzebujesz: przez Include albo przez projekcję.

Jak złapać N+1, zanim zrobi to produkcja

Licznik zapytań, którego użyłem do tego wpisu, ma kilka linii i nadaje się też do testu. Klasa dziedziczy po DbCommandInterceptor, nadpisuje ReaderExecuted i zwiększa pole Count. Test rejestruje ją przez AddInterceptors, uruchamia raport i sprawdza Assert.Equal(1, counter.Count).

Taki test pilnuje rzeczy, której pierwszy test jednostkowy porównujący wynik nigdy by nie zauważył. Raport z 51 zapytaniami daje poprawny wynik, więc test wyniku przechodzi. Test liczby zapytań pada.

Drugi sposób nie wymaga pisania kodu. Włącz LogTo w trybie deweloperskim i przejrzyj log, kiedy strona albo endpoint ładuje się podejrzanie długo. Seria identycznych zapytań różniących się tylko parametrem @p to znak rozpoznawczy N+1. Domyślnie EF Core nie wypisuje wartości parametrów, więc każda linia wygląda tak samo:

Executed DbCommand (0ms) [Parameters=[@p='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']

Po dopisaniu EnableSensitiveDataLogging() do opcji kontekstu w tym samym logu pojawiają się konkretne wartości: @p='1', @p='2' i tak dalej, aż do @p='50' w ostatnim zapytaniu. N z nazwy problemu da się wtedy policzyć wprost z logu. Tej opcji używaj tylko lokalnie, bo do logów trafiają wtedy dane z zapytań, a w prawdziwej aplikacji są wśród nich dane klientów.

Debugger tego nie pokaże, bo każdy krok pętli wygląda poprawnie. Ten problem widać dopiero w logu, co dobrze uzupełnia wpis o tym, kiedy debugger wygrywa z Console.WriteLine.

Każdy odczyt właściwości nawigacyjnej w pętli to potencjalne zapytanie. W pętli czytaj tylko to, co załadowałeś wcześniej.

EF Core, ładowanie powiązanych danych i projekcje są częścią kursu ASP.NET Core, a rozdziały o nich znajdziesz w programie kursu.