Timeout exceptions

[David Pfeffer]

Hello,

I'm getting timeout exceptions while querying my RavenDB database (in production).

The lines of code in our application are:

var existingKeysLazily = _session.Advanced.Lazily.Load<FeedItemSourceUniqueKey>(uniqueKeys.Select(x => x.KeyDocument.Id));
_session.Advanced.Eagerly.ExecuteAllPendingLazyOperations();
var existingKeyDocumentsBySource = existingKeysLazily.Value
    .WhereNotNull()
    .ToDictionary(x => x.Source);

The exception is as follows:

System.AggregateException: One or more errors occurred. ---> System.Net.WebException: The operation has timed out
   at System.Net.HttpWebRequest.GetResponse()
   at Raven.Client.Connection.HttpJsonRequest.ReadJsonInternal(Func`1 getResponse) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 341
   at Raven.Client.Connection.HttpJsonRequest.ReadResponseJson() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 239
   at Raven.Client.Connection.ServerClient.<>c__DisplayClass99.<MultiGet>b__97(String operationUrl) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ServerClient.cs:line 1550
   at Raven.Client.Connection.ReplicationInformer.TryOperation[T](Func`2 operation, String operationUrl, Boolean avoidThrowing, T& result) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 559
   at Raven.Client.Connection.ReplicationInformer.ExecuteWithReplication[T](String method, String primaryUrl, Int32 currentRequest, Int32 currentReadStripingBase, Func`2 operation) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 525
   at Raven.Client.Connection.ServerClient.ExecuteWithReplication[T](String method, Func`2 operation) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ServerClient.cs:line 174
   at Raven.Client.Document.DocumentSession.ExecuteLazyOperationsSingleStep() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\DocumentSession.cs:line 654
   at Raven.Client.Document.DocumentSession.ExecuteAllPendingLazyOperations() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\DocumentSession.cs:line 628
   at FunnelFire.Worker.Handlers.FeedItemHandler.<>c__DisplayClass2d.<<Consume>b__1b>d__42.MoveNext() in e:\BuildAgent\work\620227ff9f60a5ca\Core\src\Worker\Handlers\FeedItemHandler.cs:line 214
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at FunnelFire.Worker.Handlers.FeedItemHandler.<Consume>d__53.MoveNext() in e:\BuildAgent\work\620227ff9f60a5ca\Core\src\Worker\Handlers\FeedItemHandler.cs:line 188
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at FunnelFire.Bus.BusModule.<>c__DisplayClass1b.<>c__DisplayClass24.<<Load>b__14>d__2a.MoveNext() in e:\BuildAgent\work\620227ff9f60a5ca\Core\src\Bus\BusModule.cs:line 152
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.Net.WebException: The operation has timed out
   at System.Net.HttpWebRequest.GetResponse()
   at Raven.Client.Connection.HttpJsonRequest.ReadJsonInternal(Func`1 getResponse) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 341
   at Raven.Client.Connection.HttpJsonRequest.ReadResponseJson() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 239
   at Raven.Client.Connection.ServerClient.<>c__DisplayClass99.<MultiGet>b__97(String operationUrl) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ServerClient.cs:line 1550
   at Raven.Client.Connection.ReplicationInformer.TryOperation[T](Func`2 operation, String operationUrl, Boolean avoidThrowing, T& result) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 559
   at Raven.Client.Connection.ReplicationInformer.ExecuteWithReplication[T](String method, String primaryUrl, Int32 currentRequest, Int32 currentReadStripingBase, Func`2 operation) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 525
   at Raven.Client.Connection.ServerClient.ExecuteWithReplication[T](String method, Func`2 operation) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ServerClient.cs:line 174
   at Raven.Client.Document.DocumentSession.ExecuteLazyOperationsSingleStep() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\DocumentSession.cs:line 654
   at Raven.Client.Document.DocumentSession.ExecuteAllPendingLazyOperations() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\DocumentSession.cs:line 628
   at FunnelFire.Worker.Handlers.FeedItemHandler.<>c__DisplayClass2d.<<Consume>b__1b>d__42.MoveNext() in e:\BuildAgent\work\620227ff9f60a5ca\Core\src\Worker\Handlers\FeedItemHandler.cs:line 214
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at FunnelFire.Worker.Handlers.FeedItemHandler.<Consume>d__53.MoveNext() in e:\BuildAgent\work\620227ff9f60a5ca\Core\src\Worker\Handlers\FeedItemHandler.cs:line 188
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at FunnelFire.Bus.BusModule.<>c__DisplayClass1b.<>c__DisplayClass24.<<Load>b__14>d__2a.MoveNext() in e:\BuildAgent\work\620227ff9f60a5ca\Core\src\Bus\BusModule.cs:line 152<---

Your prompt attention to this issue would be appreciated, as this issue is occurring on our production system.

Thanks,

David Pfeffer

[David Pfeffer]

Build 2373, by the way.

[Oren Eini (Ayende Rahien)]

Any load on the system ? 

How many items do you have in uniqueKeys? 

What is the document sizes that you get back?

--
You received this message because you are subscribed to the Google Groups "ravendb" 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.
 
 

[David Pfeffer]

There's nearly no load -- probably 4 or 5 other jobs doing insertions a few times a minute.

There's 411,000 documents in the collection being queried. Unique keys ranged between containing 10 and 100 items, but it times out randomly and with seemingly no correlation to the count in unique keys. The documents are tiny; they seem to have about 301 bytes.

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

[Oren Eini (Ayende Rahien)]

Can you track the requests through fiddler?

[David Pfeffer]

Unfortunately it would be nontrivial to do so, because only a small percentage of requests fail. Also, the client for Raven in question is an Azure worker role.

[Oren Eini (Ayende Rahien)]

In the failing request, can you try to capture the full URL they are using?

Did you play with the timeout settings?

One thing to note, Azure IO tend to be pretty bad, and that might be impacting this. 

Are you running RavenDB in IIS or as a service? In either case, can you enable the logs and match the time of such an error?

[David Pfeffer]

How do I get the full URL? I'm happy to make a small code patch to log this.

I set my timeout to 90 seconds.

Running RavenDB as a service on a separate VM on Azure (same Azure virtual network).  I have logging turned on already but am not showing any errors on the Raven side.

[Oren Eini (Ayende Rahien)]

store.JsonRequestFactory.CustomizeRequest <-- then log it from here.

Do you see the request that is failing? Can you tell how much time it took?

[David Pfeffer]

Apparently the error logs were not appearing on the console, even though they were showing up in a log file. I see lots of log messages like the following:

• Jul 14 20:01:20 funnelfire-db1 RavenDB: 00:01:17.7201|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:01:20 funnelfire-db1 RavenDB: 00:01:19.1419|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:01:20 funnelfire-db1 RavenDB: 00:01:19.7512|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:01:24 funnelfire-db1 RavenDB: 00:01:23.0325|ERROR|Raven.Database.Server.Abstractions.HttpListenerContextAdpater|Failed to close response
• Jul 14 20:01:24 funnelfire-db1 RavenDB: 00:01:23.2981|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:01:26 funnelfire-db1 RavenDB: 00:01:23.9571|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:01:30 funnelfire-db1 RavenDB: 00:01:27.9758|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:05:28 funnelfire-db1 RavenDB: 00:05:28.0032|ERROR|Raven.Database.Server.Abstractions.HttpListenerContextAdpater|Failed to close response
• Jul 14 20:05:34 funnelfire-db1 RavenDB: 00:05:33.4719|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:05:34 funnelfire-db1 RavenDB: 00:05:33.4719|WARN|Raven.Database.Server.HttpServer|Error on request
• Jul 14 20:05:34 funnelfire-db1 RavenDB: 00:05:33.7219|ERROR|Raven.Database.Server.Abstractions.HttpListenerContextAdpater|Failed to close response
• Jul 14 20:10:25 funnelfire-db1 RavenDB: 00:10:24.1306|ERROR|Raven.Database.Server.Abstractions.HttpListenerContextAdpater|Failed to close response
• Jul 14 20:10:54 funnelfire-db1 RavenDB: 00:10:52.3843|ERROR|Raven.Database.Server.Abstractions.HttpListenerContextAdpater|Failed to close response
• Jul 14 20:11:31 funnelfire-db1 RavenDB: 00:11:28.9415|WARN|Raven.Database.Server.HttpServer|Error on request

[Oren Eini (Ayende Rahien)]

Can you also log the error as well?

[Oren Eini (Ayende Rahien)]

BTW, Failed to close response is normal and can be ignored.

On Mon, Jul 15, 2013 at 3:30 AM, David Pfeffer <da...@funnelfire.com> wrote: