Uploaded image for project: 'Percona Monitoring and Management'
  1. Percona Monitoring and Management
  2. PMM-948

Wrong Load Reported by QAN due to mis-alignment of time intervals

    Details

    • Type: Bug
    • Status: Done
    • Priority: Low
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.9.0
    • Component/s: QAN App
    • Labels:
    • Story Points:
      1

      Description

      Hi,

      I'm running benchmark with 32 connections as such the load normally should be at 32 or below with possible little spikes for additional connections for monitoring etc. We see the reasonably expected avg load of 28.5

      [image: Inline image 1]

      However we see the spike to over 50 here:

      [image: Inline image 2]

      Similar spike can be observed in the count:

      [image: Inline image 3]

      We can validate there is not corresponding spike in the QPS

      [image: Inline image 4]

      Note the AVG is relatively similar - 23.2 vs 23.8 while this spike is probably caused by some bug. There are no corresponding errors or warnings in pmm-mysql-queries-0.log. The log file from QAN interface:

      2017-06-04T14:57:01.003989631Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log 24401610-36463492: 100.0% 36463493/36463492 12061882 1.0s
       2017-06-04T14:56:44.10507331Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:a786dce6-a771-4bb7-56ff-5c689ec082a5]
       2017-06-04T14:56:44.101269302Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:56:44.101362158 +0000 UTC' User:api AgentUUID: Id:a786dce6-a771-4bb7-56ff-5c689ec082a5]
       2017-06-04T14:56:13.018663328Z data-sender info at 2017-06-04 14:56:12 UTC: 1 files, 16.14 kB, 781ms, 0.17 Mbps net util, 2158.08 Mbps net speed
       2017-06-04T14:56:01.029423588Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log 12147029-24401610: 100.0% 24401611/24401610 12254581 1.0s
       2017-06-04T14:55:44.104914433Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:b459e544-37a7-4e96-58f9-b07c595a0134]
       2017-06-04T14:55:44.101235956Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:55:44.101416693 +0000 UTC' User:api AgentUUID: Id:b459e544-37a7-4e96-58f9-b07c595a0134]
       2017-06-04T14:55:09.984523667Z data-sender info at 2017-06-04 14:55:09 UTC: 1 files, 16.08 kB, 747ms, 0.17 Mbps net util, 1650.86 Mbps net speed
       2017-06-04T14:55:01.068396753Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log 0-12147029: 100.0% 12147030/12147029 12147029 1.1s
       2017-06-04T14:55:00.000712722Z qan-interval info File changed
       2017-06-04T14:54:44.105433152Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:0d8f2ce6-b103-489f-6a50-6ea074771d85]
       2017-06-04T14:54:44.102333964Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:54:44.102368228 +0000 UTC' User:api AgentUUID: Id:0d8f2ce6-b103-489f-6a50-6ea074771d85]
       2017-06-04T14:54:07.026287105Z data-sender info at 2017-06-04 14:54:06 UTC: 1 files, 16.34 kB, 789ms, 0.17 Mbps net util, 2470.23 Mbps net speed
       2017-06-04T14:54:01.139667236Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log-1496588040 1071585753-1083761157: 100.0% 1083760253/1083761157 12175404 1.0s
       2017-06-04T14:54:00.128948581Z qan-analyzer-mysql-c9b0b790-worker info Removed old slow log /var/lib/mysql/ts140i-slow.log-1496523720
       2017-06-04T14:54:00.000859406Z qan-analyzer-mysql-c9b0b790-worker info Rotating slow log: 1.08 GB >= 1.07 GB
       2017-06-04T14:53:44.10504914Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:40320ed9-ff34-43f3-51e7-b2167905fb8f]
       2017-06-04T14:53:44.101861406Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:53:44.101941175 +0000 UTC' User:api AgentUUID: Id:40320ed9-ff34-43f3-51e7-b2167905fb8f]
       2017-06-04T14:53:05.017045602Z data-sender info at 2017-06-04 14:53:03 UTC: 2 files, 34.17 kB, 1.78s, 0.15 Mbps net util, 1815.77 Mbps net speed
       2017-06-04T14:53:00.95507216Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log 1060296745-1071585753: 100.0% 1071585754/1071585753 11289008 0.9s
       2017-06-04T14:52:44.10490652Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:9f8739c5-bba8-4a06-5c13-1540b94a8fbe]
       2017-06-04T14:52:44.100923483Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:52:44.101123963 +0000 UTC' User:api AgentUUID: Id:9f8739c5-bba8-4a06-5c13-1540b94a8fbe]
       2017-06-04T14:52:01.079324373Z data-sender info at 2017-06-04 14:52:00 UTC: 1 files, 16.00 kB, 833ms, 0.15 Mbps net util, 2243.85 Mbps net speed
       2017-06-04T14:52:00.902970191Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log 1049807977-1060296745: 100.0% 1060296746/1060296745 10488768 0.9s
       2017-06-04T14:51:44.105622362Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:f8782709-ac9a-4789-6747-45bfa5be8090]
       2017-06-04T14:51:44.101768191Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:51:44.101697025 +0000 UTC' User:api AgentUUID: Id:f8782709-ac9a-4789-6747-45bfa5be8090]
       2017-06-04T14:51:00.8222974Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log 1039836468-1049807977: 100.0% 1049807978/1049807977 9971509 0.8s
       2017-06-04T14:50:58.030889763Z data-sender info at 2017-06-04 14:50:57 UTC: 1 files, 15.91 kB, 793ms, 0.16 Mbps net util, 1828.97 Mbps net speed
       2017-06-04T14:50:44.105294912Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:ab2b8079-61e1-4621-67bc-bb390e85d9b9]
       2017-06-04T14:50:44.101576237Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:50:44.101409508 +0000 UTC' User:api AgentUUID: Id:ab2b8079-61e1-4621-67bc-bb390e85d9b9]
      2017-06-04T14:50:00.801470257Z qan-analyzer-mysql-c9b0b790-worker info Parsed
       /var/lib/mysql/ts140i-slow.log 1030425015-1039836468: 100.0% 1039836469/1039836468 9411453 0.8s
       2017-06-04T14:49:55.041254256Z data-sender info at 2017-06-04 14:49:54 UTC: 1 files, 14.97 kB, 803ms, 0.15 Mbps net util, 1964.95 Mbps net speed
       2017-06-04T14:49:44.104917697Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:2c677c6e-2ccd-4a60-5f2c-dae68534ce40]
       2017-06-04T14:49:44.102282646Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:49:44.101998092 +0000 UTC' User:api AgentUUID: Id:2c677c6e-2ccd-4a60-5f2c-dae68534ce40]
       2017-06-04T14:49:00.701793448Z qan-analyzer-mysql-c9b0b790-worker info Parsed /var/lib/mysql/ts140i-slow.log 1022085073-1030425015: 100.0% 1030425016/1030425015 8339942 0.7s
       2017-06-04T14:48:52.020156534Z data-sender info at 2017-06-04 14:48:51 UTC: 1 files, 14.55 kB, 782ms, 0.15 Mbps net util, 1232.37 Mbps net speed
       2017-06-04T14:48:44.105633688Z agent info Cmd ok: Reply[Cmd:Version Error:'' Id:8f9e9f7b-ba87-4717-417f-c2a4dd7e6542]
       2017-06-04T14:48:44.102551943Z agent info Cmd begin: Cmd[Service:agent Cmd:Version Ts:'2017-06-04 14:48:44.102338729 +0000 UTC' User:api AgentUUID: Id:8f9e9f7b-ba87-4717-417f-c2a4dd7e6542]
      

      There does not seem to be anything unusual at this time. The log file is rotated but few min later.

       

      TODO: Implement sparklines for less than 1 hour interval with a smaller amount of datapoints 

        Smart Checklist

          Attachments

          1. image.png
            image.png
            71 kB
          2. image.png
            image.png
            19 kB
          3. image.png
            image.png
            22 kB
          4. image.png
            image.png
            60 kB
          5. image-2017-06-04-18-19-49-779.png
            image-2017-06-04-18-19-49-779.png
            11 kB
          6. image-2017-06-04-18-21-38-261.png
            image-2017-06-04-18-21-38-261.png
            21 kB
          7. image-2017-06-04-18-24-18-758.png
            image-2017-06-04-18-24-18-758.png
            15 kB
          8. Screen Shot 2018-03-26 at 15.37.33.png
            Screen Shot 2018-03-26 at 15.37.33.png
            102 kB
          9. Screen Shot 2018-03-28 at 10.35.29.png
            Screen Shot 2018-03-28 at 10.35.29.png
            110 kB

            Issue Links

              Activity

                People

                • Assignee:
                  Unassigned
                  Reporter:
                  pz Peter Zaitsev
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  4 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved:

                    Time Tracking

                    Estimated:
                    Original Estimate - Not Specified
                    Not Specified
                    Remaining:
                    Remaining Estimate - 0 minutes
                    0m
                    Logged:
                    Time Spent - 7 hours, 30 minutes
                    7h 30m