Re: [RavenDB] Questions on RavenDB read performance

[Oren Eini (Ayende Rahien)]

Can you check if you might have persistent connections that were timed out by the firewall?

That is the very first thing to try.

On Fri, May 31, 2013 at 11:29 PM, Colin Johnson <col...@gmail.com> wrote:

We are seeing regular errors in our production environment where reads are failing across our farm for several seconds.

The errors we are seeing are as follows:

<11>Sometaro: ERROR Web.Data.EntityStore`1: System.Net.WebException: The underlying connection was closed: An unexpected error occurred on a receive. ---> System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host 
at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size) 
--- End of inner exception stack trace --- 
at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size) 
at System.Net.PooledStream.Read(Byte[] buffer, Int32 offset, Int32 size) 
at System.Net.Connection.SyncRead(HttpWebRequest request, Boolean userRetrievedStream, Boolean probeRead) 
--- End of inner exception stack trace --- 
at System.Net.HttpWebRequest.GetResponse() 
at Raven.Client.Connection.HttpJsonRequest.ReadJsonInternal(Func`1 getResponse) in c:\Builds\RavenDB-Stable\Raven.Client.Ligh

We see these error in our logs at the beginning of the day when most of our users are causing reads from RavenDB.  We experience high failure rates for 9-15 seconds every 6 minutes or so right at the beginning of our day.

 

We are running build 2261 on two EC2 c1.xlarge instances with master-master replication between nodes.

We have the periodic backup job running every 24 hours backing up to the same EBS volumes as the data and indexes. This is something that looks like it is ill-advised  and we are looking into moving them to another volume.

 

So far we have not been watching the performance counts on the database, but we will during the next heavy load time.

 

We are also considering disabling incremental backups during our next high load time. 

What we are seeing in the backup intervals is interesting.

·         On the primary instance even though we have not restarted, we have seen the incremental file’s create timestamps move from after the load for the day is gone to several times during the first hour of the day when the site is active.

·         On the secondary instance, backup times have also drifted to during high load hours, but we are only getting one dump per day.

 

 

Could this shift in backup times be causing our low availability event?

Can you help us with some performance recommendations? 

We have previously tested 2261 with EBS provisioned IOPS, but did not see any difference in the read throughput. Should we look into this issue?

It looks like slow GET performance has been improved in build 2340(http://issues.hibernatingrhinos.com/issue/RavenDB-1011), will moving to this version also reduce the number of errors returned from RavenDB?

Is moving the periodic backup to a difference volume the only change in storage or should we also move the indexes to another EBS volume?

What other information should we collect to help find a solution to this issue?

--
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.
 
 

[Kijana Woodard]

Hi Colin. 

Do you see anything interesting in the Raven.Server logs during this time frame? How about any raven performance counters? What is the general state of the raven box when these errors start? Are you seeing the errors on web servers in the same "availability zone" as the raven server setup in the ConnectionString or are they concentrated in the "cross zone" web servers?

[Oren Eini (Ayende Rahien)]

The failed to close response errors are fine. They just say that the client disconnected early. No issue there, happens all the time.

You want to use persistent HTTP connections.

On Wed, Jun 12, 2013 at 8:22 PM, Jonathan Keith <jke...@tradestation.com> wrote:

On the server we see a pretty steady stream of these exceptions:

Severity: Error

Facility: RavenDB

ExceptionMessage: One or more errors occurred.

LoggerName: Raven.Database.Server.Abstractions.HttpListenerContextAdpater

Full message: Failed to close response

The perf counters -- everything but # of concurrent requests stays in single digits. # of concurrent requests seems inaccurate. When the perf counters were installed, the # was around 100. Now it shows 31,800. The database instance has been recycled since then with no impact to this perf counter.

The server itself appears to be in good health even when a large # of the errors Colin posted occur. CPU and memory are normal. Network activity is high sometimes, but not always.

The majority of the errors come from instances (clients) in a different availability zone than the database. We've disabled replication while we're debugging the issue so just one DB now.

Is Raven using persistent HTTP connections? Is there a way to configure the client or server to force the use of HTTP 1.0 and/or disable the use of persistent HTTP connections?

Thanks

[Colin Johnson]

We are currently in a state where we have high read activity on the  Here is a screenshot of our instance stats.  There is minimal load on the system, but RavenDB is doing something with the disk. 

I checked the backup directory and there are no recently modified files.  

http://imgur.com/Jebd9Pr

What should we look for to identify what is going on?

[Kijana Woodard]

On 2360 now?

Interesting that it's on the data folder and not the indexes folder, that would have been my first guess.

[Colin Johnson]

No still on 2261.

[Oren Eini (Ayende Rahien)]

Huh. Is it possible that you have a map/reduce index there?

[Colin Johnson]

Yes and we did have stale indexes during that whole time. Though the number of documents processed in each batch was low (mostly 2-5 docs up to 356 docs per batch).

Here are our index definitions: http://imgur.com/qyfGdcy

During this time we had very low activity on the site. 

[Oren Eini (Ayende Rahien)]

Those aren't map/reduce indexes.

[Kijana Woodard]

You have map only indexes.

Which index was stale?

I'd be surprised if the "entities by name" index was stale. How many new docs are Stored every day?

I'm guessing that the UsageMonth index would be most heavily updated first thing in the morning / first days of the month. The docs indexed by the usage month index are updated so the system is going through them to make sure the index is up to date. It could be that the answer is "they are fine", but if they are updated at all, the index has to check.

Would that explain the behavior?

Do you see anything at /stats that indicates index activity?

[Kijana Woodard]

I just checked the source code because Jonathan mentioned that the concurrent request counters wasn't decreasing. That seems weird in and of itself give the code:

https://github.com/ravendb/ravendb/blob/master/Raven.Database/Indexing/WorkContext.cs#L307

The call to this is within a finally:

https://github.com/ravendb/ravendb/blob/master/Raven.Database/Server/HttpServer.cs#L884

I think the source in ravendb/ravendb master is currently 2375.

[Jonathan Keith]

Thanks. We're still working on getting upgraded to 2375 in prod and are on 2261 there currently.

We noticed more read errors last night. They seemed to correlate with spikes in I/O on the EBS volume. Because EBS volumes also use the network, we have one theory that the high disk I/O and network issues could be related. We're still surprised by how much disk activity occurs even during periods of low usage. What could be causing several MB/s of I/O throughput from Raven.Server.exe when only a few requests per second are coming in?

This morning (low usage time) we attempted a full export of our data via Smuggler. Shortly after starting the export, Raven consumed nearly 100% the amount of physical memory (7GB), causing paging to occur. Even Smuggler, which is running on the box of course, began throwing timeout errors. We ended up stopping the export due to the errors caused on active clients. Is this expected behavior when disk operations take longer than usual? What is the timeout on reads/writes?

Based on our observations, we're considering some changes to the configuration of the Raven EC2 instance: using an EBS-optimized instance type with high network performance (10Gbps) and/or using an instance type with SSDs for data and index storage, using an instance type with more memory, and splitting indexes/data/backups across multiple volumes.

[Oren Eini (Ayende Rahien)]

Please check the event log, there should be some messages there about it.

In general, we assume a relatively low latency storage, and a lot of stuff might get stuck in memory while waiting for IO operations to complete.

I don't think it would cause high memory usage, but that depend on exactly what you are doing. Probably on the exact version of smuggler against the server build. There is a bug that cause us to buffer all results before replying on large dbs.

SSD is the recommended choice, yes.

[Kijana Woodard]

Is there a correlation between requests per second and the network errors?

When there are lots of these network errors, how many requests per second is the raven server taking?

100?

1000?

10000?

Perhaps someone from RavenHQ can chime in with tips for running on AWS?

[Kijana Woodard]

@Colin/Jonathan,

I put together a program to exercise raven to try and reproduce the issues you guys are seeing.

I put nearly everything in one file so it would be easy to understand:

https://github.com/kijanawoodard/raven-exercise/blob/master/src/RavenExercise/App.cs

It's an mvc4 / .net 4.5 project. Fork and build.

/init - puts one million 2kb docs into a raven database specified by the connection string. [make sure the app pool has admin privs or set the database config to Admin instead of Get/All or create the db 'exercise-raven' manually.

/read - reads a random document and returns the id

/write - updates a random document with a random 2k of data.

I uploaded the project to an Azure VM since I am running Win 7 Pro and can't have more than 10 connections to IIS. The Azure VM is hosting the raven exercise website on port 80 and ravendb on 8080.

Using apache bench for /read with -n 1000 -c 100 yielded ~400/s.

Using apache bench for /write with -n 1000 -c 100 yielded ~32/s.

There is a significant delta between the time reported by raven and the time spent "elsewhere" (iis? network? not sure). I ran into an issue using apache benchmark on my MacBook Pro where it seems to exhaust connections and I have to restart terminal. I thought I was on to something, but when hitting the endpoints from my windows machine while ab was in a hung state, everything worked. Rather than continuing to try and figure that out and test more scenarios, I wanted to share the code.

My thought is that you guys could upload the code to AWS and use "tool of choice" to apply load and see if you can get the same network problems without any significant application code. I used mvc 4 so you can easily put it behind the AWS load balancer and see if the multiple availability zones or the load balancer itself makes any difference.

One anecdote about Azure. I ran /init to create the million test documents. I could tell it was significantly slower than my local machine. When the azure machine was at 750k docs created, I started my local machine. My local got to 780k by the time the Azure box finished and my local finished with a minute. IIRC, the timing was something like ~3000/s local and ~900/s on Azure.

[Kijana Woodard]

Had to update ab and build and replace gcc on my macbook. Now able to test more consistently.

Ran some tests with -n 50,000 and -c 500.

Seeing ~420/s for /read. Seems consistent whether -c 100, 250, or 500. CPU is ~90% so that may be limiting factor. IIS and Raven split the majority of the cpu charge. Perform shows ~12% Disk Time.

/write is interesting. Perfmon is reporting ~100% Disk Time. CPU is ~40%. Raven is reporting 1 ms reads and ~150ms writes. But the average response time from the web app is ~15 seconds.

[Kijana Woodard]

Just ran /read ab -n 1000 -c 10 against my desktop from my macbook: 

~900/s. 

50% - 10ms

98% - 20ms

99% - 22ms

Same against Azure VM: 

~63/s.

50% - 135ms

98% - 169ms

99% - 447ms

I think what this test tells me is that it's time to upgrade my desktop to Server 2012 so I can throw more concurrent requests at it. ;-D

[Jonathan Keith]

I've been doing some benchmarking as well, testing out the different disk configurations.

I batch insert 1 million docs to a Raven instance in zone C first, then run multiple clients from instances in zone A that read, change, and write a random document. So 50% reads, 50% writes.

Without provisioned IOPS: ~200 req/sec

With 4000 IOPS provisioned: ~1800 req/sec

I then had the thought to run in memory to see the upper limit of this test, but hit some issues:

- batch insert doesn't seem to work when running in this mode. is that known or maybe something i'm doing wrong?

- after letting a process that created the docs via store/savechanges run for hours (~130 writes/sec) ... Raven became unresponsive and crashed. I can provide the WER if needed. Exception:

Unhandled Exception: System.Net.HttpListenerException: An operation was attempted on a nonexistent network connection
   at System.Net.HttpResponseStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at Raven.Database.Util.Streams.BufferPoolStream.InternalFlush() in c:\Builds\RavenDB-Stable\Raven.Database\Util\Streams\BufferPoolStream.cs:line 69
   at Raven.Database.Util.Streams.BufferPoolStream.Flush() in c:\Builds\RavenDB-Stable\Raven.Database\Util\Streams\BufferPoolStream.cs:line 61
   at Raven.Database.Server.HttpServer.GetContext(IAsyncResult ar) in c:\Builds\RavenDB-Stable\Raven.Database\Server\HttpServer.cs:line 474
   at System.Net.LazyAsyncResult.Complete(IntPtr userToken)
   at System.Net.ListenerAsyncResult.IOCompleted(ListenerAsyncResult asyncResult, UInt32 errorCode, UInt32 numBytes)
   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)

[Kijana Woodard]

Benchmarking 2375?

I couldn't get raven.server.exe /ram working locally. Run out of memory. Nothing crashes and no errors, but the memory is pegged. Never saw documents get created via bulk insert.

Three years ago 12 GB of RAM seemed like a a lot. ;-)

[Jonathan Keith]

2261 -- trying to keep in sync with production environment.

I thought I hit ram limit and that had caused the crash the first time, then I ran on a box with 30GB of ram and never got over 8GB before the crash.

[Oren Eini (Ayende Rahien)]

in memory mode isn't really robust enough to handle that, probably.

It is mostly meant for testing, right now.