Slow ReadIndex rebuild?

jarchin · April 4, 2016, 6:50am

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

jarchin · April 4, 2016, 7:19am

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”

Greg_Young1 · April 4, 2016, 7:22am

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?

jarchin · April 5, 2016, 10:32am

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

jarchin · April 5, 2016, 10:39am

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

Greg_Young1 · April 5, 2016, 10:45am

"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

jarchin · April 5, 2016, 11:20am

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?

Greg_Young1 · April 5, 2016, 11:22am

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.

jarchin · April 5, 2016, 1:03pm

Thanks Greg.