ESENT "Too many active database users"

[Kyle Levien]

We recently were having trouble installing our product on Windows 10 after the Fall Creators Update, getting "Task Canceled" timeouts consistently on db setup scripts. Upgrading raven from 3.5.4 to 3.5.5-35244 has resolved this issue but we have started to see EsentTempPathInUseException on occasion during normal operation. Looking into the logs we notice that raven's logs first report this on the server side while idle:

2018-01-02 15:49:14.5635,Raven.Storage.Esent.TransactionalStorage,Error,Unexpected error occurred while terminating Esent Storage. Ignoring this error to allow to shutdown RavenDB instance.,"Microsoft.Isam.Esent.Interop.EsentTooManyActiveUsersException: Too many active database users

   at Microsoft.Isam.Esent.Interop.Api.JetTerm2(JET_INSTANCE instance, TermGrbit grbit)

   at Raven.Storage.Esent.TransactionalStorage.<Dispose>b__39_0()"

2018-01-02 15:49:14.5635,Raven.Storage.Esent.TransactionalStorage,Warn,"Will now attempt to perform an abrupt shutdown, because asking nicely didn't work. You might need to run defrag on the database to recover potentially lost space (but no data will be lost).",

2018-01-02 15:49:14.5635,Raven.Storage.Esent.TransactionalStorage,Fatal,"Couldn't shut down the database server even when using abrupt, something is probably wrong and you'll need to restart the server process to access the database","Microsoft.Isam.Esent.Interop.EsentTooManyActiveUsersException: Too many active database users

   at Microsoft.Isam.Esent.Interop.Api.JetTerm2(JET_INSTANCE instance, TermGrbit grbit)

   at Raven.Storage.Esent.TransactionalStorage.<Dispose>b__39_0()"

Followed by the temp path in use exception on the client side later when we try to access the db:

[ERROR] [2018-01-02 16:44:12.4198] - [admin from 127.0.0.1] - Could not open resource named: IGXContentStore

System.AggregateException: One or more errors occurred. ---> System.InvalidOperationException: Could not open transactional storage: C:\igxsites\cms100\qabsamb331\DB\IGXContentStore\Data ---> Microsoft.Isam.Esent.Interop.EsentTempPathInUseException: Temp path already used by another database instance

   at Microsoft.Isam.Esent.Interop.Api.JetInit(JET_INSTANCE& instance)

   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)

   --- End of inner exception stack trace ---

   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)

   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)

   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)

   at Raven.Database.Server.Tenancy.DatabasesLandlord.<>c__DisplayClass27_0.<TryGetOrCreateResourceStore>b__1()

   at System.Threading.Tasks.Task`1.InnerInvoke()

   at System.Threading.Tasks.Task.Execute()

   --- End of inner exception stack trace ---

   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)

   at Raven.Database.Common.ResourceApiController`2.<TrySetupRequestToProperResource>d__33.MoveNext()

---> (Inner Exception #0) System.InvalidOperationException: Could not open transactional storage: C:\igxsites\cms100\qabsamb331\DB\IGXContentStore\Data ---> Microsoft.Isam.Esent.Interop.EsentTempPathInUseException: Temp path already used by another database instance

   at Microsoft.Isam.Esent.Interop.Api.JetInit(JET_INSTANCE& instance)

   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)

   --- End of inner exception stack trace ---

   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)

   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)

   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)

   at Raven.Database.Server.Tenancy.DatabasesLandlord.<>c__DisplayClass27_0.<TryGetOrCreateResourceStore>b__1()

   at System.Threading.Tasks.Task`1.InnerInvoke()

   at System.Threading.Tasks.Task.Execute()<---

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<CheckForErrorsAndReturnCachedResultIfAnyAsync>d__41.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<>c__DisplayClass36_0.<<SendRequestInternal>b__0>d.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<RunWithAuthRetry>d__38`1.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<ReadResponseJsonAsync>d__35.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Connection.Async.AsyncServerClient.<DirectGetAsync>d__75.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Connection.ReplicationInformerBase`1.<TryOperationAsync>d__34`1.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Connection.ReplicationInformerBase`1.<ExecuteWithReplicationAsync>d__33`1.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Connection.Async.AsyncServerClient.<ExecuteWithReplication>d__172`1.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Abstractions.Util.AsyncHelpers.<>c__DisplayClass1_1`1.<<RunSync>b__0>d.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at Raven.Abstractions.Util.AsyncHelpers.RunSync[T](Func`1 task)

   at Raven.Client.Document.DocumentSession.Load[T](String id)

There doesn't seem to be a whole lot of documentation out there about EsentTooManyActiveUsersException, has anyone else encountered this or have an idea what might cause it? Our RavenDB runs under IIS with its data and index directories outside the application root.

Thanks,

Kyle

[Oren Eini (Ayende Rahien)]

This looks like something else has already opened up the file?

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Kyle Levien]

No other users on the system or product instances pointing to that location.

We used to see the temp path exception in our upgrader when recycling the app pool and the previous db engine instance wouldn't shut down completely before the new one starts up, but there are no app pool recycles or app domain dumps going on here, the system is just idle. Doesn't Raven try to shut down and restart the esent engine when idle?

Kyle

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

Yes, but that shouldn't cause this error. How are you running RavenDB?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

We run our product as an IIS app, and ravendb as a virtual directory to that, both with separate app pool and with raven's data directories sibling to our product site.

[Oren Eini (Ayende Rahien)]

Can you see who holds the files open?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Samson Lee]

We just encountered it this error in our environment, and procexp only shows the expected IIS workerprocess with a handle on the data path.

[Kyle Levien]

Any idea what might be causing the "Too many active database users" exception in Esent.TransactionalStorage.Dispose()?

[Kyle Levien]

Sorry double post, but here's another data point. Shortly before the initial "too many active users' exception in the raven log we get this in the server event logs:

Raven (6160,D,0) 7-6N1pdop8Rr0/--C:\igxsites\cms100\qabsamb331\DB\IGXContentStore\Data: The database engine detected multiple threads illegally using the same database session to perform database operations. 

SessionId: 0x000001471D7C4A60 

Session-context: 0x00000000 

Session-context ThreadId: 0x0000000000005D90 

Current ThreadId: 0x0000000000003A7C 

Session-trace: 

57573@3:26:44 PM

[Oren Eini (Ayende Rahien)]

This is reproducible to you?

Are you also upgrading from previous version when this happens?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Samson Lee]

Working with Kyle on this: An upgrade is not happening at the time of the error, the site is simply sitting idle. We seem to be able to reproduce it on one test environment, and have seen it on other environments as well (Windows 10 Fall Creator, Windows 2012 r2).

[Oren Eini (Ayende Rahien)]

How do you reproduce this?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

Could it perhaps be something related to Commit 640c63f6 - "RavenDB-9476 - Concurrency exception during indexes PUT"?

[Oren Eini (Ayende Rahien)]

That seems unlikely to me. There isn't anything that that should cause that kind of error 

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

We are able to get a reliable repro on our side but haven't narrowed it to a single base case yet. We get repeated ESENT 902 errors when performing a publ;ish operation in our app, which does a few writes and a lot of parallel reads from the client. We don't see any exceptions in the client code or raven server logs.

Something I also noticed is there is an ESENT 916 info event log before any exceptions occur of "svchost (4896,G,0) The beta feature EseDiskFlushConsistency is enabled in ESENT due to the beta site mode settings 0x800000."

This appears to be a new esent feature added in the windows 10 FCU. Could it possibly have an effect on raven's esent sessions?

Thanks,

Kyle

[Kyle Levien]

Well we also get a repro on our server 2012 boxes without that new beta feature, so probably not.

[Oren Eini (Ayende Rahien)]

I don't think that this is related, no.

If you can send us a repro, that would be very helpful

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

I have a reproducing case narrowed down in our code. What seems to be the issue is a rapid series of batch queries using the stream API.

foreach (var batch in pageVerIds.Batch(128))

{

using (var pageSession = readSession.Site.ContentStore.OpenReadSession(readSession.OperatingUser))

{

var pageVersionsByPageId = new Dictionary<string, PageVersion>();

using (var ravenSession = (pageSession.Site.ContentStore as ContentStore)._Store.OpenSession())

{

var q = ravenSession.Query<PageVersion>("Raven/DocumentsByEntityName").Where(doc => doc.Id.In(batch));

using (var enumerator = ravenSession.Advanced.Stream(q))

while (enumerator.MoveNext())

if (!pageVersionsByPageId.ContainsKey(enumerator.Current.Document.XID))

pageVersionsByPageId.Add(enumerator.Current.Document.XID, enumerator.Current.Document);

}

}

}

pageVerIds is a specific list of ~3000 version document ids that we are streaming in. The above snippet is a simplified snippet of a section in our publish operation that will reproduce the 902 event log errors when run in isolation.

Curiously, if I adjust the batch size it affects how many errors I see. With a batch size of 128 (or 256) I can get between 4-7 902 errors. If I change it to some other extremes of 16 and 1024, there are no errors.

Any thoughts? These event log errors started showing up after we upgraded to raven 3.5.5 to resolve an issue we had starting a raven document store inside our MSI installer on the windows 10 fall creators update. My tests are currently running on latest 3.5.6

Thanks,

Kyle

[Oren Eini (Ayende Rahien)]

Okay, this make sense now.

You are basically creating a LOT of ongoing tasks. The way it works, streaming will keep a transaction alive for the duration of the stream.

You can try increasing the size of Raven/Esent/MaxCursors

There is also the number of concurrent sessions, which is limited to 1024, but I'm not sure which limit exactly you are hitting

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

We tried increasing the MaxCursors up to 32768 without any change in behavior, still around2 dozen ESENT 902 errors each time we run the test.

[Kyle Levien]

As a further follow up, I built a test between repeated stream queries for a short query using skip() take() and repeated stream queries with batched explicit Id values.
I see a number of 902 ESENT errors when batching explicit ids in the query and no 902s when skip().take()-ing the generic query.

It appears the issue may be in the server's handling of long lists of query calls generated from the Raven.Client.Linq .In() expression?

Here is the new method I'm using to compare, this one generates no 902 errors while the above still generates a couple dozen:

for (int ix = 0; ix < 100000; ix += 128)

{

using (var ravenSession = (store as ContentStore)._Store.OpenSession())

{

var pageVersionsByPageId = new Dictionary<string, PageVersion>();

var q = ravenSession.Query<PageVersion>("Raven/DocumentsByEntityName").Where(doc => doc.Id.StartsWith("PageVersion")).Skip(ix).Take(128);

using (var enumerator = ravenSession.Advanced.Stream(q))

while (enumerator.MoveNext())

if (!pageVersionsByPageId.ContainsKey(enumerator.Current.Document.XID) && enumerator.Current.Document is PageVersion)

pageVersionsByPageId.Add(enumerator.Current.Document.XID, enumerator.Current.Document);

}

}

[Kyle Levien]

As a side note I tried increasing Raven/MaxClauseCount for testing larger id set queries, but it didn't seem to make a difference, I got a too many clauses exception of >1024 each time.

In the 3.5 source I noticed the BooleanQuery.MaxClauseCount value is set twice in a row?

https://github.com/ravendb/ravendb/blob/97ddb4e3f62a7019bd136c9c7b0d10b4019b45c5/Raven.Database/Server/RavenDbServer.cs#L127

Thanks,

Kyle

[Michael Yarichuk]

Hi,

I have tried to reproduce this in a unit test (attached). The test didn't fail. 

Can you take a look at it - am I  reproducing what you are doing in your code?

I would like to try and reproduce this issue on my end. Perhaps you have some steps I can follow, or maybe you can provide code for a stand alone test?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Best regards,

 

Hibernating Rhinos Ltd  

Michael Yarichuk l RavenDB Core Team 

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

RavenDB paving the way to "Data Made Simple"   http://ravendb.net/  

[Kyle Levien]

This reproduces for us. Note that it doesn't throw any .net exception or anything in the raven log, we are seeing numerous ESENT 902 errors in the windows event log:

[Michael Yarichuk]

Just to make sure I understand correctly: the unit test that I have sent reproduces the issue?

Also, what Windows version are you running this on? Did you install any big updates lately?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Kyle Levien]

Correct, the only change I made to your test was I used a new "Tmp" object instead of "User" as we already have a defined User.

We see this on Windows 10 and Server 2008, and 2012r2 so far.

[Kyle Levien]

As another addendum, we don't have concrete proof of it, but it does appear that after a slew of 902 ESENT errors are recorded in log viewer we observe a slow-down of the raven DB response time. Queries gain ~.5-1.5s increases in response and the studio becomes very unresponsive. Maybe there is some sort of leak or handle that lucene doesn't release quick enough when the queries have a large number of clauses? Perhaps the ESENT engine silently attempts to restart but existing instances are lingering causing resource exhaustion?

Thanks

Kyle Levien

[Oren Eini (Ayende Rahien)]

I'm not sure that I understand the issue then.

This test passes, but you are worried about the event log entry, is that it?

--

You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Michael Yarichuk]

Maybe there is some sort of leak or handle that lucene doesn't release quick enough when the queries have a large number of clauses? 

Perhaps. But if it is so, it is not likely that handle leak/memory leak is related to the Esent errors. What you describe - is this consistent or happens predictably?

I suspect that this 902 Esent error is related to some specific Windows update.

I have some another question: 

What are the specs of Windows 10 machine you reproduced this on? I am interested in memory, CPU, Windows updates that are installed.

--

You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Best regards,

 

Hibernating Rhinos Ltd  

Michael Yarichuk l RavenDB Core Team 

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

RavenDB paving the way to "Data Made Simple"   http://ravendb.net/  

[Kyle Levien]

It's definitely looking like something windows update related. I tried rolling the ravendb server dlls back to 3.5.4 and I still get a lot of ESENT 902 errors in the event log when running Michael's test code, in the area of 80-120 per run.

This is on my dev machine - Windows 10 ver.1709, 16GB RAM, Intel i7-6700HQ @2.6GHz

We upgraded from 3.5.4 to 3.5.5 this fall because our sites would not install in machines with the Fall Creators Update installed. The store.Initialize() would consistently throw a "Task Cancelled" exception.

We have two concerns about the 902 errors we are observing. One is they appear to be the initiating cause of actual errors we get later as reported at the beginning of this thread. We first see a 902 error in the event log, then if the DB is idle long enough it throws and logs the following raven exception:

2018-01-02 15:49:14.5635,Raven.Storage.Esent.TransactionalStorage,Error,Unexpected error occurred while terminating Esent Storage. Ignoring this error to allow to shutdown RavenDB instance.,"Microsoft.Isam.Esent.Interop.EsentTooManyActiveUsersException: Too many active database users

  at Microsoft.Isam.Esent.Interop.Api.JetTerm2(JET_INSTANCE instance, TermGrbit grbit)

  at Raven.Storage.Esent.TransactionalStorage.<Dispose>b__39_0()"

2018-01-02 15:49:14.5635,Raven.Storage.Esent.TransactionalStorage,Warn,"Will now attempt to perform an abrupt shutdown, because asking nicely didn't work. You might need to run defrag on the database to recover potentially lost space (but no data will be lost).",

2018-01-02 15:49:14.5635,Raven.Storage.Esent.TransactionalStorage,Fatal,"Couldn't shut down the database server even when using abrupt, something is probably wrong and you'll need to restart the server process to access the database","Microsoft.Isam.Esent.Interop.EsentTooManyActiveUsersException: Too many active database users

  at Microsoft.Isam.Esent.Interop.Api.JetTerm2(JET_INSTANCE instance, TermGrbit grbit)

  at Raven.Storage.Esent.TransactionalStorage.<Dispose>b__39_0()"

After which the first attempt to open a session from the DocumentStore throws a Temp Path in Use exception in the client and is unrecoverable until we recycle the DB's IIS Application Pool.

We currently have a workaround for some of our servers in which we set the "Raven/Tenants/MaxIdleTimeForTenantDatabase" and "Raven/Tenants/FrequencyToCheckForIdleDatabases" to very high values in an attempt to not let the DBs idle and shutdown.

The second concern we have is a little less concrete, but we can observe degradation of the DB response time over time when 902 errors are plentiful in the event log. It gets bad to the point of simple queries in the RavenDB studio to an index can take 500-1500ms when they usually take ~5ms. This state seems to get incrementally worse and does not resolve unless we also recycle the app pool.

Kyle

</

[Oren Eini (Ayende Rahien)]

The simplest solution from your perspective is to move to Voron storage, which will have none of these issues

--