前言

相关链接：

• pt-query-digest ： https://www.percona.com/doc/percona-toolkit/LATEST/pt-query-digest.html
• 参考链接：https://www.cnblogs.com/peter-yan/p/8670005.html

  日志文件分为三部分

1. 总体统计结果
2. 查询分组统计结果
3. 每一种查询的详细统计结果

   总体统计结果

   ## 该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小
   # 40.2s user time, 2.3s system time, 49.61M rss, 244.28M vsz
   ## 工具执行时间
   # Current date: Fri Nov 26 15:16:45 2021
   ## 运行分析工具的主机名
   # Hostname: HZPL132182
   ## 被分析的文件名
   # Files: /data/mysql/mysql-slow.log
   ## 语句总数量，唯一的语句数量，QPS，并发数
   # Overall: 21.70k total, 403 unique, 0.18 QPS, 0.18x concurrency _________
   ## 日志记录的时间范围
   # Time range: 2021-11-25T05:00:33 to 2021-11-26T15:00:09
   ## 属性               总计      最小    最大    平均     95%  标准    中等
   # Attribute          total     min     max     avg     95%  stddev  median
   # ============     ======= ======= ======= ======= ======= ======= =======
   ## 语句执行时间
   # Exec time         21774s   100ms    880s      1s      2s     12s   208ms
   ## 锁占用时间
   # Lock time             5s       0    24ms   238us   236us     1ms   113us
   ## 发送到客户端的行数
   # Rows sent          1.65M       0  70.02k   79.79  313.99   1.01k    0.99
   ## select语句扫描行数
   # Rows examine       3.43G       0  29.11M 165.61k 419.40k 781.22k  68.96k
   ## 查询的字符数
   # Query size        23.36M       6   1.11M   1.10k   2.06k  11.39k  652.75

   查询分组统计结果

• rank：所有语句的排序，默认按照查询时间降序排序，通过—order-by指定
• query id：语句的id，（去掉多余空格和文本字符，计算hash值）
• response：总的响应时间
• time：该查询在本次分析中总的时间占比
• calls：执行次数，即本次分析总共有多少条这种类型的查询语句
• r/call：平均每次执行的响应时间
• v/m：响应时间variance-to-mean的比率

• item：查询对象

  # Profile
  # Rank Query ID                            Response time   Calls R/Call   
  # ==== =================================== =============== ===== ======== 
  #    1 0xB2B0798779C1185F917C9074F4BE4EA9  2589.9736 11.9%  1993   1.2995  0.00 SELECT route_asset_create
  #    2 0xFFFCA4D67EA0A788813031B8BBC3B329  1746.9138  8.0%  1005   1.7382 43.41 COMMIT
  #    3 0xED89ABC6896E62BFF2BF515C0B59ED9D  1336.8208  6.1%     2 668.4104 13... DELETE asset_stock_change_record
  #    4 0x54C95D7CE255F6B3AD2F2D6A49E5FD84  1333.4389  6.1%   677   1.9696  3.66 SELECT asset_stock_deliver asset_stock_deliver_details
  #    5 0xD594015F22D8A44B03D1EA9B57AC9365  1170.6767  5.4%     2 585.3384 10... DELETE asset_stock_deliver_details
  #    6 0xEA00D8C5A5C30D8E1861D293FDD8E12B  1024.8648  4.7%     5 204.9730  2.66 DELETE asset_stock_log
  #    7 0xB84E008E1C583E5CD1E03185B5F2514F   918.5127  4.2%    44  20.8753 25.45 SHOW BINARY LOGS
  #    8 0x5070EB979450C5010A580B79F58290B8   754.8236  3.5%     2 377.4118  2.40 DELETE asset_stock_deliver
  #    9 0x685FA5D5D3355C6FE0D8658EB693EF83   746.5994  3.4%   652   1.1451  9.21 SELECT asset_stock_deliver asset_stock_deliver_details
  #   10 0x60D0DA7F2430E6B818B354B5C56EAF3D   738.5486  3.4%    16  46.1593  0.45 SELECT asset_stock_statement asset_stock_statement_details
  #   11 0x5DCB2B57A2AF77BB4E940E8495874731   738.2868  3.4%    33  22.3723 29.52 SHOW MASTER STATUS
  #   12 0xB28509F0EDDE7BBE8F0C37247D658553   586.3970  2.7%     1 586.3970  0.00 DELETE asset_stock_change_record
  #   13 0x38B0E61F1C107EF69C3F5684A15B30A6   534.9132  2.5%     1 534.9132  0.00 DELETE asset_stock_deliver_details
  #   14 0xE3ADF9C0AFD1F3CA5EA4810281543456   481.9571  2.2%   728   0.6620 14.19 UPDATE asset_base_supplier
  #   15 0xD9B4E109EC4436FFA6873D56F8D78F71   424.1016  1.9%     1 424.1016  0.00 DELETE asset_fixed_inventory_details
  #   16 0x5440296FE2AD3B57B4F2ACCA1A79E313   419.4397  1.9%  1912   0.2194  0.00 SELECT zto_eps_apply_event
  #   17 0x70164896C7389A31E65D86C9455752F5   394.6824  1.8%   733   0.5384  5.16 UPDATE asset_base_account
  #   18 0x74896C4CAA20F2933F9DAE152AE9F3E5   344.6213  1.6%  2726   0.1264  0.00 SELECT require_sheet_item
  #   19 0x24787618599F488A6209AE0D89AE66C9   292.1928  1.3%   117   2.4974  0.18 SELECT asset_fixed_card asset_base_permissions
  #   20 0xC45B9ED23F4B222EBD12B037EA63BE45   283.4558  1.3%     2 141.7279 17... DELETE asset_stock_psi_details
  #   22 0xFFF66E9B3D962FA319C8068B5C1997CD   244.9044  1.1%   540   0.4535  0.36 ROLLBACK
  #   23 0x9F08F176468E36BC38DB14CCE2E7AA13   244.7036  1.1%    88   2.7807  0.01 SELECT asset_fixed_card asset_base_permissions
  #   24 0x7DBEF32531C4AA21488FEDD7107B89B2   229.6844  1.1%   130   1.7668 45.68 UPDATE zto_eps_reconciliation
  #   27 0xA44E82DEC8D96A37A8B1850F368E5067   180.8019  0.8%    94   1.9234  0.78 SELECT asset_fixed_card asset_base_permissions
  #   30 0xED729D3DEBF2064EBC3155C59A230A1E   114.1509  0.5%    18   6.3417  2.29 SELECT asset_stock_statement
  #   31 0x09420503C56CE0F5327DC44B0C341C98   109.7244  0.5%    19   5.7750  2.41 SELECT asset_stock_statement
  #   32 0xB4602F7B14F034E023EE24BA7E6A1C7E    93.6596  0.4%    18   5.2033 25.51 UPDATE asset_base_notice
  #   34 0x4171049FE95D8B716249BD471819C981    87.0217  0.4%    33   2.6370  0.03 SELECT asset_fixed_card asset_base_permissions
  #   38 0xDFE26A40497ED18EA09E01EC381159B0    71.6004  0.3%    26   2.7539  0.00 SELECT asset_fixed_card asset_base_permissions
  #   45 0x97A916987EF00168F76BEC911C975822    49.6040  0.2%    18   2.7558  0.00 SELECT asset_fixed_card asset_base_permissions
  #   49 0x17DE7DE0DB8EC9C9117B9ED662AC9A4E    40.3882  0.2%    49   0.8242  3.52 SELECT asset_stock_change_record
  #   53 0xCE5ADDE6F9602ECA5EE0A50CB7EB06B9    35.1247  0.2%    21   1.6726  0.47 SELECT asset_fixed_card asset_base_permissions
  #   54 0x1DC5E2478C02B061596AC41AC805A52D    33.4037  0.2%    12   2.7836  0.00 SELECT asset_fixed_card asset_base_permissions
  #   56 0x318CD7ADECE180F64EA3AB3AF7AC8A4A    31.2933  0.1%    17   1.8408  0.79 SELECT asset_fixed_card asset_base_permissions
  #   57 0xE1E27E746E56611E4B3BC2985E974D61    30.2920  0.1%    11   2.7538  0.00 SELECT asset_fixed_card
  #   62 0xDDC12BFF3D56315457BE3028D75A94FE    27.3043  0.1%    14   1.9503  0.64 SELECT asset_fixed_card asset_base_permissions asset_base_goods
  #   64 0x4E341726DD1C59E46C7FB0FB7E309F9F    22.8971  0.1%    10   2.2897  0.11 SELECT asset_fixed_card asset_base_permissions
  #   65 0xEC965A39F14618F83CF382BF25D1F74E    22.8122  0.1%    11   2.0738  0.03 SELECT asset_fixed_card asset_base_permissions
  #   72 0x8874A291638C5EF80FECF05711FEDBAF    18.7686  0.1%    10   1.8769  0.72 SELECT asset_fixed_card asset_base_permissions
  #   73 0x689E3494A1281CCBD9EF4AB986751B74    18.1146  0.1%    20   0.9057  0.33 INSERT asset_stock_statement
  #   75 0xBD1C9BA0CC2E03EF380626537AFBD25D    17.8556  0.1%    18   0.9920  0.19 UPDATE bid_supplier
  #   88 0x5DC9B0D7CD4066A927641E428F51E203    14.3011  0.1%    11   1.3001  0.32 SELECT asset_fixed_card asset_base_permissions
  #  132 0xDFBA49C782C2BAB492E3EB435F6EF50A     5.6427  0.0%    15   0.3762  0.49 SELECT asset_stock_deliver asset_stock_deliver_details
  #  134 0xC6D6F31AC559A7DF05F28D3974183DCC     5.5700  0.0%    15   0.3713  0.48 SELECT asset_stock_deliver asset_stock_deliver_details
  #  144 0x5E4137CF8B84ED9B38C0E31750FD9D91     5.1630  0.0%    13   0.3972  0.46 SELECT asset_stock_deliver asset_stock_deliver_details
  #  148 0xE3B64AFE65127A19BD6A9678850D787C     5.0032  0.0%    13   0.3849  0.43 SELECT asset_stock_deliver asset_stock_deliver_details
  # MISC 0xMISC                              3153.4335 14.5%  9799   0.3218   0.0 <357 ITEMS>
  

  每一种查询的详细统计结果

• id：查询的id号，和上面的query id对应

• databases：数据库名
• users：各个用户执行的次数（占比）
• query_time_distribution：查询时间分布，长短体现区间占比
• tables：查询中设计到的表
• explain：sql语句 ```sql

  Query 1: 0.02 QPS, 0.02x concurrency, ID 0xB2B0798779C1185F917C9074F4BE4EA9 at byte 684347627

  This item is included in the report because it matches —limit.

  Scores: V/M = 0.00

  Time range: 2021-11-25T05:00:33 to 2021-11-26T14:59:51

  Attribute pct total min max avg 95% stddev median

  ============ === ======= ======= ======= ======= ======= ======= =======

  Count 9 1993

  Exec time 11 2590s 1s 2s 1s 1s 51ms 1s

  Lock time 5 308ms 114us 646us 154us 194us 25us 144us

  Rows sent 0 135 0 108 0.07 0 2.43 0

  Rows examine 17 610.52M 313.67k 313.70k 313.68k 312.96k 0 312.96k

  Query size 9 2.12M 1.09k 1.09k 1.09k 1.09k 0 1.09k

  String:

  Databases asset

  Hosts 10.4.83.5

  Users asset

  Query_time distribution

  1us

  10us

  100us

  1ms

  10ms

  100ms

  1s

  10s+

  Tables

  SHOW TABLE STATUS FROM asset LIKE ‘route_asset_create’\G

  SHOW CREATE TABLE asset.route_asset_create\G

  EXPLAIN /!50100 PARTITIONS/

  SELECT id,biz_no,source_type,source_order_no,build_detail_id,warehouse_id,warehouse_code,warehouse_name,department_id,department_name,use_date,use_status,admin_employee_code,admin_employee_name,use_employee_code,use_employee_name,label_type,equipment_code,asset_location,use_site_id,use_site_code,use_site_name,tax_rate,asset_money,lease_organization_code,lease_organization_name,financial_code,asset_type,parent_asset_code,parent_asset_name,supplier_code,supplier_name,material_code,material_name,goods_code,goods_name,brand_code,brand_name,spec_code,spec_name,organization_code,organization_name,pact_no,three_type_code,three_type_name,status,audit_status,remark,fixed_type,length,width,height,deleted_status,create_date,create_user_id,create_user_code,create_user_name,modify_date,modify_user_id,modify_user_code,modify_user_name,version,asset_code,price_exclude_tax,err_msg,create_department_id,create_department_name FROM route_asset_create WHERE ( deleted_status = 0

          and status = 1



          and source_type = 1 )\G

Query 2: 0.01 QPS, 0.02x concurrency, ID 0xFFFCA4D67EA0A788813031B8BBC3B329 at byte 685443544

This item is included in the report because it matches —limit.

Scores: V/M = 43.41

Time range: 2021-11-25T09:43:12 to 2021-11-26T13:33:26

Attribute pct total min max avg 95% stddev median

============ === ======= ======= ======= ======= ======= ======= =======

Count 4 1005

Exec time 8 1747s 101ms 113s 2s 2s 9s 526ms

Lock time 0 0 0 0 0 0 0 0

Rows sent 0 0 0 0 0 0 0 0

Rows examine 0 0 0 0 0 0 0 0

Query size 0 5.89k 6 6 6 6 0 6

String:

Databases asset (994/98%), asset_user (8/0%)… 1 more

Hosts 10.4.83.3 (864/85%), 10.5.144.176 (42/4%)… 11 more

Users asset (993/98%), asset_user (8/0%)… 2 more

Query_time distribution

1us

10us

100us

1ms

10ms

100ms

1s

10s+

commit\G

Query 3: 0.00 QPS, 2.93x concurrency, ID 0xED89ABC6896E62BFF2BF515C0B59ED9D at byte 683977837

This item is included in the report because it matches —limit.

Scores: V/M = 134.25

Time range: 2021-11-25T22:33:30 to 2021-11-25T22:41:07

Attribute pct total min max avg 95% stddev median

============ === ======= ======= ======= ======= ======= ======= =======

Count 0 2

Exec time 6 1337s 457s 880s 668s 880s 300s 668s

Lock time 0 117us 55us 62us 58us 62us 4us 58us

Rows sent 0 0 0 0 0 0 0 0

Rows examine 0 10.37M 4.32M 6.05M 5.19M 6.05M 1.22M 5.19M

Query size 0 240 120 120 120 120 0 120

String:

Databases asset

Hosts localhost

Users daily_dba

Query_time distribution

1us

10us

100us

1ms

10ms

100ms

1s

10s+

Tables

SHOW TABLE STATUS FROM asset LIKE ‘asset_stock_change_record’\G

SHOW CREATE TABLE asset.asset_stock_change_record\G

delete from asset_stock_change_record where create_date >= ‘2021-05-01 00:00:00’ and create_date < ‘2021-07-01 00:00:00’\G

Converted for EXPLAIN

EXPLAIN /!50100 PARTITIONS/

select * from asset_stock_change_record where create_date >= ‘2021-05-01 00:00:00’ and create_date < ‘2021-07-01 00:00:00’\G

Query 4: 0.01 QPS, 0.01x concurrency, ID 0x54C95D7CE255F6B3AD2F2D6A49E5FD84 at byte 674754184

This item is included in the report because it matches —limit.

Scores: V/M = 3.66

Time range: 2021-11-25T07:57:54 to 2021-11-26T14:58:27

Attribute pct total min max avg 95% stddev median

============ === ======= ======= ======= ======= ======= ======= =======

Count 3 677

Exec time 6 1333s 104ms 12s 2s 9s 3s 356ms

Lock time 2 124ms 150us 897us 182us 224us 40us 167us

Rows sent 1 17.40k 1 117 26.31 49.17 21.13 16.81

Rows examine 10 376.90M 46.87k 2.49M 570.09k 2.26M 670.45k 165.97k

Query size 5 1.18M 1.66k 2.86k 1.79k 1.96k 158.15 1.69k

String:

Databases asset

Hosts 10.5.154.247 (232/34%), 10.5.156.222 (223/32%)… 1 more

Users asset

Query_time distribution

1us

10us

100us

1ms

10ms

100ms

1s

10s+

Tables

SHOW TABLE STATUS FROM asset LIKE ‘asset_stock_deliver’\G

SHOW CREATE TABLE asset.asset_stock_deliver\G

SHOW TABLE STATUS FROM asset LIKE ‘asset_stock_deliver_details’\G

SHOW CREATE TABLE asset.asset_stock_deliver_details\G

EXPLAIN /!50100 PARTITIONS/

SELECT id, deliver_order_code, bill_type_id, bill_type_name, receive_use_code, receive_use_name, receive_department_id, receive_department_name, delivery_department_id, delivery_department_name, warehouse_id, warehouse_code, warehouse_name, quantity, direct_receive, abnormal, status, offset_type, oa_workflow_code, remark, audit_user_id, audit_user_code, audit_user_name, audit_date, audit_remark, supplier_code, supplier_name, deleted_status, create_date, create_user_id, create_user_code, create_user_name, modify_date, modify_user_id, modify_user_code, modify_user_name, version, business_order_id, business_order_code, take_site_id, take_site_code, take_site_name, level1_department_id, level1_department_name, market_dept_name,business_date, is_materiel_warehouse_straight_branch FROM asset_stock_deliver force index(asset_stock_deliver_index_4) WHERE deleted_status = 0 AND NOT (version = 0 AND quantity = 0)

        and id in (
        select main_order_id from asset_stock_deliver_details
        where deleted_status = 0 and warehouse_id IN
             (  
                203
             , 
                262
             , 
                304
             , 
                583
             , 
                584
             , 
                1985
             ) 
        )




















        and create_date between '2021-08-27' and '2021-11-25 23:59:59'







    order by modify_date desc LIMIT 1\G

Query 5: 0.00 QPS, 2.88x concurrency, ID 0xD594015F22D8A44B03D1EA9B57AC9365 at byte 684748366

This item is included in the report because it matches —limit.

Scores: V/M = 107.93

Time range: 2021-11-25T23:36:46 to 2021-11-25T23:43:33

Attribute pct total min max avg 95% stddev median

============ === ======= ======= ======= ======= ======= ======= =======

Count 0 2

Exec time 5 1171s 408s 763s 585s 763s 251s 585s

Lock time 0 127us 57us 70us 63us 70us 9us 63us

Rows sent 0 0 0 0 0 0 0 0

Rows examine 0 10.30M 4.29M 6.00M 5.15M 6.00M 1.21M 5.15M

Query size 0 244 122 122 122 122 0 122

String:

Databases asset

Hosts localhost

Users daily_dba

Query_time distribution

1us

10us

100us

1ms

10ms

100ms

1s

10s+

Tables

SHOW TABLE STATUS FROM asset LIKE ‘asset_stock_deliver_details’\G

SHOW CREATE TABLE asset.asset_stock_deliver_details\G

delete from asset_stock_deliver_details where create_date >= ‘2021-05-01 00:00:00’ and create_date < ‘2021-07-01 00:00:00’\G

Converted for EXPLAIN

EXPLAIN /!50100 PARTITIONS/

select * from asset_stock_deliver_details where create_date >= ‘2021-05-01 00:00:00’ and create_date < ‘2021-07-01 00:00:00’\G

Query 6: 0.00 QPS, 0.60x concurrency, ID 0xEA00D8C5A5C30D8E1861D293FDD8E12B at byte 686087761

This item is included in the report because it matches —limit.

Scores: V/M = 2.66

Time range: 2021-11-26T00:22:34 to 2021-11-26T00:50:53

Attribute pct total min max avg 95% stddev median

============ === ======= ======= ======= ======= ======= ======= =======

Count 0 5

Exec time 4 1025s 172s 241s 205s 234s 23s 202s

Lock time 0 331us 48us 105us 66us 103us 20us 60us

Rows sent 0 0 0 0 0 0 0 0

Rows examine 0 16.88M 859.00k 8.07M 3.38M 8.03M 3.10M 871.90k

Query size 0 580 116 116 116 116 0 116

String:

Databases asset

Hosts localhost

Users daily_dba

Query_time distribution

1us

10us

100us

1ms

10ms

100ms

1s

10s+

Tables

SHOW TABLE STATUS FROM asset LIKE ‘asset_stock_log’\G

SHOW CREATE TABLE asset.asset_stock_log\G

delete from asset_stock_log where operation_date >= ‘2021-07-01 00:00:00’ and operation_date < ‘2021-08-01 00:00:00’\G

Converted for EXPLAIN

EXPLAIN /!50100 PARTITIONS/

select * from asset_stock_log where operation_date >= ‘2021-07-01 00:00:00’ and operation_date < ‘2021-08-01 00:00:00’\G ```