Repeating ESENT error messages in event log

[Matt]

RavenDB Build 2230

IIS 7 Hosting 

We are having a problems with Raven. It seems sluggish to respond and there seems to be a pattern of the W3wp.exe process consuming all the available memory and then a subsequent event log message of:

A process serving application pool 'RavenDB' failed to respond to a ping. The process id was '1288'.

IIS cycles the process and then IIS starts consuming memory again. CPU and disk IO load seem to be normal.

Unsure if this is related but we are also seeing each one of our databases is cycled through every 15 minutes with these messages in the app event log:

Raven (2732) 7-1XJQcm-D:\RavenDB\Web\Tenants\xxx\Data: The database engine (6.01.7601.0000) started a new instance (6).

Raven (2732) 7-1XJQcm-D:\RavenDB\Web\Tenants\xxx\Data: The database engine is initiating recovery steps.

Raven (2732) 7-1XJQcm-D:\RavenDB\Web\Tenants\xxx\Data: The database engine has begun replaying logfile D:\RavenDB\Web\Tenants\xxx\logs\RVN.log.

Raven (2732) 7-1XJQcm-D:\RavenDB\Web\Tenants\xxx\Data: The database engine has successfully completed recovery steps.

Any ideas?

[Khalid Abuhakmeh]

Any reason you can't upgrade to 2.5? It really is considerably better.

[Oren Eini (Ayende Rahien)]

The two are related, the db process is dying, and then recover from being killed.

--
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+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[balazs]

We are seeing the same problem with build 2380. Happened after running for about 24 hours.  No other issues in Event Viewer around that time.  Log file is huge but looking through it now.  Any ideas?

[Oren Eini (Ayende Rahien)]

Those aren't actually errors.

It just means that you were restarted.

On IIS, this happens automatically ever 29 hours unless you changed the config.

[Balazs Czifra]

Yes, but I've got "Regular Time Interval", "Request Limit", "Private Memory Limit", and "Virtual Memory Limit" all set to zero for the app pool.  Is there anything else you'd recommend configuring to prevent the recycling?  We didn't touch the directory or .config file.  Could it have run out of memory? I was running load testing against it (only reads).  SQL Server was running on it at the time and complaining a lot that "A significant part of sql server process memory has been paged out".  I've turned off SQL Server now and am giving it another try.

--
You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/7jBd54wMyz4/unsubscribe.
To unsubscribe from this group and all its topics, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

Maybe they competed for memory? Not sure.

[Matt]

Still seeing

A process serving application pool 'RavenDB' failed to respond to a ping. 

After upgrade to 2666

[balazs]

I've disabled SQL and  it occurred again.  Hasn't recurred since then, though.

[Matt]

It looks like the episode happens when we are requesting multiple documents at once. I am seeing this in the event log. If i reissue the query it brings raven down again. 

Event code: 3001 

Event message: The request has been aborted. 

Event time: 9/13/2013 1:42:09 PM 

Event time (UTC): 9/13/2013 8:42:09 PM 

Event ID: 5de7491466d64925b61ccebfec94c9d6 

Event sequence: 122127 

Event occurrence: 1 

Event detail code: 0 

 

Application information: 

    Application domain: /LM/W3SVC/2/ROOT-1-130235688818065173 

    Trust level: Full 

    Application Virtual Path: / 

    Application Path: D:\RavenDB\Web\ 

    Machine name: XXX

 

Process information: 

    Process ID: 2444 

    Process name: w3wp.exe 

    Account name: XXX 

 

Exception information: 

    Exception type: HttpException 

    Exception message: Request timed out.

 

 

Request information: 

    Request URL: XXX

    Request path: XXX

    User host address: XXX

    User: XXX

    Is authenticated: True 

    Authentication Type: Negotiate 

    Thread account name: XXX

 

Thread information: 

    Thread ID: 154 

    Thread account name: XXX 

    Is impersonating: False 

    Stack trace: 

 

 

Custom event details: 

[Oren Eini (Ayende Rahien)]

What is the actual request url?

[balazs]

I am having a similar, if not identical problem. Below you will find the Event Viewer warnings I get every 1-3 minutes (this occurs for a variety of different responders I've written).  Below that you will find the Raven errors that seem to correspond to those warnings.  The database seems to recover well each time, with no corruption.  The first time this happened was after about 24 hours of load testing.  The next time it was within a few hours.  The final time it was after 1.5 days.  Any ideas?

I get the following warnings in Event Viewer every 1-3 mins:

 

Event code: 3001 

Event message: The request has been aborted. 

Event time: 9/15/2013 4:05:28 AM 

Event time (UTC): 9/15/2013 8:05:28 AM 

Event ID: cd074e301bbe4f45a28e11f54633463a 

Event sequence: 10126 

Event occurrence: 9 

Event detail code: 0 

 

Application information: 

    Application domain: /LM/W3SVC/2/ROOT-1-130237042453192170 

    Trust level: Full 

    Application Virtual Path: / 

    Application Path: XXX

    Machine name: XXX 

 

Process information: 

    Process ID: 23048 

    Process name: w3wp.exe 

    Account name: IIS APPPOOL\XXX

 

Exception information: 

    Exception type: HttpException 

    Exception message: Request timed out.

 

 

Request information: 

    Request URL: MYOWNRESPONDERURL 

    Request path: MYOWNRESPONDERPATH

    User host address: 192.168.200.246 

    User:  

    Is authenticated: False 

    Authentication Type:  

    Thread account name: IIS APPPOOL\XXX 

 

Thread information: 

    Thread ID: 52 

    Thread account name: IIS APPPOOL\XXX 

    Is impersonating: False 

    Stack trace: 

Each of these failed requests in the Event Viewer also seem to correspond to one of these two errors logged by Raven:

2013-09-15 03:55:58.2098,Raven.Database.Server.HttpServer,Warn,Error on request,"System.Threading.ThreadAbortException: Thread was being aborted.

   at Microsoft.Win32.Win32Native.ReadFile(SafeFileHandle handle, Byte* bytes, Int32 numBytesToRead, Int32& numBytesRead, IntPtr mustBeZero)

   at System.IO.FileStream.ReadFileNative(SafeFileHandle handle, Byte[] bytes, Int32 offset, Int32 count, NativeOverlapped* overlapped, Int32& hr)

   at System.IO.FileStream.ReadCore(Byte[] buffer, Int32 offset, Int32 count)

   at System.IO.FileStream.Read(Byte[] array, Int32 offset, Int32 count)

   at Raven.Abstractions.Extensions.StreamExtensions.ReadEntireBlock(Stream stream, Byte[] buffer, Int32 start, Int32 count) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Abstractions\Extensions\StreamExtensions.cs:line 84

   at Raven.Database.Indexing.LuceneCodecDirectory.CodecIndexInput.ReadInternal(Byte[] b, Int32 offset, Int32 length) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Indexing\LuceneCodecDirectory.cs:line 136

   at Lucene.Net.Store.BufferedIndexInput.Refill() in c:\Work\lucene.net\src\core\Store\BufferedIndexInput.cs:line 187

   at Lucene.Net.Store.BufferedIndexInput.ReadByte() in c:\Work\lucene.net\src\core\Store\BufferedIndexInput.cs:line 42

   at Lucene.Net.Store.IndexInput.ReadVInt() in c:\Work\lucene.net\src\core\Store\IndexInput.cs:line 89

   at Lucene.Net.Index.SegmentTermPositions.ReadDeltaPosition() in c:\Work\lucene.net\src\core\Index\SegmentTermPositions.cs:line 78

   at Lucene.Net.Index.SegmentTermPositions.LazySkip() in c:\Work\lucene.net\src\core\Index\SegmentTermPositions.cs:line 182

   at Lucene.Net.Index.SegmentTermPositions.NextPosition() in c:\Work\lucene.net\src\core\Index\SegmentTermPositions.cs:line 72

   at Lucene.Net.Search.PhrasePositions.NextPosition() in c:\Work\lucene.net\src\core\Search\PhrasePositions.cs:line 86

   at Lucene.Net.Search.ExactPhraseScorer.PhraseFreq() in c:\Work\lucene.net\src\core\Search\ExactPhraseScorer.cs:line 39

   at Lucene.Net.Search.PhraseScorer.DoNext() in c:\Work\lucene.net\src\core\Search\PhraseScorer.cs:line 116

   at Lucene.Net.Search.PhraseScorer.NextDoc() in c:\Work\lucene.net\src\core\Search\PhraseScorer.cs:line 94

   at Lucene.Net.Util.ScorerDocQueue.TopNextAndAdjustElsePop() in c:\Work\lucene.net\src\core\Util\ScorerDocQueue.cs:line 156

   at Lucene.Net.Search.DisjunctionSumScorer.AdvanceAfterCurrent() in c:\Work\lucene.net\src\core\Search\DisjunctionSumScorer.cs:line 192

   at Lucene.Net.Search.DisjunctionSumScorer.NextDoc() in c:\Work\lucene.net\src\core\Search\DisjunctionSumScorer.cs:line 155

   at Lucene.Net.Search.BooleanScorer2.NextDoc() in c:\Work\lucene.net\src\core\Search\BooleanScorer2.cs:line 397

   at Lucene.Net.Search.Function.CustomScoreQuery.CustomScorer.NextDoc() in c:\Work\lucene.net\src\core\Search\Function\CustomScoreQuery.cs:line 505

   at Lucene.Net.Search.Scorer.Score(Collector collector) in c:\Work\lucene.net\src\core\Search\Scorer.cs:line 66

   at Lucene.Net.Search.IndexSearcher.Search(Weight weight, Filter filter, Collector collector) in c:\Work\lucene.net\src\core\Search\IndexSearcher.cs:line 221

   at Lucene.Net.Search.Searcher.Search(Query query, Collector results) in c:\Work\lucene.net\src\core\Search\Searcher.cs:line 74

   at Fastcase.Search.Responders.CaseQuerying.GetSortedResults(SortOption sortOption, Int32 numHits, IndexSearcher searcher, Query query, Boolean scoreResults, Boolean scoreWithDocumentBoost) in 

   [MYOWNRESPONDER]

   at Raven.Database.Server.AbstractRequestResponder.ReplicationAwareRespond(IHttpContext context) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Server\AbstractRequestResponder.cs:line 62

   at Raven.Database.Server.HttpServer.DispatchRequest(IHttpContext ctx) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Server\HttpServer.cs:line 863

   at Raven.Database.Server.HttpServer.HandleActualRequest(IHttpContext ctx) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Server\HttpServer.cs:line 609"

2013-09-15 03:56:43.4188,Raven.Database.Server.HttpServer,Warn,Error on request,"System.Threading.ThreadAbortException: Thread was being aborted.

   at System.Runtime.InteropServices.SafeHandle.DangerousAddRef(Boolean& success)

   at Microsoft.Win32.Win32Native.GetFileSize(SafeFileHandle hFile, Int32& highSize)

   at System.IO.FileStream.get_Length()

   at Raven.Database.Indexing.LuceneCodecDirectory.CodecIndexInput.Length() in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Indexing\LuceneCodecDirectory.cs:line 124

   at Lucene.Net.Store.BufferedIndexInput.Refill() in c:\Work\lucene.net\src\core\Store\BufferedIndexInput.cs:line 174

   at Lucene.Net.Store.BufferedIndexInput.ReadByte() in c:\Work\lucene.net\src\core\Store\BufferedIndexInput.cs:line 42

   at Lucene.Net.Store.IndexInput.ReadVInt() in c:\Work\lucene.net\src\core\Store\IndexInput.cs:line 89

   at Lucene.Net.Index.SegmentTermPositions.NextPosition() in c:\Work\lucene.net\src\core\Index\SegmentTermPositions.cs:line 73

   at Lucene.Net.Search.Spans.TermSpans.Next() in c:\Work\lucene.net\src\core\Search\Spans\TermSpans.cs:line 60

   at Lucene.Net.Search.Spans.NearSpansOrdered.ShrinkToAfterShortestMatch() in c:\Work\lucene.net\src\core\Search\Spans\NearSpansOrdered.cs:line 361

   at Lucene.Net.Search.Spans.NearSpansOrdered.AdvanceAfterOrdered() in c:\Work\lucene.net\src\core\Search\Spans\NearSpansOrdered.cs:line 228

   at Lucene.Net.Search.Spans.NearSpansUnordered.SpansCell.SkipTo(Int32 target) in c:\Work\lucene.net\src\core\Search\Spans\NearSpansUnordered.cs:line 121

   at Lucene.Net.Search.Spans.NearSpansUnordered.Next() in c:\Work\lucene.net\src\core\Search\Spans\NearSpansUnordered.cs:line 233

   at Lucene.Net.Search.Spans.SpanScorer.SetFreqCurrentDoc() in c:\Work\lucene.net\src\core\Search\Spans\SpanScorer.cs:line 96

   at Lucene.Net.Search.Spans.SpanScorer.NextDoc() in c:\Work\lucene.net\src\core\Search\Spans\SpanScorer.cs:line 59

   at Lucene.Net.Util.ScorerDocQueue.TopNextAndAdjustElsePop() in c:\Work\lucene.net\src\core\Util\ScorerDocQueue.cs:line 156

   at Lucene.Net.Search.DisjunctionSumScorer.AdvanceAfterCurrent() in c:\Work\lucene.net\src\core\Search\DisjunctionSumScorer.cs:line 192

   at Lucene.Net.Search.DisjunctionSumScorer.NextDoc() in c:\Work\lucene.net\src\core\Search\DisjunctionSumScorer.cs:line 155

   at Lucene.Net.Search.BooleanScorer2.NextDoc() in c:\Work\lucene.net\src\core\Search\BooleanScorer2.cs:line 397

   at Lucene.Net.Search.Function.CustomScoreQuery.CustomScorer.NextDoc() in c:\Work\lucene.net\src\core\Search\Function\CustomScoreQuery.cs:line 505

   at Lucene.Net.Search.Scorer.Score(Collector collector) in c:\Work\lucene.net\src\core\Search\Scorer.cs:line 66

   at Lucene.Net.Search.IndexSearcher.Search(Weight weight, Filter filter, Collector collector) in c:\Work\lucene.net\src\core\Search\IndexSearcher.cs:line 221

   [MYOWNRESPONDER]

   at Raven.Database.Server.AbstractRequestResponder.ReplicationAwareRespond(IHttpContext context) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Server\AbstractRequestResponder.cs:line 62

   at Raven.Database.Server.HttpServer.DispatchRequest(IHttpContext ctx) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Server\HttpServer.cs:line 863

   at Raven.Database.Server.HttpServer.HandleActualRequest(IHttpContext ctx) in C:\ravendb-build-2380\ravendb-build-2380\Raven.Database\Server\HttpServer.cs:line 609

[Matt]

Just loading a bunch of documents:

http://raven:8080/databases/DB/queries/?&id=Message/764&id=Message/777&id=Message/779&id=Message/781&id=Message/783&id=Message/798&id=Message/805&id=Message/810&id=Message/813&id=Message/824&id=Message/835&id=Message/837&id=Message/843&id=Message/845&id=Message/850&id=Message/853&id=Message/856&id=Message/858&id=Message/861&id=Message/862&id=Message/863&id=Message/864&id=Message/866&id=Message/867&id=Message/868&id=Message/874&id=Message/877&id=Message/892&id=Message/893&id=Message/899 

These are fairly large messages and we found that loading less of them at one time resolves the problem. Not sure if there is a limit on how much data can be requested. 

[Oren Eini (Ayende Rahien)]

Are you running this inside IIS?

ThreadAbortException is usually generated by it when it noticed that a request takes way too long.

[Oren Eini (Ayende Rahien)]

How big are those? 

If it takes a very long time to stream them, IIS might kill the app