kudu-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "lk_hadoop"<lk_had...@163.com>
Subject Re: Re: is this mean the disk read rate was too slow
Date Tue, 16 Jul 2019 01:32:50 GMT
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