Re: Confusing debug=timing parameter

[Walter Underwood]

One other thing. How many results are being requested? That is, what is the 
“rows” parameter?

Time includes query time. It does not include networking time for sending 
10,000 huge results to the client.

wunder
Walter Underwood
wun...@wunderwood.org
http://observer.wunderwood.org/  (my blog)


> On Dec 19, 2016, at 9:47 AM, Chris Hostetter <hossman_luc...@fucit.org> wrote:
> 
> 
> SG:
> 
> IIRC, when doing a distributed/cloud search, the timing info returned for 
> each stage is the *cummulative* time spent on that stage in all shards -- 
> so if you have 4 shards, the "process" time reported could be 4x as much 
> as the actual process time spent.
> 
> The QTime reported back (in a distributed query) is the "wall clock' time 
> spent by the single node that coordinated the response, *NOT* including 
> time spent writting the response back to the client.
> 
> 
> So let's imagine you have a single Solr node, and a client that says the 
> total time for a Solr query took 5 seconds, but the QTime reported by solr 
> is 1 second -- that suggests that 4 seconds was spent in either some sort 
> of general network overhead between the client & solr, or in time spent 
> reading docs from disk if (AND ONLY IF) Solr is running in single node 
> mode, where Solr defers disk reads as long as possible and does those 
> reads only as needed to write the response.  In this single node setup, 
> you should *NEVER* see the cumulative debug=timing time exceed the QTime 
> (for any reason i can think of)
> 
> In a distributed query, with multiple solr nodes, any discrepency between 
> the QTime and the time reported by the client is going to be related to 
> network overhead (or client overhead, parsing hte response) because Solr 
> isn't able to do any "local reads" of docs from disk when writting the 
> response.  imagine in this situation you have client reports 5 seconds, 
> QTime reports 1 second, and debug=timing reports 45 seconds.   that 45 
> seconds isn't "real" wall clock time, it's just 45 total seconds of time 
> spent on all the nodes in parallel added up cumulatively.  the 5 second vs 
> 1 second discrepency would be from the network communication overhead, or 
> client overhead in parsing hte response before proting "success"
> 
> does that make sense?
> 
> 
> 
> : Date: Sat, 17 Dec 2016 08:43:53 -0800
> : From: S G <sg.online.em...@gmail.com>
> : Reply-To: solr-user@lucene.apache.org
> : To: solr-user@lucene.apache.org
> : Subject: Confusing debug=timing parameter
> : 
> : Hi,
> : 
> : I am using Solr 4.10 and its response time for the clients is not very good.
> : Even though the Solr's plugin/stats shows less than 200 milliseconds,
> : clients report several seconds in response time.
> : 
> : So I tried using debug-timing parameter from the Solr UI and this is what I
> : got.
> : Note how the QTime is 2978 while the time in debug-timing is 19320.
> : 
> : What does this mean?
> : How can Solr return a result in 3 seconds when time taken between two
> : points in the same path is 20 seconds ?
> : 
> : {
> :   "responseHeader": {
> : "status": 0,
> : "QTime": 2978,
> : "params": {
> :   "q": "*:*",
> :   "debug": "timing",
> :   "indent": "true",
> :   "wt": "json",
> :   "_": "1481992653008"
> : }
> :   },
> :   "response": {
> : "numFound": 1565135270,
> : "start": 0,
> : "maxScore": 1,
> : "docs": [
> :   
> : ]
> :   },
> :   "debug": {
> : "timing": {
> :   "time": 19320,
> :   "prepare": {
> : "time": 4,
> : "query": {
> :   "time": 3
> : },
> : "facet": {
> :   "time": 0
> : },
> : "mlt": {
> :   "time": 0
> : },
> : "highlight": {
> :   "time": 0
> : },
> : "stats": {
> :   "time": 0
> : },
> : "expand": {
> :   "time": 0
> : },
> : "debug": {
> :   "time": 0
> : }
> :   },
> :   "process": {
> : "time": 19315,
> : "query": {
> :   "time": 19309
> : },
> : "facet": {
> :   "time": 0
> : },
> : "mlt": {
> :   "time": 1
> : },
> : "highlight": {
> :   "time": 0
> : },
> : "stats": {
> :   "time": 0
> : },
> : "expand": {
> :   "time": 0
> : },
> : "debug": {
> :   "time": 5
> : }
> :   }
> : }
> :   }
> : }
> : 
> 
> -Hoss
> http://www.lucidworks.com/

Re: Confusing debug=timing parameter

[Chris Hostetter]

SG:

IIRC, when doing a distributed/cloud search, the timing info returned for 
each stage is the *cummulative* time spent on that stage in all shards -- 
so if you have 4 shards, the "process" time reported could be 4x as much 
as the actual process time spent.

The QTime reported back (in a distributed query) is the "wall clock' time 
spent by the single node that coordinated the response, *NOT* including 
time spent writting the response back to the client.


So let's imagine you have a single Solr node, and a client that says the 
total time for a Solr query took 5 seconds, but the QTime reported by solr 
is 1 second -- that suggests that 4 seconds was spent in either some sort 
of general network overhead between the client & solr, or in time spent 
reading docs from disk if (AND ONLY IF) Solr is running in single node 
mode, where Solr defers disk reads as long as possible and does those 
reads only as needed to write the response.  In this single node setup, 
you should *NEVER* see the cumulative debug=timing time exceed the QTime 
(for any reason i can think of)

In a distributed query, with multiple solr nodes, any discrepency between 
the QTime and the time reported by the client is going to be related to 
network overhead (or client overhead, parsing hte response) because Solr 
isn't able to do any "local reads" of docs from disk when writting the 
response.  imagine in this situation you have client reports 5 seconds, 
QTime reports 1 second, and debug=timing reports 45 seconds.   that 45 
seconds isn't "real" wall clock time, it's just 45 total seconds of time 
spent on all the nodes in parallel added up cumulatively.  the 5 second vs 
1 second discrepency would be from the network communication overhead, or 
client overhead in parsing hte response before proting "success"

does that make sense?



: Date: Sat, 17 Dec 2016 08:43:53 -0800
: From: S G <sg.online.em...@gmail.com>
: Reply-To: solr-user@lucene.apache.org
: To: solr-user@lucene.apache.org
: Subject: Confusing debug=timing parameter
: 
: Hi,
: 
: I am using Solr 4.10 and its response time for the clients is not very good.
: Even though the Solr's plugin/stats shows less than 200 milliseconds,
: clients report several seconds in response time.
: 
: So I tried using debug-timing parameter from the Solr UI and this is what I
: got.
: Note how the QTime is 2978 while the time in debug-timing is 19320.
: 
: What does this mean?
: How can Solr return a result in 3 seconds when time taken between two
: points in the same path is 20 seconds ?
: 
: {
:   "responseHeader": {
: "status": 0,
: "QTime": 2978,
: "params": {
:   "q": "*:*",
:   "debug": "timing",
:   "indent": "true",
:   "wt": "json",
:   "_": "1481992653008"
: }
:   },
:   "response": {
: "numFound": 1565135270,
: "start": 0,
: "maxScore": 1,
: "docs": [
:   
: ]
:   },
:   "debug": {
: "timing": {
:   "time": 19320,
:   "prepare": {
: "time": 4,
: "query": {
:   "time": 3
: },
: "facet": {
:   "time": 0
: },
: "mlt": {
:   "time": 0
: },
: "highlight": {
:   "time": 0
: },
: "stats": {
:   "time": 0
: },
: "expand": {
:   "time": 0
: },
: "debug": {
:   "time": 0
: }
:   },
:   "process": {
: "time": 19315,
: "query": {
:   "time": 19309
: },
: "facet": {
:   "time": 0
: },
: "mlt": {
:   "time": 1
: },
: "highlight": {
:   "time": 0
: },
: "stats": {
:   "time": 0
: },
: "expand": {
:   "time": 0
: },
: "debug": {
:   "time": 5
: }
:   }
: }
:   }
: }
: 

-Hoss
http://www.lucidworks.com/

Re: Confusing debug=timing parameter

[S G]

Thank you Furkan.

I am still a little confused.
So I will shorten the response and post only the relevant pieces for easier
understanding.

 "responseHeader": {
"status": 0,
"QTime": 2978
}
 "response": {
"numFound": 1565135270,
  },
  "debug": {
"timing": {
  "time": 19320,
  "prepare": {
"time": 4,
"query": {
  "time": 3
},
  "process": {
"time": 19315,
"query": {
  "time": 19309
}
   }
}

As I understand, QTime is the total time spent by the core.
"process", "prepare" etc. are all the parts that together make the part of
query processing.
And so their times should approximately add up to the QTime.
Numbers wise, I would have expected prepare-time + process-time <= QTime
Or 4 + 19315 <= 2978
This is obviously not correct.

Where am I making a mistake?
Any pointers would be greatly appreciated.

Thanks
SG




On Sun, Dec 18, 2016 at 4:40 AM, Furkan KAMACI 
wrote:

> Hi,
>
> Let me explain you *time* *parameters in Solr*:
>
> *Timing* parameter of debug returns information about how long the query
> took to process.
>
> *Query time* shows information of how long did it take in Solr to get the
> search
> results. It doesn't include reading bits from disk, etc.
>
> Also, there is another parameter named as *elapsed time*. It shows time
> frame of the query sent to Solr and response is returned. Includes query
> time, reading bits from disk, constructing the response and transmissioning
> it, etc.
>
> Kind Regards,
> Furkan KAMACI
>
> On Sat, Dec 17, 2016 at 6:43 PM, S G  wrote:
>
> > Hi,
> >
> > I am using Solr 4.10 and its response time for the clients is not very
> > good.
> > Even though the Solr's plugin/stats shows less than 200 milliseconds,
> > clients report several seconds in response time.
> >
> > So I tried using debug-timing parameter from the Solr UI and this is
> what I
> > got.
> > Note how the QTime is 2978 while the time in debug-timing is 19320.
> >
> > What does this mean?
> > How can Solr return a result in 3 seconds when time taken between two
> > points in the same path is 20 seconds ?
> >
> > {
> >   "responseHeader": {
> > "status": 0,
> > "QTime": 2978,
> > "params": {
> >   "q": "*:*",
> >   "debug": "timing",
> >   "indent": "true",
> >   "wt": "json",
> >   "_": "1481992653008"
> > }
> >   },
> >   "response": {
> > "numFound": 1565135270,
> > "start": 0,
> > "maxScore": 1,
> > "docs": [
> >   
> > ]
> >   },
> >   "debug": {
> > "timing": {
> >   "time": 19320,
> >   "prepare": {
> > "time": 4,
> > "query": {
> >   "time": 3
> > },
> > "facet": {
> >   "time": 0
> > },
> > "mlt": {
> >   "time": 0
> > },
> > "highlight": {
> >   "time": 0
> > },
> > "stats": {
> >   "time": 0
> > },
> > "expand": {
> >   "time": 0
> > },
> > "debug": {
> >   "time": 0
> > }
> >   },
> >   "process": {
> > "time": 19315,
> > "query": {
> >   "time": 19309
> > },
> > "facet": {
> >   "time": 0
> > },
> > "mlt": {
> >   "time": 1
> > },
> > "highlight": {
> >   "time": 0
> > },
> > "stats": {
> >   "time": 0
> > },
> > "expand": {
> >   "time": 0
> > },
> > "debug": {
> >   "time": 5
> > }
> >   }
> > }
> >   }
> > }
> >
>

Re: Confusing debug=timing parameter

[Furkan KAMACI]

Hi,

Let me explain you *time* *parameters in Solr*:

*Timing* parameter of debug returns information about how long the query
took to process.

*Query time* shows information of how long did it take in Solr to get the
search
results. It doesn't include reading bits from disk, etc.

Also, there is another parameter named as *elapsed time*. It shows time
frame of the query sent to Solr and response is returned. Includes query
time, reading bits from disk, constructing the response and transmissioning
it, etc.

Kind Regards,
Furkan KAMACI

On Sat, Dec 17, 2016 at 6:43 PM, S G  wrote:

> Hi,
>
> I am using Solr 4.10 and its response time for the clients is not very
> good.
> Even though the Solr's plugin/stats shows less than 200 milliseconds,
> clients report several seconds in response time.
>
> So I tried using debug-timing parameter from the Solr UI and this is what I
> got.
> Note how the QTime is 2978 while the time in debug-timing is 19320.
>
> What does this mean?
> How can Solr return a result in 3 seconds when time taken between two
> points in the same path is 20 seconds ?
>
> {
>   "responseHeader": {
> "status": 0,
> "QTime": 2978,
> "params": {
>   "q": "*:*",
>   "debug": "timing",
>   "indent": "true",
>   "wt": "json",
>   "_": "1481992653008"
> }
>   },
>   "response": {
> "numFound": 1565135270,
> "start": 0,
> "maxScore": 1,
> "docs": [
>   
> ]
>   },
>   "debug": {
> "timing": {
>   "time": 19320,
>   "prepare": {
> "time": 4,
> "query": {
>   "time": 3
> },
> "facet": {
>   "time": 0
> },
> "mlt": {
>   "time": 0
> },
> "highlight": {
>   "time": 0
> },
> "stats": {
>   "time": 0
> },
> "expand": {
>   "time": 0
> },
> "debug": {
>   "time": 0
> }
>   },
>   "process": {
> "time": 19315,
> "query": {
>   "time": 19309
> },
> "facet": {
>   "time": 0
> },
> "mlt": {
>   "time": 1
> },
> "highlight": {
>   "time": 0
> },
> "stats": {
>   "time": 0
> },
> "expand": {
>   "time": 0
> },
> "debug": {
>   "time": 5
> }
>   }
> }
>   }
> }
>

Confusing debug=timing parameter

[S G]

Hi,

I am using Solr 4.10 and its response time for the clients is not very good.
Even though the Solr's plugin/stats shows less than 200 milliseconds,
clients report several seconds in response time.

So I tried using debug-timing parameter from the Solr UI and this is what I
got.
Note how the QTime is 2978 while the time in debug-timing is 19320.

What does this mean?
How can Solr return a result in 3 seconds when time taken between two
points in the same path is 20 seconds ?

{
  "responseHeader": {
"status": 0,
"QTime": 2978,
"params": {
  "q": "*:*",
  "debug": "timing",
  "indent": "true",
  "wt": "json",
  "_": "1481992653008"
}
  },
  "response": {
"numFound": 1565135270,
"start": 0,
"maxScore": 1,
"docs": [
  
]
  },
  "debug": {
"timing": {
  "time": 19320,
  "prepare": {
"time": 4,
"query": {
  "time": 3
},
"facet": {
  "time": 0
},
"mlt": {
  "time": 0
},
"highlight": {
  "time": 0
},
"stats": {
  "time": 0
},
"expand": {
  "time": 0
},
"debug": {
  "time": 0
}
  },
  "process": {
"time": 19315,
"query": {
  "time": 19309
},
"facet": {
  "time": 0
},
"mlt": {
  "time": 1
},
"highlight": {
  "time": 0
},
"stats": {
  "time": 0
},
"expand": {
  "time": 0
},
"debug": {
  "time": 5
}
  }
}
  }
}