Details
-
Bug
-
Status: Closed (View Workflow)
-
Minor
-
Resolution: Not a Bug
-
10.1.22, 5.5(EOL), 10.0(EOL), 10.1(EOL), 10.2(EOL)
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?