Tracking down "Out of memory" exceptions can take awhile.
Anyway, long story short I eventually discovered the following Data Access issue or behavior that I do not understand and created a small test application to isolate the findings to report here.
This test application saves data via Data Access with two methods, one that checks the connection state and one that does not.
The method below that checks the connection appears to not release connection resources and over time will eventually cause the application to crash.
Now, I know the code below is not super efficient but the point was to demonstrate the problem by adding 1000-5000 objects to the database I can definitely see memory trending up in Just Trace (and lots of sql releated objects not GCd), the good news is adding one data object via Data Access also demonstrates the issue.
In my production application I removed the Connection State check and process memory remains stable even over long periods of time however it would be nice to know that ) the Data Context will not leak if any connection methods or properties are used b) and of course, please tell me the proper way if I am not doing things correctly.
I ran into a problem with an application that is using Data Access where eventually it would crash to due "Out of Memory" exceptions (was taking 12-20 hours) to run out of memory.
Tracking down "Out of memory" exceptions can take awhile.
Anyway, long story short I eventually discovered the following Data Access issue or behavior that I do not understand and created a small test application to isolate the findings to report here.
This test application saves data via Data Access with two methods, one that checks the connection state and one that does not.
The method below that checks the connection appears to not release
connection resources and over time will eventually cause the application
to crash.
Now, I know the code below is not super efficient but the point was to demonstrate the problem by adding 1000-5000 I can definitely see memory trending up in Just Trace but the good news is adding even one data object via Data Access also demonstrates the issue.
In my production application I removed the Connection State check and process memory remains stable even over long periods of time however it would be nice to know that a) the Data Context will not leak if any connection methods or properties are used b) and the proper way if I am not doing things correctly.
- Here are the two methods in the test application that add and save a small data object via Data Access
This one works (no resource leaks)
private
void
ExecuteAddNewRecords()
{
for
(
int
i = 0; i <
this
.NumberOfRecords; i++)
{
using
(EntitiesModel context =
new
EntitiesModel())
{
context.Add(
new
MyEventLog
{
Message = DateTime.Now.ToString(
"MM/dd/yyyy HH:mm:ss.fff"
)
});
context.SaveChanges();
}
}
}
Here is the one that appears to leak via connection related SQL objects
private
void
ExecuteAddNewRecordsWithConnectionCheck()
{
for
(
int
i = 0; i <
this
.NumberOfRecords; i++)
{
using
(EntitiesModel context =
new
EntitiesModel())
{
if
(context.Connection.State == System.Data.ConnectionState.Open)
{
context.Add(
new
MyEventLog
{
Message = DateTime.Now.ToString(
"MM/dd/yyyy HH:mm:ss.fff"
)
});
context.SaveChanges();
}
}
}
}
I turned on logging for Data Access and also used Just Trace to confirm the results.
Data Access Log with No Check for connection state (there are 4 releases during the add/save process)
Telerik.OpenAccess Information: 385 : driver.rs.close
Telerik.OpenAccess Information: 386 : driver.con.commit 9
Telerik.OpenAccess Information: 387 : driver.pool.release 19 active=0/10 idle=2/10 con=-843401329
Telerik.OpenAccess Information: 388 : sm.begin 19 optimistic
Data Access Log with Check for connection state (also notice that since there are previous releases missing on 464 - MultipleActiveResults was enabled).
(There are 0 release during add/save process)
Telerik.OpenAccess Information: 457 : driver.rs.close
Telerik.OpenAccess Information: 458 : driver.con.commit 12
Telerik.OpenAccess Information: 459 : sm.begin 24 optimistic
Telerik.OpenAccess Information: 460 : driver.con.begin 12 ReadCommitted
Telerik.OpenAccess Information: 461 : driver.con.connect 13 MultipleActiveResultSets=true;Pooling=false;Enlist=false;data source=ES-3\sqlexpress;initial catalog=DataAccessTestDatabase;integrated security=True
Telerik.OpenAccess Information: 462 : driver.con.createStat 13
Telerik.OpenAccess Information: 463 : driver.stat.executeNonQuery 13 SET LOCK_TIMEOUT 5000 []
Telerik.OpenAccess Information: 464 : driver.con.connect 14 MultipleActiveResultSets=true;Pooling=false;Enlist=false;data source=ES-3\sqlexpress;initial catalog=DataAccessTestDatabase;integrated security=True
Telerik.OpenAccess Information: 465 : driver.con.createStat 14
Telerik.OpenAccess Information: 466 : driver.stat.executeNonQuery 14 SET LOCK_TIMEOUT 5000 []
In Just Trace I also confirmed these results and can see the memory growing over time and it does appear there are a number of SQL related objects retained in memory and GC will never free them.
My Questions and comments are:
- *First, I can post the test application if needed as well as the copies of the Telerik Data logs (actually I copied them below)
- What is the proper way to check the state of a connection and/or use any property method on the connection object, is there something I missed ?
- Below are the "Complete" Data logs for adding and saving one record to the database via both approaches.
Let me know if you require the test application of copies of the logs.
Thanks for your help and time,
Mark.
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
DATA ACCESS LOGS
No connection check (no leaks) - Release calls are in bold (there are 4 of them)
Telerik.OpenAccess Information: 329 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 330 : sm.begin 15 optimistic
Telerik.OpenAccess Information: 331 : sm.store 15 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 332 : driver.pool.alloc 15 active=1/10 idle=1/10 con=-843401329
Telerik.OpenAccess Information: 333 : driver.con.begin 9 ReadCommitted
Telerik.OpenAccess Information: 334 : driver.con.createStat 9
Telerik.OpenAccess Information: 335 : driver.con.prepareCall 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 336 : driver.stat.execQuery 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:32:44.4164"]
Telerik.OpenAccess Information: 337 : driver.rs.close
Telerik.OpenAccess Information: 338 : driver.con.commit 9
Telerik.OpenAccess Information: 339 : driver.pool.release 15 active=0/10 idle=2/10 con=-843401329
Telerik.OpenAccess Information: 340 : sm.begin 15 optimistic
Telerik.OpenAccess Information: 341 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 342 : sm.begin 16 optimistic
Telerik.OpenAccess Information: 343 : sm.store 16 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 344 : driver.pool.alloc 16 active=1/10 idle=1/10 con=-842352745
Telerik.OpenAccess Information: 345 : driver.con.begin 8 ReadCommitted
Telerik.OpenAccess Information: 346 : driver.con.createStat 8
Telerik.OpenAccess Information: 347 : driver.con.prepareCall 8 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 348 : driver.stat.execQuery 8 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:32:44.4294"]
Telerik.OpenAccess Information: 349 : driver.rs.close
Telerik.OpenAccess Information: 350 : driver.con.commit 8
Telerik.OpenAccess Information: 351 : driver.pool.release 16 active=0/10 idle=2/10 con=-842352745
Telerik.OpenAccess Information: 352 : sm.begin 16 optimistic
Telerik.OpenAccess Information: 353 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 354 : sm.begin 17 optimistic
Telerik.OpenAccess Information: 355 : sm.store 17 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 356 : driver.pool.alloc 17 active=1/10 idle=1/10 con=-843401329
Telerik.OpenAccess Information: 357 : driver.con.begin 9 ReadCommitted
Telerik.OpenAccess Information: 358 : driver.con.createStat 9
Telerik.OpenAccess Information: 359 : driver.con.prepareCall 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 360 : driver.stat.execQuery 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:32:44.4407"]
Telerik.OpenAccess Information: 361 : driver.rs.close
Telerik.OpenAccess Information: 362 : driver.con.commit 9
Telerik.OpenAccess Information: 363 : driver.pool.release 17 active=0/10 idle=2/10 con=-843401329
Telerik.OpenAccess Information: 364 : sm.begin 17 optimistic
Telerik.OpenAccess Information: 365 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 366 : sm.begin 18 optimistic
Telerik.OpenAccess Information: 367 : sm.store 18 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 368 : driver.pool.alloc 18 active=1/10 idle=1/10 con=-842352745
Telerik.OpenAccess Information: 369 : driver.con.begin 8 ReadCommitted
Telerik.OpenAccess Information: 370 : driver.con.createStat 8
Telerik.OpenAccess Information: 371 : driver.con.prepareCall 8 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 372 : driver.stat.execQuery 8 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:32:44.4497"]
Telerik.OpenAccess Information: 373 : driver.rs.close
Telerik.OpenAccess Information: 374 : driver.con.commit 8
Telerik.OpenAccess Information: 375 : driver.pool.release 18 active=0/10 idle=2/10 con=-842352745
Telerik.OpenAccess Information: 376 : sm.begin 18 optimistic
Telerik.OpenAccess Information: 377 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 378 : sm.begin 19 optimistic
Telerik.OpenAccess Information: 379 : sm.store 19 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 380 : driver.pool.alloc 19 active=1/10 idle=1/10 con=-843401329
Telerik.OpenAccess Information: 381 : driver.con.begin 9 ReadCommitted
Telerik.OpenAccess Information: 382 : driver.con.createStat 9
Telerik.OpenAccess Information: 383 : driver.con.prepareCall 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 384 : driver.stat.execQuery 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:32:44.4595"]
Telerik.OpenAccess Information: 385 : driver.rs.close
Telerik.OpenAccess Information: 386 : driver.con.commit 9
Telerik.OpenAccess Information: 387 : driver.pool.release 19 active=0/10 idle=2/10 con=-843401329
Telerik.OpenAccess Information: 388 : sm.begin 19 optimistic
Data Access Log with a connection state check (Leaks?) (note that there are 0 release calls)
Telerik.OpenAccess Information: 392 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 393 : sm.begin 20 optimistic
Telerik.OpenAccess Information: 394 : driver.pool.alloc 20 active=1/10 idle=1/10 con=-843401329
Telerik.OpenAccess Information: 395 : driver.con.begin 9 ReadCommitted
Telerik.OpenAccess Information: 396 : sm.store 20 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 397 : driver.con.createStat 9
Telerik.OpenAccess Information: 398 : driver.con.prepareCall 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 399 : driver.stat.execQuery 9 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:33:09.9508"]
Telerik.OpenAccess Information: 400 : driver.rs.close
Telerik.OpenAccess Information: 401 : driver.con.commit 9
Telerik.OpenAccess Information: 402 : sm.begin 20 optimistic
Telerik.OpenAccess Information: 403 : driver.con.begin 9 ReadCommitted
Telerik.OpenAccess Information: 404 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 405 : sm.begin 21 optimistic
Telerik.OpenAccess Information: 406 : driver.pool.alloc 21 active=1/10 idle=0/10 con=-842352745
Telerik.OpenAccess Information: 407 : driver.con.begin 8 ReadCommitted
Telerik.OpenAccess Information: 408 : sm.store 21 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 409 : driver.con.createStat 8
Telerik.OpenAccess Information: 410 : driver.con.prepareCall 8 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 411 : driver.stat.execQuery 8 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:33:09.9616"]
Telerik.OpenAccess Information: 412 : driver.rs.close
Telerik.OpenAccess Information: 413 : driver.con.commit 8
Telerik.OpenAccess Information: 414 : sm.begin 21 optimistic
Telerik.OpenAccess Information: 415 : driver.con.begin 8 ReadCommitted
Telerik.OpenAccess Information: 416 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 417 : sm.begin 22 optimistic
Telerik.OpenAccess Information: 418 : driver.con.connect 10 MultipleActiveResultSets=true;Pooling=false;Enlist=false;data source=MOERKFITZ-ES-3\sqlexpress;initial catalog=DataAccessTestDatabase;integrated security=True
Telerik.OpenAccess Information: 419 : driver.con.createStat 10
Telerik.OpenAccess Information: 420 : driver.stat.executeNonQuery 10 SET LOCK_TIMEOUT 5000 []
Telerik.OpenAccess Information: 421 : driver.pool.alloc 22 active=1/10 idle=0/10 con=-843466865
Telerik.OpenAccess Information: 422 : driver.con.begin 10 ReadCommitted
Telerik.OpenAccess Information: 423 : sm.store 22 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 424 : driver.con.createStat 10
Telerik.OpenAccess Information: 425 : driver.con.prepareCall 10 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 426 : driver.stat.execQuery 10 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:33:09.9756"]
Telerik.OpenAccess Information: 427 : driver.rs.close
Telerik.OpenAccess Information: 428 : driver.con.commit 10
Telerik.OpenAccess Information: 429 : sm.begin 22 optimistic
Telerik.OpenAccess Information: 430 : driver.con.begin 10 ReadCommitted
Telerik.OpenAccess Information: 431 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 432 : sm.begin 23 optimistic
Telerik.OpenAccess Information: 433 : driver.con.connect 11 MultipleActiveResultSets=true;Pooling=false;Enlist=false;data source=MOERKFITZ-ES-3\sqlexpress;initial catalog=DataAccessTestDatabase;integrated security=True
Telerik.OpenAccess Information: 434 : driver.con.createStat 11
Telerik.OpenAccess Information: 435 : driver.stat.executeNonQuery 11 SET LOCK_TIMEOUT 5000 []
Telerik.OpenAccess Information: 436 : driver.pool.alloc 23 active=1/10 idle=0/10 con=-843532401
Telerik.OpenAccess Information: 437 : driver.con.begin 11 ReadCommitted
Telerik.OpenAccess Information: 438 : sm.store 23 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 439 : driver.con.createStat 11
Telerik.OpenAccess Information: 440 : driver.con.prepareCall 11 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 441 : driver.stat.execQuery 11 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:33:09.9896"]
Telerik.OpenAccess Information: 442 : driver.rs.close
Telerik.OpenAccess Information: 443 : driver.con.commit 11
Telerik.OpenAccess Information: 444 : sm.begin 23 optimistic
Telerik.OpenAccess Information: 445 : driver.con.begin 11 ReadCommitted
Telerik.OpenAccess Information: 446 : pm.alloc idle 0/8
Telerik.OpenAccess Information: 447 : sm.begin 24 optimistic
Telerik.OpenAccess Information: 448 : driver.con.connect 12 MultipleActiveResultSets=true;Pooling=false;Enlist=false;data source=MOERKFITZ-ES-3\sqlexpress;initial catalog=DataAccessTestDatabase;integrated security=True
Telerik.OpenAccess Information: 449 : driver.con.createStat 12
Telerik.OpenAccess Information: 450 : driver.stat.executeNonQuery 12 SET LOCK_TIMEOUT 5000 []
Telerik.OpenAccess Information: 451 : driver.pool.alloc 24 active=1/10 idle=0/10 con=-843597937
Telerik.OpenAccess Information: 452 : driver.con.begin 12 ReadCommitted
Telerik.OpenAccess Information: 453 : sm.store 24 1 OID(s) delete 0 OID(s) 3 returnFieldsUpdatedBySM
Telerik.OpenAccess Information: 454 : driver.con.createStat 12
Telerik.OpenAccess Information: 455 : driver.con.prepareCall 12 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0
Telerik.OpenAccess Information: 456 : driver.stat.execQuery 12 declare @generated_ids table([LogId] int)
insert [MyEventLog] ([msg])
output inserted.[LogId] into @generated_ids
VALUES (@p0)
select t.[LogId]
from @generated_ids as g join [MyEventLog] as t on g.[LogId] = t.[LogId]
where @@ROWCOUNT > 0 [@p0="12/13/2014 22:33:10.0057"]
Telerik.OpenAccess Information: 457 : driver.rs.close
Telerik.OpenAccess Information: 458 : driver.con.commit 12
Telerik.OpenAccess Information: 459 : sm.begin 24 optimistic
Telerik.OpenAccess Information: 460 : driver.con.begin 12 ReadCommitted
Telerik.OpenAccess Information: 461 : driver.con.connect 13 MultipleActiveResultSets=true;Pooling=false;Enlist=false;data source=MOERKFITZ-ES-3\sqlexpress;initial catalog=DataAccessTestDatabase;integrated security=True
Telerik.OpenAccess Information: 462 : driver.con.createStat 13
Telerik.OpenAccess Information: 463 : driver.stat.executeNonQuery 13 SET LOCK_TIMEOUT 5000 []
Telerik.OpenAccess Information: 464 : driver.con.connect 14 MultipleActiveResultSets=true;Pooling=false;Enlist=false;data source=MOERKFITZ-ES-3\sqlexpress;initial catalog=DataAccessTestDatabase;integrated security=True
Telerik.OpenAccess Information: 465 : driver.con.createStat 14
Telerik.OpenAccess Information: 466 : driver.stat.executeNonQuery 14 SET LOCK_TIMEOUT 5000 []