Update to v2 and Standard Projections

Jeremie_Chassaing · July 22, 2013, 4:41pm

Hi,

I’m currently testing upgrade from v1 to v2…

When upgrading to v2, all existing Standard projections disapear ($by_category, $by_event_yype, $stream_by_category, $streams)…

I tried to create new one using the ‘You can also post a standard projection’ link (I found I should pass ‘-’ as source since my quetion on twitter…)

But the projection fails…

The problem is also that I already have loads of events in categories, and restarting categories from scratch would surely duplicate events…

So the question is: how to I get old standard projections to be upgraded to v2 ?

Cheers,

jeremie / thinkbeforecoding

Joao_Braganca · July 22, 2013, 4:46pm

Are the projections enabled? or they don’t even show up in the list?

Greg_Young1 · July 22, 2013, 4:52pm

This is a change in the command line I'll update docs. Try --run-projections=all

Greg

Jeremie_Chassaing · July 22, 2013, 5:00pm

They don't show up in the ui at all...

Jeremie_Chassaing · July 22, 2013, 5:02pm

There's only $users..

Greg_Young1 · July 22, 2013, 5:12pm

I have them on master running with --run-projections=all

Greg

Jeremie_Chassaing · July 22, 2013, 5:31pm

Ok i'll try that

Jeremie_Chassaing · July 22, 2013, 6:34pm

Btw, what do the different options for --run-projections mean, and why did the projection not appear ?

jeremie / thinkbeforecoding

Greg_Young1 · July 22, 2013, 6:35pm

All none system

Users is an internal projection that is on by default.

Yuri_Solodkyy · July 22, 2013, 7:58pm

Jeremie,

Even with default option which is “system” you should see all the projections on the list. However, they won’t start. You should see “stopped (enabled)” status instead.

Could you make sure that your browser does not cache some old script? Let me know if you only see $users projection as it is not the indented behavior.

Joao_Braganca · July 22, 2013, 8:31pm

Doh, I’ve been running with --run-projections=1 not sure why that worked

Jeremie_Chassaing · July 23, 2013, 3:37pm

I did the test, and I still have no sign of standard projections except the ne $users, either by ui or using the rest interface (through my PS cmdlets)…

They don’t appear at all.

Though, the projection declaration stream still exist… for instance:

$projections-$stream_by_category contains two events (after the $stream-created-implicit)) :

No 1:
Type: ProjectionUpdated

{
  "handlerType": "native:EventStore.Projections.Core.Standard.CategorizeStreamByPath",
  "query": "-",
  "mode": 4,
  "enabled": false,
  "deleted": false,
  "sourceDefintion": {
    "allEvents": true,
    "allStreams": true,
    "byStream": false,
    "byCustomPartitions": false,
    "categories": [],
    "events": [],
    "streams": [],
    "options": {
      "useEventIndexes": false,
      "reorderEvents": false,
      "processingLag": 0,
      "emitStateUpdated": false
    }
  },
  "emitEnabled": true,
  "checkpointsDisabled": false
}

No 2:

Type: ProjectionUpdated:

{
  "handlerType": "native:EventStore.Projections.Core.Standard.CategorizeStreamByPath",
  "query": "-",
  "mode": 4,
  "enabled": true,
  "deleted": false,
  "sourceDefintion": {
    "allEvents": true,
    "allStreams": true,
    "byStream": false,
    "byCustomPartitions": false,
    "categories": [],
    "events": [],
    "streams": [],
    "options": {
      "useEventIndexes": false,
      "reorderEvents": false,
      "processingLag": 0,
      "emitStateUpdated": false
    }
  },
  "emitEnabled": true,
  "checkpointsDisabled": false
}

But no sign of this projection… and it doesn’t seem to be running either since new events don’t show up in $ce-… streams…

jeremie / thinkbeforecoding

Jeremie_Chassaing · July 23, 2013, 3:43pm

I also noticed this:

[00048,17,14:49:57.743] Projection manager is initializing from the empty $projections-$all stream

… why is the $projection-$all stream empty ??

would this have anything to do with the fact the at this point the index has not yet been build ??!

Full start log:

[PID:04488:001 2013.07.23 08:39:40.902 INFO ProgramBase`1 ]
ES VERSION: 2.0.0.0 (master/f84a4bbeef5f329893c83969dc2a86f279c04154, Fri, 19 Jul 2013 19:32:39 +0100)
OS: Windows (Microsoft Windows NT 6.2.9200.0)
RUNTIME: .NET 4.0.30319.18051 (64-bit)
GC: 3 GENERATIONS
LOGS: C:\Data\Logs

SHOW HELP: False ()
SHOW VERSION: False ()
LOGS DIR: C:\Data\Logs (–logsdir from command line)
CONFIGS: ()
DEFINES: ()
IP: 127.0.0.1 ()
TCP PORT: 1113 ()
SECURE TCP PORT: 0 ()
HTTP PORT: 2113 ()
STATS PERIOD SEC: 30 ()
CACHED CHUNKS: -1 ()
CHUNKS CACHE SIZE: 536871424 ()
MIN FLUSH DELAY MS: 2 ()
DB PATH: C:\Data\Events (–db from command line)
SKIP DB VERIFY: False ()
RUN PROJECTIONS: All (–run-projections from command line)
PROJECTION THREADS: 3 ()
WORKER THREADS: 5 ()
HTTP PREFIXES: ()
ENABLE TRUSTED AUTH: False ()
CERTIFICATE STORE: ()
CERTIFICATE NAME: ()
CERTIFICATE FILE: ()
CERTIFICATE PASSWORD: ()
PREPARE TIMEOUT MS: 2000 ()
COMMIT TIMEOUT MS: 2000 ()

[PID:04488:001 2013.07.23 08:39:41.043 INFO ProgramBase`1 ]
DATABASE: C:\Data\Events
WRITER CHECKPOINT: 145981558 (0x8B38076)
CHASER CHECKPOINT: 145981558 (0x8B38076)
EPOCH CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)
TRUNCATE CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)

[PID:04488:001 2013.07.23 08:39:41.214 TRACE MessageHierarchy ] MessageHierarchy initialization took 00:00:00.0984623.
[PID:04488:001 2013.07.23 08:39:41.901 TRACE TFChunk ] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0976639.
[PID:04488:001 2013.07.23 08:39:42.244 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections ==> C:\Program Files\EventStore\EventStore 2\singlenode-web\js\projections
[PID:04488:001 2013.07.23 08:39:42.244 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> C:\Program Files\EventStore\EventStore 2\Prelude
[PID:04488:001 2013.07.23 08:39:42.244 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/resources ==> C:\Program Files\EventStore\EventStore 2\web-resources\js
[PID:04488:001 2013.07.23 08:39:42.244 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:04488:001 2013.07.23 08:39:42.244 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:04488:001 2013.07.23 08:39:42.244 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:04488:001 2013.07.23 08:39:42.244 INFO MiniWeb ] Starting MiniWeb for /web ==> C:\Program Files\EventStore\EventStore 2\singlenode-web
[PID:04488:001 2013.07.23 08:39:42.244 INFO MiniWeb ] Starting MiniWeb for /web/es ==> C:\Program Files\EventStore\EventStore 2\es-common-web
[PID:04488:001 2013.07.23 08:39:42.260 TRACE MiniWeb ] Binding MiniWeb to /web/{*remaining_path}
[PID:04488:001 2013.07.23 08:39:42.260 TRACE MiniWeb ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:04488:001 2013.07.23 08:39:42.260 INFO MiniWeb ] Starting MiniWeb for /web/users ==> C:\Program Files\EventStore\EventStore 2\Users\web
[PID:04488:001 2013.07.23 08:39:42.260 TRACE MiniWeb ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:04488:012 2013.07.23 08:39:42.275 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] SYSTEM INIT…
[PID:04488:012 2013.07.23 08:39:42.306 INFO TcpServerListener ] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.
[PID:04488:010 2013.07.23 08:39:42.338 INFO ReadIndex ] TableIndex initialization…
[PID:04488:010 2013.07.23 08:39:42.353 INFO ReadIndex ] ReadIndex building…
[PID:04488:012 2013.07.23 08:39:42.353 INFO HttpAsyncServer ] Starting HTTP server on [http://127.0.0.1:2113/]…
[PID:04488:012 2013.07.23 08:39:42.353 INFO HttpAsyncServer ] HTTP server is up and listening on [http://127.0.0.1:2113/]
[PID:04488:012 2013.07.23 08:39:42.369 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: SystemInit - 93ms. Q: 0/3.
[PID:04488:013 2013.07.23 08:39:42.696 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 405ms. Q: 0/0.
[PID:04488:010 2013.07.23 08:39:42.977 DEBUG ReadIndex ] ReadIndex Rebuilding Done: total processed 88174 records, time elapsed: 00:00:00.6239979.
[PID:04488:010 2013.07.23 08:39:42.993 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [StorageWriterQueue]: SystemInit - 702ms. Q: 0/0.
[PID:04488:012 2013.07.23 08:39:42.993 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] SYSTEM START…
[PID:04488:012 2013.07.23 08:39:42.993 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP…
[PID:04488:012 2013.07.23 08:39:42.993 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] IS WORKING!!! SPARTA!!!
[PID:04488:014 2013.07.23 08:39:43.086 INFO ProjectionManager ] Projection manager is initializing from the empty $projections-$all stream
[PID:04488:010 2013.07.23 08:39:43.227 DEBUG EpochManager ] === Writing E0@145981558:{d21e0bfe-be11-4473-bff2-408b1f75dc7c} (previous epoch at -1).
[PID:04488:010 2013.07.23 08:39:43.258 DEBUG EpochManager ] === Update Last Epoch E0@145981558:{d21e0bfe-be11-4473-bff2-408b1f75dc7c} (previous epoch at -1).
[PID:04488:013 2013.07.23 08:39:43.710 TRACE MonitoringService ] Created stats stream ‘$stats-127.0.0.1:2113’, code = Success
[PID:04488:012 2013.07.23 08:39:43.835 INFO UserManagementServic] ‘admin’ user account has been created
[PID:04488:014 2013.07.23 08:39:43.929 INFO ProjectionManager ] ‘$users’ projection source has been written
[PID:04488:015 2013.07.23 08:39:43.991 TRACE EventReorderingReade] Creating an event distribution point at 'C:0/P:-1; $UserCreated: -1; ’
[PID:04488:015 2013.07.23 08:39:44.022 TRACE ProjectionCoreServic] The ‘7d3779f9-eb59-44c2-83fb-074466f1382a’ projection subscribed to the ‘3553e409-9247-41c2-8c5f-db4b0e1ff49a’ distribution point
[PID:04488:015 2013.07.23 08:39:44.054 TRACE InMemoryBus ] SLOW BUS MSG [bus]: Subscribe - 62ms. Handler: EventReaderCoreService.
[PID:04488:015 2013.07.23 08:39:44.054 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: Subscribe - 93ms. Q: 2/7.
[PID:04488:015 2013.07.23 08:39:44.912 TRACE HeadingEventReader ] The ‘7d3779f9-eb59-44c2-83fb-074466f1382a’ subscription has joined the heading distribution point at ‘145982396’
[PID:04488:015 2013.07.23 08:39:44.927 TRACE HeadingEventReader ] The ‘7d3779f9-eb59-44c2-83fb-074466f1382a’ projection subscribed to the ‘107d02c8-beca-4106-accc-4453322779fb’ heading distribution point
[PID:04488:015 2013.07.23 08:39:45.021 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CoreTick - 77ms. Handler: ProjectionCoreService.
[PID:04488:015 2013.07.23 08:39:45.021 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CoreTick - 77ms. Q: 0/4.
[PID:00048:001 2013.07.23 14:03:52.819 INFO ProgramBase`1 ]
ES VERSION: 2.0.0.0 (master/f84a4bbeef5f329893c83969dc2a86f279c04154, Fri, 19 Jul 2013 19:32:39 +0100)
OS: Windows (Microsoft Windows NT 6.2.9200.0)
RUNTIME: .NET 4.0.30319.18051 (64-bit)
GC: 3 GENERATIONS
LOGS: C:\Data\Logs

SHOW HELP: False ()
SHOW VERSION: False ()
LOGS DIR: C:\Data\Logs (–logsdir from command line)
CONFIGS: ()
DEFINES: ()
IP: 127.0.0.1 ()
TCP PORT: 1113 ()
SECURE TCP PORT: 0 ()
HTTP PORT: 2113 ()
STATS PERIOD SEC: 30 ()
CACHED CHUNKS: -1 ()
CHUNKS CACHE SIZE: 536871424 ()
MIN FLUSH DELAY MS: 2 ()
DB PATH: C:\Data\Events (–db from command line)
SKIP DB VERIFY: False ()
RUN PROJECTIONS: All (–run-projections from command line)
PROJECTION THREADS: 3 ()
WORKER THREADS: 5 ()
HTTP PREFIXES: ()
ENABLE TRUSTED AUTH: False ()
CERTIFICATE STORE: ()
CERTIFICATE NAME: ()
CERTIFICATE FILE: ()
CERTIFICATE PASSWORD: ()
PREPARE TIMEOUT MS: 2000 ()
COMMIT TIMEOUT MS: 2000 ()

[PID:00048:001 2013.07.23 14:03:52.961 INFO ProgramBase`1 ]
DATABASE: C:\Data\Events
WRITER CHECKPOINT: 11396227149 (0x2A744A04D)
CHASER CHECKPOINT: 11396227149 (0x2A744A04D)
EPOCH CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)
TRUNCATE CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)

[PID:00048:001 2013.07.23 14:03:53.852 TRACE MessageHierarchy ] MessageHierarchy initialization took 00:00:00.8255439.
[PID:00048:008 2013.07.23 14:04:02.203 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000040.000001’…
[PID:00048:001 2013.07.23 14:04:02.262 TRACE TFChunk ] CACHED TFChunk #42-42 (chunk-000042.000000) in 00:00:00.0793982.
[PID:00048:007 2013.07.23 14:04:02.432 TRACE TFChunk ] CACHED TFChunk #41-41 (chunk-000041.000001) in 00:00:00.1691265.
[PID:00048:008 2013.07.23 14:04:03.083 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000039.000001’…
[PID:00048:008 2013.07.23 14:04:03.936 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000038.000001’…
[PID:00048:008 2013.07.23 14:04:04.805 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000037.000001’…
[PID:00048:008 2013.07.23 14:04:05.643 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000036.000001’…
[PID:00048:008 2013.07.23 14:04:06.487 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000035.000001’…
[PID:00048:008 2013.07.23 14:04:07.314 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000034.000001’…
[PID:00048:008 2013.07.23 14:04:08.037 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000033.000001’…
[PID:00048:008 2013.07.23 14:04:08.924 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000032.000001’…
[PID:00048:008 2013.07.23 14:04:09.761 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000031.000001’…
[PID:00048:008 2013.07.23 14:04:10.461 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000030.000001’…
[PID:00048:008 2013.07.23 14:04:11.102 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000029.000001’…
[PID:00048:008 2013.07.23 14:04:11.996 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000028.000001’…
[PID:00048:008 2013.07.23 14:04:16.300 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000027.000002’…
[PID:00048:008 2013.07.23 14:04:20.791 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000026.000002’…
[PID:00048:008 2013.07.23 14:04:55.257 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000025.000002’…
[PID:00048:008 2013.07.23 14:05:34.333 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000024.000002’…
[PID:00048:008 2013.07.23 14:06:07.014 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000023.000002’…
[PID:00048:008 2013.07.23 14:06:47.823 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000022.000002’…
[PID:00048:008 2013.07.23 14:07:23.421 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000021.000002’…
[PID:00048:008 2013.07.23 14:08:04.656 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000020.000002’…
[PID:00048:008 2013.07.23 14:08:49.015 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000019.000002’…
[PID:00048:008 2013.07.23 14:09:32.968 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000018.000002’…
[PID:00048:008 2013.07.23 14:10:20.421 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000017.000002’…
[PID:00048:008 2013.07.23 14:10:39.861 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000016.000002’…
[PID:00048:008 2013.07.23 14:10:57.189 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000015.000002’…
[PID:00048:008 2013.07.23 14:11:29.742 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000014.000002’…
[PID:00048:008 2013.07.23 14:12:01.649 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000013.000002’…
[PID:00048:008 2013.07.23 14:12:21.844 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000012.000002’…
[PID:00048:008 2013.07.23 14:12:43.511 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000011.000002’…
[PID:00048:008 2013.07.23 14:13:00.671 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000010.000002’…
[PID:00048:008 2013.07.23 14:13:23.525 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000009.000002’…
[PID:00048:008 2013.07.23 14:13:44.147 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000008.000002’…
[PID:00048:008 2013.07.23 14:14:00.777 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000007.000002’…
[PID:00048:008 2013.07.23 14:14:18.092 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000006.000002’…
[PID:00048:008 2013.07.23 14:14:37.358 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000005.000003’…
[PID:00048:008 2013.07.23 14:14:54.830 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000004.000003’…
[PID:00048:008 2013.07.23 14:15:12.847 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000003.000003’…
[PID:00048:008 2013.07.23 14:15:30.548 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000002.000003’…
[PID:00048:008 2013.07.23 14:15:48.223 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000001.000003’…
[PID:00048:008 2013.07.23 14:16:07.114 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\Data\Events\chunk-000000.000003’…
[PID:00048:001 2013.07.23 14:16:58.525 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections ==> C:\Program Files\EventStore\EventStore 2\singlenode-web\js\projections
[PID:00048:001 2013.07.23 14:16:58.938 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> C:\Program Files\EventStore\EventStore 2\Prelude
[PID:00048:001 2013.07.23 14:16:58.938 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/resources ==> C:\Program Files\EventStore\EventStore 2\web-resources\js
[PID:00048:001 2013.07.23 14:16:59.076 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:00048:001 2013.07.23 14:16:59.076 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:00048:001 2013.07.23 14:16:59.076 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:00048:001 2013.07.23 14:16:59.104 INFO MiniWeb ] Starting MiniWeb for /web ==> C:\Program Files\EventStore\EventStore 2\singlenode-web
[PID:00048:001 2013.07.23 14:16:59.104 INFO MiniWeb ] Starting MiniWeb for /web/es ==> C:\Program Files\EventStore\EventStore 2\es-common-web
[PID:00048:001 2013.07.23 14:16:59.104 TRACE MiniWeb ] Binding MiniWeb to /web/{*remaining_path}
[PID:00048:001 2013.07.23 14:16:59.104 TRACE MiniWeb ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:00048:001 2013.07.23 14:16:59.122 INFO MiniWeb ] Starting MiniWeb for /web/users ==> C:\Program Files\EventStore\EventStore 2\Users\web
[PID:00048:001 2013.07.23 14:16:59.122 TRACE MiniWeb ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:00048:014 2013.07.23 14:16:59.241 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] SYSTEM INIT…
[PID:00048:014 2013.07.23 14:16:59.434 INFO TcpServerListener ] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.
[PID:00048:011 2013.07.23 14:16:59.752 INFO ReadIndex ] TableIndex initialization…
[PID:00048:014 2013.07.23 14:17:00.053 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: SystemInit - 351ms. Handler: TcpService.
[PID:00048:014 2013.07.23 14:17:00.124 INFO HttpAsyncServer ] Starting HTTP server on [http://127.0.0.1:2113/]…
[PID:00048:014 2013.07.23 14:17:00.274 INFO HttpAsyncServer ] HTTP server is up and listening on [http://127.0.0.1:2113/]
[PID:00048:014 2013.07.23 14:17:00.274 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: SystemInit - 221ms. Handler: HttpService.
[PID:00048:014 2013.07.23 14:17:00.300 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: SystemInit - 1072ms. Q: 0/3.
[PID:00048:011 2013.07.23 14:17:00.319 TRACE IndexMap ] Loading PTable ‘C:\Data\Events\index\7ed37b05-6cad-4c6f-963c-46c276c75f2b’ started…
[PID:00048:014 2013.07.23 14:17:01.400 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: RequestManagerTimerTick - 87ms. Handler: RequestManagementService.
[PID:00048:014 2013.07.23 14:17:01.400 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: RequestManagerTimerTick - 87ms. Q: 1/2.
[PID:00048:011 2013.07.23 14:17:23.001 TRACE IndexMap ] Loading PTable ‘C:\Data\Events\index\7ed37b05-6cad-4c6f-963c-46c276c75f2b’ done in 00:00:22.7149133.
[PID:00048:011 2013.07.23 14:17:23.001 TRACE IndexMap ] Verifying file hash of PTable ‘C:\Data\Events\index\7ed37b05-6cad-4c6f-963c-46c276c75f2b’ started…
[PID:00048:011 2013.07.23 14:17:23.208 TRACE IndexMap ] Verifying file hash of PTable ‘C:\Data\Events\index\7ed37b05-6cad-4c6f-963c-46c276c75f2b’ done in 00:00:00.2070835.
[PID:00048:011 2013.07.23 14:17:23.208 TRACE IndexMap ] Loading PTable ‘C:\Data\Events\index\54ea881c-1ec5-4ef1-9ded-e3b7e071307a’ started…
[PID:00048:007 2013.07.23 14:17:26.100 TRACE InMemoryBus ] SLOW BUS MSG [Worker #1 Bus]: IncomingHttpRequestMessage - 258ms. Handler: IncomingHttpRequestAuthenticationManager.
[PID:00048:007 2013.07.23 14:17:26.120 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #1]: IncomingHttpRequestMessage - 258ms. Q: 0/0.
[PID:00048:015 2013.07.23 14:17:27.011 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 27602ms. Q: 0/0.
[PID:00048:012 2013.07.23 14:17:29.949 TRACE InMemoryBus ] SLOW BUS MSG [Worker #2 Bus]: AuthenticatedHttpRequestMessage - 3849ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:012 2013.07.23 14:17:29.949 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #2]: AuthenticatedHttpRequestMessage - 3849ms. Q: 0/4.
[PID:00048:006 2013.07.23 14:17:30.612 TRACE InMemoryBus ] SLOW BUS MSG [Worker #4 Bus]: AuthenticatedHttpRequestMessage - 488ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:006 2013.07.23 14:17:30.612 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #4]: AuthenticatedHttpRequestMessage - 488ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:17:31.495 TRACE InMemoryBus ] SLOW BUS MSG [Worker #1 Bus]: AuthenticatedHttpRequestMessage - 246ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:006 2013.07.23 14:17:31.495 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #1]: AuthenticatedHttpRequestMessage - 246ms. Q: 0/0.
[PID:00048:008 2013.07.23 14:17:31.498 TRACE InMemoryBus ] SLOW BUS MSG [Worker #3 Bus]: AuthenticatedHttpRequestMessage - 249ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:008 2013.07.23 14:17:31.498 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #3]: AuthenticatedHttpRequestMessage - 249ms. Q: 0/0.
[PID:00048:012 2013.07.23 14:17:32.242 TRACE InMemoryBus ] SLOW BUS MSG [Worker #2 Bus]: AuthenticatedHttpRequestMessage - 221ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:012 2013.07.23 14:17:32.242 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #2]: AuthenticatedHttpRequestMessage - 221ms. Q: 0/0.
[PID:00048:006 2013.07.23 14:17:32.657 TRACE InMemoryBus ] SLOW BUS MSG [Worker #4 Bus]: AuthenticatedHttpRequestMessage - 246ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:006 2013.07.23 14:17:32.657 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #4]: AuthenticatedHttpRequestMessage - 246ms. Q: 0/2.
[PID:00048:005 2013.07.23 14:17:39.886 TRACE InMemoryBus ] SLOW BUS MSG [Worker #1 Bus]: AuthenticatedHttpRequestMessage - 6271ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:005 2013.07.23 14:17:39.886 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #1]: AuthenticatedHttpRequestMessage - 6272ms. Q: 0/6.
[PID:00048:005 2013.07.23 14:17:45.819 TRACE InMemoryBus ] SLOW BUS MSG [Worker #5 Bus]: AuthenticatedHttpRequestMessage - 237ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:005 2013.07.23 14:17:45.819 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #5]: AuthenticatedHttpRequestMessage - 237ms. Q: 0/0.
[PID:00048:005 2013.07.23 14:17:46.861 TRACE InMemoryBus ] SLOW BUS MSG [Worker #5 Bus]: AuthenticatedHttpRequestMessage - 364ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:005 2013.07.23 14:17:46.861 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #5]: AuthenticatedHttpRequestMessage - 365ms. Q: 0/1.
[PID:00048:009 2013.07.23 14:17:46.861 TRACE InMemoryBus ] SLOW BUS MSG [Worker #2 Bus]: AuthenticatedHttpRequestMessage - 363ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:009 2013.07.23 14:17:46.861 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #2]: AuthenticatedHttpRequestMessage - 363ms. Q: 0/1.
[PID:00048:008 2013.07.23 14:18:04.331 TRACE InMemoryBus ] SLOW BUS MSG [Worker #2 Bus]: AuthenticatedHttpRequestMessage - 220ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:008 2013.07.23 14:18:04.331 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #2]: AuthenticatedHttpRequestMessage - 220ms. Q: 0/0.
[PID:00048:011 2013.07.23 14:18:05.843 TRACE IndexMap ] Loading PTable ‘C:\Data\Events\index\54ea881c-1ec5-4ef1-9ded-e3b7e071307a’ done in 00:00:42.6349133.
[PID:00048:011 2013.07.23 14:18:05.843 TRACE IndexMap ] Verifying file hash of PTable ‘C:\Data\Events\index\54ea881c-1ec5-4ef1-9ded-e3b7e071307a’ started…
[PID:00048:011 2013.07.23 14:18:05.933 TRACE IndexMap ] Verifying file hash of PTable ‘C:\Data\Events\index\54ea881c-1ec5-4ef1-9ded-e3b7e071307a’ done in 00:00:00.0906537.
[PID:00048:011 2013.07.23 14:18:05.996 INFO ReadIndex ] ReadIndex building…
[PID:00048:005 2013.07.23 14:18:06.692 TRACE InMemoryBus ] SLOW BUS MSG [Worker #5 Bus]: AuthenticatedHttpRequestMessage - 1503ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:005 2013.07.23 14:18:06.692 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #5]: AuthenticatedHttpRequestMessage - 1503ms. Q: 0/2.
[PID:00048:011 2013.07.23 14:18:11.047 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 448 records (0,2%).
[PID:00048:011 2013.07.23 14:18:16.048 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1124 records (0,6%).
[PID:00048:011 2013.07.23 14:18:21.078 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1684 records (0,8%).
[PID:00048:011 2013.07.23 14:18:26.137 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 2188 records (1,1%).
[PID:00048:011 2013.07.23 14:18:31.146 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 2762 records (1,4%).
[PID:00048:011 2013.07.23 14:18:36.150 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 3238 records (1,6%).
[PID:00048:011 2013.07.23 14:18:41.627 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 3672 records (1,8%).
[PID:00048:011 2013.07.23 14:18:46.674 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 4126 records (2,1%).
[PID:00048:011 2013.07.23 14:18:51.675 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 6533 records (3,3%).
[PID:00048:011 2013.07.23 14:18:56.694 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 20278 records (3,6%).
[PID:00048:011 2013.07.23 14:19:01.694 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 27732 records (3,8%).
[PID:00048:011 2013.07.23 14:19:06.773 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 35389 records (4,0%).
[PID:00048:011 2013.07.23 14:19:11.805 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 42317 records (4,3%).
[PID:00048:011 2013.07.23 14:19:16.805 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 46383 records (4,5%).
[PID:00048:011 2013.07.23 14:19:21.819 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 55002 records (4,7%).
[PID:00048:011 2013.07.23 14:19:26.827 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 61699 records (4,9%).
[PID:00048:011 2013.07.23 14:19:31.836 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 69430 records (5,0%).
[PID:00048:014 2013.07.23 14:19:32.261 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: EventCommited - 50ms. Handler: WideningHandler2. [PID:00048:014 2013.07.23 14:19:32.261 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: EventCommited - 50ms. Q: 10/30. [PID:00048:011 2013.07.23 14:19:36.836 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 76348 records (5,3%). [PID:00048:011 2013.07.23 14:19:41.868 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 85242 records (5,5%). [PID:00048:011 2013.07.23 14:19:46.906 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 93442 records (5,7%). [PID:00048:011 2013.07.23 14:19:50.897 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 100000 records (5,9%). [PID:00048:011 2013.07.23 14:19:55.920 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 102969 records (6,1%). [PID:00048:011 2013.07.23 14:20:00.921 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 110182 records (6,3%). [PID:00048:011 2013.07.23 14:20:06.091 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 116351 records (6,4%). [PID:00048:011 2013.07.23 14:20:11.127 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 124154 records (6,6%). [PID:00048:011 2013.07.23 14:20:16.127 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 131415 records (6,8%). [PID:00048:011 2013.07.23 14:20:21.180 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 134500 records (7,0%). [PID:00048:011 2013.07.23 14:20:26.260 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 134922 records (7,2%). [PID:00048:011 2013.07.23 14:20:31.261 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 135388 records (7,5%). [PID:00048:011 2013.07.23 14:20:36.425 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 135694 records (7,6%). [PID:00048:011 2013.07.23 14:20:41.479 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 136134 records (7,8%). [PID:00048:011 2013.07.23 14:20:46.504 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 136660 records (8,1%). [PID:00048:011 2013.07.23 14:20:51.514 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 141998 records (8,4%). [PID:00048:011 2013.07.23 14:20:56.563 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 150778 records (8,7%). [PID:00048:011 2013.07.23 14:21:01.565 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 157625 records (8,8%). [PID:00048:011 2013.07.23 14:21:06.746 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 164789 records (9,0%). [PID:00048:011 2013.07.23 14:21:11.748 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 171696 records (9,2%). [PID:00048:011 2013.07.23 14:21:16.755 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 174784 records (9,3%). [PID:00048:011 2013.07.23 14:21:21.827 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 181841 records (9,4%). [PID:00048:011 2013.07.23 14:21:26.834 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 187564 records (9,6%). [PID:00048:011 2013.07.23 14:21:31.845 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 193327 records (9,8%). [PID:00048:011 2013.07.23 14:21:36.869 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 199471 records (10,0%). [PID:00048:011 2013.07.23 14:21:37.874 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 200000 records (10,1%). [PID:00048:011 2013.07.23 14:21:42.929 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 201602 records (10,2%). [PID:00048:011 2013.07.23 14:21:48.116 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 204067 records (10,5%). [PID:00048:011 2013.07.23 14:21:53.117 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 208570 records (10,6%). [PID:00048:011 2013.07.23 14:21:58.122 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 217564 records (10,7%). [PID:00048:011 2013.07.23 14:22:03.322 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 221730 records (10,9%). [PID:00048:011 2013.07.23 14:22:08.322 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 231450 records (11,1%). [PID:00048:011 2013.07.23 14:22:13.333 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 232013 records (11,3%). [PID:00048:011 2013.07.23 14:22:18.347 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 232597 records (11,6%). [PID:00048:011 2013.07.23 14:22:23.391 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 233097 records (11,9%). [PID:00048:011 2013.07.23 14:22:28.426 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 233645 records (12,2%). [PID:00048:011 2013.07.23 14:22:33.426 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 233913 records (12,3%). [PID:00048:011 2013.07.23 14:22:38.476 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 234393 records (12,5%). [PID:00048:011 2013.07.23 14:22:43.486 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 235071 records (12,8%). [PID:00048:011 2013.07.23 14:22:48.488 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 250207 records (12,9%). [PID:00048:011 2013.07.23 14:22:53.513 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 262603 records (13,1%). [PID:00048:011 2013.07.23 14:22:58.519 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 273865 records (13,2%). [PID:00048:011 2013.07.23 14:23:03.533 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 284506 records (13,4%). [PID:00048:011 2013.07.23 14:23:08.608 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 297170 records (13,6%). [PID:00048:011 2013.07.23 14:23:10.454 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 300000 records (13,6%). [PID:00048:011 2013.07.23 14:23:15.511 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 310929 records (13,7%). [PID:00048:011 2013.07.23 14:23:20.668 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 318806 records (13,9%). [PID:00048:011 2013.07.23 14:23:25.677 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 327754 records (14,0%). [PID:00048:011 2013.07.23 14:23:30.704 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 337363 records (14,1%). [PID:00048:011 2013.07.23 14:23:35.724 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 345505 records (14,2%). [PID:00048:011 2013.07.23 14:23:41.085 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 349726 records (14,4%). [PID:00048:011 2013.07.23 14:23:46.098 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 354431 records (14,5%). [PID:00048:011 2013.07.23 14:23:51.133 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 361463 records (14,6%). [PID:00048:011 2013.07.23 14:23:56.155 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 370778 records (14,8%). [PID:00048:011 2013.07.23 14:24:01.186 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 381077 records (15,0%). [PID:00048:011 2013.07.23 14:24:06.232 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 381665 records (15,2%). [PID:00048:011 2013.07.23 14:24:11.235 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 382427 records (15,5%). [PID:00048:011 2013.07.23 14:24:16.264 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 382919 records (15,7%). [PID:00048:011 2013.07.23 14:24:21.279 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 383431 records (16,0%). [PID:00048:011 2013.07.23 14:24:26.321 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 383903 records (16,2%). [PID:00048:011 2013.07.23 14:24:31.325 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 384389 records (16,5%). [PID:00048:011 2013.07.23 14:24:36.328 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 384879 records (16,7%). [PID:00048:011 2013.07.23 14:24:41.350 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 385421 records (17,0%). [PID:00048:011 2013.07.23 14:24:46.351 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 385973 records (17,3%). [PID:00048:011 2013.07.23 14:24:51.368 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 392940 records (17,5%). [PID:00048:011 2013.07.23 14:24:55.366 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 400000 records (17,6%). [PID:00048:011 2013.07.23 14:25:00.416 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 410598 records (17,7%). [PID:00048:011 2013.07.23 14:25:05.441 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 416055 records (17,9%). [PID:00048:011 2013.07.23 14:25:10.444 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 426125 records (18,1%). [PID:00048:011 2013.07.23 14:25:15.459 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 437167 records (18,3%). [PID:00048:011 2013.07.23 14:25:20.462 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 449520 records (18,4%). [PID:00048:011 2013.07.23 14:25:25.492 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 458661 records (18,5%). [PID:00048:011 2013.07.23 14:25:30.623 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 466842 records (18,6%). [PID:00048:011 2013.07.23 14:25:35.696 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 474134 records (18,8%). [PID:00048:011 2013.07.23 14:25:40.711 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 480815 records (18,9%). [PID:00048:011 2013.07.23 14:25:45.745 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 490982 records (19,0%). [PID:00048:011 2013.07.23 14:25:50.027 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 500000 records (19,2%). [PID:00048:011 2013.07.23 14:25:55.052 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 512812 records (19,3%). [PID:00048:011 2013.07.23 14:26:00.113 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 524263 records (19,5%). [PID:00048:011 2013.07.23 14:26:05.155 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 537371 records (19,6%). [PID:00048:011 2013.07.23 14:26:10.157 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 548471 records (19,8%). [PID:00048:011 2013.07.23 14:26:15.187 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 560806 records (19,9%). [PID:00048:011 2013.07.23 14:26:20.205 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 571266 records (20,1%). [PID:00048:011 2013.07.23 14:26:25.217 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 580094 records (20,3%). [PID:00048:011 2013.07.23 14:26:30.231 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 592930 records (20,4%). [PID:00048:011 2013.07.23 14:26:32.765 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 600000 records (20,5%). [PID:00048:011 2013.07.23 14:26:37.769 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 611411 records (20,7%). [PID:00048:011 2013.07.23 14:26:42.786 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 616808 records (20,9%). [PID:00048:011 2013.07.23 14:26:47.807 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 617264 records (21,1%). [PID:00048:011 2013.07.23 14:26:52.832 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 617738 records (21,3%). [PID:00048:011 2013.07.23 14:26:57.832 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 618188 records (21,6%). [PID:00048:011 2013.07.23 14:27:02.836 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 618754 records (21,8%). [PID:00048:011 2013.07.23 14:27:07.845 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 619396 records (22,2%). [PID:00048:011 2013.07.23 14:27:12.896 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 619882 records (22,4%). [PID:00048:011 2013.07.23 14:27:17.903 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 628947 records (22,7%). [PID:00048:011 2013.07.23 14:27:22.906 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 647244 records (23,0%). [PID:00048:011 2013.07.23 14:27:27.950 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 651736 records (23,2%). [PID:00048:011 2013.07.23 14:27:33.034 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 652050 records (23,3%). [PID:00048:011 2013.07.23 14:27:38.042 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 652348 records (23,5%). [PID:00048:011 2013.07.23 14:27:43.087 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 652850 records (23,7%). [PID:00048:011 2013.07.23 14:27:48.112 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 653427 records (24,0%). [PID:00048:011 2013.07.23 14:27:53.176 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 654022 records (24,3%). [PID:00048:011 2013.07.23 14:27:58.264 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 654596 records (24,6%). [PID:00048:011 2013.07.23 14:28:03.276 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 655022 records (24,8%). [PID:00048:011 2013.07.23 14:28:08.283 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 655319 records (25,0%). [PID:00048:011 2013.07.23 14:28:13.350 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 655658 records (25,1%). [PID:00048:011 2013.07.23 14:28:18.428 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 655938 records (25,3%). [PID:00048:011 2013.07.23 14:28:23.444 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 656622 records (25,6%). [PID:00048:011 2013.07.23 14:28:28.758 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 657146 records (25,9%). [PID:00048:011 2013.07.23 14:28:33.765 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 657478 records (26,0%). [PID:00048:011 2013.07.23 14:28:38.887 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 657940 records (26,3%). [PID:00048:011 2013.07.23 14:28:43.896 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 658318 records (26,5%). [PID:00048:011 2013.07.23 14:28:48.903 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 658880 records (26,7%). [PID:00048:011 2013.07.23 14:28:53.903 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 659557 records (27,1%). [PID:00048:011 2013.07.23 14:28:59.080 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 660250 records (27,4%). [PID:00048:011 2013.07.23 14:29:04.097 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 660738 records (27,7%). [PID:00048:011 2013.07.23 14:29:09.121 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 661138 records (27,9%). [PID:00048:011 2013.07.23 14:29:14.135 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 661460 records (28,0%). [PID:00048:011 2013.07.23 14:29:19.571 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 661772 records (28,2%). [PID:00048:011 2013.07.23 14:29:24.725 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 662096 records (28,4%). [PID:00048:011 2013.07.23 14:29:29.828 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 662542 records (28,6%). [PID:00048:011 2013.07.23 14:29:34.828 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 663091 records (28,9%). [PID:00048:011 2013.07.23 14:29:39.842 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 663698 records (29,2%). [PID:00048:011 2013.07.23 14:29:44.853 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 664068 records (29,4%). [PID:00048:011 2013.07.23 14:29:49.866 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 664498 records (29,6%). [PID:00048:011 2013.07.23 14:29:54.872 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 664998 records (29,8%). [PID:00048:011 2013.07.23 14:29:59.873 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 665526 records (30,1%). [PID:00048:011 2013.07.23 14:30:04.889 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 665930 records (30,3%). [PID:00048:011 2013.07.23 14:30:09.890 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 666406 records (30,5%). [PID:00048:011 2013.07.23 14:30:14.938 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 666915 records (30,7%). [PID:00048:011 2013.07.23 14:30:19.999 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 667923 records (30,8%). [PID:00048:011 2013.07.23 14:30:25.034 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 668397 records (31,1%). [PID:00048:011 2013.07.23 14:30:30.072 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 668889 records (31,3%). [PID:00048:011 2013.07.23 14:30:35.279 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 669319 records (31,5%). [PID:00048:011 2013.07.23 14:30:40.287 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 675150 records (31,7%). [PID:00048:011 2013.07.23 14:30:45.292 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 676049 records (31,9%). [PID:00048:011 2013.07.23 14:30:50.437 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 676473 records (32,1%). [PID:00048:011 2013.07.23 14:30:55.437 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 676985 records (32,4%). [PID:00048:011 2013.07.23 14:31:00.440 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 677793 records (32,6%). [PID:00048:011 2013.07.23 14:31:05.506 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 685505 records (32,8%). [PID:00048:011 2013.07.23 14:31:10.520 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 696728 records (33,0%). [PID:00048:011 2013.07.23 14:31:12.213 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 700000 records (33,0%). [PID:00048:011 2013.07.23 14:31:17.257 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 712151 records (33,2%). [PID:00048:011 2013.07.23 14:31:22.258 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 722780 records (33,3%). [PID:00048:011 2013.07.23 14:31:27.272 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 732558 records (33,5%). [PID:00048:011 2013.07.23 14:31:32.312 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 742418 records (33,6%). [PID:00048:011 2013.07.23 14:31:37.316 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 752051 records (33,8%). [PID:00048:011 2013.07.23 14:31:42.371 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 763619 records (33,9%). [PID:00048:011 2013.07.23 14:31:47.422 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 770157 records (34,1%). [PID:00048:011 2013.07.23 14:31:52.446 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 781294 records (34,3%). [PID:00048:011 2013.07.23 14:31:57.494 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 793721 records (34,4%). [PID:00048:011 2013.07.23 14:31:59.817 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 800000 records (34,5%). [PID:00048:011 2013.07.23 14:32:04.868 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 811428 records (34,6%). [PID:00048:011 2013.07.23 14:32:09.968 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 822351 records (34,8%). [PID:00048:011 2013.07.23 14:32:15.018 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 829457 records (35,0%). [PID:00048:011 2013.07.23 14:32:20.068 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 830015 records (35,2%). [PID:00048:011 2013.07.23 14:32:25.130 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 830585 records (35,5%). [PID:00048:011 2013.07.23 14:32:30.159 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 831281 records (35,9%). [PID:00048:011 2013.07.23 14:32:35.160 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 838537 records (36,2%). [PID:00048:011 2013.07.23 14:32:40.207 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 848218 records (36,3%). [PID:00048:011 2013.07.23 14:32:45.213 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 856552 records (36,4%). [PID:00048:011 2013.07.23 14:32:50.221 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 864800 records (36,5%). [PID:00048:011 2013.07.23 14:32:55.230 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 877574 records (36,7%). [PID:00048:011 2013.07.23 14:33:00.345 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 888011 records (36,8%). [PID:00048:011 2013.07.23 14:33:05.361 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 895046 records (37,1%). [PID:00048:011 2013.07.23 14:33:10.362 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 896179 records (37,4%). [PID:00048:011 2013.07.23 14:33:11.682 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 900000 records (37,4%). [PID:00048:011 2013.07.23 14:33:16.703 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 909368 records (37,6%). [PID:00048:011 2013.07.23 14:33:21.722 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 914832 records (37,8%). [PID:00048:011 2013.07.23 14:33:26.726 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 916305 records (38,1%). [PID:00048:011 2013.07.23 14:33:31.772 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 916745 records (38,3%). [PID:00048:011 2013.07.23 14:33:36.791 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 917159 records (38,6%). [PID:00048:011 2013.07.23 14:33:41.804 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 917669 records (38,8%). [PID:00048:011 2013.07.23 14:33:46.867 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 918213 records (39,1%). [PID:00048:011 2013.07.23 14:33:51.901 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 918691 records (39,3%). [PID:00048:011 2013.07.23 14:33:56.903 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 919103 records (39,5%). [PID:00048:011 2013.07.23 14:34:01.945 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 919681 records (39,8%). [PID:00048:011 2013.07.23 14:34:06.964 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 920213 records (40,0%). [PID:00048:011 2013.07.23 14:34:12.026 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 926407 records (40,2%). [PID:00048:011 2013.07.23 14:34:17.059 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 934489 records (40,4%). [PID:00048:011 2013.07.23 14:34:22.124 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 939788 records (40,6%). [PID:00048:011 2013.07.23 14:34:27.126 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 940292 records (40,8%). [PID:00048:011 2013.07.23 14:34:32.166 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 940788 records (41,1%). [PID:00048:011 2013.07.23 14:34:37.168 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 941280 records (41,3%). [PID:00048:011 2013.07.23 14:34:42.190 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 941670 records (41,5%). [PID:00048:011 2013.07.23 14:34:47.335 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 942140 records (41,8%). [PID:00048:011 2013.07.23 14:34:52.364 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 942372 records (41,9%). [PID:00048:011 2013.07.23 14:34:57.386 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 942756 records (42,1%). [PID:00048:011 2013.07.23 14:35:02.399 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 943354 records (42,4%). [PID:00048:011 2013.07.23 14:35:07.423 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 943882 records (42,6%). [PID:00048:011 2013.07.23 14:35:12.444 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 944236 records (42,8%). [PID:00048:011 2013.07.23 14:35:17.467 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 944660 records (43,0%). [PID:00048:011 2013.07.23 14:35:22.568 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 945108 records (43,3%). [PID:00048:011 2013.07.23 14:35:27.576 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 945672 records (43,5%). [PID:00048:011 2013.07.23 14:35:32.582 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 947738 records (43,7%). [PID:00048:011 2013.07.23 14:35:37.592 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 948274 records (44,0%). [PID:00048:011 2013.07.23 14:35:42.607 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 948760 records (44,2%). [PID:00048:011 2013.07.23 14:35:47.633 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 949306 records (44,5%). [PID:00048:011 2013.07.23 14:35:52.641 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 949846 records (44,7%). [PID:00048:011 2013.07.23 14:35:57.668 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 950264 records (45,0%). [PID:00048:011 2013.07.23 14:36:02.699 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 950762 records (45,2%). [PID:00048:011 2013.07.23 14:36:07.740 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 951316 records (45,5%). [PID:00048:011 2013.07.23 14:36:12.748 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 951822 records (45,7%). [PID:00048:011 2013.07.23 14:36:17.759 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 952376 records (46,0%). [PID:00048:011 2013.07.23 14:36:22.773 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 952914 records (46,3%). [PID:00048:011 2013.07.23 14:36:27.786 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 953500 records (46,6%). [PID:00048:011 2013.07.23 14:36:32.807 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 956408 records (46,8%). [PID:00048:011 2013.07.23 14:36:37.842 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 963099 records (47,0%). [PID:00048:011 2013.07.23 14:36:42.844 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 963649 records (47,3%). [PID:00048:011 2013.07.23 14:36:47.859 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 964297 records (47,6%). [PID:00048:011 2013.07.23 14:36:52.893 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 964775 records (47,8%). [PID:00048:011 2013.07.23 14:36:57.916 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 965437 records (48,2%). [PID:00048:011 2013.07.23 14:37:02.918 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 965885 records (48,4%). [PID:00048:011 2013.07.23 14:37:07.932 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 966315 records (48,6%). [PID:00048:011 2013.07.23 14:37:12.971 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 966759 records (48,8%). [PID:00048:011 2013.07.23 14:37:17.999 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 967139 records (49,0%). [PID:00048:011 2013.07.23 14:37:23.009 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 967465 records (49,2%). [PID:00048:011 2013.07.23 14:37:28.011 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 967921 records (49,4%). [PID:00048:011 2013.07.23 14:37:33.040 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 968532 records (49,7%). [PID:00048:011 2013.07.23 14:37:38.044 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 968857 records (49,9%). [PID:00048:011 2013.07.23 14:37:43.066 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 969251 records (50,1%). [PID:00048:011 2013.07.23 14:37:48.111 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 969649 records (50,3%). [PID:00048:011 2013.07.23 14:37:53.135 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 970385 records (50,6%). [PID:00048:011 2013.07.23 14:37:58.172 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 970677 records (50,8%). [PID:00048:011 2013.07.23 14:38:03.194 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 971069 records (51,0%). [PID:00048:011 2013.07.23 14:38:08.204 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 971741 records (51,3%). [PID:00048:011 2013.07.23 14:38:13.207 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 972427 records (51,7%). [PID:00048:011 2013.07.23 14:38:18.241 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 972855 records (51,9%). [PID:00048:011 2013.07.23 14:38:23.310 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 973315 records (52,1%). [PID:00048:011 2013.07.23 14:38:28.326 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 973833 records (52,4%). [PID:00048:011 2013.07.23 14:38:33.329 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 974407 records (52,7%). [PID:00048:011 2013.07.23 14:38:38.357 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 974891 records (52,9%). [PID:00048:011 2013.07.23 14:38:43.411 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 975373 records (53,2%). [PID:00048:011 2013.07.23 14:38:48.412 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 975821 records (53,4%). [PID:00048:011 2013.07.23 14:38:53.470 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 976175 records (53,6%). [PID:00048:011 2013.07.23 14:38:58.483 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 976720 records (53,8%). [PID:00048:011 2013.07.23 14:39:03.491 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 977233 records (54,1%). [PID:00048:011 2013.07.23 14:39:08.495 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 977745 records (54,3%). [PID:00048:011 2013.07.23 14:39:13.550 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 978181 records (54,6%). [PID:00048:011 2013.07.23 14:39:18.563 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 978413 records (54,7%). [PID:00048:011 2013.07.23 14:39:23.567 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 979155 records (55,0%). [PID:00048:011 2013.07.23 14:39:28.638 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 979733 records (55,2%). [PID:00048:011 2013.07.23 14:39:33.639 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 980325 records (55,5%). [PID:00048:011 2013.07.23 14:39:38.641 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 980807 records (55,7%). [PID:00048:011 2013.07.23 14:39:43.670 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 981291 records (56,0%). [PID:00048:011 2013.07.23 14:39:48.672 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 981755 records (56,2%). [PID:00048:011 2013.07.23 14:39:53.775 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 982177 records (56,4%). [PID:00048:011 2013.07.23 14:39:58.792 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 982849 records (56,8%). [PID:00048:011 2013.07.23 14:40:03.793 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 983295 records (57,0%). [PID:00048:011 2013.07.23 14:40:08.800 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 983773 records (57,2%). [PID:00048:011 2013.07.23 14:40:13.860 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 984853 records (57,7%). [PID:00048:011 2013.07.23 14:40:18.872 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 985451 records (57,9%). [PID:00048:011 2013.07.23 14:40:23.893 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 986011 records (58,2%). [PID:00048:011 2013.07.23 14:40:28.894 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 986609 records (58,4%). [PID:00048:011 2013.07.23 14:40:33.927 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 987055 records (58,6%). [PID:00048:011 2013.07.23 14:40:38.965 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 987553 records (58,9%). [PID:00048:011 2013.07.23 14:40:43.975 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 987997 records (59,1%). [PID:00048:011 2013.07.23 14:40:48.996 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 988389 records (59,3%). [PID:00048:011 2013.07.23 14:40:54.000 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 988787 records (59,5%). [PID:00048:011 2013.07.23 14:40:59.001 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 989147 records (59,7%). [PID:00048:011 2013.07.23 14:41:04.024 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 989599 records (59,9%). [PID:00048:011 2013.07.23 14:41:09.066 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 990123 records (60,2%). [PID:00048:011 2013.07.23 14:41:14.085 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 990613 records (60,4%). [PID:00048:011 2013.07.23 14:41:19.127 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 991089 records (60,6%). [PID:00048:011 2013.07.23 14:41:24.132 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 998639 records (60,8%). [PID:00048:011 2013.07.23 14:41:29.186 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 999117 records (61,0%). [PID:00048:011 2013.07.23 14:41:34.220 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 999517 records (61,2%). [PID:00048:011 2013.07.23 14:41:37.318 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1000000 records (61,4%). [PID:00048:011 2013.07.23 14:41:42.350 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1009303 records (61,5%). [PID:00048:011 2013.07.23 14:41:47.393 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1009861 records (61,7%). [PID:00048:011 2013.07.23 14:41:52.461 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1010231 records (61,9%). [PID:00048:011 2013.07.23 14:41:57.471 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1010659 records (62,1%). [PID:00048:011 2013.07.23 14:42:02.512 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1011549 records (62,6%). [PID:00048:011 2013.07.23 14:42:07.523 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1012085 records (62,8%). [PID:00048:011 2013.07.23 14:42:12.590 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1012577 records (63,1%). [PID:00048:011 2013.07.23 14:42:17.630 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1013419 records (63,5%). [PID:00048:011 2013.07.23 14:42:22.706 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1013967 records (63,7%). [PID:00048:011 2013.07.23 14:42:27.711 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1014625 records (64,0%). [PID:00048:011 2013.07.23 14:42:32.733 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1015399 records (64,3%). [PID:00048:011 2013.07.23 14:42:37.765 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1016343 records (64,6%). [PID:00048:011 2013.07.23 14:42:42.778 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1029298 records (64,7%). [PID:00048:011 2013.07.23 14:42:47.812 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1036083 records (64,9%). [PID:00048:011 2013.07.23 14:42:52.851 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1036503 records (65,1%). [PID:00048:011 2013.07.23 14:42:57.852 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1036857 records (65,3%). [PID:00048:011 2013.07.23 14:43:02.870 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1037119 records (65,5%). [PID:00048:011 2013.07.23 14:43:08.045 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1037413 records (65,6%). [PID:00048:011 2013.07.23 14:43:13.193 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1037595 records (65,7%). [PID:00048:011 2013.07.23 14:43:18.239 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1037944 records (65,9%). [PID:00048:011 2013.07.23 14:43:23.246 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1038368 records (66,1%). [PID:00048:011 2013.07.23 14:43:28.261 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1038818 records (66,3%). [PID:00048:011 2013.07.23 14:43:33.292 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1039226 records (66,5%). [PID:00048:011 2013.07.23 14:43:38.336 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1039720 records (66,8%). [PID:00048:011 2013.07.23 14:43:43.355 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1040190 records (67,0%). [PID:00048:011 2013.07.23 14:43:48.738 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1040676 records (67,2%). [PID:00048:011 2013.07.23 14:43:53.812 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1041050 records (67,4%). [PID:00048:011 2013.07.23 14:43:58.814 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1041522 records (67,6%). [PID:00048:011 2013.07.23 14:44:03.874 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1042044 records (67,9%). [PID:00048:011 2013.07.23 14:44:08.938 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1042376 records (68,0%). [PID:00048:011 2013.07.23 14:44:13.980 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1042748 records (68,2%). [PID:00048:011 2013.07.23 14:44:18.990 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1043132 records (68,4%). [PID:00048:011 2013.07.23 14:44:24.082 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1043586 records (68,7%). [PID:00048:011 2013.07.23 14:44:29.096 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1043980 records (68,9%). [PID:00048:011 2013.07.23 14:44:34.191 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1044472 records (69,1%). [PID:00048:011 2013.07.23 14:44:39.214 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1044790 records (69,3%). [PID:00048:011 2013.07.23 14:44:44.254 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1045132 records (69,4%). [PID:00048:011 2013.07.23 14:44:49.287 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1045472 records (69,6%). [PID:00048:011 2013.07.23 14:44:54.301 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1045748 records (69,7%). [PID:00048:011 2013.07.23 14:44:59.304 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1046210 records (70,0%). [PID:00048:011 2013.07.23 14:45:04.328 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1046648 records (70,2%). [PID:00048:011 2013.07.23 14:45:09.355 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1047106 records (70,4%). [PID:00048:011 2013.07.23 14:45:14.430 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1047454 records (70,6%). [PID:00048:011 2013.07.23 14:45:19.490 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1047658 records (70,7%). [PID:00048:011 2013.07.23 14:45:24.490 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1048202 records (71,0%). [PID:00048:011 2013.07.23 14:45:29.524 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1048702 records (71,2%). [PID:00048:011 2013.07.23 14:45:34.549 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1049226 records (71,5%). [PID:00048:011 2013.07.23 14:45:39.555 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1049626 records (71,7%). [PID:00048:011 2013.07.23 14:45:44.571 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1050056 records (71,9%). [PID:00048:011 2013.07.23 14:45:49.610 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1050392 records (72,1%). [PID:00048:011 2013.07.23 14:45:54.613 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1051032 records (72,4%). [PID:00048:011 2013.07.23 14:45:59.674 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1051444 records (72,6%). [PID:00048:011 2013.07.23 14:46:04.701 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1051940 records (72,8%). [PID:00048:011 2013.07.23 14:46:09.734 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1052590 records (73,2%). [PID:00048:011 2013.07.23 14:46:14.746 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1053512 records (73,6%). [PID:00048:011 2013.07.23 14:46:19.772 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1054000 records (73,9%). [PID:00048:011 2013.07.23 14:46:24.842 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1054474 records (74,1%). [PID:00048:011 2013.07.23 14:46:29.871 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1054914 records (74,3%). [PID:00048:011 2013.07.23 14:46:34.874 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1055354 records (74,6%). [PID:00048:011 2013.07.23 14:46:39.881 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1055848 records (74,8%). [PID:00048:011 2013.07.23 14:46:44.935 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1056432 records (75,1%). [PID:00048:011 2013.07.23 14:46:49.953 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1057780 records (75,4%). [PID:00048:011 2013.07.23 14:46:54.971 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1058230 records (75,6%). [PID:00048:011 2013.07.23 14:46:59.980 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1058566 records (75,8%). [PID:00048:011 2013.07.23 14:47:05.013 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1058990 records (76,0%). [PID:00048:011 2013.07.23 14:47:10.027 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1059436 records (76,2%). [PID:00048:011 2013.07.23 14:47:15.096 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1059782 records (76,4%). [PID:00048:011 2013.07.23 14:47:20.126 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1060228 records (76,6%). [PID:00048:011 2013.07.23 14:47:25.142 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1060608 records (76,8%). [PID:00048:011 2013.07.23 14:47:30.218 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1061002 records (77,0%). [PID:00048:011 2013.07.23 14:47:35.301 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1061496 records (77,2%). [PID:00048:011 2013.07.23 14:47:40.308 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1061960 records (77,5%). [PID:00048:011 2013.07.23 14:47:45.338 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1062380 records (77,7%). [PID:00048:011 2013.07.23 14:47:50.383 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1062834 records (77,9%). [PID:00048:011 2013.07.23 14:47:55.403 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1063254 records (78,1%). [PID:00048:011 2013.07.23 14:48:00.457 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1063684 records (78,3%). [PID:00048:011 2013.07.23 14:48:05.461 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1064216 records (78,6%). [PID:00048:011 2013.07.23 14:48:10.476 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1068021 records (78,8%). [PID:00048:011 2013.07.23 14:48:15.549 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1068609 records (79,1%). [PID:00048:011 2013.07.23 14:48:20.554 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1069071 records (79,3%). [PID:00048:011 2013.07.23 14:48:25.556 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1069477 records (79,5%). [PID:00048:011 2013.07.23 14:48:30.593 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1070123 records (79,9%). [PID:00048:011 2013.07.23 14:48:35.640 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1070703 records (80,1%). [PID:00048:011 2013.07.23 14:48:40.695 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1071133 records (80,4%). [PID:00048:011 2013.07.23 14:48:45.723 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1071605 records (80,6%). [PID:00048:011 2013.07.23 14:48:50.750 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1071943 records (80,8%). [PID:00048:011 2013.07.23 14:48:55.785 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1072395 records (81,0%). [PID:00048:011 2013.07.23 14:49:00.794 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1072865 records (81,2%). [PID:00048:011 2013.07.23 14:49:05.812 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1073133 records (81,3%). [PID:00048:011 2013.07.23 14:49:10.837 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1078442 records (81,5%). [PID:00048:011 2013.07.23 14:49:15.851 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1089545 records (81,6%). [PID:00048:011 2013.07.23 14:49:20.884 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1093640 records (81,8%). [PID:00048:011 2013.07.23 14:49:25.914 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1094949 records (82,0%). [PID:00048:011 2013.07.23 14:49:30.926 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1095839 records (82,2%). [PID:00048:011 2013.07.23 14:49:35.930 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1096488 records (82,5%). [PID:00048:011 2013.07.23 14:49:40.931 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1096890 records (82,7%). [PID:00048:011 2013.07.23 14:49:45.966 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1097376 records (82,9%). [PID:00048:011 2013.07.23 14:49:50.986 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1097848 records (83,1%). [PID:00048:011 2013.07.23 14:49:54.594 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1100000 records (84,2%). [PID:00048:011 2013.07.23 14:49:55.899 DEBUG ReadIndex ] ReadIndex Rebuilding: processed 1200000 records (97,2%). [PID:00048:011 2013.07.23 14:49:56.348 DEBUG ReadIndex ] ReadIndex Rebuilding Done: total processed 1267167 records, time elapsed: 00:31:50.3527876. [PID:00048:011 2013.07.23 14:49:56.348 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [StorageWriterQueue]: SystemInit - 1976938ms. Q: 0/0. [PID:00048:014 2013.07.23 14:49:56.348 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] SYSTEM START.... [PID:00048:014 2013.07.23 14:49:56.348 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP... [PID:00048:014 2013.07.23 14:49:56.348 INFO SingleVNodeControlle] ========== [127.0.0.1:2113] IS WORKING!!! SPARTA!!! [PID:00048:014 2013.07.23 14:49:56.523 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: ReadStreamEventsBackwardCompleted - 164ms. Handler: RequestResponseDispatcher2.
[PID:00048:014 2013.07.23 14:49:56.523 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: ReadStreamEventsBackwardCompleted - 164ms. Q: 0/6.
[PID:00048:011 2013.07.23 14:49:56.554 DEBUG EpochManager ] === Writing E0@11396227149:{b6955dbd-40ca-4a33-a30c-bace2396ec04} (previous epoch at -1).
[PID:00048:018 2013.07.23 14:49:56.837 TRACE InMemoryBus ] SLOW BUS MSG [bus]: EventReaderIdle - 297ms. Handler: EventReaderCoreService.
[PID:00048:019 2013.07.23 14:49:56.837 TRACE InMemoryBus ] SLOW BUS MSG [bus]: EventReaderIdle - 297ms. Handler: EventReaderCoreService.
[PID:00048:018 2013.07.23 14:49:56.837 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: EventReaderIdle - 297ms. Q: 0/2.
[PID:00048:019 2013.07.23 14:49:56.837 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: EventReaderIdle - 297ms. Q: 0/1.
[PID:00048:020 2013.07.23 14:49:56.837 TRACE InMemoryBus ] SLOW BUS MSG [bus]: EventReaderIdle - 297ms. Handler: EventReaderCoreService.
[PID:00048:020 2013.07.23 14:49:56.837 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #2]: EventReaderIdle - 297ms. Q: 0/2.
[PID:00048:011 2013.07.23 14:49:57.030 DEBUG EpochManager ] === Update Last Epoch E0@11396227149:{b6955dbd-40ca-4a33-a30c-bace2396ec04} (previous epoch at -1).
[PID:00048:011 2013.07.23 14:49:57.030 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [StorageWriterQueue]: BecomeMaster - 673ms. Q: 0/1.
[PID:00048:023 2013.07.23 14:49:57.227 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadStreamEventsBackward - 703ms. Q: 0/2.
[PID:00048:017 2013.07.23 14:49:57.743 INFO ProjectionManager ] Projection manager is initializing from the empty $projections-$all stream
[PID:00048:017 2013.07.23 14:49:57.743 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: ReadStreamEventsBackwardCompleted - 518ms. Handler: ProjectionManager.
[PID:00048:017 2013.07.23 14:49:57.743 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: ReadStreamEventsBackwardCompleted - 518ms. Q: 0/3.
[PID:00048:015 2013.07.23 14:49:58.213 TRACE MonitoringService ] Created stats stream ‘$stats-127.0.0.1:2113’, code = Success
[PID:00048:019 2013.07.23 14:49:58.288 TRACE InMemoryBus ] SLOW BUS MSG [bus]: UnwrapEnvelopeMessage - 55ms. Handler: UnwrapEnvelopeHandler.
[PID:00048:019 2013.07.23 14:49:58.288 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: UnwrapEnvelopeMessage - 55ms. Q: 0/3.
[PID:00048:019 2013.07.23 14:49:58.364 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CommittedEventDistributed - 76ms. Handler: EventReaderCoreService.
[PID:00048:019 2013.07.23 14:49:58.364 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: CommittedEventDistributed - 76ms. Q: 2/2.
[PID:00048:017 2013.07.23 14:49:58.476 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: WriteEventsCompleted - 49ms. Handler: ProjectionManager.
[PID:00048:017 2013.07.23 14:49:58.476 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: WriteEventsCompleted - 50ms. Q: 0/1.
[PID:00048:014 2013.07.23 14:49:58.775 INFO UserManagementServic] ‘admin’ user account has been created
[PID:00048:018 2013.07.23 14:49:59.194 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CreateAndPrepare - 711ms. Handler: ProjectionCoreService.
[PID:00048:018 2013.07.23 14:49:59.194 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CreateAndPrepare - 712ms. Q: 0/2.
[PID:00048:017 2013.07.23 14:49:59.292 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: Prepared - 98ms. Handler: ProjectionManager.
[PID:00048:017 2013.07.23 14:49:59.292 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: Prepared - 99ms. Q: 0/2.
[PID:00048:017 2013.07.23 14:49:59.473 INFO ProjectionManager ] ‘$users’ projection source has been written
[PID:00048:018 2013.07.23 14:49:59.535 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CheckpointLoaded - 53ms. Handler: ProjectionCoreService.
[PID:00048:018 2013.07.23 14:49:59.535 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CheckpointLoaded - 54ms. Q: 1/1.
[PID:00048:018 2013.07.23 14:49:59.615 TRACE InMemoryBus ] SLOW BUS MSG [bus]: PrerecordedEventsLoaded - 79ms. Handler: ProjectionCoreService.
[PID:00048:018 2013.07.23 14:49:59.615 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: PrerecordedEventsLoaded - 79ms. Q: 0/3.
[PID:00048:018 2013.07.23 14:49:59.684 TRACE EventReorderingReade] Creating an event distribution point at 'C:0/P:-1; $UserCreated: -1; ’
[PID:00048:018 2013.07.23 14:49:59.715 TRACE ProjectionCoreServic] The ‘29a27af8-b8f4-4ebb-b660-c632074b855e’ projection subscribed to the ‘4807e88b-d74f-4eab-8416-1a8bc0441b98’ distribution point
[PID:00048:018 2013.07.23 14:49:59.749 TRACE InMemoryBus ] SLOW BUS MSG [bus]: Subscribe - 138ms. Handler: EventReaderCoreService.
[PID:00048:018 2013.07.23 14:49:59.749 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: Subscribe - 138ms. Q: 2/9.
[PID:00048:013 2013.07.23 14:50:00.761 TRACE InMemoryBus ] SLOW BUS MSG [Core Output]: ReadAllEventsForward - 83ms. Handler: RequestResponseQueueForwarder.
[PID:00048:007 2013.07.23 14:50:03.926 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 482ms. Q: 0/1.
[PID:00048:013 2013.07.23 14:50:06.018 TRACE InMemoryBus ] SLOW BUS MSG [Core Output]: ReadAllEventsForward - 55ms. Handler: RequestResponseQueueForwarder.
[PID:00048:013 2013.07.23 14:50:06.569 TRACE InMemoryBus ] SLOW BUS MSG [Core Output]: ReadAllEventsForward - 49ms. Handler: RequestResponseQueueForwarder.
[PID:00048:009 2013.07.23 14:50:12.606 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 208ms. Q: 0/1.
[PID:00048:024 2013.07.23 14:50:13.226 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 268ms. Q: 0/0.
[PID:00048:024 2013.07.23 14:50:13.481 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 255ms. Q: 0/1.
[PID:00048:024 2013.07.23 14:50:13.827 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 336ms. Q: 0/0.
[PID:00048:024 2013.07.23 14:50:14.264 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 308ms. Q: 0/0.
[PID:00048:023 2013.07.23 14:50:16.825 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 2443ms. Q: 0/3.
[PID:00048:006 2013.07.23 14:50:19.203 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 2378ms. Q: 0/3.
[PID:00048:005 2013.07.23 14:50:21.639 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 2436ms. Q: 0/4.
[PID:00048:009 2013.07.23 14:50:23.911 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 2272ms. Q: 0/3.
[PID:00048:023 2013.07.23 14:50:28.047 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 4134ms. Q: 0/3.
[PID:00048:023 2013.07.23 14:50:32.403 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 4356ms. Q: 0/4.
[PID:00048:009 2013.07.23 14:50:35.708 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 3305ms. Q: 0/3.
[PID:00048:023 2013.07.23 14:50:38.545 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 2836ms. Q: 0/3.
[PID:00048:009 2013.07.23 14:50:40.786 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 2241ms. Q: 0/3.
[PID:00048:023 2013.07.23 14:50:43.388 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 2602ms. Q: 0/3.
[PID:00048:006 2013.07.23 14:50:46.343 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 2954ms. Q: 0/3.
[PID:00048:022 2013.07.23 14:50:48.979 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 2636ms. Q: 0/3.
[PID:00048:009 2013.07.23 14:50:51.814 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 2835ms. Q: 0/4.
[PID:00048:006 2013.07.23 14:50:54.285 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 2471ms. Q: 0/3.
[PID:00048:022 2013.07.23 14:50:56.791 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 2505ms. Q: 0/3.
[PID:00048:017 2013.07.23 14:50:57.823 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: CleanupExpired - 78ms. Handler: ProjectionManager.
[PID:00048:017 2013.07.23 14:50:57.823 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: CleanupExpired - 78ms. Q: 0/2.
[PID:00048:024 2013.07.23 14:50:58.903 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 2112ms. Q: 0/3.
[PID:00048:005 2013.07.23 14:51:01.461 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 2558ms. Q: 0/3.
[PID:00048:023 2013.07.23 14:51:01.894 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 411ms. Q: 0/1.
[PID:00048:009 2013.07.23 14:51:02.269 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 375ms. Q: 0/1.
[PID:00048:009 2013.07.23 14:51:02.829 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 480ms. Q: 0/1.
[PID:00048:005 2013.07.23 14:51:05.508 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 2678ms. Q: 0/3.
[PID:00048:023 2013.07.23 14:51:08.044 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 2536ms. Q: 0/4.
[PID:00048:005 2013.07.23 14:51:10.375 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 2331ms. Q: 0/3.
[PID:00048:009 2013.07.23 14:51:12.821 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 2446ms. Q: 0/3.
[PID:00048:005 2013.07.23 14:51:15.301 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 2479ms. Q: 0/3.
[PID:00048:022 2013.07.23 14:51:15.723 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 422ms. Q: 0/0.
[PID:00048:025 2013.07.23 14:51:16.439 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 439ms. Q: 0/1.
[PID:00048:025 2013.07.23 14:51:17.404 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 788ms. Q: 0/2.
[PID:00048:009 2013.07.23 14:51:18.408 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 884ms. Q: 0/2.
[PID:00048:025 2013.07.23 14:51:21.202 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 2794ms. Q: 0/3.
[PID:00048:022 2013.07.23 14:51:21.890 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 688ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:51:23.152 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 1262ms. Q: 0/2.
[PID:00048:006 2013.07.23 14:51:23.623 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 471ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:51:24.072 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 404ms. Q: 0/1.
[PID:00048:005 2013.07.23 14:51:24.536 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 463ms. Q: 0/1.
[PID:00048:024 2013.07.23 14:51:25.039 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 503ms. Q: 0/1.
[PID:00048:005 2013.07.23 14:51:26.688 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 661ms. Q: 0/2.
[PID:00048:005 2013.07.23 14:51:27.033 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 344ms. Q: 0/0.
[PID:00048:024 2013.07.23 14:51:30.440 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 252ms. Q: 0/0.
[PID:00048:005 2013.07.23 14:51:35.106 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 514ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:52:13.116 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 205ms. Q: 0/0.
[PID:00048:006 2013.07.23 14:52:15.201 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 251ms. Q: 0/1.
[PID:00048:025 2013.07.23 14:52:16.422 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 342ms. Q: 0/1.
[PID:00048:023 2013.07.23 14:52:18.930 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 481ms. Q: 0/1.
[PID:00048:022 2013.07.23 14:52:22.597 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 216ms. Q: 0/0.
[PID:00048:022 2013.07.23 14:52:22.855 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 258ms. Q: 0/0.
[PID:00048:024 2013.07.23 14:52:35.507 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 222ms. Q: 0/0.
[PID:00048:023 2013.07.23 14:52:56.664 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 579ms. Q: 0/1.
[PID:00048:024 2013.07.23 14:52:57.416 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 752ms. Q: 0/2.
[PID:00048:005 2013.07.23 14:53:12.068 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 1112ms. Q: 0/2.
[PID:00048:005 2013.07.23 14:53:14.082 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 2014ms. Q: 0/3.
[PID:00048:024 2013.07.23 14:53:15.354 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 1272ms. Q: 0/2.
[PID:00048:009 2013.07.23 14:53:27.274 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 296ms. Q: 0/0.
[PID:00048:025 2013.07.23 14:53:28.369 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 298ms. Q: 0/1.
[PID:00048:024 2013.07.23 14:53:28.614 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 245ms. Q: 0/0.
[PID:00048:024 2013.07.23 14:53:34.532 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 252ms. Q: 0/1.
[PID:00048:017 2013.07.23 14:53:57.819 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: CleanupExpired - 55ms. Handler: ProjectionManager.
[PID:00048:017 2013.07.23 14:53:57.819 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: CleanupExpired - 55ms. Q: 0/2.
[PID:00048:006 2013.07.23 14:55:34.004 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 201ms. Q: 0/0.
[PID:00048:022 2013.07.23 14:56:31.808 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 301ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:56:32.172 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 364ms. Q: 0/1.
[PID:00048:024 2013.07.23 14:57:25.617 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 304ms. Q: 0/1.
[PID:00048:025 2013.07.23 14:57:26.030 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 413ms. Q: 0/1.
[PID:00048:009 2013.07.23 14:57:31.896 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 374ms. Q: 0/2.
[PID:00048:024 2013.07.23 14:57:34.474 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 592ms. Q: 0/1.
[PID:00048:020 2013.07.23 14:57:54.351 TRACE InMemoryBus ] SLOW BUS MSG [bus]: UnwrapEnvelopeMessage - 67ms. Handler: UnwrapEnvelopeHandler.
[PID:00048:020 2013.07.23 14:57:54.351 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #2]: UnwrapEnvelopeMessage - 67ms. Q: 0/2.
[PID:00048:022 2013.07.23 14:57:54.626 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 223ms. Q: 0/0.
[PID:00048:024 2013.07.23 14:57:59.843 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 251ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:58:00.962 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 215ms. Q: 0/0.
[PID:00048:009 2013.07.23 14:58:31.852 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 231ms. Q: 0/1.
[PID:00048:005 2013.07.23 14:58:42.593 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 218ms. Q: 0/0.
[PID:00048:024 2013.07.23 14:58:42.875 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 282ms. Q: 0/1.
[PID:00048:022 2013.07.23 14:59:17.475 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 1060ms. Q: 0/2.
[PID:00048:024 2013.07.23 14:59:19.198 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #1]: ReadAllEventsForward - 1723ms. Q: 0/3.
[PID:00048:023 2013.07.23 14:59:20.726 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 1527ms. Q: 0/3.
[PID:00048:025 2013.07.23 14:59:31.974 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #2]: ReadAllEventsForward - 329ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:59:32.337 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #4]: ReadAllEventsForward - 306ms. Q: 0/1.
[PID:00048:006 2013.07.23 14:59:37.756 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadAllEventsForward - 208ms. Q: 0/0.
[PID:00048:017 2013.07.23 14:59:40.005 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: RegularTimeout - 51ms. Handler: ProjectionManager.
[PID:00048:017 2013.07.23 14:59:40.005 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: RegularTimeout - 52ms. Q: 0/1.
[PID:00048:018 2013.07.23 14:59:41.669 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CommittedEventDistributed - 289ms. Handler: EventReaderCoreService.
[PID:00048:018 2013.07.23 14:59:41.669 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CommittedEventDistributed - 289ms. Q: 3/8.
[PID:00048:018 2013.07.23 14:59:41.725 TRACE HeadingEventReader ] The ‘29a27af8-b8f4-4ebb-b660-c632074b855e’ subscription has joined the heading distribution point at ‘11396563531’
[PID:00048:018 2013.07.23 14:59:42.067 TRACE HeadingEventReader ] The ‘29a27af8-b8f4-4ebb-b660-c632074b855e’ projection subscribed to the ‘e4493f12-1df0-48c2-b8c3-79488b3584bc’ heading distribution point
[PID:00048:018 2013.07.23 14:59:42.067 TRACE ProjectionCoreServic] The ‘29a27af8-b8f4-4ebb-b660-c632074b855e’ is subscribing to the heading distribution point with TF-EOF marker event at ‘11396563531’
[PID:00048:018 2013.07.23 14:59:42.067 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CommittedEventDistributed - 399ms. Handler: EventReaderCoreService.
[PID:00048:018 2013.07.23 14:59:42.067 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CommittedEventDistributed - 399ms. Q: 6/7.
[PID:00048:018 2013.07.23 14:59:42.216 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CommittedEventReceived - 148ms. Handler: Subscriber1. [PID:00048:018 2013.07.23 14:59:42.216 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CommittedEventReceived - 148ms. Q: 3/4. [PID:00048:018 2013.07.23 14:59:42.651 TRACE InMemoryBus ] SLOW BUS MSG [bus]: CoreTick - 435ms. Handler: ProjectionCoreService. [PID:00048:018 2013.07.23 14:59:42.651 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: CoreTick - 435ms. Q: 0/6. [PID:00048:018 2013.07.23 14:59:42.707 TRACE InMemoryBus ] SLOW BUS MSG [bus]: ReadStreamEventsBackwardCompleted - 57ms. Handler: ProjectionCoreService. [PID:00048:018 2013.07.23 14:59:42.707 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: ReadStreamEventsBackwardCompleted - 57ms. Q: 0/1. [PID:00048:018 2013.07.23 14:59:42.904 TRACE InMemoryBus ] SLOW BUS MSG [bus]: WriteEventsCompleted - 191ms. Handler: ProjectionCoreService. [PID:00048:018 2013.07.23 14:59:42.904 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: WriteEventsCompleted - 191ms. Q: 0/2. [PID:00048:014 2013.07.23 15:22:48.789 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: ReadStreamEventsBackwardCompleted - 108ms. Handler: RequestResponseDispatcher2.
[PID:00048:014 2013.07.23 15:22:48.789 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: ReadStreamEventsBackwardCompleted - 108ms. Q: 0/2.
[PID:00048:022 2013.07.23 15:22:49.608 TRACE InMemoryBus ] SLOW BUS MSG [Worker #3 Bus]: AuthenticatedHttpRequestMessage - 307ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:022 2013.07.23 15:22:49.608 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #3]: AuthenticatedHttpRequestMessage - 307ms. Q: 0/1.
[PID:00048:023 2013.07.23 15:22:49.608 TRACE InMemoryBus ] SLOW BUS MSG [Worker #5 Bus]: AuthenticatedHttpRequestMessage - 311ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:023 2013.07.23 15:22:49.608 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #5]: AuthenticatedHttpRequestMessage - 311ms. Q: 0/1.
[PID:00048:017 2013.07.23 15:22:56.134 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: GetStatistics - 545ms. Handler: ProjectionManager.
[PID:00048:017 2013.07.23 15:22:56.134 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: GetStatistics - 545ms. Q: 0/2.
[PID:00048:023 2013.07.23 15:25:38.646 TRACE InMemoryBus ] SLOW BUS MSG [Worker #3 Bus]: AuthenticatedHttpRequestMessage - 305ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00048:023 2013.07.23 15:25:38.646 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #3]: AuthenticatedHttpRequestMessage - 305ms. Q: 0/1.
[PID:00048:015 2013.07.23 15:25:38.833 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MonitoringQueue]: GetFreshStats - 187ms. Q: 0/0.
[PID:00048:003 2013.07.23 15:33:10.018 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue #3]: ReadEvent - 253ms. Q: 0/1.

Enjoy…

jeremie / thinkbeforecoding

Greg_Young1 · July 23, 2013, 4:12pm

What cmd line did you run with?

Yuri_Solodkyy · July 23, 2013, 4:33pm

Hi Jérémie,

The released version does not correctly upgrade all the required system streams with the projection data. I’m creating a small external utility to upgrade system streams with projections. I’ll post here when it is ready.

would this have anything to do with the fact the at this point the index has not yet been build ??!

Projections are initialized when the system is ready for use. (There are two system starts on the log, so there are two projection initialization records there. )

best regards

-yuriy

Jeremie_Chassaing · July 24, 2013, 5:42am

The commande line is:

EventStore.SingleNode.exe -d c:\Data\Events -log c:\Data\Logs --run-projections=all

Jeremie_Chassaing · July 24, 2013, 5:45am

Ok, thanks !

For info, what kind of change is required on system streams for the upgrade?

Yuri_Solodkyy · July 24, 2013, 7:58am

Jérémie,

I pushed a small utility that should fix the problem.

https://github.com/EventStore/EventStore/tree/dev/src/EventStore/Tools/EventStore.UpgradeProjections

(We will make binaries downloadable soon).

We changed the event names used in the projections subsystem to be consistent with the rest of the system. All the internal event names are prefixed with $. The utility just reads all the definitions and writes the same data back with new event types.

You should run it connected to the EventStore v2.0. Restart the event store when it completes.

Note, that you need to pass at least --upgrade to run the conversion. See --help.

kind regards

-yuriy

Jeremie_Chassaing · July 24, 2013, 8:35am

Nice !

I tried it and it works.

Thx

jeremie / thinkbeforecoding

Jeremie_Chassaing · July 24, 2013, 10:17am

I’ve crafted a PowerShell version of the tool, no need to compile anything this way.

More about this later

jeremie / thinkbeforecoding