Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-773

LP:611878 - user_statistics.busy_time is unreliable

Details

    Description

      I was testing MariaDB 5.2.1-beta (on Debian 5.0), and bumped into the following weird behavior of user_statistics.busy_time: the value of this column seems completely unreliable and randomly increases at some points in time:

      MariaDB [(none)]> SELECT CONNECTED_TIME,BUSY_TIME,CPU_TIME FROM information_schema.user_statistics WHERE USER='core_d7';
      		 
      +----------------+------------------+------------------+
      		 
      | CONNECTED_TIME | BUSY_TIME        | CPU_TIME         |
      		 
      +----------------+------------------+------------------+
      		 
      |           2887 | 36893488147880.9 | 237.741877899973 |

      later...

      |           2919 | 36893488147887.3 | 241.586389299972 |

      later...

      |           2921 | 36893488147888.2 | 242.004482199972 |

      and now:

      |           3144 | 55340232221635 | 268.829147599973 |

      I don't have any additional information information at this point, just wanted to report the behavior in case it rings a bell for someone.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-775 LP:1018694 - CPU_TIME counter from USER_STATISTICS gets wrong after some uptime

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Open

          Bug - A problem which impairs or prevents the functions of the product. MDEV-673 LP:706991 - incorrect Bytes_received in user_statistics table

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Open

          Bug - A problem which impairs or prevents the functions of the product. MDEV-4578 information_schema.processlist reports incorrect value for Time (2147483647)

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            knielsen Kristian Nielsen added a comment -

            Re: user_statistics.busy_time is unreliable
            I believe the reporter meant to say that MariaDB 5.2.1 beta was being tested.

            knielsen Kristian Nielsen added a comment - Re: user_statistics.busy_time is unreliable I believe the reporter meant to say that MariaDB 5. 2 .1 beta was being tested.
            damientournoud Damien Tournoud (Inactive) added a comment -

            Re: user_statistics.busy_time is unreliable
            Indeed, that was 5.2.1-beta (Debian 5.0 build).

            damientournoud Damien Tournoud (Inactive) added a comment - Re: user_statistics.busy_time is unreliable Indeed, that was 5.2.1-beta (Debian 5.0 build).
            damientournoud Damien Tournoud (Inactive) added a comment -

            Re: user_statistics.busy_time is unreliable
            Anything I could do to help this go forward?

            damientournoud Damien Tournoud (Inactive) added a comment - Re: user_statistics.busy_time is unreliable Anything I could do to help this go forward?
            antonkhalikov Anton Khalikov (Inactive) added a comment -

            Re: user_statistics.busy_time is unreliable
            I can confirm this bug. We collect user statistics and run "SELECT * FROM INFORMATION_SCHEMA.USER_STATISTICS; FLUSH USER_STATISTICS" every 5 minutes. This is what I've got just before the end of a 5 minute interval:

            MariaDB [(none)]> select USER, TOTAL_CONNECTIONS, CPU_TIME, BYTES_RECEIVED, BYTES_SENT, ROWS_READ, ROWS_SENT, ROWS_DELETED, ROWS_INSERTED, ROWS_UPDATED, SELECT_COMMANDS, UPDATE_COMMANDS, OTHER_COMMANDS from INFORMATION_SCHEMA.USER_STATISTICS order by CPU_TIME desc limit 0,1\G

                                                                • 1. row ***************************
                                                                  USER: u4740
                                                                  TOTAL_CONNECTIONS: 3311
                                                                  CPU_TIME: 168767.2010919
                                                                  BYTES_RECEIVED: 722875
                                                                  BYTES_SENT: 15747206
                                                                  ROWS_READ: 73910638
                                                                  ROWS_SENT: 13124
                                                                  ROWS_DELETED: 0
                                                                  ROWS_INSERTED: 5749
                                                                  ROWS_UPDATED: 2982
                                                                  SELECT_COMMANDS: 1466
                                                                  UPDATE_COMMANDS: 3360
                                                                  OTHER_COMMANDS: 3311
                                                                  1 row in set (0.00 sec)

            and right after FLUSH again:

            MariaDB [(none)]> select USER, TOTAL_CONNECTIONS, CPU_TIME, BYTES_RECEIVED, BYTES_SENT, ROWS_READ, ROWS_SENT, ROWS_DELETED, ROWS_INSERTED, ROWS_UPDATED, SELECT_COMMANDS, UPDATE_COMMANDS, OTHER_COMMANDS from INFORMATION_SCHEMA.USER_STATISTICS order by CPU_TIME desc limit 0,1\G

                                                                • 1. row ***************************
                                                                  USER: u4740
                                                                  TOTAL_CONNECTIONS: 31
                                                                  CPU_TIME: 827.8829815
                                                                  BYTES_RECEIVED: 8945
                                                                  BYTES_SENT: 4590920
                                                                  ROWS_READ: 177196
                                                                  ROWS_SENT: 1709
                                                                  ROWS_DELETED: 0
                                                                  ROWS_INSERTED: 0
                                                                  ROWS_UPDATED: 27
                                                                  SELECT_COMMANDS: 7
                                                                  UPDATE_COMMANDS: 30
                                                                  OTHER_COMMANDS: 30
                                                                  1 row in set (0.00 sec)

            So we see here CPU_TIME has been reset but increased to over 800 units within a couple of seconds. And it reached about 170000 units within 5 minutes. Either units are milliseconds or there is something really wrong.

            Could anyone confirm ?

            I use Debian 6 on amd64, MariaDB 5.2.12

            antonkhalikov Anton Khalikov (Inactive) added a comment - Re: user_statistics.busy_time is unreliable I can confirm this bug. We collect user statistics and run "SELECT * FROM INFORMATION_SCHEMA.USER_STATISTICS; FLUSH USER_STATISTICS" every 5 minutes. This is what I've got just before the end of a 5 minute interval: MariaDB [(none)] > select USER, TOTAL_CONNECTIONS, CPU_TIME, BYTES_RECEIVED, BYTES_SENT, ROWS_READ, ROWS_SENT, ROWS_DELETED, ROWS_INSERTED, ROWS_UPDATED, SELECT_COMMANDS, UPDATE_COMMANDS, OTHER_COMMANDS from INFORMATION_SCHEMA.USER_STATISTICS order by CPU_TIME desc limit 0,1\G 1. row *************************** USER: u4740 TOTAL_CONNECTIONS: 3311 CPU_TIME: 168767.2010919 BYTES_RECEIVED: 722875 BYTES_SENT: 15747206 ROWS_READ: 73910638 ROWS_SENT: 13124 ROWS_DELETED: 0 ROWS_INSERTED: 5749 ROWS_UPDATED: 2982 SELECT_COMMANDS: 1466 UPDATE_COMMANDS: 3360 OTHER_COMMANDS: 3311 1 row in set (0.00 sec) and right after FLUSH again: MariaDB [(none)] > select USER, TOTAL_CONNECTIONS, CPU_TIME, BYTES_RECEIVED, BYTES_SENT, ROWS_READ, ROWS_SENT, ROWS_DELETED, ROWS_INSERTED, ROWS_UPDATED, SELECT_COMMANDS, UPDATE_COMMANDS, OTHER_COMMANDS from INFORMATION_SCHEMA.USER_STATISTICS order by CPU_TIME desc limit 0,1\G 1. row *************************** USER: u4740 TOTAL_CONNECTIONS: 31 CPU_TIME: 827.8829815 BYTES_RECEIVED: 8945 BYTES_SENT: 4590920 ROWS_READ: 177196 ROWS_SENT: 1709 ROWS_DELETED: 0 ROWS_INSERTED: 0 ROWS_UPDATED: 27 SELECT_COMMANDS: 7 UPDATE_COMMANDS: 30 OTHER_COMMANDS: 30 1 row in set (0.00 sec) So we see here CPU_TIME has been reset but increased to over 800 units within a couple of seconds. And it reached about 170000 units within 5 minutes. Either units are milliseconds or there is something really wrong. Could anyone confirm ? I use Debian 6 on amd64, MariaDB 5.2.12
            ratzpo Rasmus Johansson (Inactive) added a comment -

            Launchpad bug id: 611878

            ratzpo Rasmus Johansson (Inactive) added a comment - Launchpad bug id: 611878
            elenst Elena Stepanova added a comment - - edited

            See also MDEV-673, MDEV-775 and comments to it with LP bugs in Percona project. There have been and still are several bugs related to user_statistics, some of them fixed, some still open.

            elenst Elena Stepanova added a comment - - edited See also MDEV-673 , MDEV-775 and comments to it with LP bugs in Percona project. There have been and still are several bugs related to user_statistics, some of them fixed, some still open.

            People

              Unassigned Unassigned
              damientournoud Damien Tournoud (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.