Why is reading a stream much slower second time?

Daniel_Ryan · April 10, 2014, 4:14pm

I am evaluating Event Store and am running into a funny performance problem. I am trying to ascertain how many events I can replay for a aggregate whilst trying to avoid snapshots. I was happy to discover that I could replay 15,000 events as part of a test within 0.8 seconds which I am happy with; unfortunately when I run alongside a test that only replays 4 events on another stream, the original test takes 1.5 seconds which is too long.

Is there any reason for this strange behaviour (or maybe I am doing something stupid)?

Here is some code:

public Stock GetResults()

    {

        const int sliceSize = 2000;

        var stock = new Stock();

        using (var connection = EventStoreConnection.Create(new IPEndPoint(IPAddress.Loopback, 1113)))

        {

            connection.Connect();

            StreamEventsSlice currentSlice;

            var streamEvents = new List<ResolvedEvent>();

            var sw = new Stopwatch();

            sw.Start();

            var nextSliceStart = StreamPosition.Start;

            do

            {

                

                currentSlice = connection.ReadStreamEventsForward(_sku, nextSliceStart, sliceSize, false);

                nextSliceStart = currentSlice.NextEventNumber;

                streamEvents.AddRange(currentSlice.Events);

            } while (!currentSlice.IsEndOfStream);

            sw.Stop();

// This shows as 200 milliseconds the first time but over a second next time

            Debug.WriteLine("1:{0}", sw.ElapsedMilliseconds);

            sw.Reset();

            sw.Start();

            

            var events = streamEvents.AsParallel().Select(DeserializeObject).ToList();

            sw.Stop();

            Debug.WriteLine("2:{0}", sw.ElapsedMilliseconds);

            sw.Reset();

            sw.Start();

            foreach (var stockEventProcessor in _eventProcessors)

            {

                stockEventProcessor.Handle(stock, events);

            }

            sw.Stop();

            Debug.WriteLine("3:{0}", sw.ElapsedMilliseconds);

            connection.Close();

        }

        return stock;

    }

Here is the test:

[Test]

public void HowQuicklyAreTheEventsReplayed()

{

string skuIdentifier1 = Guid.NewGuid().ToString();

var stockEventController2 = Bootstrapper.GetInstance().Resolve();

var stockEvents1 = new List

{

new PutAwayEvent(Guid.NewGuid(), skuIdentifier1, 4),

new DespatchEvent(Guid.NewGuid(), skuIdentifier1, 1)

};

stockEventController2.Put(skuIdentifier1, stockEvents1);

// If I comment this line then the performance is good again.

var stock1 = stockEventController2.Get(skuIdentifier1);

string skuIdentifier = Guid.NewGuid().ToString();

var stockEventHandler = Bootstrapper.GetInstance().Resolve();

var stockEvents = new List();

for (int i = 0; i < 10000; i++)

{

stockEvents.Add(new PutAwayEvent(Guid.NewGuid(), skuIdentifier, 1));

}

for (int i = 0; i < 5000; i++)

{

stockEvents.Add(new DespatchEvent(Guid.NewGuid(), skuIdentifier, 1));

}

stockEventHandler.Put(skuIdentifier, stockEvents);

var sw = new Stopwatch();

sw.Start();

var stock = stockEventHandler.Get(skuIdentifier);

sw.Stop();

Assert.AreEqual(5000, stock.InStock);

Assert.AreEqual(5000, stock.Available);

Debug.WriteLine(“Milli={0}”, sw.ElapsedMilliseconds);

Assert.IsTrue(sw.ElapsedMilliseconds < 1000);

}

Greg_Young1 · April 10, 2014, 4:17pm

What is the size of your database? Are you on a ssd/spindle?

What version are you running?

Do you have other things going on in the threadpool that could be locking up threadpool threads (eg does adding more etc help?)

Cheers,

Greg

Daniel_Ryan · April 10, 2014, 4:26pm

I am running the release version from the main download link.

The database is very small; around 100,000 events.

All the code executes on the main thread (apart from the AsParallel() which happens after the reading of events). It’s almost as if switching of streams (that are being read) causes the delay but this doesn’t seem right?

Greg_Young1 · April 10, 2014, 4:28pm

the RC release or the 2.0.x release?

Daniel_Ryan · April 10, 2014, 4:31pm

Sorry: it’s the 2.0.0.0 release.

Greg_Young1 · April 10, 2014, 4:50pm

So quite a few questions here as this is really a micro-benchmark (many things can cause a 500ms change in measurements).

What happens if they are run 50-100 times with sampling.
What serialization are you using that must be hitting 50k/sec I dont think most of the default serializers can do this well
Is this a “warmed up” run or a first run? In general you should prefer to run tests on warmed up code.
Is this over a network or loopback? it says loopback but maybe you are running differently

Some of these changes can be seen easily just using the testclient (eg try running wr in it twice and you will see a big difference). As your code is also .net this will also have affect in your code as well.

Also I don’t have an immediate way of running this can you drop in just some meaningful text when you do printouts and include it?

Greg

Daniel_Ryan · April 10, 2014, 4:50pm

I have managed to put all the necessary code to recreate this issue in a GIST:

https://gist.github.com/anonymous/10401348

Daniel_Ryan · April 10, 2014, 6:06pm

The results are very consistent. I have isolated the test, removing deserialization. I have put a stopwatch around just the code that read events in slices. When I append 15000 events to a stream and then read these back (as resolved events only), this takes around 250ms. If I read 4 events on a different stream (using the same function) and then read the stream that contains the 15000 events, this now takes 1000ms. What could cause such a difference?
I’'ve removed the deserialization to isolate the problem. Originally I used jsonsoft to serialize to Json which I converted to a byte stream.
I have a single test that I run. Without fail it runs 4 times quicker when I get 15000 events as a first action as opposed to getting a small stream of events first.
Loopback
Hopefully my gist sheds some more light on this issue? I would be happy to send you a demo tomorrow if that helps?

Greg_Young1 · April 10, 2014, 6:43pm

Inline…

The results are very consistent. I have isolated the test, removing deserialization. I have put a stopwatch around just the code that read events in slices. When I append 15000 events to a stream and then read these back (as resolved events only), this takes around 250ms. If I read 4 events on a different stream (using the same function) and then read the stream that contains the 15000 events, this now takes 1000ms. What could cause such a difference?

Have you tried running 500 times in a row without tearing everything down in between? It could be something as simple as waiting on creation of a thread pool thread. If you can post your latest I can try this though I run in Linux which is possibly different.

Daniel_Ryan · April 10, 2014, 6:59pm

Thanks, I’ll give this a try and get back to you.

Greg_Young1 · April 11, 2014, 7:56am

What is StockEvent? It is not included.

Greg_Young1 · April 11, 2014, 8:43am

I have altered your code to make it compile and runnable.

I am not seeing the behaviour you discussed. Please see code at https://gist.github.com/gregoryyoung/10449466

To fully reproduce I am running latest mono (master) and you can compile against event store with:

dmcs -r:System -r:…/EventStore/bin/eventstore/release/anycpu/EventStore.ClientAPI.dll -r …/EventStore/src/EventStore/libs/Newtonsoft.Json.dll foo.cs

obviously changing out the paths for your own libraries.

I am seeing some runs that take ±1sec vs 300ms but I am seeing 0 correlation between the line of code you mentioned and it happening (I can get it to happen with and without that line of code in terms of difference). With verbose logging enabled you can see what is going on a bit better. Most of mine (±85% come out ± 1 second to read 15000 events sized ± 5 MB)

Cheers,

Greg

Greg_Young1 · April 11, 2014, 9:13am

some further information in the ones that take one second the difference can be seen happening in the client not on the backend. Below is a log of the full interchange of such a circumstance.

Note that a 800ms pause happens between connecting and starting the message interchanges. My guess this is a thread starting in the client. If I run on a reused connection this behaviour is only seen on the first run. The updated code showing this can be found here https://gist.github.com/gregoryyoung/10451703 the first read takes 1.2 seconds then all others are between 200-300ms. As such it seems that the creation of the thread internally is what is taking the time (if a new connection every time its back to ± 1 second).

A bit further digging leads to https://github.com/EventStore/EventStore/blob/master/src/EventStore/EventStore.ClientAPI/Core/SimpleQueuedHandler.cs which is used for internal handling. You will notice that it uses the ThreadPool. It seems the first call through the threadpool takes ± 800ms which sounds like a thread getting started internally. We can likely move this off the ThreadPool and to our own Thread (or a Task with longrunning=true) however if you were to have lots of connection simultaneously opened this would cause issues for you as every connection would have its own thread.

Hope this makes sense.

Cheers,

Greg

[01,08:51:54.306,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartConnectionMessage…

[04,08:51:54.311,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartConnection.

[04,08:51:54.311,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: DiscoverEndPoint.

[04,08:51:54.311,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.EstablishTcpConnectionMessage…

Reading events.

[01,08:51:54.312,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:54.312,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: EstablishTcpConnection to [127.0.0.1:1113].

[04,08:51:54.314,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation enqueue ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 0, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:54.315,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: EnqueueOperation WAITING for Operation ReadStreamEventsForwardOperation ({a24851b2-0d33-46ee-92cc-b0ec15a6d3be}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 0, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:54.314, last updated: 08:51:54.314…

[04,08:51:54.315,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:60913, {8afac9f6-0290-48d4-95ce-edaeb0d98dd9}].

[04,08:51:54.315,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.TcpConnectionEstablishedMessage…

[04,08:51:54.315,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: TCP connection to [127.0.0.1:1113, L127.0.0.1:60913, {8afac9f6-0290-48d4-95ce-edaeb0d98dd9}] established…

[04,08:51:55.107,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.114,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package HeartbeatResponseCommand, 986175eb-27f1-4606-a200-55968497055d…

[04,08:51:55.311,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, a24851b2-0d33-46ee-92cc-b0ec15a6d3be, Operation ReadStreamEventsForwardOperation ({a24851b2-0d33-46ee-92cc-b0ec15a6d3be}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 0, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:54.314, last updated: 08:51:55.306…

[04,08:51:55.335,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.335,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, a24851b2-0d33-46ee-92cc-b0ec15a6d3be…

[04,08:51:55.361,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({a24851b2-0d33-46ee-92cc-b0ec15a6d3be}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 0, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:54.314, last updated: 08:51:55.306.

[04,08:51:55.361,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({a24851b2-0d33-46ee-92cc-b0ec15a6d3be}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 0, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:54.314, last updated: 08:51:55.306.

[01,08:51:55.362,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:55.362,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation schedule ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 2000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:55.362,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, 856d61fe-76be-407b-96fc-c531e399b69b, Operation ReadStreamEventsForwardOperation ({856d61fe-76be-407b-96fc-c531e399b69b}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 2000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.362, last updated: 08:51:55.362…

[04,08:51:55.383,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.383,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, 856d61fe-76be-407b-96fc-c531e399b69b…

[04,08:51:55.392,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({856d61fe-76be-407b-96fc-c531e399b69b}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 2000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.362, last updated: 08:51:55.362.

[04,08:51:55.392,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({856d61fe-76be-407b-96fc-c531e399b69b}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 2000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.362, last updated: 08:51:55.362.

[01,08:51:55.392,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:55.392,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation schedule ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 4000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:55.392,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, 3a5ebbe6-9bd5-4bfb-8482-5595cae00d98, Operation ReadStreamEventsForwardOperation ({3a5ebbe6-9bd5-4bfb-8482-5595cae00d98}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 4000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.392, last updated: 08:51:55.392…

[04,08:51:55.410,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.410,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, 3a5ebbe6-9bd5-4bfb-8482-5595cae00d98…

[04,08:51:55.417,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({3a5ebbe6-9bd5-4bfb-8482-5595cae00d98}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 4000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.392, last updated: 08:51:55.392.

[01,08:51:55.417,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:55.417,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({3a5ebbe6-9bd5-4bfb-8482-5595cae00d98}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 4000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.392, last updated: 08:51:55.392.

[04,08:51:55.417,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation schedule ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 6000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:55.417,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, bd2ee770-2a60-48be-9f21-d8a7709a6ad2, Operation ReadStreamEventsForwardOperation ({bd2ee770-2a60-48be-9f21-d8a7709a6ad2}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 6000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.417, last updated: 08:51:55.417…

[04,08:51:55.441,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.441,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, bd2ee770-2a60-48be-9f21-d8a7709a6ad2…

[04,08:51:55.446,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({bd2ee770-2a60-48be-9f21-d8a7709a6ad2}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 6000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.417, last updated: 08:51:55.417.

[01,08:51:55.446,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:55.446,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({bd2ee770-2a60-48be-9f21-d8a7709a6ad2}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 6000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.417, last updated: 08:51:55.417.

[04,08:51:55.447,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation schedule ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 8000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:55.447,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, 0a7f417e-7562-4184-b80d-adbcba7d22f4, Operation ReadStreamEventsForwardOperation ({0a7f417e-7562-4184-b80d-adbcba7d22f4}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 8000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.447, last updated: 08:51:55.447…

[04,08:51:55.463,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.464,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, 0a7f417e-7562-4184-b80d-adbcba7d22f4…

[04,08:51:55.482,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({0a7f417e-7562-4184-b80d-adbcba7d22f4}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 8000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.447, last updated: 08:51:55.447.

[04,08:51:55.482,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({0a7f417e-7562-4184-b80d-adbcba7d22f4}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 8000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.447, last updated: 08:51:55.447.

[01,08:51:55.482,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:55.482,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation schedule ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 10000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:55.482,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, 58512b46-9d1a-4b0c-afcf-566ccbe6fa42, Operation ReadStreamEventsForwardOperation ({58512b46-9d1a-4b0c-afcf-566ccbe6fa42}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 10000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.482, last updated: 08:51:55.482…

[04,08:51:55.516,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.516,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, 58512b46-9d1a-4b0c-afcf-566ccbe6fa42…

[04,08:51:55.520,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({58512b46-9d1a-4b0c-afcf-566ccbe6fa42}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 10000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.482, last updated: 08:51:55.482.

[01,08:51:55.520,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:55.520,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({58512b46-9d1a-4b0c-afcf-566ccbe6fa42}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 10000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.482, last updated: 08:51:55.482.

[04,08:51:55.520,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation schedule ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 12000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:55.520,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, f752f73e-9e62-405c-b3af-c041ceaee424, Operation ReadStreamEventsForwardOperation ({f752f73e-9e62-405c-b3af-c041ceaee424}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 12000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.520, last updated: 08:51:55.520…

[04,08:51:55.537,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.537,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, f752f73e-9e62-405c-b3af-c041ceaee424…

[04,08:51:55.548,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({f752f73e-9e62-405c-b3af-c041ceaee424}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 12000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.520, last updated: 08:51:55.520.

[01,08:51:55.548,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.StartOperationMessage…

[04,08:51:55.548,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({f752f73e-9e62-405c-b3af-c041ceaee424}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 12000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.520, last updated: 08:51:55.520.

[04,08:51:55.548,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: StartOperation schedule ReadStreamEventsForwardOperation, Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 14000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

[04,08:51:55.548,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: ScheduleOperation package ReadStreamEventsForward, bf71ec89-ad65-44fd-adbe-174aab706529, Operation ReadStreamEventsForwardOperation ({bf71ec89-ad65-44fd-adbe-174aab706529}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 14000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.548, last updated: 08:51:55.548…

[04,08:51:55.561,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.HandleTcpPackageMessage…

[04,08:51:55.562,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage connId 8afac9f6-0290-48d4-95ce-edaeb0d98dd9, package ReadStreamEventsForwardCompleted, bf71ec89-ad65-44fd-adbe-174aab706529…

[04,08:51:55.565,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadStreamEventsForwardOperation ({bf71ec89-ad65-44fd-adbe-174aab706529}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 14000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.548, last updated: 08:51:55.548.

[01,08:51:55.565,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: enqueueing message EventStore.ClientAPI.Core.CloseConnectionMessage…

[04,08:51:55.565,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: RemoveOperation SUCCEEDED for Operation ReadStreamEventsForwardOperation ({bf71ec89-ad65-44fd-adbe-174aab706529}): Stream: 39a48230-1c0d-488c-9804-2c738b94a603, FromEventNumber: 14000, MaxCount: 2000, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 08:51:55.548, last updated: 08:51:55.548.

[04,08:51:55.565,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: CloseConnection, reason Connection close requested by client., exception …

[04,08:51:55.565,DEBUG] EventStoreConnection ‘ES-c5306123-f6b9-4da6-b669-6a1debfe06b7’: CloseTcpConnection.

done. 00:00:01.2535808

Daniel_Ryan · April 11, 2014, 10:04am

Makes perfect sense. Thanks a lot for your assistance.