[MDEV-15008] CPU_User value from SHOW PROFILE ALL output can be greater than Duration value Created: 2018-01-19  Updated: 2023-12-15  Resolved: 2023-12-15

Status: Closed
Project: MariaDB Server
Component/s: Admin statements, Server
Affects Version/s: 5.5, 10.0, 10.1, 10.1.22, 10.2
Fix Version/s: 10.2.44

Type: Bug Priority: Minor
Reporter: Geoff Montee (Inactive) Assignee: Unassigned
Resolution: Not a Bug Votes: 0
Labels: profiling, upstream


 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?

 Comments   
Comment by Elena Stepanova [ 2018-01-23 ]

Reproducible to some extent on all versions of MariaDB and MySQL (in MySQL profiling is deprecated, but in current 5.6 and 5.7 it still works). MariaDB seems to be affected more, though.

--source include/have_innodb.inc
 
create table t1 (i int) engine=InnoDB;
 
begin;
 
insert into t1 values (1),(2),(3),(4);
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
commit;
 
 
 
set profiling=1;
 
 
 
insert into t1 select * from t1;
 
 
 
--query_vertical show profile cpu
 
 
 
# Cleanup
 
drop table t1;

Examples:

MySQL 5.7

 
Status	Sending data
 
Duration	1.047521
 
CPU_user	1.048000
 
CPU_system	0.000000
 
 
 
Status	converting HEAP to ondisk
 
Duration	0.361143
 
CPU_user	0.364000
 
CPU_system	0.000000
 
 
 
Status	removing tmp table
 
Duration	0.003983
 
CPU_user	0.004000
 
CPU_system	0.000000

MariaDB 10.2

 
Status	Sending data
 
Duration	2.116595
 
CPU_user	3.248000
 
CPU_system	0.836000
 
 
 
Status	Converting HEAP to Aria
 
Duration	0.032794
 
CPU_user	0.124000
 
CPU_system	0.024000
 
 
 
Status	Sending data
 
Duration	15.103946
 
CPU_user	25.980000
 
CPU_system	12.996000
 
 
 
Status	Closing tables
 
Duration	0.000027
 
CPU_user	0.004000
 
CPU_system	0.000000

Comment by Dave Gosselin [ 2023-12-15 ]

This is not a bug because the Duration column is not computed in terms of the other columns nor does it depend on them. Roughly speaking, the Duration is the wall clock time of the query. However, the CPU_user and CPU_system are based on calling getrusage which gets the total time that the process executed user and system time (respectively), including all threads in the process. You can think of two threads running concurrently on separate CPUs as essentially 'double-counting' time. Hence why CPU_user in this example may be greater than Duration.

Separately, and for the sake of work logged, I spent time attempting to cleanup the PROFILING class and in the process removed one unused field, removed the set_thd method, and made another method private as there are no class-external callers to it. I changed the constructor to require the THD pointer. These changes are based on 10.6 and I have them saved to a local branch and could be delivered at some point.

Generated at Thu Feb 08 08:18:00 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.