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

CPU_User value from SHOW PROFILE ALL output can be greater than Duration value

    XMLWordPrintable

Details

    Description

      In the output from "SHOW PROFILE ALL", I would expect the "Duration" value for a particular state to be greater than the values for all other fields, since the "Duration" should be the total time spent in that state. However, it looks like the value for CPU_User can actually be greater than the value for Duration in some cases. For example:

      MariaDB [db]> show profile all for query 1;
      +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+
      | Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
      +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+
      | starting | 0.000416 | 0.000765 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
      | checking permissions | 0.000025 | 0.000044 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 6069 |
      | checking permissions | 0.000015 | 0.000029 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 6069 |
      | checking permissions | 0.000015 | 0.000063 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 6069 |
      | checking permissions | 0.000018 | 0.000057 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 6069 |
      | Opening tables | 0.000087 | 0.000266 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 4508 |
      | After opening tables | 0.000027 | 0.000074 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 4755 |
      | System lock | 0.000024 | 0.000031 | 0.000041 | 0 | 0 | 0 | 8 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 308 |
      | Table lock | 0.000249 | 0.000762 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 313 |
      | init | 0.000297 | 0.000690 | 0.000000 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 3421 |
      | optimizing | 0.000026 | 0.000040 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize_inner | sql_select.cc | 1084 |
      | optimizing | 0.000060 | 0.000000 | 0.000115 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize_inner | sql_select.cc | 1084 |
      | statistics | 0.000186 | 0.000000 | 0.000378 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize_inner | sql_select.cc | 1365 |
      | preparing | 0.000132 | 0.000000 | 0.000267 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize_inner | sql_select.cc | 1390 |
      | statistics | 0.000117 | 0.000044 | 0.000277 | 2 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize_inner | sql_select.cc | 1365 |
      | preparing | 0.000089 | 0.000170 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize_inner | sql_select.cc | 1390 |
      | executing | 0.000022 | 0.000046 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec_inner | sql_select.cc | 2544 |
      | Creating tmp table | 0.000075 | 0.000152 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | init_execution | sql_select.cc | 2078 |
      | Copying to tmp table | 0.000122 | 0.000248 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec_inner | sql_select.cc | 2755 |
      | Sorting result | 0.000079 | 0.000156 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | exec_inner | sql_select.cc | 3061 |
      | Sending data | 0.000043 | 0.000082 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec_inner | sql_select.cc | 3216 |
      | end | 0.000025 | 0.000050 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 3456 |
      | removing tmp table | 0.000028 | 0.000236 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | free_tmp_table | sql_select.cc | 17745 |
      | end | 0.000123 | 0.000066 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | free_tmp_table | sql_select.cc | 17769 |
      | query end | 0.000028 | 0.000056 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5705 |
      | closing tables | 0.000024 | 0.000047 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | close_thread_tables | sql_base.cc | 919 |
      | removing tmp table | 0.000024 | 0.000048 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | free_tmp_table | sql_select.cc | 17745 |
      | closing tables | 0.000024 | 0.000047 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | free_tmp_table | sql_select.cc | 17769 |
      | Unlocking tables | 0.000049 | 0.000100 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_unlock_tables | lock.cc | 395 |
      | freeing items | 0.000057 | 0.000072 | 0.000041 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 7360 |
      | updating status | 0.000062 | 0.000126 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1946 |
      | cleaning up | 0.000030 | 0.000057 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1965 |
      +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+
      

      In the "starting" state, you can see that Duration=0.000416 and CPU_User=0.000765, which is the greater value. The same pattern seems to hold for other states. How can the operation spend more time consuming CPU than it does for the whole duration? Could it be that these specific times too low for the recorded times to be accurate?

      Attachments

        Activity

          People

            Unassigned Unassigned
            GeoffMontee Geoff Montee (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

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