kudu-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Attila Bukor <abu...@apache.org>
Subject Re: Re: is this mean the disk read rate was too slow
Date Tue, 16 Jul 2019 08:23:52 GMT
Hi,

Based on the ExecSummary the slowest 00:SCAN KUDU finished within half a
second, but the slowest 09:AGGREGATE took over a minute to finish with
the other AGGREGATE-s taking on average ~30 seconds too.

It seems the slowness is on the Impala side rather than Kudu and it's
most likely caused by the aggregate function applied to the projection.

Maybe someone on the Impala user@ mailing list can help with tweaking
the query or the configuration.

--
Attila

On Tue, Jul 16, 2019 at 09:32:50AM +0800, lk_hadoop wrote:
> Thank you , @Alexey and @Andrew ,  my scenario is the same sql and same table without
new data added , the query become very slow , because my kudu cluster was deployed on some
VM , so I doubt  about the vm's disk not work well, and I need to figure out if the most time
was spend on data scan . 
> 
> ExecSummary: 
> Operator       #Hosts   Avg Time   Max Time    #Rows  Est. #Rows   Peak Mem  Est. Peak
Mem  Detail                                                                           
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> 15:AGGREGATE        1    1.000ms    1.000ms        1           1   16.00 KB       10.00
MB  FINALIZE                                                                         
> 14:EXCHANGE         1    1.000ms    1.000ms        5           1   48.00 KB         
    0  UNPARTITIONED                                                                    
> 05:AGGREGATE        5    6.800ms   14.000ms        5           1   16.00 KB       10.00
MB                                                                                   
> 13:AGGREGATE        5   87.401ms  142.003ms  304.86K       4.76M   36.03 MB       63.18
MB                                                                                   
> 12:EXCHANGE         5    2.600ms    6.000ms  509.28K       4.76M  192.00 KB         
    0  HASH(membership_card_id)                                                         
> 04:AGGREGATE        5  261.605ms  505.010ms  509.28K       4.76M   38.52 MB       63.18
MB  STREAMING                                                                        
> 11:AGGREGATE        5   25s731ms   50s730ms  654.97K       4.76M  450.00 MB      700.54
MB  FINALIZE                                                                         
> 10:EXCHANGE         5  603.212ms    1s423ms   15.13M       4.76M   17.00 MB         
    0  HASH(a.membership_card_id,a.GOODS_ID,a.goods_name)                               
> 03:AGGREGATE        5   20s265ms   37s675ms   15.13M       4.76M  178.08 MB      700.54
MB  STREAMING                                                                        
> 09:AGGREGATE        5   34s213ms       1m3s   16.34M       4.76M  754.02 MB      852.87
MB                                                                                   
> 08:EXCHANGE         5  644.012ms    1s498ms   16.34M       4.76M   15.90 MB         
    0  HASH(a.membership_card_id,a.GOODS_ID,a.goods_name,a.TBILL_CODE)                  
> 02:AGGREGATE        5   16s595ms   30s407ms   16.34M       4.76M   40.07 MB      852.87
MB  STREAMING                                                                        
> 07:AGGREGATE        5   18s623ms   37s277ms   16.34M       4.76M  698.13 MB      902.79
MB  FINALIZE                                                                         
> 06:EXCHANGE         5  705.418ms    1s461ms   16.34M       4.76M   16.01 MB         
    0  HASH(membership_card_id,TBILL_CODE,GOODS_ID,goods_name,PAID_IN_AMT,profit,Dates) 
> 01:AGGREGATE        5   11s937ms   24s199ms   16.34M       4.76M   36.46 MB      902.79
MB  STREAMING                                                                        
> 00:SCAN KUDU        5  207.805ms  517.012ms   16.34M       4.76M   28.80 MB         
    0  test.sale_base_fact_with_membership_20190626                 
> 
> some info of the impala's query_profile :   I think the `StreamingTime` was too long
, but I don't know if this mean it spend too much time to read data out from kudu to impala
> 
> AGGREGATION_NODE (id=1):(Total: 12s144ms, non-child: 11s937ms, % non-child: 98.29%)
>          - GetResultsTime: 18.400ms
>          - HTResizeTime: 17.200ms
>          - HashBuckets: 131.07K (131072)
>          - LargestPartitionPercent: 0 (0)
>          - PartitionsCreated: 16 (16)
>          - PeakMemoryUsage: 36.46 MB (38230144)
>          - ReductionFactorEstimate: 1.11 
>          - ReductionFactorThresholdToExpand: 2.00 
>          - RowsPassedThrough: 3.17M (3169044)
>          - RowsReturned: 3.27M (3267348)
>          - RowsReturnedRate: 1.33 M/sec
>          - StreamingTime: 11s895ms
>         Buffer pool:
>            - AllocTime: 11.400ms
>            - CumulativeAllocationBytes: 36.00 MB (37748736)
>            - CumulativeAllocations: 18 (18)
>            - PeakReservation: 36.00 MB (37748736)
>            - PeakUnpinnedBytes: 0
>            - PeakUsedReservation: 36.00 MB (37748736)
>            - ReadIoBytes: 0
>            - ReadIoOps: 0 (0)
>            - ReadIoWaitTime: 0.000ns
>            - WriteIoBytes: 0
>            - WriteIoOps: 0 (0)
>            - WriteIoWaitTime: 0.000ns
>       KUDU_SCAN_NODE (id=0):(Total: 207.805ms, non-child: 207.805ms, % non-child: 100.00%)
>          - BytesRead: 0
>          - CollectionItemsRead: 0 (0)
>          - KuduRemoteScanTokens: 0 (0)
>          - NumScannerThreadsStarted: 3 (3)
>          - PeakMemoryUsage: 28.60 MB (29991321)
>          - RowsRead: 3.27M (3267348)
>          - RowsReturned: 3.27M (3267348)
>          - RowsReturnedRate: 59.15 M/sec
>          - ScanRangesComplete: 15 (15)
>          - ScannerThreadsInvoluntaryContextSwitches: 89 (89)
>          - ScannerThreadsTotalWallClockTime: 1m58s
>            - MaterializeTupleTime(*): 176.404ms
>            - ScannerThreadsSysTime: 1s250ms
>            - ScannerThreadsUserTime: 7s232ms
>          - ScannerThreadsVoluntaryContextSwitches: 3.56K (3561)
>          - TotalKuduScanRoundTrips: 546 (546)
>          - TotalReadThroughput: 0.00 /sec
> 
> 2019-07-16 
> 
> lk_hadoop 
> 
> 
> 
> 发件人:Andrew Wong <awong@cloudera.com>
> 发送时间:2019-07-16 01:34
> 主题:Re: is this mean the disk read rate was too slow
> 收件人:"user"<user@kudu.apache.org>
> 抄送:
> 
> A page that may help debug KUDU-1400 would be <tserver>:8050/tablet-rowsetlayout-svg?id=7a2bb2a7e62d4614b423f26c3117b49e,
which will show you the rowset layout for the given tablet. A large number of rowsets may
contribute to slow reads/writes.
> 
> 
> Another page that may be useful in debugging scan performance is the /rpcz page in the
tablet server web UI. You should see some traces from ScanRequestPBs that have traces indicating
where time was spend during the RPC and some metrics for the request, including how many rowsets
the scan hit, caching info, etc.
> 
> 
> On Mon, Jul 15, 2019 at 10:07 AM Alexey Serbin <aserbin@cloudera.com> wrote:
> 
> Hi,
> 
> 
> What was the expectation for the scan operation's timing w.r.t. the size of the result
set?  Did you see it was much faster in past?  I would start with making sure the primary
key of the table has indeed the columns used in the predicate.  Also, if there has been 'trickle
inserts' running against the table for a long time, it might be https://issues.apache.org/jira/browse/KUDU-1400
> 
> 
> 
> 
> 
> Probably, a good starting point would be running SUMMARY and EXPLAIN for the query in
impala-shell:
>   https://www.cloudera.com/documentation/enterprise/latest/topics/impala_explain_plan.html#perf_profile
> 
> 
> If you see times for SCAN KUDU is much higher than you expect, most likely it's either
too much data being read or KUDU-1400.  Also, check the logs of tserver at one of the machines
where the scan is running: if case of slow scan operations there should be traces for scan
operations, search for 'Created scanner ' pattern or the UUID of the scanner in the logs.
> 
> 
> 
> 
> Kind regards,
> 
> 
> Alexey
> 
> 
> 
> 
> On Mon, Jul 15, 2019 at 2:45 AM lk_hadoop <lk_hadoop@163.com> wrote:
> 
> hi,all:
>        My impala+kudu cluster suddenly become slow , I doubt  about the disk not work
well, I saw some scan infomation from kudu's web : xxx:8050/scans 
>        
>        7a2bb2a7e62d4614b423f26c3117b49e1934b20b8ab34ab98f1deb43c3eba4b2CompleteSELECT
membership_card_id,       tbill_code,       goods_id,       goods_name,       paid_in_amt,
      profit,       dates  FROM impala::TEST.SALE_BASE_FACT_WITH_MEMBERSHIP_20190626 WHERE
PRIMARY KEY >= <redacted>   AND PRIMARY KEY < <redacted>
> {username='hive'} at 10.8.50.58:4668219.3 s37 mincolumncells readbytes readblocks read
> membership_card_id381.10k3.85M18
> tbill_code372.82k5.99M27
> goods_id426.24k281.3K8
> dates426.24k8.5K8
> business_id426.24k2.7K8
> goods_name426.24k291.1K8
> paid_in_amt376.93k1019.6K24
> profit376.93k1.14M24
> total3.21M12.55M125
> 
>     is this mean the disk read rate was too slow ?      
> 
> 2019-07-15
> 
> 
> lk_hadoop 
> 
> 
> 
> 
> -- 
> 
> Andrew Wong

Mime
View raw message