How long does a query?q=field1:2312 should cost? exactly hit one document.

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

How long does a query?q=field1:2312 should cost? exactly hit one document.

zhenyuan wei
Hi ,
   I am curious “How long does a  query q=field1:2312 cost ,   which
exactly match only one document? ”,  Of course we just discuss  no
 queryResultCache with match in this situation.
   In fact  my QTime is  150ms+, it is too long.
Reply | Threaded
Open this post in threaded view
|

Re: How long does a query?q=field1:2312 should cost? exactly hit one document.

Erik Hatcher-4
Add debug=true and see where the time goes, in which components?

Highlighting is my culprit guess.   Or faceting?

> On Sep 3, 2018, at 07:45, zhenyuan wei <[hidden email]> wrote:
>
> Hi ,
>   I am curious “How long does a  query q=field1:2312 cost ,   which
> exactly match only one document? ”,  Of course we just discuss  no
> queryResultCache with match in this situation.
>   In fact  my QTime is  150ms+, it is too long.
Reply | Threaded
Open this post in threaded view
|

Re: How long does a query?q=field1:2312 should cost? exactly hit one document.

zhenyuan wei
Only a termQuery q=field1:2312, No other conditions.
I try debug now, but can not find out  what is the main cost.
Debug=timing output like :

{
  "responseHeader":{
    "zkConnected":true,
    "status":0,
    "QTime":157,
    "params":{
      "q":"v00_s:15de21c670ae7c3f6f3f1f37029303c9",
      "debug":"timing"}},
  "response":{"numFound":1,"start":0,"maxScore":17.099754,"docs":[
      {
        "v00_s":"15de21c670ae7c3f6f3f1f37029303c9",
        "v01_s":"7596295605015",
        "v02_s":"Mp9XkmrRXhFChgMAGoydOvAD",
        "v03_l":555,
        "v04_s":"55",
        "v05_s":"39994237071313698949",
        "v06_s":"3",
        "v07_s":"155",
        "v08_s":"5",
        "v09_s":"15",
        "v10_s":"15",
        "v11_s":"555",
        "v12_s":"43819292",
        "v13_s":"549754428",
        "v14_s":"8111596961",
        "id":"00000000000000000000000555",
        "_version_":1610106981630083079}]
  },
  "debug":{
    "timing":{
      "time":6336.0,
      "prepare":{
        "time":8.0,
        "query":{
          "time":8.0},
        "facet":{
          "time":0.0},
        "facet_module":{
          "time":0.0},
        "mlt":{
          "time":0.0},
        "highlight":{
          "time":0.0},
        "stats":{
          "time":0.0},
        "expand":{
          "time":0.0},
        "terms":{
          "time":0.0},
        "debug":{
          "time":0.0}},
      "process":{
        "time":6270.0,
        "query":{
          "time":6268.0,
          "doProcessSearchByIds":{
            "time":0.0},
          "doProcessUngroupedSearch":{
            "time":6265.0,
            "search":{
              "time":6261.0,
              "getDocListC":{
                "time":6261.0,
                "lookup_queryResultCache":{
                  "time":0.0},
                "lookupNotuseFilterCacheTimer":{
                  "time":6258.0},
                "getDocListNCTimer":{
                  "time":6258.0,
                  "getProcessedFilter":{
                    "time":0.0},
                  "buildAndRunCollectorChain2":{
                    "time":6255.0},
                  "topDocs":{
                    "time":0.0}}}},
            "doFieldSortValues":{
              "time":0.0},
            "doPrefetch":{
              "time":0.0}}},
        "facet":{
          "time":0.0},
        "facet_module":{
          "time":0.0},
        "mlt":{
          "time":0.0},
        "highlight":{
          "time":0.0},
        "stats":{
          "time":0.0},
        "expand":{
          "time":0.0},
        "terms":{
          "time":0.0},
        "debug":{
          "time":0.0}}}}}


My request is :  curl "
http://emr-worker-2:8983/solr/collection001/query?q=v00_s:
15de21c670ae7c3f6f3f1f37029303c9&debug=timing"

I  also hope to using debug=true to find out more things,so I added some
sub timer to trace which sub method is slowly.
And found , as above,  the "SolrIndexSearch.buildAndRunCollectorChain() "
cost a lot。
( if I want to  find out the answer, I think I have not idea but  debug
tracing  to deeper into lucene level method.)

*At this moment, I have another question too, why  debug time is 6336.0,
which less than QTime=157 ? *
















Erik Hatcher <[hidden email]> 于2018年9月3日周一 下午8:30写道:

> Add debug=true and see where the time goes, in which components?
>
> Highlighting is my culprit guess.   Or faceting?
>
> > On Sep 3, 2018, at 07:45, zhenyuan wei <[hidden email]> wrote:
> >
> > Hi ,
> >   I am curious “How long does a  query q=field1:2312 cost ,   which
> > exactly match only one document? ”,  Of course we just discuss  no
> > queryResultCache with match in this situation.
> >   In fact  my QTime is  150ms+, it is too long.
>
Reply | Threaded
Open this post in threaded view
|

Re: How long does a query?q=field1:2312 should cost? exactly hit one document.

zhenyuan wei
In reply to this post by Erik Hatcher-4
Only a termQuery q=field1:2312, No other conditions.
I try debug now, but can not find out  what is the main cost.
Debug=timing output like :

{
  "responseHeader":{
    "zkConnected":true,
    "status":0,
    "QTime":157,
    "params":{
      "q":"v00_s:15de21c670ae7c3f6f3f1f37029303c9",
      "debug":"timing"}},
  "response":{"numFound":1,"start":0,"maxScore":17.099754,"docs":[
      {
        "v00_s":"15de21c670ae7c3f6f3f1f37029303c9",
        "v01_s":"7596295605015",
        "v02_s":"Mp9XkmrRXhFChgMAGoydOvAD",
        "v03_l":555,
        "v04_s":"55",
        "v05_s":"39994237071313698949",
        "v06_s":"3",
        "v07_s":"155",
        "v08_s":"5",
        "v09_s":"15",
        "v10_s":"15",
        "v11_s":"555",
        "v12_s":"43819292",
        "v13_s":"549754428",
        "v14_s":"8111596961",
        "id":"00000000000000000000000555",
        "_version_":1610106981630083079}]
  },
  "debug":{
    "timing":{
      "time":6336.0,
      "prepare":{
        "time":8.0,
        "query":{
          "time":8.0},
        "facet":{
          "time":0.0},
        "facet_module":{
          "time":0.0},
        "mlt":{
          "time":0.0},
        "highlight":{
          "time":0.0},
        "stats":{
          "time":0.0},
        "expand":{
          "time":0.0},
        "terms":{
          "time":0.0},
        "debug":{
          "time":0.0}},
      "process":{
        "time":6270.0,
        "query":{
          "time":6268.0,
          "doProcessSearchByIds":{
            "time":0.0},
          "doProcessUngroupedSearch":{
            "time":6265.0,
            "search":{
              "time":6261.0,
              "getDocListC":{
                "time":6261.0,
                "lookup_queryResultCache":{
                  "time":0.0},
                "lookupNotuseFilterCacheTimer":{
                  "time":6258.0},
                "getDocListNCTimer":{
                  "time":6258.0,
                  "getProcessedFilter":{
                    "time":0.0},
                  "buildAndRunCollectorChain2":{
                    "time":6255.0},
                  "topDocs":{
                    "time":0.0}}}},
            "doFieldSortValues":{
              "time":0.0},
            "doPrefetch":{
              "time":0.0}}},
        "facet":{
          "time":0.0},
        "facet_module":{
          "time":0.0},
        "mlt":{
          "time":0.0},
        "highlight":{
          "time":0.0},
        "stats":{
          "time":0.0},
        "expand":{
          "time":0.0},
        "terms":{
          "time":0.0},
        "debug":{
          "time":0.0}}}}}


My request is :  curl "
http://localhost:8983/solr/collection001/query?q=v00_s
<http://emr-worker-2:8983/solr/collection001/query?q=v00_s>:
15de21c670ae7c3f6f3f1f37029303c9&debug=timing"

I  also hope to using debug=true to find out more things,so I added some
sub timer to trace which sub method is slowly.
And found , as above,  the "SolrIndexSearch.buildAndRunCollectorChain() "
cost a lot。
( if I want to  find out the answer, I think I have not idea but  debug
tracing  to deeper into lucene level method.)

*At this moment, I have another question too, why  debug time is 6336.0,
which less than QTime=157 ?*

Erik Hatcher <[hidden email]> 于2018年9月3日周一 下午8:30写道:

> Add debug=true and see where the time goes, in which components?
>
> Highlighting is my culprit guess.   Or faceting?
>
> > On Sep 3, 2018, at 07:45, zhenyuan wei <[hidden email]> wrote:
> >
> > Hi ,
> >   I am curious “How long does a  query q=field1:2312 cost ,   which
> > exactly match only one document? ”,  Of course we just discuss  no
> > queryResultCache with match in this situation.
> >   In fact  my QTime is  150ms+, it is too long.
>
Reply | Threaded
Open this post in threaded view
|

Re: How long does a query?q=field1:2312 should cost? exactly hit one document.

Erick Erickson
My guess is that you're searching un-warmed instances of Solr and are
seeing the time it takes to read the index structures into memory the
first time. What happens if you turn off indexing and query a number
of values (not the same one or you'll hit the queryResultCache).

So your first query would be:
"q":"v00_s:1"
your second
"q":"v00_s:2",

and so on. I'd expect to see decreasing QTimes and after the first few
a pretty steady response time.

Beyond that, what are your machine/index characteristics? How many
docs per replica? What version of Solr? How much heap allocated to the
JVM? How much RAM on the machine? you might review:'
https://wiki.apache.org/solr/UsingMailingLists

Debug adds overhead to the query response time, I suspect that's what
you're seeing although 6 seconds is surprisingly long.

Best,
Erick
On Mon, Sep 3, 2018 at 6:08 AM zhenyuan wei <[hidden email]> wrote:

>
> Only a termQuery q=field1:2312, No other conditions.
> I try debug now, but can not find out  what is the main cost.
> Debug=timing output like :
>
> {
>   "responseHeader":{
>     "zkConnected":true,
>     "status":0,
>     "QTime":157,
>     "params":{
>       "q":"v00_s:15de21c670ae7c3f6f3f1f37029303c9",
>       "debug":"timing"}},
>   "response":{"numFound":1,"start":0,"maxScore":17.099754,"docs":[
>       {
>         "v00_s":"15de21c670ae7c3f6f3f1f37029303c9",
>         "v01_s":"7596295605015",
>         "v02_s":"Mp9XkmrRXhFChgMAGoydOvAD",
>         "v03_l":555,
>         "v04_s":"55",
>         "v05_s":"39994237071313698949",
>         "v06_s":"3",
>         "v07_s":"155",
>         "v08_s":"5",
>         "v09_s":"15",
>         "v10_s":"15",
>         "v11_s":"555",
>         "v12_s":"43819292",
>         "v13_s":"549754428",
>         "v14_s":"8111596961",
>         "id":"00000000000000000000000555",
>         "_version_":1610106981630083079}]
>   },
>   "debug":{
>     "timing":{
>       "time":6336.0,
>       "prepare":{
>         "time":8.0,
>         "query":{
>           "time":8.0},
>         "facet":{
>           "time":0.0},
>         "facet_module":{
>           "time":0.0},
>         "mlt":{
>           "time":0.0},
>         "highlight":{
>           "time":0.0},
>         "stats":{
>           "time":0.0},
>         "expand":{
>           "time":0.0},
>         "terms":{
>           "time":0.0},
>         "debug":{
>           "time":0.0}},
>       "process":{
>         "time":6270.0,
>         "query":{
>           "time":6268.0,
>           "doProcessSearchByIds":{
>             "time":0.0},
>           "doProcessUngroupedSearch":{
>             "time":6265.0,
>             "search":{
>               "time":6261.0,
>               "getDocListC":{
>                 "time":6261.0,
>                 "lookup_queryResultCache":{
>                   "time":0.0},
>                 "lookupNotuseFilterCacheTimer":{
>                   "time":6258.0},
>                 "getDocListNCTimer":{
>                   "time":6258.0,
>                   "getProcessedFilter":{
>                     "time":0.0},
>                   "buildAndRunCollectorChain2":{
>                     "time":6255.0},
>                   "topDocs":{
>                     "time":0.0}}}},
>             "doFieldSortValues":{
>               "time":0.0},
>             "doPrefetch":{
>               "time":0.0}}},
>         "facet":{
>           "time":0.0},
>         "facet_module":{
>           "time":0.0},
>         "mlt":{
>           "time":0.0},
>         "highlight":{
>           "time":0.0},
>         "stats":{
>           "time":0.0},
>         "expand":{
>           "time":0.0},
>         "terms":{
>           "time":0.0},
>         "debug":{
>           "time":0.0}}}}}
>
>
> My request is :  curl "
> http://localhost:8983/solr/collection001/query?q=v00_s
> <http://emr-worker-2:8983/solr/collection001/query?q=v00_s>:
> 15de21c670ae7c3f6f3f1f37029303c9&debug=timing"
>
> I  also hope to using debug=true to find out more things,so I added some
> sub timer to trace which sub method is slowly.
> And found , as above,  the "SolrIndexSearch.buildAndRunCollectorChain() "
> cost a lot。
> ( if I want to  find out the answer, I think I have not idea but  debug
> tracing  to deeper into lucene level method.)
>
> *At this moment, I have another question too, why  debug time is 6336.0,
> which less than QTime=157 ?*
>
> Erik Hatcher <[hidden email]> 于2018年9月3日周一 下午8:30写道:
>
> > Add debug=true and see where the time goes, in which components?
> >
> > Highlighting is my culprit guess.   Or faceting?
> >
> > > On Sep 3, 2018, at 07:45, zhenyuan wei <[hidden email]> wrote:
> > >
> > > Hi ,
> > >   I am curious “How long does a  query q=field1:2312 cost ,   which
> > > exactly match only one document? ”,  Of course we just discuss  no
> > > queryResultCache with match in this situation.
> > >   In fact  my QTime is  150ms+, it is too long.
> >