Description
Build
4.5.0-2047
Testcase
./testrunner -i INI_FILE.ini -p get-cbcollect-info=True,get-coredumps=True,get-logs=False,stop-on-failure=False,compare_es=True,cluster=D+F,GROUP=P1 -t fts.stable_topology_fts.StableTopFTS.test_query_type,items=30000,num_queries=200,query_types=wildcard,cluster=D,F,F,compare_es=True,dataset=wiki,GROUP=P1
Many queries in this test cause memory usage to go up really high that gets cbft killed.
Full test log - https://gist.github.com/arunapiravi/b13f175a2a281b0364b32e0d4aac2cfa
[2016-04-13 05:25:50,601] - [task:1097] INFO - ------------------------------------------------------------------ Query # 1 -----------------------------------------------------------------
|
[2016-04-13 05:25:50,633] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "title", "wildcard": "Bielefel?"}, "size": 10000000} on node: 172.23.107.125
|
[2016-04-13 05:25:50,710] - [rest_client:2236] INFO - Status: {u'successful': 32, u'failed': 0, u'total': 32}
|
[2016-04-13 05:25:50,711] - [task:1106] INFO - FTS hits for query: {"field": "title", "wildcard": "Bielefel?"} is 0 (took 28.573244ms)
|
[2016-04-13 05:25:50,725] - [task:1116] INFO - ES hits for query: {"wildcard": {"title": "Bielefel?"}} on es_index is 0 (took 2ms)
|
[2016-04-13 05:25:50,725] - [task:1125] INFO - SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
|
[2016-04-13 05:25:50,726] - [task:1097] INFO - ------------------------------------------------------------------ Query # 2 -----------------------------------------------------------------
|
[2016-04-13 05:25:50,752] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "Category:A*"}, "size": 10000000} on node: 172.23.107.125
|
[2016-04-13 05:25:50,800] - [rest_client:2236] INFO - Status: {u'successful': 32, u'failed': 0, u'total': 32}
|
[2016-04-13 05:25:50,801] - [task:1106] INFO - FTS hits for query: {"field": "revision.text.#text", "wildcard": "Category:A*"} is 0 (took 7.482979ms)
|
[2016-04-13 05:25:50,812] - [task:1116] INFO - ES hits for query: {"wildcard": {"revision.text.#text": "Category:A*"}} on es_index is 0 (took 1ms)
|
[2016-04-13 05:25:50,813] - [task:1125] INFO - SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
|
[2016-04-13 05:25:50,813] - [task:1097] INFO - ------------------------------------------------------------------ Query # 3 -----------------------------------------------------------------
|
[2016-04-13 05:25:50,828] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "R?spiration"}, "size": 10000000} on node: 172.23.107.125
|
[2016-04-13 05:25:50,852] - [rest_client:2236] INFO - Status: {u'successful': 32, u'failed': 0, u'total': 32}
|
[2016-04-13 05:25:50,853] - [task:1106] INFO - FTS hits for query: {"field": "revision.text.#text", "wildcard": "R?spiration"} is 0 (took 4.375983ms)
|
[2016-04-13 05:25:50,861] - [task:1116] INFO - ES hits for query: {"wildcard": {"revision.text.#text": "R?spiration"}} on es_index is 0 (took 2ms)
|
[2016-04-13 05:25:50,861] - [task:1125] INFO - SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
|
[2016-04-13 05:25:50,861] - [task:1097] INFO - ------------------------------------------------------------------ Query # 4 -----------------------------------------------------------------
|
[2016-04-13 05:25:50,877] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "title", "wildcard": "Template:Country data Arkansa*"}, "size": 10000000} on node: 172.23.107.125
|
[2016-04-13 05:25:50,917] - [rest_client:2236] INFO - Status: {u'successful': 32, u'failed': 0, u'total': 32}
|
[2016-04-13 05:25:50,917] - [task:1106] INFO - FTS hits for query: {"field": "title", "wildcard": "Template:Country data Arkansa*"} is 0 (took 5.026719ms)
|
[2016-04-13 05:25:50,933] - [task:1116] INFO - ES hits for query: {"wildcard": {"title": "Template:Country data Arkansa*"}} on es_index is 0 (took 2ms)
|
[2016-04-13 05:25:50,934] - [task:1125] INFO - SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
|
[2016-04-13 05:25:50,934] - [task:1097] INFO - ------------------------------------------------------------------ Query # 5 -----------------------------------------------------------------
|
[2016-04-13 05:25:50,972] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "*"}, "size": 10000000} on node: 172.23.107.125
|
[2016-04-13 05:26:51,054] - [rest_client:760] ERROR - socket error while connecting to http://172.23.107.125:8094/api/index/default_index/query error timed out
|
[2016-04-13 05:26:51,055] - [task:1108] ERROR - ERROR: FTS Query timed out (timeout=60s)!
|
[2016-04-13 05:27:07,393] - [task:1116] INFO - ES hits for query: {"wildcard": {"revision.text.#text": "*"}} on es_index is 29997 (took 1413ms)
|
[2016-04-13 05:27:07,402] - [task:1097] INFO - ------------------------------------------------------------------ Query # 6 -----------------------------------------------------------------
|
[2016-04-13 05:27:08,999] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "Pter?dactyl"}, "size": 10000000} on node: 172.23.107.125
|
[2016-04-13 05:27:34,529] - [rest_client:760] ERROR - socket error while connecting to http://172.23.107.125:8094/api/index/default_index/query error [Errno 111] Connection refused
|
[2016-04-13 05:27:37,554] - [rest_client:757] ERROR - http://172.23.107.125:8094/api/index/default_index/query error 400 reason: status: 400, content: rest_index: Query, indexName: default_index, requestBody: {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "Pter?dactyl"}, "size": 10000000}, req: &http.Request{Method:"POST", URL:(*url.URL)(0xc820348400), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{"Accept-Encoding":[]string{"identity"}, "Content-Length":[]string{"233"}, "Content-Type":[]string{"application/json"}, "Authorization":[]string{"Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA=="}, "Accept":[]string{"*/*"}, "User-Agent":[]string{"Python-httplib2/$Rev: 259 $"}}, Body:(*http.body)(0xc820664180), ContentLength:233, TransferEncoding:[]string(nil), Close:false, Host:"172.23.107.125:8094", Form:url.Values{}, PostForm:url.Values{}, MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"172.23.123.146:51640", RequestURI:"/api/index/default_index/query", TLS:(*tls.ConnectionState)(nil), Cancel:(<-chan struct {})(nil)}, err: bleve: bleveIndexTargets, err: pindex: queries may have been disabled; no nodes are enabled/allocated to serve queries for the index partition(s)
|
rest_index: Query, indexName: default_index, requestBody: {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "Pter?dactyl"}, "size": 10000000}, req: &http.Request{Method:"POST", URL:(*url.URL)(0xc820348400), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{"Accept-Encoding":[]string{"identity"}, "Content-Length":[]string{"233"}, "Content-Type":[]string{"application/json"}, "Authorization":[]string{"Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA=="}, "Accept":[]string{"*/*"}, "User-Agent":[]string{"Python-httplib2/$Rev: 259 $"}}, Body:(*http.body)(0xc820664180), ContentLength:233, TransferEncoding:[]string(nil), Close:false, Host:"172.23.107.125:8094", Form:url.Values{}, PostForm:url.Values{}, MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"172.23.123.146:51640", RequestURI:"/api/index/default_index/query", TLS:(*tls.ConnectionState)(nil), Cancel:(<-chan struct {})(nil)}, err: bleve: bleveIndexTargets, err: pindex: queries may have been disabled; no nodes are enabled/allocated to serve queries for the index partition(s)
|
[2016-04-13 05:27:37,555] - [fts_base:683] ERROR - Error running query: 'NoneType' object is not iterable
|
[2016-04-13 05:27:37,563] - [task:1116] INFO - ES hits for query: {"wildcard": {"revision.text.#text": "Pter?dactyl"}} on es_index is 0 (took 2ms)
|
[2016-04-13 05:27:37,563] - [task:1097] INFO - ------------------------------------------------------------------ Query # 7 -----------------------------------------------------------------
|
[2016-04-13 05:27:37,593] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "Seth M?cF?rl?ne"}, "size": 10000000} on node: 172.23.107.125
|
[2016-04-13 05:27:37,610] - [rest_client:757] ERROR - http://172.23.107.125:8094/api/index/default_index/query error 400 reason: status: 400, content: rest_index: Query, indexName: default_index, requestBody: {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "Seth M?cF?rl?ne"}, "size": 10000000}, req: &http.Request{Method:"POST", URL:(*url.URL)(0xc82018ce80), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{"Accept-Encoding":[]string{"identity"}, "Content-Length":[]string{"237"}, "Content-Type":[]string{"application/json"}, "Authorization":[]string{"Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA=="}, "Accept":[]string{"*/*"}, "User-Agent":[]string{"Python-httplib2/$Rev: 259 $"}}, Body:(*http.body)(0xc8203ad300), ContentLength:237, TransferEncoding:[]string(nil), Close:false, Host:"172.23.107.125:8094", Form:url.Values{}, PostForm:url.Values{}, MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"172.23.123.146:51645", RequestURI:"/api/index/default_index/query", TLS:(*tls.ConnectionState)(nil), Cancel:(<-chan struct {})(nil)}, err: bleve: bleveIndexTargets, err: pindex: queries may have been disabled; no nodes are enabled/allocated to serve queries for the index partition(s)
|
rest_index: Query, indexName: default_index, requestBody: {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "revision.text.#text", "wildcard": "Seth M?cF?rl?ne"}, "size": 10000000}, req: &http.Request{Method:"POST", URL:(*url.URL)(0xc82018ce80), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{"Accept-Encoding":[]string{"identity"}, "Content-Length":[]string{"237"}, "Content-Type":[]string{"application/json"}, "Authorization":[]string{"Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA=="}, "Accept":[]string{"*/*"}, "User-Agent":[]string{"Python-httplib2/$Rev: 259 $"}}, Body:(*http.body)(0xc8203ad300), ContentLength:237, TransferEncoding:[]string(nil), Close:false, Host:"172.23.107.125:8094", Form:url.Values{}, PostForm:url.Values{}, MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"172.23.123.146:51645", RequestURI:"/api/index/default_index/query", TLS:(*tls.ConnectionState)(nil), Cancel:(<-chan struct {})(nil)}, err: bleve: bleveIndexTargets, err: pindex: queries may have been disabled; no nodes are enabled/allocated to serve queries for the index partition(s)
|
[2016-04-13 05:27:37,611] - [fts_base:683] ERROR - Error running query: 'NoneType' object is not iterable
|
[2016-04-13 05:27:37,618] - [task:1116] INFO - ES hits for query: {"wildcard": {"revision.text.#text": "Seth M?cF?rl?ne"}} on es_index is 0 (took 2ms)
|
|
from syslog/messages
|
Apr 13 05:27:32 localhost kernel: Out of memory: Kill process 21219 (cbft) score 898 or sacrifice child
|
Some queries like the following are preempted if they contain > 1024 disjunction clauses
|
|
[2016-04-13 05:30:25,281] - [task:1097] INFO - ------------------------------------------------------------------ Query # 49 -----------------------------------------------------------------
[2016-04-13 05:30:25,298] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query":
, "size": 10000000} on node: 172.23.107.125
[2016-04-13 05:30:33,257] - [rest_client:2236] INFO - Status: {u'successful': 0, u'failed': 32, u'total': 32, u'errors': {u'default_index_3a5faf891bfcf863_d90ca3e7': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_5c5f941e': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_27184a97': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_e64340fa': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_4a7ce4ca': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_b7ff6b68': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_54127e67': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_24e7ea2d': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_4cdba0cf': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_9284f0ad': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_0a44bddb': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_596cc6a1': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_8b80958a': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_dee61dfa': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_3cf74ad7': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_d6109bff': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_9e13fa43': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_63ef8109': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_f17535e5': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_cd5a61e8': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_348f5c3c': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_321cbb28': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_d8c75a95': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_a4a23588': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_77082885': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_0ffd4517': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_577e9974': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_4728ab89': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_ee590b16': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_37fdcf3c': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_5b1351c0': u'TooManyClauses[maxClauseCount is set to 1024]', u'default_index_3a5faf891bfcf863_76ac2a42': u'TooManyClauses[maxClauseCount is set to 1024]'}}
[2016-04-13 05:30:33,257] - [task:1106] INFO - FTS hits for query:
is 0 (took 7936.898046ms)
[2016-04-13 05:30:40,740] - [task:1116] INFO - ES hits for query: {"wildcard": {"title": "*"}} on es_index is 29985 (took 1413ms)
[2016-04-13 05:30:40,740] - [task:1121] ERROR - FAIL: FTS hits: 0, while ES hits: 29985
[2016-04-13 05:30:40,785] - [task:1136] ERROR - FAIL: Following 29985 docs were not returned by FTS, but ES, printing 50: [u'wiki10009372', u'wiki10009373', u'wiki10009370', u'wiki10009371', u'wiki10009376', u'wiki10009377', u'wiki10009374', u'wiki10009375', u'wiki10009378', u'wiki10009379', u'wiki10016860', u'wiki10003628', u'wiki10003629', u'wiki10003626', u'wiki10003627', u'wiki10003624', u'wiki10003625', u'wiki10003622', u'wiki10003623', u'wiki10003620', u'wiki10003621', u'wiki10008685', u'wiki10008684', u'wiki10008687', u'wiki10008686', u'wiki10008681', u'wiki10008680', u'wiki10008683', u'wiki10008682', u'wiki10008689', u'wiki10008688', u'wiki10008973', u'wiki10008972', u'wiki10008971', u'wiki10008970', u'wiki10008977', u'wiki10008976', u'wiki10008975', u'wiki10008974', u'wiki10008979', u'wiki10008978', u'wiki10027028', u'wiki10009088', u'wiki10009089', u'wiki10015507', u'wiki10004078', u'wiki10004079', u'wiki10004076', u'wiki10004077', u'wiki10009082']
|
...while the same query a few secs later causes fts to get killed. Just curious, how are the clauses for the same query different?
|
|
[2016-04-13 05:35:06,823] - [task:1097] INFO - ------------------------------------------------------------------ Query # 114 -----------------------------------------------------------------
[2016-04-13 05:35:06,838] - [fts_base:1091] INFO - Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query":
, "size": 10000000} on node: 172.23.107.125
[2016-04-13 05:35:18,148] - [rest_client:760] ERROR - socket error while connecting to http://172.23.107.125:8094/api/index/default_index/query error [Errno 111] Connection refused
[2016-04-13 05:35:21,188] - [rest_client:757] ERROR - http://172.23.107.125:8094/api/index/default_index/query error 400 reason: status: 400, content: rest_index: Query, indexName: default_index, requestBody: {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query":
, "size": 10000000}, req: &http.Request{Method:"POST", URL*url.URL)(0xc8203d0100), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{"Accept-Encoding":[]string
![](/images/icons/emoticons/sad.png)
![](/images/icons/emoticons/sad.png)
![](/images/icons/emoticons/sad.png)
![](/images/icons/emoticons/sad.png)
rest_index: Query, indexName: default_index, requestBody: {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "title", "wildcard": "*"}, "size": 10000000}, req: &http.Request{Method:"POST", URL
![](/images/icons/emoticons/sad.png)
, "Content-Length":[]string
{"209"}, "Content-Type":[]string
{"application/json"}, "Authorization":[]string
{"Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA=="}, "Accept":[]string
{"*/*"}, "User-Agent":[]string{"Python-httplib2/$Rev: 259 $"}}, Body*http.body)(0xc82070a140), ContentLength:209, TransferEncoding:[]string(nil), Close:false, Host:"172.23.107.125:8094", Form:url.Values{}, PostForm:url.Values{}, MultipartForm
*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"172.23.123.146:52192", RequestURI:"/api/index/default_index/query", TLS
*tls.ConnectionState)(nil), Cancel
<-chan struct {})(nil)}, err: bleve: bleveIndexTargets, err: pindex: queries may have been disabled; no nodes are enabled/allocated to serve queries for the index partition(s)
[2016-04-13 05:35:21,189] - [fts_base:683] ERROR - Error running query: 'NoneType' object is not iterable
[2016-04-13 05:35:29,154] - [task:1116] INFO - ES hits for query: {"wildcard": {"title": "*"}} on es_index is 29985 (took 1198ms)
|
Attachments
For Gerrit Dashboard: MB-19198 | ||||||
---|---|---|---|---|---|---|
# | Subject | Branch | Project | Status | CR | V |
62953,2 | bump bleve SHA for MB-19198 | master | manifest | Status: MERGED | +2 | +1 |