Details
Major Description
This query, with profiling set to timings:
query = select meta().id from default where join_day between 0 and 5 and join_yr = 2011
query['profile']['executionTimings']['~children'][0]['~child']['~children'][1]['~children'][2]'#stats'
{u'execTime': u'654.34\xb5s', u'#phaseSwitches': 3241, u'#itemsOut': 1080, u'kernTime': u'12.948384ms'}
This snippet of the profiling used to contain #itemsIn: 1080(in build 1563, when 5.5 was still 5.1), now it does not. The below is an example of what it should look like.
query['profile']['executionTimings']['~children'][0]['~child']['~children'][1]['~children'][2]'#stats'
{u'#itemsIn': 1080, u'execTime': u'1.951437ms', u'#phaseSwitches': 3245, u'#itemsOut': 1080, u'kernTime': u'7.648773ms'}
You can verify this behavior by running this test:
./testrunner -i VMs.ini -p doc-per-day=6,reload_data=True,primary_indx_type=GSI -t tuqquery.tuq_2i_index.QueriesIndexTests.test_pushdown_complex_filter
It passes in 1563 but fails in 1610 (failure also seen in 5.5.0-1593)
Here is the full profiling information:
u'profile': {u'phaseOperators': {u'authorize': 1, u'indexScan': 1}, u'executionTimings': {u'#operator': u'Sequence', u'~versions': [u'2.0.0-N1QL', u'5.5.0-1610-enterprise'], u'~children': [{u'#operator': u'Authorize', u'privileges': {u'List': [\{u'Target': u'default:default', u'Priv': 7}]}, u'#stats': {u'execTime': u'1.602\xb5s', u'#phaseSwitches': 3, u'servTime': u'20.542\xb5s'}, u'~child': {u'#operator': u'Sequence', u'~children': [{u'index': u'idxjoining', u'namespace': u'default', u'covers': [u'cover ((`default`.`join_yr`))', u'cover ((`default`.`join_day`))', u'cover ((meta(`default`).`id`))'], u'keyspace': u'default', u'#operator': u'IndexScan2', u'spans': [{u'range': [\{u'high': u'2011', u'low': u'2011', u'inclusion': 3}, \{u'high': u'5', u'low': u'0', u'inclusion': 3}], u'exact': True}], u'using': u'gsi', u'index_id': u'488986d70dc284e2', u'#stats': {u'execTime': u'3.796253ms', u'#phaseSwitches': 4323, u'servTime': u'12.26893ms', u'#itemsOut': 1080, u'kernTime': u'286.124\xb5s'}}, {u'#operator': u'Sequence', u'~children': {u'#operator': u'Filter', u'condition': u'((cover ((`default`.`join_day`)) between 0 and 5) and (cover ((`default`.`join_yr`)) = 2011))', u'#stats': {u'#itemsIn': 1080, u'execTime': u'1.506876ms', u'#phaseSwitches': 4323, u'#itemsOut': 1080, u'kernTime': u'16.868914ms'}}, {u'#operator': u'InitialProject', u'#stats': {u'#itemsIn': 1080, u'execTime': u'1.951437ms', u'#phaseSwitches': 3245, u'#itemsOut': 1080, u'kernTime': u'7.648773ms'}, u'result_terms': [{u'expr': u'cover ((meta(`default`).`id`))'}]}, {u'#operator': u'FinalProject', u'#stats': {u'execTime': u'654.34\xb5s', u'#phaseSwitches': 3241, u'#itemsOut': 1080, u'kernTime': u'12.948384ms'}}, u'#stats': {u'execTime': u'953ns', u'#phaseSwitches': 1}}], u'#stats': {u'execTime': u'3.267\xb5s', u'#phaseSwitches': 1}}}, {u'#operator': u'Stream', u'#stats': {u'#itemsIn': 1080, u'execTime': u'468.549\xb5s', u'#phaseSwitches': 4323, u'#itemsOut': 1080, u'kernTime': u'23.108627ms'}}], u'#stats': {u'execTime': u'2.078\xb5s', u'#phaseSwitches': 1}}, u'phaseCounts': {u'indexScan': 1080}, u'phaseTimes': {u'authorize': u'22.144\xb5s', u'run': u'3.774\xb5s', u'instantiate': u'21.422\xb5s', u'parse': u'523.623\xb5s', u'plan': u'145.093\xb5s', u'indexScan': u'16.065183ms'}}