Losowe zawieszanie się aplikacji

Cześć wszystkim,
W sumie to nie wiedziałem, w której kategorii napisać - padło na bazy danych. Dlaczego? Już wyjaśniam.
Aplikacja, która stwarza problem służy do obsługi firmy. Napisana w C#, łączy się z Sql Serverem 2014. Kilka tabel, zapytania są proste - 2 joiny w najtrudniejszym zapytaniu. Aplikacja opiera się na komponencie DbGrid (crud inline). Wszystko niby fajnie, ale podczas korzystania z apki przez klienta pojawiają się losowe zwiechy np. po kilku godzinach pracy, potem po 15 minutach, itp. Nie można wyłapać schematu. Podpiąłem logowanie pod Entity Framework i sprawdziłem, faktycznie jedno zapytanie powoduje problem i trwa w momencie zwiechy około 13 sekund. Przerobiłem zapytanie, tak aby nie wykorzystywało EF, a jedynie SqlConnection - efekt taki sam. Po wyczerpaniu się wszystkich pomysłów co do tego zapytania - raz się zwiesza, raz działa poprawnie - jedynie co się zmienia to parametry zapytania - postanowiłem podejść do sprawy trochę inaczej. Otóż zmieniłem ustawienia w Sql Serverze co do maksymalnego wykorzystania pamięci, ustawiłem na 1024MB. Wcześniej było ustawione na domyślne maksimum. Po zmianie aplikacja zaczęła działać zdecydowanie szybciej sama w sobie i co najważniejsze nie postawały zwiechy do momentu... no właśnie, do momentu ponownego uruchomienia komputera klienta, na którym stoi zarówno serwer bazy danych jak i aplikacja. W ustawieniach jest ustawione 1024, ale Sql Server, tak jakby tego nie widzi i do momentu ponownego wywołania:

sp_configure 'max server memory', 1024;  
GO  
RECONFIGURE;  

sytuacja pozostaje beznadziejnie taka sama.

Czy ktoś ma jakiś pomysł na rozwiązanie problemu losowych zwiech? Proszę o jakieś wskazówki, na co można byłoby jeszcze zwrócić uwagę podczas diagnozy tego problemu.
Od strony kodu sprawdziłem (chyba) wszystko. Zapytanie przerobiłem na czysty sql, mapowanie z modelu bazowego na grid model jest wykonywane ręcznie. Pytanie jest również takie - gdzie szukać problemu, czy raczej w zapytaniu czy raczej po stronie ustawień samego serwera. Obstawiam to drugie, stąd kategoria Bazy danych.
Pozdrawiam

PS. Problemy występują (a jakżeby inaczej) tylko na wersji produkcyjnej, u klienta.

Brzmi jak 'nie wiem co się dzieje, ale nie działa' ;-)

Możliwe, że tworzą się jakieś deadlocki, ale to tylko zgadywanie. Żeby mieć kompletny obraz sytuacji, trzeba zobaczyć co dzieje się w aplikacji jak i po stronie bazy danych.

1. Po stronie aplikacji - zrzut stosu dla wszystkich wątków (pod windowsem uruchamiasz Taskmanagera, wybierasz proces aplikacji, która zawiesiłą się i opcję Create Dump File, który później analizujesz w jakichś narzędziach M$: http://wallaceturner.com/debugging-dump-files-created-on-another-machine)
2. Od strony bazy może jakieś trace: https://www.mssqltips.com/sqlservertutorial/252/tracing-a-sql-server-deadlock/

edited:
Windows to nie moja bajka, ale pewne metody sprawdzają są niezależnie od OS.

Stawiałbym na jakieś deadlocki.
Ewentualnie sprawdź plany zapytań i brakujące indeksy np. zgodnie z https://blog.sqlauthority.com/2011/01/03/sql-server-2008-missing-index-script-download/

Andrzej Guziec napisał(a):

Stawiałbym na jakieś deadlocki.

Z tego co rozumiem deadlocki występują przy zapytaniach np. SELECT + UPDATE. Natomiast w zrzucie z profilera mam przykładowo zapytania SELECT + SELECT + SELECT, gdzie środkowy SELECT podowuje zwiechę (WTF).

[10.06.2017 11:04:29:7734] Opening connection to database xxx on server localhost\SQLEXPRESS
[10.06.2017 11:04:29:7794] Executed DbCommand (4ms) (zapytanie SELECT)
[10.06.2017 11:04:29:7814] Closing connection to database xxx on server localhost\SQLEXPRESS
[10.06.2017 11:05:04:6939] Opening connection to database xxx on server localhost\SQLEXPRESS
[10.06.2017 11:05:17:1264] Executed DbCommand (12,418ms) (zapytanie SELECT)
[10.06.2017 11:05:17:1344] Closing connection to database xxx on server localhost\SQLEXPRESS
[10.06.2017 11:05:29:4515] Opening connection to database xxx on server localhost\SQLEXPRESS
[10.06.2017 11:05:29:4605] Executed DbCommand (7ms) (zapytanie SELECT)
[10.06.2017 11:05:29:4625] Closing connection to database xxx on server localhost\SQLEXPRESS

Zaproponuję jeszcze raz próbę zdiagnozowania. Ściągnij:

1. procdumpa: https://docs.microsoft.com/pl-pl/sysinternals/downloads/procdump
2. WinDbg: https://developer.microsoft.com/en-us/windows/hardware/download-windbg
3. Jeśli aplikacja będzie "zawieszona", wykonaj zrzut procesu (za pomocą procdump) albo z Task Managera.
4. Załaduj dumpa do WInDbg i przeanalizuj -> call stack pokaże Ci co robi aplikacja jak jest zawieszona...

"Zawieszona" aplikacja pewnie próbuje uzyskać zasób i nie może go uzyskać z jakiegoś powodu... Trzeba zlokalizować o jaki zasób chodzi i zastanowić się z czego taka sytuacja wynika.
Może masz jakąś pulę połączeń i nie zwracasz połączenia do puli, gdy już z niego nie korzystasz, a może błąd w tym komponencie, którego używasz do dostępu do bazy?

Podstawa to umieć odpowiedzieć na pytanie: "Co robi aplikacja jak z perspektywy użytkownika jest zawieszona?", a nie zgadywać co może być nie tak...

Może środowisko (.net?) ma jakieś fajniejsze sposoby analizy stosu wywołań i powyższe da się zrealizować prościej? Odsyłałbym do działu C# po porady ;-)

Pytanie co robi to zapytanie
[10.06.2017 11:05:17:1264] Executed DbCommand (12,418ms) (zapytanie SELECT) powinieneś móc podejrzeć to zapytanie w logach? Przejrzyj jego plan i przeanalizuj co można zmienić?
Rozumiem, że wykonanie zapytania jest źródłem zawieszenia, więc to po stronie bazy danych szukać należy odpowiedzi, jak dojdziesz do tego jakie to zapytanie.

Andrzej Guziec napisał(a):

Pytanie co robi to zapytanie
[10.06.2017 11:05:17:1264] Executed DbCommand (12,418ms) (zapytanie SELECT) powinieneś móc podejrzeć to zapytanie w logach? Przejrzyj jego plan i przeanalizuj co można zmienić?
Rozumiem, że wykonanie zapytania jest źródłem zawieszenia, więc to po stronie bazy danych szukać należy odpowiedzi, jak dojdziesz do tego jakie to zapytanie.

Mam to zapytanie. Przejrzałem i nic. Szkopuł tkwi w tym, że to zapytanie jest wykonywane najczęściej ze wszystkich i działa zawsze tak samo szybko (milisekundy) poza wyjątkami, w których występuje zwiecha właśnie na tym zapytaniu. Również parametry zapytania podczas zwiechy nie odbiegają od tych, w których działa poprawnie. Zmieniają się jedynie daty i identyfikator firmy.

                    SELECT 
                    o.Id AS OrderId, 
                    o.CompanyId, 
                    .
                    .
                    .
                    FROM xxx.Orders o 
                    INNER JOIN xxx.Paints p ON p.Id = o.PaintId
                    INNER JOIN xxx.Customers c ON c.Id = o.CustomerId
                    WHERE o.AdoptionDate >= @startDate AND o.AdoptionDate <= @endDate AND o.CompanyId = @companyId
                    ORDER BY o.AdoptionDate, o.No

Zapytanie faktycznie wygląda normalnie, rozumiem, że start i end raczej nie stają się czasami nullem albo coś w tym stylu?
Ciekaw jestem czy czasami nie masz ustawionego timeouta na 15 sekund. I czy zapytane trwałoby np. 30 sekund jakbyś zmienił na timeout na 30 sekund?
Czy używasz gdzieś transakcji? Może którejś nie zamknąłeś?

Andrzej Guziec napisał(a):

Zapytanie faktycznie wygląda normalnie, rozumiem, że start i end raczej nie stają się czasami nullem albo coś w tym stylu?

Nie. Też na to zwracałem uwagę, niestety.

Ciekaw jestem czy czasami nie masz ustawionego timeouta na 15 sekund. I czy zapytane trwałoby np. 30 sekund jakbyś zmienił na timeout na 30 sekund?

Przechodziło mi to przez myśl, natomiast zapytanie w momencie zwiechy nigdy nie trwało więcej niż 12-13 sekund.

Czy używasz gdzieś transakcji? Może którejś nie zamknąłeś?

Tak, używam, ale wyłącznie z using podczas insertów, update'ów (EF). Przy selectach korzystam z DbContextu EF lub tak jak w przypadku tego feralnego zapytania zwykłego SqlConnection bez transakcji.

ja bym się jednak pokusił o sprawdzenie tych 30 sekund. 12-13, czy będzie to miało jakiś wpływ.
I jeszcze co będzie jak dasz np.: SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED; GO;

Andrzej Guziec napisał(a):

ja bym się jednak pokusił o sprawdzenie tych 30 sekund. 12-13, czy będzie to miało jakiś wpływ.

Nic to nie zmieniło.

Zauważyłem jednak, że zwiechy występują też na krótko np. 2 sekundy. I co ciekawe zazwyczaj (nie zawsze niestety) po commicie transakcji poprzedniego zapytania. Transakcja składa się z kilku zapytań, SELECT, UPDATE.

[04.08.2017 10:13:06:0683] Opening connection to database 'xxx' on server 'localhost\SQLEXPRESS'.
[04.08.2017 10:13:06:0783] Beginning transaction with isolation level 'ReadUncommitted'.

[04.08.2017 10:13:06:1118] Executed DbCommand (2ms) [Parameters=[@__orderId_0='1'], CommandType='Text', CommandTimeout='30']
SELECT TOP(1) [p].[Id], ...
FROM [xxx].[Orders] AS [p]
WHERE [p].[Id] = @__orderId_0
ORDER BY [p].[Id]

[04.08.2017 10:13:06:1314] Executed DbCommand (10ms) [Parameters=[@__orderId_0='1'], CommandType='Text', CommandTimeout='30']
SELECT [o].[Id], [o].[OrderId], ...
FROM [xxx].[OrdersHistory] AS [o]
INNER JOIN (
SELECT DISTINCT TOP(1) [p].[Id]
FROM [xxx].[Orders] AS [p]
WHERE [p].[Id] = @__orderId_0
ORDER BY [p].[Id]
) AS [p0] ON [o].[OrderId] = [p0].[Id]
ORDER BY [p0].[Id]

[04.08.2017 10:13:06:1439] Executed DbCommand (6ms) [Parameters=[@__model_PaintCode_0=1 (Size = 64), @__model_PaintRalProducer_1='' (Size = 100)], CommandType='Text', CommandTimeout='30']
SELECT TOP(1) [p].[Id], [p].[c], [p].[Quantity], [p].[RalProducer]
FROM [xxx].[Paints] AS [p]
WHERE ([p].[c] = @__model_PaintCode_0) AND ([p].[RalProducer] = @__model_PaintRalProducer_1)

[04.08.2017 10:13:06:1599] Executed DbCommand (7ms) [Parameters=[@__model_CustomerName_0='nazwa' (Size = 300)], CommandType='Text', CommandTimeout='30']
SELECT TOP(1) [c].[Id], [c].[Name]
FROM [xxx].[Customers] AS [c]
WHERE [c].[Name] = @__model_CustomerName_0

[04.08.2017 10:13:06:1774] Executed DbCommand (14ms) [Parameters=[@p1='57418', @p0='2315', @p2='0x0000000000022993' (Size = 8), @p3='08/04/2017 00:00:00', @p4='' (DbType = DateTime2), @p5='' (Size = 256), @p6='1', @p7='22', @p8='' (Size = 500), @p9='' (DbType = DateTime2), @p10='' (Size = 30), @p11='137', @p12='57418', @p13='2315', @p14='' (DbType = Int32), @p15='' (DbType = DateTime2), @p16='3', @p17='' (Size = 64)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
UPDATE [xxx].[Orders] SET [PaintId] = @p0
WHERE [Id] = @p1 AND [Timestamp] = @p2;
SELECT [AdoptionMonth], [AdoptionYear], [Timestamp]
FROM [xxx].[Orders]
WHERE @@ROWCOUNT = 1 AND [Id] = @p1;
INSERT INTO [xxx].[OrdersHistory] ([AdoptionDate], [ChromingDate], [Comments], [CompanyId], [CustomerId], [Description], [ExecutionDate], [InvoiceNo], [No], [OrderId], [PaintId], [PaintshopNo], [ReceiptDate], [UserInsId], [WzNo])
VALUES (@p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10, @p11, @p12, @p13, @p14, @p15, @p16, @p17);
SELECT [Id], [AdoptionMonth], [AdoptionYear], [DateTimeIns]
FROM [xxx].[OrdersHistory]
WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity();

[04.08.2017 10:13:06:1799] Committing transaction.
[04.08.2017 10:13:06:1819] Closing connection to database 'xxx' on server 'localhost\SQLEXPRESS'.

Następnie jest zapytanie które robi zwiechę:

[04.08.2017 10:13:06:1849] Opening connection to database 'xxx' on server 'localhost\SQLEXPRESS'.
[04.08.2017 10:13:09:0238] Executed DbCommand (2,837ms) [Parameters=[@__startDate_Date_0='08/01/2017 00:00:00', @__endDate_Date_1='08/31/2017 00:00:00', @__company_Id_2='1'], CommandType='Text', CommandTimeout='30']
SELECT [o].[Id], ...
FROM [xxx].[Orders] AS [o]
INNER JOIN [xxx].[Paints] AS [o.Paint] ON [o].[PaintId] = [o.Paint].[Id]
INNER JOIN [xxx].[Customers] AS [o.Customer] ON [o].[CustomerId] = [o.Customer].[Id]
WHERE ((CONVERT(date, [o].[AdoptionDate]) >= @__startDate_Date_0) AND (CONVERT(date, [o].[AdoptionDate]) <= @__endDate_Date_1)) AND ([o].[CompanyId] = @__company_Id_2)
ORDER BY CONVERT(date, [o].[AdoptionDate]), [o].[No]
[04.08.2017 10:13:09:0313] Closing connection to database 'xxx' on server 'localhost\SQLEXPRESS'.

rozumiem, że SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED nic nie zmieniło?

Nie masz w bazie jakiś triggerów albo indexów?

Andrzej Guziec napisał(a):

rozumiem, że SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED nic nie zmieniło?

Wrzuciłem Read Uncommited dla metod wstawiających i aktualizujących wiersze. Wcześniej ustawiało poziom izolacji na Unspecified.
Triggerów nie ma, to jest bardzo prosta baza. Indeksy oczywiście są. Pierwszy to unique na 4 pola, następne 2 to do kluczów obcych, a ostatni to klucz główny.

CREATE UNIQUE NONCLUSTERED INDEX [IX_Orders_CompanyId_No_AdoptionYear_AdoptionMonth] ON [xxx].[Orders]
(
	[CompanyId] ASC,
	[No] ASC,
	[AdoptionYear] ASC,
	[AdoptionMonth] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, IGNORE_DUP_KEY = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
GO

CREATE NONCLUSTERED INDEX [IX_Orders_CustomerId] ON [xxx].[Orders]
(
	[CustomerId] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
GO

CREATE NONCLUSTERED INDEX [IX_Orders_PaintId] ON [xxx].[Orders]
(
	[PaintId] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
GO

ALTER TABLE [xxx].[Orders] ADD  CONSTRAINT [PK_Orders] PRIMARY KEY CLUSTERED 
(
	[Id] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, IGNORE_DUP_KEY = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
GO

Ten level (SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED) to się ustawia bardziej przy SELECTach, żeby nie czekały, na dane, aż jakaś transakcja się zakończy, przynajmniej z tego co wiem.

Co do insertów, z nimi może być problem, każdy update zmieniający wartość, powoduje, że taki index musi być przebudowany, z tego co kojarzę.