Uploaded image for project: 'Percona Toolkit'
  1. Percona Toolkit
  2. PT-701

LP #1547225: pt-query-digest 32bit variable counters break output (are shown as 0)

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Done
    • Priority: High
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None

      Description

      **Reported in Launchpad by Agustín last update 24-06-2016 13:10:51

      As you can see in the following example (trivial slow log with only one query), once the counters exceed 4G (2^32), the output breaks and 0 is displayed instead.

      So, we have the following:

      Rows_sent = 10
      Rows_examined = 4294967297 (4G + 1)
      Rows_affected: 4294967296 (4G)
      Rows_read: 1024

      (note the same happens with InnoDB_IO_*, InnoDB_pages_distinct, etc., so the fix should include these counters, too).

      Then, pt-query-digest report as example below will show:

      1. Rows sent 10 10 10 10 10 0 10
      2. Rows examine 0 0 0 0 0 0 0
      3. Rows affecte 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
      4. Rows read 1.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k

      Clearly, rows_examined is wrongly displayed as 0.

      Example to reproduce this:

      $ cat mysql-slow.log

      1. User@Host: user[user] @ [192.168.1.2]
      2. Thread_id: 434469 Schema: some_schema Last_errno: 1265 Killed: 0
      3. Query_time: 29304.231566 Lock_time: 0.000480 Rows_sent: 10 Rows_examined: 4294967297 Rows_affected: 4294967296 Rows_read: 1024
      4. Bytes_sent: 153 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
      5. InnoDB_trx_id: 936E5
      6. QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
      7. Filesort: No Filesort_on_disk: No Merge_passes: 0
      8. InnoDB_IO_r_ops: 4294967296 InnoDB_IO_r_bytes: 4294967297 InnoDB_IO_r_wait: 5008.481097
      9. InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
      10. InnoDB_pages_distinct: 65536
        use some_schema;
        SET timestamp=1455618263;
        load data local infile '/tmp/load.tsv' into table test;

      $ pt-query-digest --group-by fingerprint --order-by InnoDB_IO_r_bytes:sum mysql-slow.log

      1. 520ms user time, 80ms system time, 31.88M rss, 110.12M vsz
      2. Current date: Thu Feb 18 16:21:38 2016
      3. Hostname: bm-support01
      4. Files: mysql-slow.log
      5. Overall: 1 total, 1 unique, 0 QPS, 0x concurrency ______________________
      6. Attribute total min max avg 95% stddev median
      7. ============ ======= ======= ======= ======= ======= ======= =======
      8. Exec time 29304s 29304s 29304s 29304s 29304s 0 29304s
      9. Lock time 480us 480us 480us 480us 480us 0 480us
      10. Rows sent 10 10 10 10 10 0 10
      11. Rows examine 0 0 0 0 0 0 0
      12. Rows affecte 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
      13. Rows read 1.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k
      14. Bytes sent 153 153 153 153 153 0 153
      15. Merge passes 0 0 0 0 0 0 0
      16. Tmp tables 0 0 0 0 0 0 0
      17. Tmp disk tbl 0 0 0 0 0 0 0
      18. Tmp tbl size 0 0 0 0 0 0 0
      19. Query size 55 55 55 55 55 0 55
      20. InnoDB:
      21. IO r bytes 0 0 0 0 0 0 0
      22. IO r ops 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
      23. IO r wait 5008s 5008s 5008s 5008s 5008s 0 5008s
      24. pages distin 64.00k 64.00k 64.00k 64.00k 64.00k 0 64.00k
      25. queue wait 0 0 0 0 0 0 0
      26. rec lock wai 0 0 0 0 0 0 0
      1. Profile
      2. Rank Query ID Response time Calls R/Call V/M Item
      3. ==== ================== ================= ===== ========== ===== =======
      4. 1 0x13A200BAE26EB6B7 29304.2316 100.0% 1 29304.2316 0.00 LOAD DATA test
      1. Query 1: 0 QPS, 0x concurrency, ID 0x13A200BAE26EB6B7 at byte 0 ________
      2. This item is included in the report because it matches --limit.
      3. Scores: V/M = 0.00
      4. Attribute pct total min max avg 95% stddev median
      5. ============ === ======= ======= ======= ======= ======= ======= =======
      6. Count 100 1
      7. Exec time 100 29304s 29304s 29304s 29304s 29304s 0 29304s
      8. Lock time 100 480us 480us 480us 480us 480us 0 480us
      9. Rows sent 100 10 10 10 10 10 0 10
      10. Rows examine 0 0 0 0 0 0 0 0
      11. Rows affecte 100 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
      12. Rows read 100 1.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k
      13. Bytes sent 100 153 153 153 153 153 0 153
      14. Merge passes 0 0 0 0 0 0 0 0
      15. Tmp tables 0 0 0 0 0 0 0 0
      16. Tmp disk tbl 0 0 0 0 0 0 0 0
      17. Tmp tbl size 0 0 0 0 0 0 0 0
      18. Query size 100 55 55 55 55 55 0 55
      19. InnoDB:
      20. IO r bytes 0 0 0 0 0 0 0 0
      21. IO r ops 100 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
      22. IO r wait 100 5008s 5008s 5008s 5008s 5008s 0 5008s
      23. pages distin 100 64.00k 64.00k 64.00k 64.00k 64.00k 0 64.00k
      24. queue wait 0 0 0 0 0 0 0 0
      25. rec lock wai 0 0 0 0 0 0 0 0
      26. String:
      27. Databases some_schema
      28. InnoDB trxID 936E5
      29. Last errno 1265
      30. Query_time distribution
      31. 1us
      32. 10us
      33. 100us
      34. 1ms
      35. 10ms
      36. 100ms
      37. 1s
      38. 10s+ ################################################################
      39. Tables
      40. SHOW TABLE STATUS FROM `some_schema` LIKE 'test'\G
      41. SHOW CREATE TABLE `some_schema`.`test`\G
        load data local infile '/tmp/load.tsv' into table test
        \G

        Smart Checklist

          Attachments

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              lpjirasync lpjirasync (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: