Slow ReadIndex rebuild?

I have never seen this before, I could always just start eventstore and connect my apps to it. Now I have to wait several minutes for readindex rebuild.

Is it something new or have I just never paid attention to it (and now did because bad performance)?

Regardless, should it be this slow?

Thanks

[PID:368984:005 2016.04.04 06:44:54.244 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 3182ms. Q: 0/0.
[PID:368984:014 2016.04.04 06:44:55.870 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 9434 records (0.9%).
[PID:368984:014 2016.04.04 06:45:00.878 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 40355 records (2.2%).
[PID:368984:004 2016.04.04 06:45:00.987 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:58666, L10.1.0.4:1112, {d66ca53b-4774-46d3-886b-bc0226b31e42}].
[PID:368984:006 2016.04.04 06:45:02.674 TRACE TFChunk ] CACHED TFChunk #3-3 (chunk-000003.000000) in 00:00:13.7020691.
[PID:368984:014 2016.04.04 06:45:05.882 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 89586 records (3.5%).
[PID:368984:014 2016.04.04 06:45:06.554 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 100000 records (3.8%).
[PID:368984:014 2016.04.04 06:45:11.563 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 162728 records (5.2%).
[PID:368984:024 2016.04.04 06:45:13.532 INFO TcpConnection ] ES TcpConnection closed [06:45:13.469: N10.1.0.4:58658, L10.1.0.4:1112, {cb556cd0-e2af-4b48-b7e7-138931b2119d}]:Received bytes: 352, Sent bytes: 132
[PID:368984:024 2016.04.04 06:45:13.532 INFO TcpConnection ] ES TcpConnection closed [06:45:13.532: N10.1.0.4:58658, L10.1.0.4:1112, {cb556cd0-e2af-4b48-b7e7-138931b2119d}]:Send calls: 6, callbacks: 6
[PID:368984:024 2016.04.04 06:45:13.532 INFO TcpConnection ] ES TcpConnection closed [06:45:13.532: N10.1.0.4:58658, L10.1.0.4:1112, {cb556cd0-e2af-4b48-b7e7-138931b2119d}]:Receive calls: 11, callbacks: 11
[PID:368984:024 2016.04.04 06:45:13.532 INFO TcpConnection ] ES TcpConnection closed [06:45:13.532: N10.1.0.4:58658, L10.1.0.4:1112, {cb556cd0-e2af-4b48-b7e7-138931b2119d}]:Close reason: [ConnectionReset] Socket receive error
[PID:368984:024 2016.04.04 06:45:13.563 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:58658, {cb556cd0-e2af-4b48-b7e7-138931b2119d}] closed: ConnectionReset.
[PID:368984:019 2016.04.04 06:45:13.657 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:58658
[PID:368984:019 2016.04.04 06:45:13.657 TRACE InMemoryBus ] SLOW BUS MSG [PersistentSubscriptionsBus]: ConnectionClosed - 93ms. Handler: PersistentSubscriptionService.
[PID:368984:017 2016.04.04 06:45:15.485 INFO TcpConnection ] ES TcpConnection closed [06:45:15.485: N10.1.0.4:58666, L10.1.0.4:1112, {d66ca53b-4774-46d3-886b-bc0226b31e42}]:Received bytes: 401, Sent bytes: 88
[PID:368984:017 2016.04.04 06:45:15.485 INFO TcpConnection ] ES TcpConnection closed [06:45:15.485: N10.1.0.4:58666, L10.1.0.4:1112, {d66ca53b-4774-46d3-886b-bc0226b31e42}]:Send calls: 4, callbacks: 4
[PID:368984:017 2016.04.04 06:45:15.485 INFO TcpConnection ] ES TcpConnection closed [06:45:15.485: N10.1.0.4:58666, L10.1.0.4:1112, {d66ca53b-4774-46d3-886b-bc0226b31e42}]:Receive calls: 10, callbacks: 10
[PID:368984:017 2016.04.04 06:45:15.485 INFO TcpConnection ] ES TcpConnection closed [06:45:15.485: N10.1.0.4:58666, L10.1.0.4:1112, {d66ca53b-4774-46d3-886b-bc0226b31e42}]:Close reason: [ConnectionReset] Socket receive error
[PID:368984:017 2016.04.04 06:45:15.485 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:58666, {d66ca53b-4774-46d3-886b-bc0226b31e42}] closed: ConnectionReset.
[PID:368984:006 2016.04.04 06:45:15.501 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:58666
[PID:368984:014 2016.04.04 06:45:16.205 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 200000 records (6.3%).
[PID:368984:014 2016.04.04 06:45:21.223 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 239956 records (7.7%).
[PID:368984:007 2016.04.04 06:45:25.615 TRACE TFChunk ] Verifying hash for TFChunk ‘E:\Data\Node1\db\chunk-000001.000000’…
[PID:368984:014 2016.04.04 06:45:26.224 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 244881 records (10.2%).
[PID:368984:014 2016.04.04 06:45:31.240 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 247708 records (12.6%).
[PID:368984:014 2016.04.04 06:45:36.246 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 250368 records (15.8%).
[PID:368984:014 2016.04.04 06:45:41.250 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 253171 records (18.8%).
[PID:368984:014 2016.04.04 06:45:46.251 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 256025 records (21.8%).
[PID:368984:014 2016.04.04 06:45:51.252 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 258186 records (24.4%).
[PID:368984:007 2016.04.04 06:45:55.877 TRACE TFChunk ] Verifying hash for TFChunk ‘E:\Data\Node1\db\chunk-000000.000000’…
[PID:368984:014 2016.04.04 06:45:56.268 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 266579 records (24.9%).
[PID:368984:014 2016.04.04 06:45:58.659 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 300000 records (25.6%).
[PID:368984:014 2016.04.04 06:46:03.675 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 364415 records (27.0%).
[PID:368984:014 2016.04.04 06:46:08.684 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 396310 records (29.1%).
[PID:368984:014 2016.04.04 06:46:13.685 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 398054 records (31.7%).
[PID:368984:014 2016.04.04 06:46:18.233 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 400000 records (34.6%).
[PID:368984:014 2016.04.04 06:46:23.240 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 402305 records (37.3%).
[PID:368984:014 2016.04.04 06:46:28.243 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 404713 records (40.0%).
[PID:368984:014 2016.04.04 06:46:33.244 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 408027 records (43.5%).
[PID:368984:014 2016.04.04 06:46:38.257 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 411821 records (47.5%).
[PID:368984:014 2016.04.04 06:46:43.272 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 414789 records (51.0%).
[PID:368984:014 2016.04.04 06:46:48.274 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 419114 records (55.1%).
[PID:368984:014 2016.04.04 06:46:53.285 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 421611 records (58.6%).

Ah, this was a rushed post. Sorry.

https://groups.google.com/forum/#!searchin/event-store/readindex/event-store/ewrLjd8bPck/AfTkWqo5BAAJ

“No this is normal basically the last up to 1m are kept in memory index then batched 1m at a time down to disk. On a restart we replay up to 1m. This size (index memory size) is configurable. Use a lower value and less will be replayed on startup. Knocking it down to 100k would make your slowest startup about 1m I guess”

The index rebuild is quite slow though what happens during the index
rebuild is a big sequential read. How long it takes is largely a
function of:

How big the db is. How big events are. What the max memtable size is
set to. Overall read speed of the machine.

For most environments 1m is a few seconds to maybe 15-30 seconds.

What is your case for the above?

Wow, 1m events at a few - up to 30secs, makes these numbers quite bad.

At least 1min 15sec has passed and only ~400 k records processed.

Default memTable size.

It’s a standard A2 machine in azure, i.e. 2 cores (AMD Opteron 4171 HE I think?), 3.5 gb ram.

At the time of that log it was at 95-96% memory usage, which slows down everything, even though this readindex rebuild seems to be cpu heavy only.

After fixing that (moving up to 14gb ram) I had this: (actually got slower)

[PID:01340:019 2016.04.04 08:34:47.009 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 11493 records (1.2%).
[PID:01340:019 2016.04.04 08:34:52.010 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 40303 records (2.1%).
[PID:01340:019 2016.04.04 08:34:57.010 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 78973 records (3.3%).
[PID:01340:019 2016.04.04 08:34:59.556 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 100000 records (3.8%).
[PID:01340:019 2016.04.04 08:35:04.556 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 142956 records (4.6%).
[PID:01340:019 2016.04.04 08:35:09.557 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 170170 records (5.3%).
[PID:01340:004 2016.04.04 08:35:09.916 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49179, L10.1.0.4:1112, {a25e2fda-2124-4499-9e7e-bb6c8eabf161}].
[PID:01340:004 2016.04.04 08:35:09.994 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49180, L10.1.0.4:1112, {4ae023f1-fc5c-4b62-93da-d47ee2613568}].
[PID:01340:004 2016.04.04 08:35:12.791 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49185, L10.1.0.4:1112, {b04b8869-3ac8-4c8f-b117-d972cf9b7070}].
[PID:01340:019 2016.04.04 08:35:14.557 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 196669 records (6.1%).
[PID:01340:019 2016.04.04 08:35:15.041 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 200000 records (6.3%).
[PID:01340:004 2016.04.04 08:35:19.697 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49194, L10.1.0.4:1112, {caacacb6-7ed9-4500-a419-3de1c5ae1b9a}].
[PID:01340:019 2016.04.04 08:35:20.072 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 213705 records (7.1%).
[PID:01340:004 2016.04.04 08:35:21.854 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49195, L10.1.0.4:1112, {4be6459d-39c8-4c03-a694-1be60b9d4203}].
[PID:01340:019 2016.04.04 08:35:25.088 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 243099 records (8.3%).
[PID:01340:004 2016.04.04 08:35:26.636 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49201, L10.1.0.4:1112, {045bba49-7974-4b26-a486-77f05d97e8f5}].
[PID:01340:019 2016.04.04 08:35:30.166 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 244385 records (9.5%).
[PID:01340:004 2016.04.04 08:35:33.056 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49221, L10.1.0.4:1112, {ab532ec5-dc99-40cb-8d9a-d5fb5a86055d}].
[PID:01340:004 2016.04.04 08:35:35.166 INFO TcpService ] External TCP connection accepted: [Normal, 10.1.0.4:49226, L10.1.0.4:1112, {98f24663-78a7-4a99-8c5c-4af1a59dc6e5}].
[PID:01340:019 2016.04.04 08:35:35.181 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 245099 records (10.4%).
[PID:01340:019 2016.04.04 08:35:40.213 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 247679 records (12.5%).
[PID:01340:005 2016.04.04 08:35:43.775 TRACE TFChunk ] CACHED TFChunk #3-3 (chunk-000003.000000) in 00:01:04.2849471.
[PID:01340:019 2016.04.04 08:35:45.260 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 248914 records (13.8%).
[PID:01340:019 2016.04.04 08:35:50.369 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 250762 records (16.1%).
[PID:01340:019 2016.04.04 08:35:55.369 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 252726 records (18.1%).
[PID:01340:019 2016.04.04 08:36:00.369 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 254574 records (20.4%).
[PID:01340:019 2016.04.04 08:36:05.620 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 256649 records (22.7%).
[PID:01340:007 2016.04.04 08:36:07.813 TRACE TFChunk ] Verifying hash for TFChunk ‘E:\Data\Node1\db\chunk-000001.000000’…
[PID:01340:019 2016.04.04 08:36:10.664 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 257861 records (24.2%).
[PID:01340:022 2016.04.04 08:36:11.594 TRACE InMemoryBus ] SLOW BUS MSG [Worker #1 Bus]: AuthenticatedHttpRequestMessage - 215ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:01340:022 2016.04.04 08:36:11.594 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #1]: AuthenticatedHttpRequestMessage - 215ms. Q: 0/0.
[PID:01340:012 2016.04.04 08:36:13.008 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: Schedule - 63ms. Handler: TimerService.
[PID:01340:012 2016.04.04 08:36:13.008 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: Schedule - 63ms. Q: 5/5.
[PID:01340:014 2016.04.04 08:36:13.890 TRACE InMemoryBus ] SLOW BUS MSG [Worker #4 Bus]: AuthenticatedHttpRequestMessage - 332ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:01340:014 2016.04.04 08:36:13.890 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #4]: AuthenticatedHttpRequestMessage - 333ms. Q: 0/0.
[PID:01340:019 2016.04.04 08:36:15.669 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 258315 records (24.5%).
[PID:01340:019 2016.04.04 08:36:20.676 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 259497 records (24.6%).
[PID:01340:019 2016.04.04 08:36:25.682 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 261266 records (24.6%).
[PID:01340:019 2016.04.04 08:36:30.682 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 263753 records (24.7%).
[PID:01340:019 2016.04.04 08:36:35.683 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 266298 records (24.8%).
[PID:01340:019 2016.04.04 08:36:40.721 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 268546 records (24.8%).
[PID:01340:019 2016.04.04 08:36:45.725 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 270639 records (24.9%).
[PID:01340:024 2016.04.04 08:36:49.370 INFO TcpConnection ] ES TcpConnection closed [08:36:49.308: N10.1.0.4:49185, L10.1.0.4:1112, {b04b8869-3ac8-4c8f-b117-d972cf9b7070}]:Received bytes: 2425, Sent bytes: 594
[PID:01340:024 2016.04.04 08:36:49.370 INFO TcpConnection ] ES TcpConnection closed [08:36:49.370: N10.1.0.4:49185, L10.1.0.4:1112, {b04b8869-3ac8-4c8f-b117-d972cf9b7070}]:Send calls: 27, callbacks: 27
[PID:01340:024 2016.04.04 08:36:49.370 INFO TcpConnection ] ES TcpConnection closed [08:36:49.370: N10.1.0.4:49185, L10.1.0.4:1112, {b04b8869-3ac8-4c8f-b117-d972cf9b7070}]:Receive calls: 55, callbacks: 55
[PID:01340:024 2016.04.04 08:36:49.370 INFO TcpConnection ] ES TcpConnection closed [08:36:49.370: N10.1.0.4:49185, L10.1.0.4:1112, {b04b8869-3ac8-4c8f-b117-d972cf9b7070}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:024 2016.04.04 08:36:49.401 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49185, {b04b8869-3ac8-4c8f-b117-d972cf9b7070}] closed: ConnectionReset.
[PID:01340:021 2016.04.04 08:36:49.464 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49185
[PID:01340:004 2016.04.04 08:36:49.574 INFO TcpConnection ] ES TcpConnection closed [08:36:49.574: N10.1.0.4:49179, L10.1.0.4:1112, {a25e2fda-2124-4499-9e7e-bb6c8eabf161}]:Received bytes: 2464, Sent bytes: 594
[PID:01340:004 2016.04.04 08:36:49.574 INFO TcpConnection ] ES TcpConnection closed [08:36:49.574: N10.1.0.4:49179, L10.1.0.4:1112, {a25e2fda-2124-4499-9e7e-bb6c8eabf161}]:Send calls: 27, callbacks: 27
[PID:01340:004 2016.04.04 08:36:49.574 INFO TcpConnection ] ES TcpConnection closed [08:36:49.574: N10.1.0.4:49179, L10.1.0.4:1112, {a25e2fda-2124-4499-9e7e-bb6c8eabf161}]:Receive calls: 54, callbacks: 54
[PID:01340:004 2016.04.04 08:36:49.574 INFO TcpConnection ] ES TcpConnection closed [08:36:49.574: N10.1.0.4:49179, L10.1.0.4:1112, {a25e2fda-2124-4499-9e7e-bb6c8eabf161}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:004 2016.04.04 08:36:49.574 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49179, {a25e2fda-2124-4499-9e7e-bb6c8eabf161}] closed: ConnectionReset.
[PID:01340:013 2016.04.04 08:36:49.620 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49179
[PID:01340:004 2016.04.04 08:36:50.042 INFO TcpConnection ] ES TcpConnection closed [08:36:50.042: N10.1.0.4:49180, L10.1.0.4:1112, {4ae023f1-fc5c-4b62-93da-d47ee2613568}]:Received bytes: 2425, Sent bytes: 594
[PID:01340:004 2016.04.04 08:36:50.042 INFO TcpConnection ] ES TcpConnection closed [08:36:50.042: N10.1.0.4:49180, L10.1.0.4:1112, {4ae023f1-fc5c-4b62-93da-d47ee2613568}]:Send calls: 27, callbacks: 27
[PID:01340:004 2016.04.04 08:36:50.042 INFO TcpConnection ] ES TcpConnection closed [08:36:50.042: N10.1.0.4:49180, L10.1.0.4:1112, {4ae023f1-fc5c-4b62-93da-d47ee2613568}]:Receive calls: 54, callbacks: 54
[PID:01340:004 2016.04.04 08:36:50.042 INFO TcpConnection ] ES TcpConnection closed [08:36:50.042: N10.1.0.4:49180, L10.1.0.4:1112, {4ae023f1-fc5c-4b62-93da-d47ee2613568}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:004 2016.04.04 08:36:50.042 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49180, {4ae023f1-fc5c-4b62-93da-d47ee2613568}] closed: ConnectionReset.
[PID:01340:022 2016.04.04 08:36:50.042 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49180
[PID:01340:019 2016.04.04 08:36:50.792 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 271757 records (24.9%).
[PID:01340:004 2016.04.04 08:36:50.886 INFO TcpConnection ] ES TcpConnection closed [08:36:50.886: N10.1.0.4:49195, L10.1.0.4:1112, {4be6459d-39c8-4c03-a694-1be60b9d4203}]:Received bytes: 1236, Sent bytes: 528
[PID:01340:004 2016.04.04 08:36:50.901 INFO TcpConnection ] ES TcpConnection closed [08:36:50.901: N10.1.0.4:49195, L10.1.0.4:1112, {4be6459d-39c8-4c03-a694-1be60b9d4203}]:Send calls: 24, callbacks: 24
[PID:01340:004 2016.04.04 08:36:50.901 INFO TcpConnection ] ES TcpConnection closed [08:36:50.901: N10.1.0.4:49195, L10.1.0.4:1112, {4be6459d-39c8-4c03-a694-1be60b9d4203}]:Receive calls: 37, callbacks: 37
[PID:01340:004 2016.04.04 08:36:50.901 INFO TcpConnection ] ES TcpConnection closed [08:36:50.901: N10.1.0.4:49195, L10.1.0.4:1112, {4be6459d-39c8-4c03-a694-1be60b9d4203}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:004 2016.04.04 08:36:50.901 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49195, {4be6459d-39c8-4c03-a694-1be60b9d4203}] closed: ConnectionReset.
[PID:01340:022 2016.04.04 08:36:50.901 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49195
[PID:01340:004 2016.04.04 08:36:51.495 INFO TcpConnection ] ES TcpConnection closed [08:36:51.495: N10.1.0.4:49194, L10.1.0.4:1112, {caacacb6-7ed9-4500-a419-3de1c5ae1b9a}]:Received bytes: 2195, Sent bytes: 550
[PID:01340:004 2016.04.04 08:36:51.495 INFO TcpConnection ] ES TcpConnection closed [08:36:51.495: N10.1.0.4:49194, L10.1.0.4:1112, {caacacb6-7ed9-4500-a419-3de1c5ae1b9a}]:Send calls: 25, callbacks: 25
[PID:01340:004 2016.04.04 08:36:51.495 INFO TcpConnection ] ES TcpConnection closed [08:36:51.495: N10.1.0.4:49194, L10.1.0.4:1112, {caacacb6-7ed9-4500-a419-3de1c5ae1b9a}]:Receive calls: 49, callbacks: 49
[PID:01340:004 2016.04.04 08:36:51.495 INFO TcpConnection ] ES TcpConnection closed [08:36:51.495: N10.1.0.4:49194, L10.1.0.4:1112, {caacacb6-7ed9-4500-a419-3de1c5ae1b9a}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:004 2016.04.04 08:36:51.495 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49194, {caacacb6-7ed9-4500-a419-3de1c5ae1b9a}] closed: ConnectionReset.
[PID:01340:022 2016.04.04 08:36:51.526 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49194
[PID:01340:004 2016.04.04 08:36:51.980 INFO TcpConnection ] ES TcpConnection closed [08:36:51.980: N10.1.0.4:49201, L10.1.0.4:1112, {045bba49-7974-4b26-a486-77f05d97e8f5}]:Received bytes: 1214, Sent bytes: 506
[PID:01340:004 2016.04.04 08:36:51.980 INFO TcpConnection ] ES TcpConnection closed [08:36:51.980: N10.1.0.4:49201, L10.1.0.4:1112, {045bba49-7974-4b26-a486-77f05d97e8f5}]:Send calls: 23, callbacks: 23
[PID:01340:004 2016.04.04 08:36:51.980 INFO TcpConnection ] ES TcpConnection closed [08:36:51.980: N10.1.0.4:49201, L10.1.0.4:1112, {045bba49-7974-4b26-a486-77f05d97e8f5}]:Receive calls: 36, callbacks: 36
[PID:01340:004 2016.04.04 08:36:51.980 INFO TcpConnection ] ES TcpConnection closed [08:36:51.980: N10.1.0.4:49201, L10.1.0.4:1112, {045bba49-7974-4b26-a486-77f05d97e8f5}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:004 2016.04.04 08:36:51.980 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49201, {045bba49-7974-4b26-a486-77f05d97e8f5}] closed: ConnectionReset.
[PID:01340:022 2016.04.04 08:36:51.995 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49201
[PID:01340:004 2016.04.04 08:36:52.448 INFO TcpConnection ] ES TcpConnection closed [08:36:52.448: N10.1.0.4:49221, L10.1.0.4:1112, {ab532ec5-dc99-40cb-8d9a-d5fb5a86055d}]:Received bytes: 2479, Sent bytes: 396
[PID:01340:004 2016.04.04 08:36:52.448 INFO TcpConnection ] ES TcpConnection closed [08:36:52.448: N10.1.0.4:49221, L10.1.0.4:1112, {ab532ec5-dc99-40cb-8d9a-d5fb5a86055d}]:Send calls: 18, callbacks: 18
[PID:01340:004 2016.04.04 08:36:52.448 INFO TcpConnection ] ES TcpConnection closed [08:36:52.448: N10.1.0.4:49221, L10.1.0.4:1112, {ab532ec5-dc99-40cb-8d9a-d5fb5a86055d}]:Receive calls: 49, callbacks: 49
[PID:01340:004 2016.04.04 08:36:52.448 INFO TcpConnection ] ES TcpConnection closed [08:36:52.448: N10.1.0.4:49221, L10.1.0.4:1112, {ab532ec5-dc99-40cb-8d9a-d5fb5a86055d}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:004 2016.04.04 08:36:52.448 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49221, {ab532ec5-dc99-40cb-8d9a-d5fb5a86055d}] closed: ConnectionReset.
[PID:01340:006 2016.04.04 08:36:52.448 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49221
[PID:01340:004 2016.04.04 08:36:54.651 INFO TcpConnection ] ES TcpConnection closed [08:36:54.651: N10.1.0.4:49226, L10.1.0.4:1112, {98f24663-78a7-4a99-8c5c-4af1a59dc6e5}]:Received bytes: 1861, Sent bytes: 484
[PID:01340:004 2016.04.04 08:36:54.651 INFO TcpConnection ] ES TcpConnection closed [08:36:54.651: N10.1.0.4:49226, L10.1.0.4:1112, {98f24663-78a7-4a99-8c5c-4af1a59dc6e5}]:Send calls: 22, callbacks: 22
[PID:01340:004 2016.04.04 08:36:54.651 INFO TcpConnection ] ES TcpConnection closed [08:36:54.651: N10.1.0.4:49226, L10.1.0.4:1112, {98f24663-78a7-4a99-8c5c-4af1a59dc6e5}]:Receive calls: 44, callbacks: 44
[PID:01340:004 2016.04.04 08:36:54.651 INFO TcpConnection ] ES TcpConnection closed [08:36:54.651: N10.1.0.4:49226, L10.1.0.4:1112, {98f24663-78a7-4a99-8c5c-4af1a59dc6e5}]:Close reason: [ConnectionReset] Socket receive error
[PID:01340:004 2016.04.04 08:36:54.651 INFO TcpConnectionManager] Connection ‘external-normal’ [10.1.0.4:49226, {98f24663-78a7-4a99-8c5c-4af1a59dc6e5}] closed: ConnectionReset.
[PID:01340:006 2016.04.04 08:36:54.698 DEBUG PersistentSubscripti] Lost connection from 10.1.0.4:49226
[PID:01340:019 2016.04.04 08:36:55.792 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 273830 records (25.0%).
[PID:01340:019 2016.04.04 08:37:00.870 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 275366 records (25.0%).
[PID:01340:007 2016.04.04 08:37:04.011 TRACE TFChunk ] Verifying hash for TFChunk ‘E:\Data\Node1\db\chunk-000000.000000’…
[PID:01340:019 2016.04.04 08:37:05.105 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 300000 records (25.5%).
[PID:01340:012 2016.04.04 08:37:07.120 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: EventCommitted - 62ms. Handler: WideningHandler`2.
[PID:01340:012 2016.04.04 08:37:07.120 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: EventCommitted - 93ms. Q: 42/215.
[PID:01340:019 2016.04.04 08:37:10.105 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 380071 records (28.0%).
[PID:01340:019 2016.04.04 08:37:15.108 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 399053 records (33.0%).
[PID:01340:019 2016.04.04 08:37:16.249 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 400000 records (34.4%).
[PID:01340:019 2016.04.04 08:37:21.280 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 406201 records (40.9%).
[PID:01340:019 2016.04.04 08:37:26.280 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 411784 records (47.3%).

A striped set across 4 discs x 500 iops as a virtual disk, thin provisioning

"A striped set across 4 discs x 500 iops as a virtual disk, thin provisioning"

Assuming each read is one iop (which may or may not be true)

That means you would cap out at +- 1m/2k = 500 seconds

Perfectly logical, matches the numbers observed.

Okay, so we can decrease memTable size then. Would that give longer response times for the db? Any other effects to consider?

You will do index move to disk operations more often but they will be
smaller operations (100k at a time vs 1m) TBF 1m is a 16mb file (100k
will be +- 1.6mb). Shouldn't be an issue.

Thanks Greg.