Hello,
It takes 36 min. for EventStore to startup.
Is it expected behavior?
We have 700GB of data.
We have one big stream with 350M messages.
EventStore is running on AWS c4.2xlagre vCPU=8;RAM=15GB
Data is on fastest SSD type io1 drive
[PID:01620:001 2016.02.18 18:47:09.850 INFO ProgramBase`1 ]
ES VERSION: 3.0.3.0 (master/a1382252dd1ed0554ddb04015cdb2cbc1b0a65c1, Fri, 13 Mar 2015 13:56:05 -0400)
OS: Windows (Microsoft Windows NT 6.2.9200.0)
RUNTIME: .NET 4.0.30319.34014 (64-bit)
GC: 3 GENERATIONS
LOGS: E:\es\logs
HELP: False (<DEFAULT>)
VERSION: False (<DEFAULT>)
LOG: <empty> (<DEFAULT>)
CONFIG: D:\es\config.yaml (Command Line)
DEFINES: <empty> (<DEFAULT>)
WHAT IF: False (<DEFAULT>)
INT IP: 127.0.0.1 (<DEFAULT>)
EXT IP: 0.0.0.0 (Config File)
INT HTTP PORT: 2112 (<DEFAULT>)
EXT HTTP PORT: 2113 (<DEFAULT>)
INT TCP PORT: 1112 (<DEFAULT>)
INT SECURE TCP PORT: 0 (<DEFAULT>)
EXT TCP PORT: 1113 (<DEFAULT>)
EXT SECURE TCP PORT: 0 (<DEFAULT>)
INT TCP HEARTBEAT TIMEOUT: 700 (<DEFAULT>)
EXT TCP HEARTBEAT TIMEOUT: 1000 (<DEFAULT>)
INT TCP HEARTBEAT INTERVAL: 700 (<DEFAULT>)
EXT TCP HEARTBEAT INTERVAL: 2000 (<DEFAULT>)
FORCE: False (<DEFAULT>)
CLUSTER SIZE: 1 (<DEFAULT>)
NODE PRIORITY: 0 (<DEFAULT>)
MIN FLUSH DELAY MS: 2 (<DEFAULT>)
COMMIT COUNT: -1 (<DEFAULT>)
PREPARE COUNT: -1 (<DEFAULT>)
ADMIN ON EXT: True (<DEFAULT>)
STATS ON EXT: True (<DEFAULT>)
GOSSIP ON EXT: True (<DEFAULT>)
DISABLE SCAVENGE MERGING: False (<DEFAULT>)
DISCOVER VIA DNS: True (<DEFAULT>)
CLUSTER DNS: fake.dns (<DEFAULT>)
CLUSTER GOSSIP PORT: 30777 (<DEFAULT>)
GOSSIP SEED: <empty> (<DEFAULT>)
STATS PERIOD SEC: 30 (<DEFAULT>)
CACHED CHUNKS: -1 (<DEFAULT>)
CHUNKS CACHE SIZE: 536871424 (<DEFAULT>)
MAX MEM TABLE SIZE: 1000000 (<DEFAULT>)
DB: E:\es\data (Config File)
MEM DB: False (<DEFAULT>)
SKIP DB VERIFY: False (<DEFAULT>)
RUN PROJECTIONS: All (Config File)
PROJECTION THREADS: 3 (<DEFAULT>)
WORKER THREADS: 5 (<DEFAULT>)
HTTP PREFIXES: [ http://*:2113/ ] (Config File)
ENABLE TRUSTED AUTH: False (<DEFAULT>)
CERTIFICATE STORE LOCATION: <empty> (<DEFAULT>)
CERTIFICATE STORE NAME: <empty> (<DEFAULT>)
CERTIFICATE SUBJECT NAME: <empty> (<DEFAULT>)
CERTIFICATE THUMBPRINT: <empty> (<DEFAULT>)
CERTIFICATE FILE: <empty> (<DEFAULT>)
CERTIFICATE PASSWORD: <empty> (<DEFAULT>)
USE INTERNAL SSL: False (<DEFAULT>)
SSL TARGET HOST: n/a (<DEFAULT>)
SSL VALIDATE SERVER: True (<DEFAULT>)
AUTHENTICATION TYPE: internal (<DEFAULT>)
PREPARE TIMEOUT MS: 2000 (<DEFAULT>)
COMMIT TIMEOUT MS: 2000 (<DEFAULT>)
UNSAFE DISABLE FLUSH TO DISK: False (<DEFAULT>)
GOSSIP INTERVAL MS: 1000 (<DEFAULT>)
GOSSIP ALLOWED DIFFERENCE MS: 60000 (<DEFAULT>)
GOSSIP TIMEOUT MS: 500 (<DEFAULT>)
[PID:01620:001 2016.02.18 18:47:09.970 INFO ProgramBase`1 ] Quorum size set to 1
[PID:01620:001 2016.02.18 18:47:10.000 INFO ProgramBase`1 ] Can't find plugins path: D:\es\plugins
[PID:01620:001 2016.02.18 18:47:10.021 INFO ProgramBase`1 ]
INSTANCE ID: 97dd7261-92b4-471c-ba77-e4f48fd81d99
DATABASE: E:\es\data
WRITER CHECKPOINT: 1247842021657 (0x122892E3119)
CHASER CHECKPOINT: 1247842021657 (0x122892E3119)
EPOCH CHECKPOINT: 566152726068 (0x83D1550634)
TRUNCATE CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)
[PID:01620:001 2016.02.18 18:47:10.467 TRACE MessageHierarchy ] MessageHierarchy initialization took 00:00:00.3509320.
[PID:01620:010 2016.02.18 18:53:45.707 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004646.000000'...
[PID:01620:001 2016.02.18 18:53:45.781 TRACE TFChunk ] CACHED TFChunk #4648-4648 (chunk-004648.000000) in 00:00:00.0849633.
[PID:01620:001 2016.02.18 18:53:46.214 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections ==> D:\es\projections
[PID:01620:001 2016.02.18 18:53:46.214 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> D:\es\Prelude
[PID:01620:001 2016.02.18 18:53:46.214 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/resources ==> D:\es\web-resources\js
[PID:01620:001 2016.02.18 18:53:46.214 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:01620:001 2016.02.18 18:53:46.214 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:01620:001 2016.02.18 18:53:46.214 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:01620:001 2016.02.18 18:53:46.235 INFO MiniWeb ] Starting MiniWeb for /web ==> D:\es\clusternode-web
[PID:01620:001 2016.02.18 18:53:46.235 TRACE MiniWeb ] Binding MiniWeb to /web/{*remaining_path}
[PID:01620:001 2016.02.18 18:53:46.271 INFO MiniWeb ] Starting MiniWeb for /web/users ==> D:\es\Users\web
[PID:01620:001 2016.02.18 18:53:46.271 TRACE MiniWeb ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:01620:016 2016.02.18 18:53:46.289 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] SYSTEM INIT...
[PID:01620:016 2016.02.18 18:53:46.308 INFO TcpServerListener ] Starting Normal TCP listening on TCP endpoint: 0.0.0.0:1113.
[PID:01620:021 2016.02.18 18:53:46.313 INFO IndexCommitter ] TableIndex initialization...
[PID:01620:016 2016.02.18 18:53:46.345 INFO HttpAsyncServer ] Starting HTTP server on [http://*:2113/]...
[PID:01620:016 2016.02.18 18:53:46.345 INFO HttpAsyncServer ] HTTP server is up and listening on [http://*:2113/]
[PID:01620:016 2016.02.18 18:53:46.345 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: SystemInit - 73ms. Q: 0/4.
[PID:01620:016 2016.02.18 18:53:46.345 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service 'StorageReader' initialized.
[PID:01620:016 2016.02.18 18:53:46.345 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service 'StorageWriter' initialized.
[PID:01620:021 2016.02.18 18:53:46.371 TRACE PTable ] Loading PTable 'aa8bb7f0-7729-4f32-bf85-1715c1ca6162' started...
[PID:01620:013 2016.02.18 18:53:46.644 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 335ms. Q: 0/0.
[PID:01620:009 2016.02.18 18:53:51.271 TRACE TFChunk ] CACHED TFChunk #4647-4647 (chunk-004647.000000) in 00:00:05.4879197.
[PID:01620:010 2016.02.18 18:53:58.911 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004645.000000'...
[PID:01620:010 2016.02.18 18:54:10.692 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004644.000000'...
[PID:01620:010 2016.02.18 18:54:22.591 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004643.000000'...
[PID:01620:021 2016.02.18 18:54:29.897 TRACE PTable ] Loading PTable 'aa8bb7f0-7729-4f32-bf85-1715c1ca6162' (32001566 entries, cache depth 16) done in 00:00:43.5265037.
[PID:01620:021 2016.02.18 18:54:29.897 TRACE PTable ] Verifying file hash of PTable 'aa8bb7f0-7729-4f32-bf85-1715c1ca6162' started...
[PID:01620:010 2016.02.18 18:54:34.689 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004642.000000'...
[PID:01620:010 2016.02.18 18:54:47.026 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004641.000000'...
[PID:01620:021 2016.02.18 18:54:49.361 TRACE PTable ] Verifying file hash of PTable 'aa8bb7f0-7729-4f32-bf85-1715c1ca6162' (32001566 entries) done in 00:00:19.4617880.
[PID:01620:021 2016.02.18 18:54:49.361 TRACE PTable ] Loading PTable '82958f64-8364-4d73-b533-a7005ca04c8c' started...
[PID:01620:010 2016.02.18 18:54:58.771 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004640.000000'...
[PID:01620:010 2016.02.18 18:55:11.526 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004639.000000'...
[PID:01620:010 2016.02.18 18:55:23.632 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004638.000000'...
[PID:01620:010 2016.02.18 18:55:35.623 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004637.000000'...
[PID:01620:010 2016.02.18 18:55:47.623 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004636.000000'...
[PID:01620:010 2016.02.18 18:55:59.459 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004635.000000'...
[PID:01620:010 2016.02.18 18:56:11.265 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004634.000000'...
[PID:01620:010 2016.02.18 18:56:22.969 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004633.000000'...
[PID:01620:022 2016.02.18 18:56:32.967 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:53211, L127.0.0.1:1113, {f8e065f5-7531-47df-b28f-348280d2896b}].
[PID:01620:022 2016.02.18 18:56:34.603 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:53225, L127.0.0.1:1113, {38742e7c-11fd-41f4-ace3-5d3e0055dace}].
[PID:01620:010 2016.02.18 18:56:34.739 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004632.000000'...
[PID:01620:022 2016.02.18 18:56:35.136 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:53231, L127.0.0.1:1113, {73867652-ad12-4ebb-a9a4-168903dba81b}].
[PID:01620:010 2016.02.18 18:56:45.191 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004631.000000'...
[PID:01620:010 2016.02.18 18:56:56.976 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004630.000000'...
[PID:01620:010 2016.02.18 18:57:08.673 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004629.000000'...
[PID:01620:010 2016.02.18 18:57:20.484 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004628.000000'...
[PID:01620:010 2016.02.18 18:57:32.789 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004627.000000'...
[PID:01620:010 2016.02.18 18:57:44.550 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004626.000000'...
[PID:01620:010 2016.02.18 18:57:56.127 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004625.000000'...
[PID:01620:010 2016.02.18 18:58:07.736 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004624.000000'...
[PID:01620:010 2016.02.18 18:58:19.399 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004623.000000'...
[PID:01620:010 2016.02.18 18:58:31.170 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004622.000000'...
[PID:01620:010 2016.02.18 18:58:42.900 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004621.000000'...
[PID:01620:010 2016.02.18 18:58:54.778 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004620.000000'...
[PID:01620:010 2016.02.18 18:59:06.465 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004619.000000'...
[PID:01620:010 2016.02.18 18:59:18.291 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004618.000000'...
[PID:01620:010 2016.02.18 18:59:30.054 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004617.000000'...
[PID:01620:010 2016.02.18 18:59:41.822 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004616.000000'...
[PID:01620:010 2016.02.18 18:59:53.457 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004615.000000'...
[PID:01620:025 2016.02.18 19:00:01.325 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:56854, L127.0.0.1:1113, {ff8a81ae-4ee9-4132-92ca-33c7868317ee}].
[PID:01620:010 2016.02.18 19:00:05.150 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004614.000000'...
[PID:01620:010 2016.02.18 19:00:16.963 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004613.000000'...
[PID:01620:010 2016.02.18 19:00:28.988 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004612.000000'...
[PID:01620:010 2016.02.18 19:00:41.062 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004611.000000'...
[PID:01620:010 2016.02.18 19:00:52.986 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004610.000000'...
[PID:01620:010 2016.02.18 19:01:04.953 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004609.000000'...
[PID:01620:010 2016.02.18 19:01:16.881 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004608.000000'...
[PID:01620:010 2016.02.18 19:01:28.843 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004607.000000'...
[PID:01620:010 2016.02.18 19:01:40.693 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004606.000000'...
[PID:01620:010 2016.02.18 19:01:52.680 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004605.000000'...
[PID:01620:010 2016.02.18 19:02:04.422 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004604.000000'...
[PID:01620:010 2016.02.18 19:02:16.284 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004603.000000'...
[PID:01620:010 2016.02.18 19:02:28.039 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004602.000000'...
[PID:01620:010 2016.02.18 19:02:39.981 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004601.000000'...
[PID:01620:010 2016.02.18 19:02:51.087 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004600.000000'...
[PID:01620:010 2016.02.18 19:03:01.849 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004599.000000'...
[PID:01620:010 2016.02.18 19:03:12.539 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004598.000000'...
[PID:01620:010 2016.02.18 19:03:24.678 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004597.000000'...
[PID:01620:010 2016.02.18 19:03:35.922 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004596.000000'...
[PID:01620:010 2016.02.18 19:03:47.120 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004595.000000'...
[PID:01620:010 2016.02.18 19:03:59.069 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004594.000000'...
[PID:01620:010 2016.02.18 19:04:10.969 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004593.000000'...
[PID:01620:010 2016.02.18 19:04:22.869 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004592.000000'...
[PID:01620:010 2016.02.18 19:04:34.671 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004591.000000'...
[PID:01620:010 2016.02.18 19:04:46.615 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004590.000000'...
[PID:01620:027 2016.02.18 19:04:55.091 INFO TcpConnection ] ES TcpConnection closed [19:04:55.078: N127.0.0.1:53211, L127.0.0.1:1113, {f8e065f5-7531-47df-b28f-348280d2896b}]:
Received bytes: 52316, Sent bytes: 24354
Send calls: 986, callbacks: 986
Receive calls: 951, callbacks: 951
Close reason: [Success] Socket closed
[PID:01620:027 2016.02.18 19:04:55.094 INFO TcpConnectionManager] Connection 'external-normal' [127.0.0.1:53211, {f8e065f5-7531-47df-b28f-348280d2896b}] closed: Success.
[PID:01620:010 2016.02.18 19:04:58.496 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004589.000000'...
[PID:01620:010 2016.02.18 19:05:10.402 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004588.000000'...
[PID:01620:010 2016.02.18 19:05:22.286 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004587.000000'...
[PID:01620:010 2016.02.18 19:05:34.216 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004586.000000'...
[PID:01620:010 2016.02.18 19:05:46.031 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004585.000000'...
[PID:01620:010 2016.02.18 19:05:57.904 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004584.000000'...
[PID:01620:010 2016.02.18 19:06:09.783 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004583.000000'...
[PID:01620:010 2016.02.18 19:06:21.684 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004582.000000'...
[PID:01620:010 2016.02.18 19:06:33.569 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004581.000000'...
[PID:01620:027 2016.02.18 19:06:40.387 INFO TcpConnection ] ES TcpConnection closed [19:06:40.387: N127.0.0.1:53231, L127.0.0.1:1113, {73867652-ad12-4ebb-a9a4-168903dba81b}]:
Received bytes: 36440, Sent bytes: 16312
Send calls: 689, callbacks: 689
Receive calls: 693, callbacks: 693
Close reason: [ConnectionReset] Socket receive error
[PID:01620:027 2016.02.18 19:06:40.387 INFO TcpConnectionManager] Connection 'external-normal' [127.0.0.1:53231, {73867652-ad12-4ebb-a9a4-168903dba81b}] closed: ConnectionReset.
[PID:01620:027 2016.02.18 19:06:43.970 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:58781, L127.0.0.1:1113, {d964261f-666c-4ac2-a2c1-5034a835c13c}].
[PID:01620:010 2016.02.18 19:06:45.477 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004580.000000'...
[PID:01620:027 2016.02.18 19:06:46.595 INFO TcpConnection ] ES TcpConnection closed [19:06:46.595: N127.0.0.1:53225, L127.0.0.1:1113, {38742e7c-11fd-41f4-ace3-5d3e0055dace}]:
Received bytes: 6424, Sent bytes: 6424
Send calls: 292, callbacks: 292
Receive calls: 293, callbacks: 293
Close reason: [Success] Socket closed
[PID:01620:027 2016.02.18 19:06:46.595 INFO TcpConnectionManager] Connection 'external-normal' [127.0.0.1:53225, {38742e7c-11fd-41f4-ace3-5d3e0055dace}] closed: Success.
[PID:01620:027 2016.02.18 19:06:48.703 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:58799, L127.0.0.1:1113, {15492031-0250-4c0a-bc25-144136b1b9c2}].
[PID:01620:010 2016.02.18 19:06:57.227 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004579.000000'...
[PID:01620:010 2016.02.18 19:07:09.223 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004578.000000'...
[PID:01620:025 2016.02.18 19:07:20.623 INFO TcpConnection ] ES TcpConnection closed [19:07:20.623: N127.0.0.1:56854, L127.0.0.1:1113, {ff8a81ae-4ee9-4132-92ca-33c7868317ee}]:
Received bytes: 296164, Sent bytes: 4686
Send calls: 212, callbacks: 212
Receive calls: 243, callbacks: 243
Close reason: [ConnectionReset] Socket receive error
[PID:01620:025 2016.02.18 19:07:20.623 INFO TcpConnectionManager] Connection 'external-normal' [127.0.0.1:56854, {ff8a81ae-4ee9-4132-92ca-33c7868317ee}] closed: ConnectionReset.
[PID:01620:010 2016.02.18 19:07:21.213 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004577.000000'...
[PID:01620:026 2016.02.18 19:07:26.890 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:59014, L127.0.0.1:1113, {2e62ef7b-2158-4d54-a6a1-2f58da45fe0a}].
[PID:01620:010 2016.02.18 19:07:32.949 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004576.000000'...
[PID:01620:010 2016.02.18 19:07:45.002 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004575.000000'...
[PID:01620:010 2016.02.18 19:07:57.173 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004574.000000'...
[PID:01620:010 2016.02.18 19:08:09.237 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004573.000000'...
[PID:01620:010 2016.02.18 19:08:21.237 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004572.000000'...
[PID:01620:010 2016.02.18 19:08:33.120 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004571.000000'...
[PID:01620:010 2016.02.18 19:08:45.127 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004570.000000'...
[PID:01620:010 2016.02.18 19:08:56.865 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004569.000000'...
[PID:01620:010 2016.02.18 19:09:08.635 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004568.000000'...
[PID:01620:010 2016.02.18 19:09:20.547 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004567.000000'...
[PID:01620:010 2016.02.18 19:09:32.260 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004566.000000'...
[PID:01620:010 2016.02.18 19:09:44.076 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004565.000000'...
[PID:01620:010 2016.02.18 19:09:56.067 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004564.000000'...
[PID:01620:010 2016.02.18 19:10:08.059 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004563.000000'...
[PID:01620:010 2016.02.18 19:10:19.956 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004562.000000'...
[PID:01620:010 2016.02.18 19:10:31.931 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004561.000000'...
[PID:01620:010 2016.02.18 19:10:43.943 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004560.000000'...
[PID:01620:010 2016.02.18 19:10:55.977 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004559.000000'...
[PID:01620:010 2016.02.18 19:11:08.046 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004558.000000'...
[PID:01620:010 2016.02.18 19:11:19.983 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004557.000000'...
[PID:01620:010 2016.02.18 19:11:37.040 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004556.000000'...
[PID:01620:010 2016.02.18 19:11:50.018 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004555.000000'...
[PID:01620:010 2016.02.18 19:12:01.735 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004554.000000'...
[PID:01620:010 2016.02.18 19:12:13.559 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004553.000000'...
[PID:01620:010 2016.02.18 19:12:25.296 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004552.000000'...
[PID:01620:010 2016.02.18 19:12:37.226 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004551.000000'...
[PID:01620:010 2016.02.18 19:12:50.007 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004550.000000'...
[PID:01620:021 2016.02.18 19:12:55.874 TRACE PTable ] Loading PTable '82958f64-8364-4d73-b533-a7005ca04c8c' (863320166 entries, cache depth 16) done in 00:18:06.5105084.
[PID:01620:021 2016.02.18 19:12:55.874 TRACE PTable ] Verifying file hash of PTable '82958f64-8364-4d73-b533-a7005ca04c8c' started...
[PID:01620:010 2016.02.18 19:13:01.904 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004549.000000'...
[PID:01620:010 2016.02.18 19:13:13.159 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004548.000000'...
[PID:01620:010 2016.02.18 19:13:24.377 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004547.000000'...
[PID:01620:010 2016.02.18 19:13:35.406 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004546.000000'...
[PID:01620:010 2016.02.18 19:13:46.611 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004545.000000'...
[PID:01620:010 2016.02.18 19:13:57.881 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004544.000000'...
[PID:01620:010 2016.02.18 19:14:08.957 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004543.000000'...
[PID:01620:010 2016.02.18 19:14:20.163 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004542.000000'...
[PID:01620:010 2016.02.18 19:14:31.424 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004541.000000'...
[PID:01620:010 2016.02.18 19:14:42.667 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004540.000000'...
[PID:01620:010 2016.02.18 19:14:54.071 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004539.000000'...
[PID:01620:010 2016.02.18 19:15:05.501 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004538.000000'...
[PID:01620:010 2016.02.18 19:15:16.593 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004537.000000'...
[PID:01620:010 2016.02.18 19:15:27.670 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004536.000000'...
[PID:01620:010 2016.02.18 19:15:38.923 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004535.000000'...
[PID:01620:010 2016.02.18 19:15:50.137 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004534.000000'...
[PID:01620:010 2016.02.18 19:16:01.364 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004533.000000'...
[PID:01620:010 2016.02.18 19:16:12.437 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004532.000000'...
[PID:01620:010 2016.02.18 19:16:23.665 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004531.000000'...
[PID:01620:010 2016.02.18 19:16:34.826 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004530.000000'...
[PID:01620:010 2016.02.18 19:16:45.844 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004529.000000'...
[PID:01620:010 2016.02.18 19:16:56.854 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004528.000000'...
[PID:01620:010 2016.02.18 19:17:08.121 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004527.000000'...
[PID:01620:010 2016.02.18 19:17:19.320 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004526.000000'...
[PID:01620:010 2016.02.18 19:17:31.055 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004525.000000'...
[PID:01620:010 2016.02.18 19:17:41.960 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004524.000000'...
[PID:01620:010 2016.02.18 19:17:53.093 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004523.000000'...
[PID:01620:010 2016.02.18 19:18:05.147 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004522.000000'...
[PID:01620:010 2016.02.18 19:18:16.326 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004521.000000'...
[PID:01620:010 2016.02.18 19:18:27.353 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004520.000000'...
[PID:01620:010 2016.02.18 19:18:38.458 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004519.000000'...
[PID:01620:010 2016.02.18 19:18:49.640 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004518.000000'...
[PID:01620:010 2016.02.18 19:19:00.842 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004517.000000'...
[PID:01620:010 2016.02.18 19:19:11.938 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004516.000000'...
[PID:01620:010 2016.02.18 19:19:23.188 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004515.000000'...
[PID:01620:010 2016.02.18 19:19:34.414 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004514.000000'...
[PID:01620:010 2016.02.18 19:19:45.627 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004513.000000'...
[PID:01620:010 2016.02.18 19:19:56.600 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004512.000000'...
[PID:01620:010 2016.02.18 19:20:07.648 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004511.000000'...
[PID:01620:010 2016.02.18 19:20:18.875 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004510.000000'...
[PID:01620:010 2016.02.18 19:20:30.115 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004509.000000'...
[PID:01620:010 2016.02.18 19:20:41.197 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004508.000000'...
[PID:01620:010 2016.02.18 19:20:53.327 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004507.000000'...
[PID:01620:010 2016.02.18 19:21:04.888 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004506.000000'...
[PID:01620:010 2016.02.18 19:21:16.132 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004505.000000'...
[PID:01620:010 2016.02.18 19:21:27.448 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004504.000000'...
[PID:01620:010 2016.02.18 19:21:38.818 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004503.000000'...
[PID:01620:010 2016.02.18 19:21:50.074 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004502.000000'...
[PID:01620:010 2016.02.18 19:22:01.223 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004501.000000'...
[PID:01620:010 2016.02.18 19:22:12.362 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004500.000000'...
[PID:01620:010 2016.02.18 19:22:23.366 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004499.000000'...
[PID:01620:021 2016.02.18 19:22:33.753 TRACE PTable ] Verifying file hash of PTable '82958f64-8364-4d73-b533-a7005ca04c8c' (863320166 entries) done in 00:09:37.8789672.
[PID:01620:021 2016.02.18 19:22:33.753 INFO IndexCommitter ] ReadIndex building...
[PID:01620:010 2016.02.18 19:22:34.484 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004498.000000'...
[PID:01620:021 2016.02.18 19:22:38.763 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 30524 records (6.8%).
[PID:01620:021 2016.02.18 19:22:43.764 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 60651 records (12.0%).
[PID:01620:010 2016.02.18 19:22:46.578 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004497.000000'...
[PID:01620:021 2016.02.18 19:22:48.765 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 91239 records (15.8%).
[PID:01620:021 2016.02.18 19:22:49.801 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 100000 records (16.5%).
[PID:01620:021 2016.02.18 19:22:54.802 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 133738 records (19.9%).
[PID:01620:010 2016.02.18 19:22:58.423 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004496.000000'...
[PID:01620:021 2016.02.18 19:22:59.803 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 166427 records (23.5%).
[PID:01620:021 2016.02.18 19:23:04.804 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 198250 records (27.1%).
[PID:01620:021 2016.02.18 19:23:05.076 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 200000 records (27.3%).
[PID:01620:021 2016.02.18 19:23:10.077 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 233745 records (33.0%).
[PID:01620:010 2016.02.18 19:23:10.171 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004495.000000'...
[PID:01620:021 2016.02.18 19:23:15.078 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 265309 records (38.7%).
[PID:01620:021 2016.02.18 19:23:20.080 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 296525 records (45.4%).
[PID:01620:021 2016.02.18 19:23:20.888 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 300000 records (46.2%).
[PID:01620:010 2016.02.18 19:23:22.028 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004494.000000'...
[PID:01620:021 2016.02.18 19:23:25.889 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 331455 records (51.4%).
[PID:01620:021 2016.02.18 19:23:30.889 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 363733 records (55.0%).
[PID:01620:010 2016.02.18 19:23:33.970 TRACE TFChunk ] Verifying hash for TFChunk 'E:\es\data\chunk-004493.000000'...
[PID:01620:021 2016.02.18 19:23:34.764 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 400000 records (59.3%).
[PID:01620:021 2016.02.18 19:23:35.194 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 500000 records (75.9%).
[PID:01620:021 2016.02.18 19:23:35.673 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 600000 records (92.2%).
[PID:01620:021 2016.02.18 19:23:35.953 DEBUG IndexCommitter ] ReadIndex rebuilding done: total processed 663786 records, time elapsed: 00:01:02.1933606.
[PID:01620:016 2016.02.18 19:23:35.990 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service 'StorageChaser' initialized.
[PID:01620:016 2016.02.18 19:23:35.990 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] SYSTEM START...
[PID:01620:016 2016.02.18 19:23:35.990 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] IS UNKNOWN!!! WHOA!!!
[PID:01620:016 2016.02.18 19:23:36.020 DEBUG ElectionsService ] ELECTIONS: STARTING ELECTIONS.
[PID:01620:016 2016.02.18 19:23:36.020 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[PID:01620:016 2016.02.18 19:23:36.020 DEBUG ElectionsService ] ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:2112, {97dd7261-92b4-471c-ba77-e4f48fd81d99}].
[PID:01620:016 2016.02.18 19:23:36.037 DEBUG ElectionsService ] ELECTIONS: (V=0) MAJORITY OF VIEWCHANGE.
[PID:01620:016 2016.02.18 19:23:36.037 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO PREPARE PHASE.
[PID:01620:016 2016.02.18 19:23:36.037 DEBUG ElectionsService ] ELECTIONS: (V=0) PREPARE_OK FROM [127.0.0.1:2112,{97dd7261-92b4-471c-ba77-e4f48fd81d99}](L=1247842020978,W=1247842021657,C=1247842021657,E7@566152726068:{89371a51-1dd7-4623-b962-5b5c470af0dd}).
[PID:01620:016 2016.02.18 19:23:36.037 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO REG_LEADER.
[PID:01620:016 2016.02.18 19:23:36.063 DEBUG ElectionsService ] ELECTIONS: (V=0) SENDING PROPOSAL CANDIDATE: [127.0.0.1:2112,{97dd7261-92b4-471c-ba77-e4f48fd81d99}](L=1247842020978,W=1247842021657,C=1247842021657,E7@566152726068:{89371a51-1dd7-4623-b962-5b5c470af0dd}), ME: [127.0.0.1:2112,{97dd7261-92b4-471c-ba77-e4f48fd81d99}](L=1247842020978,W=1247842021657,C=1247842021657,E7@566152726068:{89371a51-1dd7-4623-b962-5b5c470af0dd}).
[PID:01620:016 2016.02.18 19:23:36.063 DEBUG ElectionsService ] ELECTIONS: (V=0) ACCEPT FROM [127.0.0.1:2112,{97dd7261-92b4-471c-ba77-e4f48fd81d99}] M=[127.0.0.1:2112,{97dd7261-92b4-471c-ba77-e4f48fd81d99}]).
[PID:01620:016 2016.02.18 19:23:36.063 INFO ElectionsService ] ELECTIONS: (V=0) DONE. ELECTED MASTER = [127.0.0.1:2112,{97dd7261-92b4-471c-ba77-e4f48fd81d99}](L=1247842020978,W=1247842021657,C=1247842021657,E7@566152726068:{89371a51-1dd7-4623-b962-5b5c470af0dd}). ME=[127.0.0.1:2112,{97dd7261-92b4-471c-ba77-e4f48fd81d99}](L=1247842020978,W=1247842021657,C=1247842021657,E7@566152726068:{89371a51-1dd7-4623-b962-5b5c470af0dd}).
[PID:01620:016 2016.02.18 19:23:36.079 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: StartElections - 73ms. Handler: ElectionsService.
[PID:01620:016 2016.02.18 19:23:36.079 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: StartElections - 89ms. Q: 0/5.
[PID:01620:016 2016.02.18 19:23:36.079 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP...
[PID:01620:016 2016.02.18 19:23:36.095 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] IS MASTER!!! SPARTA!!!
[PID:01620:017 2016.02.18 19:23:36.164 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: Starting - 64ms. Handler: ProjectionManagerResponseReader.
[PID:01620:017 2016.02.18 19:23:36.164 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: Starting - 65ms. Q: 0/1.
[PID:01620:020 2016.02.18 19:23:36.181 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 71ms. Handler: ProjectionCoreServiceCommandReader.
[PID:01620:020 2016.02.18 19:23:36.181 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #2]: StartCore - 72ms. Q: 1/4.
[PID:01620:018 2016.02.18 19:23:36.181 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 72ms. Handler: ProjectionCoreServiceCommandReader.
[PID:01620:018 2016.02.18 19:23:36.181 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: StartCore - 72ms. Q: 1/4.
[PID:01620:019 2016.02.18 19:23:36.181 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 72ms. Handler: ProjectionCoreServiceCommandReader.
[PID:01620:019 2016.02.18 19:23:36.181 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: StartCore - 72ms. Q: 1/4.
[PID:01620:014 2016.02.18 19:23:36.233 DEBUG EpochManager ] === Writing E8@1247842021657:{346620bb-2263-4a27-98a2-6f5bc6d9512e} (previous epoch at 566152726068).
[PID:01620:014 2016.02.18 19:23:36.246 DEBUG EpochManager ] === Update Last Epoch E8@1247842021657:{346620bb-2263-4a27-98a2-6f5bc6d9512e} (previous epoch at 566152726068).
[PID:01620:011 2016.02.18 19:23:36.328 TRACE MonitoringService ] Created stats stream '$stats-0.0.0.0:2113', code = WrongExpectedVersion
[PID:01620:017 2016.02.18 19:23:36.442 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: ReadStreamEventsBackwardCompleted - 68ms. Handler: ProjectionManager.
[PID:01620:017 2016.02.18 19:23:36.442 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: ReadStreamEventsBackwardCompleted - 68ms. Q: 1/12.
[PID:01620:020 2016.02.18 19:23:36.555 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CreatePrepared - 57ms. Handler: ProjectionCoreService.
[PID:01620:020 2016.02.18 19:23:36.555 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #2]: CreatePrepared - 57ms. Q: 7/10.
[PID:01620:018 2016.02.18 19:23:36.688 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CreateAndPrepare - 207ms. Handler: ProjectionCoreService.
[PID:01620:018 2016.02.18 19:23:36.688 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CreateAndPrepare - 207ms. Q: 1/6.
[PID:01620:019 2016.02.18 19:23:36.688 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CreateAndPrepare - 191ms. Handler: ProjectionCoreService.
[PID:01620:019 2016.02.18 19:23:36.688 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: CreateAndPrepare - 191ms. Q: 1/6.
[PID:01620:018 2016.02.18 19:23:36.775 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CheckpointLoaded - 54ms. Handler: ProjectionCoreService.
[PID:01620:018 2016.02.18 19:23:36.775 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CheckpointLoaded - 54ms. Q: 5/9.
[PID:01620:019 2016.02.18 19:23:36.897 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CheckpointLoaded - 79ms. Handler: ProjectionCoreService.
[PID:01620:019 2016.02.18 19:23:36.897 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: CheckpointLoaded - 79ms. Q: 258/261.
[PID:01620:019 2016.02.18 19:23:37.253 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CoreTick - 50ms. Handler: ProjectionCoreService.
[PID:01620:019 2016.02.18 19:23:37.253 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: CoreTick - 50ms. Q: 6/9.
[PID:01620:019 2016.02.18 19:23:37.722 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CoreTick - 83ms. Handler: ProjectionCoreService.
``