Logg query duration, Query Statistics

[Ido Ben Ari]

Hi,

I have a query which sometimes takes long time to execute.

I set detailed timing, and here is what I got (in one specific example):

DurationInMilliseconds: 141 |

Lucene search : 0,

Loading documents : 0,

Transforming results : 139,

Query parsing : 0, 

The total duration measure with StopWatch on the client side is 2.5 seconds. You can see it in the logs below

            var caapSW = new Stopwatch();

            caapSW.Start();

            var rtcFullQuery = dbSession.Query<PI.Domain.DataStructures.RoomTypeContract>("RoomTypeContracts/ByRoomTypeID_HotelCodeAndStatus")

                               .Customize(x => x.ShowTimings())

                               .Where(rp => rp.RoomTypeID.HotelCode == hotelCode)

                               .TransformWith<RoomTypesContractWithRoomTypeTranformerFull, RoomTypesContractWithRoomTypeTranformerFull.Result>()

                               .AddTransformerParameter("dates", checkIn.ToString("yyyy-MM-dd") + "," + checkOut.ToString("yyyy-MM-dd"))

                               .AddTransformerParameter("avlByRP", availabilityByRp)

                               .AddTransformerParameter("interfaceName",interfaceId.ToString())

                               .Statistics(out stats)

                               .ToList();

            var elapsedMS = caapSW.ElapsedMilliseconds; // this is 2.5 seconds

My question - could I assume according to the statics that the total duration for the RavenQuery was 141 MS including the network? In other words, the time to last byte in the client was 141 MS? 

If yes, I would assume the other 2 seconds are spent in the client side only.

Thanks,

Ido

[Oren Eini (Ayende Rahien)]

What does RoomTypesContractWithRoomTypeTranformerFull looks like?

And 141 ms is the time for _first_ byte.

Note that the cost need to divided between cost of querying on the server (141 ms, which is _high_), cost of sending the results over the network, and cost of desrializing them.

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Ido Ben Ari]

Thanks for the prompt reply.

So  it's the network or the desalinization, plus the 141MS is also too slow.

By the way, the response size is 39KB uncompressed, 1.9KB compressed, There were ~15 concurrent quite similar other requests on the same time.

Below is the RoomTypesContractWithRoomTypeTranformerFull  code.

Thanks,

Ido

 public RoomTypesContractWithRoomTypeTranformerFull()

        {

           TransformResults =

                rtcs => from rtc in rtcs

                        let fromDate = DateTime.Parse(Parameter("dates").Value<String>().Split(',')[0])

                        let toDate = DateTime.Parse(Parameter("dates").Value<String>().Split(',')[1])

                        let rtMorRate = rtc.RoomTypeRates.RatePerDateList.Where(x => x.Date >= fromDate && x.Date <= toDate && x.RatesPerLos != null && x.RatesPerLos.Count() > 0)

                        let avlByRP = ParameterOrDefault("avlByRP",false).Value<bool>()

                        let interfaceName = ParameterOrDefault("interfaceName", false).Value<string>()

                        let availability = avlByRP ? LoadDocument<Availability>(String.Format(interfaceName + "__{0}_{1}__{2}__apl_Hotel", rtc.RoomTypeID.HotelCode, rtc.RoomTypeID.RoomTypeCode, rtc.RatePlanCode)) : LoadDocument<Availability>(String.Format(interfaceName + "__{0}_{1}____apl_Hotel", rtc.RoomTypeID.HotelCode, rtc.RoomTypeID.RoomTypeCode))

                        let lpd = availability.LosPerDate.Where(x => x.Date >= fromDate && x.Date <= toDate)

                        where rtMorRate != null && rtMorRate.Count() > 0 && lpd != null && lpd.Count() > 0

                  

                        

                        select new Result()

                        {

                                                     

                            

                          HotelId = rtc.HotelId,

                            RoomTypeID = rtc.RoomTypeID,

                            RatePlanCode = rtc.RatePlanCode,

                            MarketIdentifier = rtc.MarketIdentifier,

                            ValidCheckInDay = rtc.ValidCheckInDay,

                            RateType = rtc.RateType,

                            RoomTypeRates = rtMorRate,

                            BoardBases = rtc.BoardBases,

                            Supplements = rtc.Supplements,

                            Promotions = rtc.Promotions,

                            ContractType = rtc.ContractType,

                            RatePlanName = rtc.RatePlanCode,

                            RoomTypeReferenceDocumentId = rtc.RoomTypeReferenceDocumentId,

                            ClxPolicies = rtc.ClxPolicies,

                          Lpd = lpd,

                        };

[Oren Eini (Ayende Rahien)]

What does fiddler say?

[Ido Ben Ari]

Fiddler shows the similar duration to the DurationInMilliseconds.

So, I think that if it was the network, we would have seen it in the fiddler, right? This leaves mainly the deserialization.

Any thoughts? 

Thanks,

Ido

[Oren Eini (Ayende Rahien)]

Yes, check this in a profiler, your ctor is likely doing something very expensive.

[Ido Ben Ari]

Thanks. I still couldn't find anything which explains it, let alone maybe generally resources problem in the machine (not something obvious like high CPU / Memory though). The constructors do nothing.

I also see that in some of the cases (~10%) the time it takes to transform results in the transformer is very long, > 1 second. I wanted to check if you see anything wrong with its code? It's the same one I put in this loop before, and I am putting it down here again.

In the transformer, I suppose I load (the raw data) , in the worst case around 10 document each 200KB, so a total of 2 MB. Out of which the I extract around 50KB. Would you say it's too much data to load in one action?

[Oren Eini (Ayende Rahien)]

When you are running in a profiler, what is the output?

[Ido Ben Ari]

Thanks Oren.

I'm attaching a sample profiler results. So far I see nothing special. This is for the client side, and I keep investigating.

As for the transformer code, I was wondering if you see anything special?

Thanks,

Ido

 

[Maxim Buryak]

Hi,

This actually shows that most of the time, we are busy deserializing the json into the object. 

It seems that you get to desirialize pretty nested (I could see 5 levels) and possibly big object, what is the raw size as you see it in fiddler? 

Also, could you send us the raw profiler output, so we could have a closer look?

Best Regards,

Hibernating Rhinos Ltd  

Maxim Buryak l Core Team Developer l Mobile:+972-54-217-7751

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/  

[Ido Ben Ari]

Hi Maxim,

It's ~50KB for the big requests (uncompressed). Sometimes there can be 10-20 such in parallel.

I am attaching the vspx file.

Thanks,

Ido

--
You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/akMOtXuDPxs/unsubscribe.
To unsubscribe from this group and all its topics, send an email to ravendb+u...@googlegroups.com.

[Maxim Buryak]

Hi,

what the profiler shows is just the json deserialization. It seems that your 50KB documents are highly nested and that's why the json deserialization is so heavy.

You have to ask yourself if you need all that data in the client (or can you use a transformer to reduce object size) another option would be to stick with RavenJObject and do not try desirializing the data into your own classes.

Best Regards,

Hibernating Rhinos Ltd  

Maxim Buryak l Core Team Developer l Mobile:+972-54-217-7751

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/  

[Ido Ben Ari]

Thanks Maxim.

I am attaching an example of the most common document...Is it too complicated, am I supposed to simplify it, or to re-create my documents structure? 

Also, let's assume that I stick with RavenJObject or transform the data differently - what about serialization in the server (Raven) side?  If my structure is too complicated isn't that a problem?

Generally speaking, if I want to build a high performance application with Raveb , is the recommnded pattern to build as simple as possible document structure? 

Thanks,

Ido

[Maxim Buryak]

Hi,

About structure in general:

First, the document structure is fine, but it should it transformed according to the usage of the data. You have to ask yourself - do you need the whole object where you query it, or do you want to get the "detailed" document only in specific occations?

About transformation - note that you are already performain transformation (you actually have LoadDocument inside the transformer, what makes it heavier)

About timing:

The example you sent is very simple, and from the profiler output I see traces of more complex structures. Such a long time inside the deserialization means that there is a lot to do.

Please measure timing under load and without load.

Under what load the system is (requests per second and duration of the load)

Best Regards,

Hibernating Rhinos Ltd  

Maxim Buryak l Core Team Developer l Mobile:+972-54-217-7751

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/  

[Ido Ben Ari]

Hi again,

Still investigating the problem. Have implemented custom desalinization, didn't seem to help.

Now I see a little different behavior then what I described before:

RavenDB statistics: DurationMilliseconds: 432

But, as you can see in the fiddler times below, it took the server almost 2 seconds to begin response.and then 3 seconds between TTFB to TTLB. 

So, what should I assume if fiddler duration in MS is 432 but TTFB according to fiddler is 2 seconds?

Thanks,

Ido

== TIMING INFO ============

ClientConnected: 22:52:50.829

ClientBeginRequest: 22:52:50.829

GotRequestHeaders: 22:52:50.829

ClientDoneRequest: 22:52:50.829

Determine Gateway: 0ms

DNS Lookup: 0ms

TCP/IP Connect: 0ms

HTTPS Handshake: 0ms

ServerConnected: 22:52:50.829

FiddlerBeginRequest: 22:52:50.829

ServerGotRequest: 22:52:50.829

ServerBeginResponse: 22:52:52.672

GotResponseHeaders: 22:52:52.672

ServerDoneResponse: 22:52:55.313

ClientBeginResponse: 22:52:55.313

ClientDoneResponse: 22:52:55.313

[Oren Eini (Ayende Rahien)]

That might be the server loading the db, that is one explanation for this duration

Or a server that has a LOT of concurrent requests and is being throttled

[Ido Ben Ari]

I think that it's garbage collections of ravendb which cause the problem. 

[Tal Weiss]

you can use perfview to check Raven cpu % and time spent in gc% 

Tal Weiss l Core Team Developer l Mobile:+972-54-802-4849

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811l Skype: talweiss1982