Use inexistent key (in prefix-index) to filter rows will cost too much time to return.

[qdore]

Describe the bug
When I use existent key to filter row, doris will return result very fast, but when I use inexistent key, it will cost too much time to return.

To Reproduce

1. existent key (Cost 0.06 sec)
   

2. Inexistent key (Cost 1 min 53.06 sec)
   

Doris version: 0.9.0-rc02

[qdore]

And the table schema:

[imay]

can you provide the slow query's profile?

[qdore]

slow query:

+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Explain String                                                                                                                                                           |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PLAN FRAGMENT 0                                                                                                                                                          |
|  OUTPUT EXPRS:`event_day` | `cuid` |                                                                                                                                     |
|   PARTITION: UNPARTITIONED                                                                                                                                               |
|                                                                                                                                                                          |
|   RESULT SINK                                                                                                                                                            |
|                                                                                                                                                                          |
|   1:EXCHANGE                                                                                                                                                             |
|      tuple ids: 0                                                                                                                                                        |
|                                                                                                                                                                          |
| PLAN FRAGMENT 1                                                                                                                                                          |
|  OUTPUT EXPRS:                                                                                                                                                           |
|   PARTITION: RANDOM                                                                                                                                                      |
|                                                                                                                                                                          |
|   STREAM DATA SINK                                                                                                                                                       |
|     EXCHANGE ID: 01                                                                                                                                                      |
|     UNPARTITIONED                                                                                                                                                        |
|                                                                                                                                                                          |
|   0:OlapScanNode                                                                                                                                                         |
|      TABLE: visd_dws_topic_novel_wide_table2                                                                                                                             |
|      PREAGGREGATION: OFF. Reason: No AggregateInfo                                                                                                                       |
|      PREDICATES: `event_day` = '2019-05-14 00:00:00', `cuid` IN ('00005799A449415E6C8EA84B0FED6F3C|643611430939568', '00005799A449415E6C8EA84B0FED6F3C|643611430939567') |
|      partitions=1/58                                                                                                                                                     |
|      rollup: visd_dws_topic_novel_wide_table2                                                                                                                            |
|      buckets=2/32                                                                                                                                                        |
|      cardinality=82717417                                                                                                                                                |
|      avgRowSize=18.674715                                                                                                                                                |
|      numNodes=6                                                                                                                                                          |
|      tuple ids: 0                                                                                                                                                        |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

[qdore]

normal query:

+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Explain String                                                                                                                                                              |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PLAN FRAGMENT 0                                                                                                                                                             |
|  OUTPUT EXPRS:`event_day` | `cuid` |                                                                                                                                        |
|   PARTITION: UNPARTITIONED                                                                                                                                                  |
|                                                                                                                                                                             |
|   RESULT SINK                                                                                                                                                               |
|                                                                                                                                                                             |
|   1:EXCHANGE                                                                                                                                                                |
|      tuple ids: 0                                                                                                                                                           |
|                                                                                                                                                                             |
| PLAN FRAGMENT 1                                                                                                                                                             |
|  OUTPUT EXPRS:                                                                                                                                                              |
|   PARTITION: RANDOM                                                                                                                                                         |
|                                                                                                                                                                             |
|   STREAM DATA SINK                                                                                                                                                          |
|     EXCHANGE ID: 01                                                                                                                                                         |
|     UNPARTITIONED                                                                                                                                                           |
|                                                                                                                                                                             |
|   0:OlapScanNode                                                                                                                                                            |
|      TABLE: visd_dws_topic_novel_wide_table2                                                                                                                                |
|      PREAGGREGATION: OFF. Reason: No AggregateInfo                                                                                                                          |
|      PREDICATES: `event_day` = '2019-05-14 00:00:00', `cuid` IN ('00000556EE50B09F7F9E378E7262CF0B86E9B5EF3FHOKRADALC', '00005799A449415E6C8EA84B0FED6F3C|643611430939568') |
|      partitions=1/58                                                                                                                                                        |
|      rollup: visd_dws_topic_novel_wide_table2                                                                                                                               |
|      buckets=2/32                                                                                                                                                           |
|      cardinality=11318677                                                                                                                                                   |
|      avgRowSize=24.7009                                                                                                                                                     |
|      numNodes=5                                                                                                                                                             |
|      tuple ids: 0                                                                                                                                                           |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

[qdore]

I faked the value of cuid by modify the last character, then the query become slow:

[imay]

can you set is_report_success = true, and reexcute slow query, and see query's profile in frontend's web?

[qdore]

slow profile:

Query:
  Summary:
    Query ID: a2e2f1f8a7b64d2e:9f65f45daad76595
    Start Time: 2019-05-14 15:24:28
    End Time: 2019-05-14 15:26:39
    Total: 2m
    Query Type: Query
    Query State: EOF
    Doris Version: 0.9.0
    User: root
    Default Db: default_cluster:novel
    Sql Statement: select event_day,cuid from visd_dws_topic_novel_wide_table2 where event_day = '2019-05-14' and cuid in ('00005799A449415E6C8EA84B0FED6F3C|643611430939568', '00005799A449415E6C8EA84B0FED6F3C|643611430939567')
  Execution Profile a2e2f1f8a7b64d2e:9f65f45daad76595:(Active: 2m, % non-child: 0.00%)
    Fragment 0:
      Instance a2e2f1f8a7b64d2e:9f65f45daad76598 (host=TNetworkAddress(hostname:10.90.239.31, port:9073)):(Active: 2m, % non-child: 0.00%)
         - BytesReceived: 577.00 B
         - PeakUsedReservation: 0.00 
         - SendersBlockedTimer: 0ns
         - DeserializeRowBatchTimer: 26.305us
         - RowsProduced: 41
         - SendersBlockedTotalTimer(*): 0ns
         - AverageThreadTokens: 4607182418800017400.00
         - PeakReservation: 0.00 
         - FirstBatchArrivalWaitTime: 0ns
        BlockMgr:
           - BlocksCreated: 0
           - MemoryLimit: 30.00 GB
           - BlockWritesOutstanding: 0
           - BytesWritten: 0.00 
           - TotalEncryptionTime: 0ns
           - BufferedPins: 0
           - TotalReadBlockTime: 0ns
           - TotalBufferWaitTime: 0ns
           - BlocksRecycled: 0
           - TotalIntegrityCheckTime: 0ns
           - MaxBlockSize: 8.00 MB
        DataBufferSender (dst_fragment_instance_id=a2e2f1f8a7b64d2e:9f65f45daad76598):
        EXCHANGE_NODE (id=1):(Active: 2m, % non-child: 0.00%)
           - ConvertRowBatchTime: 2.809us
           - RowsReturned: 41
           - MemoryUsed: 0.00 
           - RowsReturnedRate: 0
    Fragment 1:
      Instance a2e2f1f8a7b64d2e:9f65f45daad76597 (host=TNetworkAddress(hostname:10.90.239.28, port:9083)):(Active: 621.184ms, % non-child: 0.00%)
         - PeakUsedReservation: 0.00 
         - RowsProduced: 41
         - AverageThreadTokens: 4607182418800017400.00
         - PeakReservation: 0.00 
        BlockMgr:
           - BlocksCreated: 0
           - MemoryLimit: 30.00 GB
           - BlockWritesOutstanding: 0
           - BytesWritten: 0.00 
           - TotalEncryptionTime: 0ns
           - BufferedPins: 0
           - TotalReadBlockTime: 0ns
           - TotalBufferWaitTime: 0ns
           - BlocksRecycled: 0
           - TotalIntegrityCheckTime: 0ns
           - MaxBlockSize: 8.00 MB
        DataStreamSender (dst_id=1):(Active: 641.540us, % non-child: 0.00%)
           - OverallThroughput: 878.318359375 KB/sec
           - SerializeBatchTime: 531.374us
           - IgnoreRows: 0
           - BytesSent: 577.00 B
           - NetworkThroughput(*): 0.0 /sec
           - ThriftTransmitTime(*): 0ns
           - UncompressedRowBatchSize: 3.37 KB
        OLAP_SCAN_NODE (id=0):(Active: 620.219ms, % non-child: 0.00%)
           - NumThread: 0
           - TotalRawReadTime(*): 0ns
           - CompressedBytesRead: 12.81 MB
           - RowsPushedCondFiltered: 0
           - ScanRangesComplete: 0
           - ScanTime: 260.732us
           - RowsStatsFiltered: 1.213828M (1213828)
           - VectorPredEvalTime: 43.146us
           - BlockSeekTime: 885.459ms
           - RawRowsRead: 34.967K (34967)
           - ScannerThreadsVoluntaryContextSwitches: 0
           - RowsDelFiltered: 0
           - IndexLoadTime: 231.724ms
           - ScannerThreadsTotalWallClockTime: 0ns
             - MaterializeTupleTime(*): 0ns
             - ScannerThreadsUserTime: 0ns
             - ScannerThreadsSysTime: 0ns
           - MemoryUsed: 0.00 
           - RowsReturnedRate: 66
           - BlockLoadTime: 42.22ms
           - BlocksLoad: 153
           - UncompressedBytesRead: 24.33 MB
           - TabletCount : 1
           - RowsReturned: 41
           - ScannerThreadsInvoluntaryContextSwitches: 0
           - DecompressorTimer: 27.432ms
           - RowsVectorPredFiltered: 0
           - ReaderInitTime: 1s208ms
           - RowsRead: 41
           - PerReadThreadRawHdfsThroughput: 0.0 /sec
           - BlockFetchTime: 1s204ms
           - ShowHintsTime: 92.321us
           - TotalReadThroughput: 0.0 /sec
           - IOTimer: 1s80ms
           - BytesRead: 5.85 MB
           - BlockConvertTime: 27.510ms
      Instance a2e2f1f8a7b64d2e:9f65f45daad76596 (host=TNetworkAddress(hostname:10.90.239.25, port:9093)):(Active: 2m, % non-child: 0.00%)
         - PeakUsedReservation: 0.00 
         - RowsProduced: 0
         - AverageThreadTokens: 4607182418800017400.00
         - PeakReservation: 0.00 
        BlockMgr:
           - BlocksCreated: 0
           - MemoryLimit: 30.00 GB
           - BlockWritesOutstanding: 0
           - BytesWritten: 0.00 
           - TotalEncryptionTime: 0ns
           - BufferedPins: 0
           - TotalReadBlockTime: 0ns
           - TotalBufferWaitTime: 0ns
           - BlocksRecycled: 0
           - TotalIntegrityCheckTime: 0ns
           - MaxBlockSize: 8.00 MB
        DataStreamSender (dst_id=1):(Active: 31.542us, % non-child: 0.00%)
           - OverallThroughput: 0.0 /sec
           - SerializeBatchTime: 0ns
           - IgnoreRows: 0
           - BytesSent: 0.00 
           - NetworkThroughput(*): 0.0 /sec
           - ThriftTransmitTime(*): 0ns
           - UncompressedRowBatchSize: 0.00 
        OLAP_SCAN_NODE (id=0):(Active: 2m, % non-child: 0.00%)
           - NumThread: 0
           - TotalRawReadTime(*): 0ns
           - CompressedBytesRead: 5.15 GB
           - RowsPushedCondFiltered: 0
           - ScanRangesComplete: 0
           - ScanTime: 1.344us
           - RowsStatsFiltered: 0
           - VectorPredEvalTime: 1s197ms
           - BlockSeekTime: 4s41ms
           - RawRowsRead: 323.726158M (323726158)
           - ScannerThreadsVoluntaryContextSwitches: 0
           - RowsDelFiltered: 0
           - IndexLoadTime: 561.877ms
           - ScannerThreadsTotalWallClockTime: 0ns
             - MaterializeTupleTime(*): 0ns
             - ScannerThreadsUserTime: 0ns
             - ScannerThreadsSysTime: 0ns
           - MemoryUsed: 0.00 
           - RowsReturnedRate: 0
           - BlockLoadTime: 2m
           - BlocksLoad: 316.5K (316500)
           - UncompressedBytesRead: 39.12 GB
           - TabletCount : 1
           - RowsReturned: 0
           - ScannerThreadsInvoluntaryContextSwitches: 0
           - DecompressorTimer: 25s176ms
           - RowsVectorPredFiltered: 161.825326M (161825326)
           - ReaderInitTime: 4m
           - RowsRead: 0
           - PerReadThreadRawHdfsThroughput: 0.0 /sec
           - BlockFetchTime: 4m
           - ShowHintsTime: 168.864us
           - TotalReadThroughput: 0.0 /sec
           - IOTimer: 11s544ms
           - BytesRead: 40.73 GB
           - BlockConvertTime: 1m

normal profile:

Query:
  Summary:
    Query ID: dcb00d6336ba4877:828d23325dbebda3
    Start Time: 2019-05-14 15:24:20
    End Time: 2019-05-14 15:24:21
    Total: 984ms
    Query Type: Query
    Query State: EOF
    Doris Version: 0.9.0
    User: root
    Default Db: default_cluster:novel
    Sql Statement: select event_day,cuid from visd_dws_topic_novel_wide_table2 where event_day = '2019-05-14' and cuid in ('00005799A449415E6C8EA84B0FED6F3C|643611430939568')
  Execution Profile dcb00d6336ba4877:828d23325dbebda3:(Active: 983.763ms, % non-child: 0.00%)
    Fragment 0:
      Instance dcb00d6336ba4877:828d23325dbebda4 (host=TNetworkAddress(hostname:10.90.239.23, port:9093)):(Active: 967.910ms, % non-child: 0.00%)
         - PeakUsedReservation: 0.00 
         - RowsProduced: 41
         - AverageThreadTokens: 4607182418800017400.00
         - PeakReservation: 0.00 
        BlockMgr:
           - BlocksCreated: 0
           - MemoryLimit: 30.00 GB
           - BlockWritesOutstanding: 0
           - BytesWritten: 0.00 
           - TotalEncryptionTime: 0ns
           - BufferedPins: 0
           - TotalReadBlockTime: 0ns
           - TotalBufferWaitTime: 0ns
           - BlocksRecycled: 0
           - TotalIntegrityCheckTime: 0ns
           - MaxBlockSize: 8.00 MB
        DataBufferSender (dst_fragment_instance_id=dcb00d6336ba4877:828d23325dbebda4):
        OLAP_SCAN_NODE (id=0):(Active: 967.827ms, % non-child: 0.00%)
           - NumThread: 0
           - TotalRawReadTime(*): 0ns
           - CompressedBytesRead: 6.83 MB
           - RowsPushedCondFiltered: 0
           - ScanRangesComplete: 0
           - ScanTime: 207.965us
           - RowsStatsFiltered: 771.335K (771335)
           - VectorPredEvalTime: 27.265us
           - BlockSeekTime: 382.733ms
           - RawRowsRead: 18.534K (18534)
           - ScannerThreadsVoluntaryContextSwitches: 0
           - RowsDelFiltered: 0
           - IndexLoadTime: 529.458ms
           - ScannerThreadsTotalWallClockTime: 0ns
             - MaterializeTupleTime(*): 0ns
             - ScannerThreadsUserTime: 0ns
             - ScannerThreadsSysTime: 0ns
           - MemoryUsed: 0.00 
           - RowsReturnedRate: 42
           - BlockLoadTime: 21.931ms
           - BlocksLoad: 90
           - UncompressedBytesRead: 12.77 MB
           - TabletCount : 1
           - RowsReturned: 41
           - ScannerThreadsInvoluntaryContextSwitches: 0
           - DecompressorTimer: 13.577ms
           - RowsVectorPredFiltered: 0
           - ReaderInitTime: 957.821ms
           - RowsRead: 41
           - PerReadThreadRawHdfsThroughput: 0.0 /sec
           - BlockFetchTime: 955.285ms
           - ShowHintsTime: 92.243us
           - TotalReadThroughput: 0.0 /sec
           - IOTimer: 894.382ms
           - BytesRead: 3.10 MB
           - BlockConvertTime: 14.439ms

[imay]

It seems like a bad case for Doris, We will look into it.

[chaoyli]

There may be has something with VARCHAR type. You can try it in another type.

[kangpinghuang]

there two reasons for this problem:

1. there is data skew in your table, The data size and row size of one tablet is 10x larger than other. and I find out that the skewed data is the data with empty cuid. And the slow cuid is in this tablet
2. there is a bug when seek position in the data with the short key of varchar type. This is fixed by pr Fix position seek bug for varchar short key #1167

[qdore]

Good Job! I will test it soon 👍