Bug #71989 Mysql information_schema.profiling store only 100 rows
Submitted: 9 Mar 2014 23:15 Modified: 18 Apr 2014 12:40
Reporter: Iza Stalo Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Information schema Severity:S3 (Non-critical)
Version:5.6.14 OS:Windows
Assigned to: CPU Architecture:Any
Tags: information_schema, profiler, profiling

[9 Mar 2014 23:15] Iza Stalo
Description:
Hi,
I'm trying to use mysql profiler.
I'm using the command:

set profiling=1;
to turn it on.
Later, i execute my query which wich looks like:
SELECT * FROM TABLE_A;

After that i use command:
show profile;
to see id of my query;
mysql> show profiles;
+----------+------------+--
| Query_ID | Duration| Query
+----------+------------+-
| 1 |1224.1249092 select ...
+----------+------------+-

But when i'm doing query to information_schema.profiling for this query duration is much smaller. Why is such difference? Always displays 100 rows, and most of it is 'sending data'. I can't see 'starting' or 'inicialization' or 'opening tables'. When i increase limit to 200 also displays 100 rows.

When i'm doing:
select count(*) from information_schema.profiling where query_id=1;
It shows:
# count(*) '100'

But when i'm doing:
select * from information_schema.profiling where query_id=1;
SEQ starts from 1099931 and shows last 100 SEQ.

mysql> select sum(duration) from information_schema.profiling where query_id=1;

# sum(duration)
12.234170

mysql> show profile for query 1;
executing 0.000003
Sending data 0.004343
executing 0.000003
Sending data 0.293625
executing 0.000003
Sending data 0.294627
executing 0.000003
Sending data 0.293227
executing 0.000003
Sending data 0.293953
executing 0.000004
Sending data 0.293879
executing 0.000004
Sending data 0.293932
executing 0.000003
Sending data 0.293652
executing 0.000003
Sending data 0.003999
executing 0.000002
Sending data 0.292655
executing 0.000004
Sending data 0.295063
executing 0.000005
Sending data 0.296534
executing 0.000003
Sending data 0.295801
executing 0.000004
Sending data 0.296010
executing 0.000004
Sending data 0.004082
executing 0.000003
Sending data 0.297623
executing 0.000004
Sending data 0.317437
executing 0.000003
Sending data 0.301188
executing 0.000004
Sending data 0.301276
executing 0.000004
Sending data 0.295963
executing 0.000004
Sending data 0.300331
executing 0.000004
Sending data 0.296260
executing 0.000003
Sending data 0.004008
executing 0.000002
Sending data 0.294382
executing 0.000004
Sending data 0.310844
executing 0.000005
Sending data 0.295127
executing 0.000006
Sending data 0.005463
executing 0.000003
Sending data 0.296227
executing 0.000003
Sending data 0.302356
executing 0.000004
Sending data 0.294737
executing 0.000004
Sending data 0.295317
executing 0.000004
Sending data 0.314639
executing 0.000003
Sending data 0.296097
executing 0.000005
Sending data 0.297066
executing 0.000003
Sending data 0.294738
executing 0.000003
Sending data 0.315274
executing 0.000004
Sending data 0.296043
executing 0.000003
Sending data 0.293831
executing 0.000003
Sending data 0.294903
executing 0.000003
Sending data 0.293740
executing 0.000003
Sending data 0.294724
executing 0.000005
Sending data 0.297695
executing 0.000004
Sending data 0.294476
executing 0.000003
Sending data 0.297282
executing 0.000004
Sending data 0.298081
executing 0.000003
Sending data 0.297057
executing 0.000004
Sending data 0.004090
end 0.000063
query end 0.000006
freeing items 0.000267
logging slow query 0.000002
logging slow query 0.000003
cleaning up 0.000004

MySQL version 5.6.14 but I also try 5.5 and 5.1 and result is the same.

How to repeat:
use the steps given in description.
[10 Mar 2014 10:56] MySQL Verification Team
Hello Iza,

Thank you for the report.
Imho -this is a known and documented behavior.

The PROFILING table provides statement profiling information and its contents correspond to the information produced by the SHOW PROFILES and SHOW PROFILE statements. The SHOW PROFILES displays a list of the most recent statements sent to the server. The size of the list is controlled by the profiling_history_size session variable, which has a default value of 15. The maximum value is 100. Setting the value to 0 has the practical effect of disabling profiling. 

Please see - http://dev.mysql.com/doc/refman/5.6/en/show-profile.html
             http://dev.mysql.com/doc/refman/5.6/en/server-system-variables.html#sysvar_profiling_histo...

Thanks,
Umesh
[10 Mar 2014 11:06] Iza Stalo
Hello,
Thank for yout resposne.
So it's impossible to see more than 100 rows from information_schema.profiling for query?

I found article and there is:

mysql> set profiling=1;

Query OK, 0 rows affected (0.00 sec)

mysql> select * from v_client_portfolio_high;
+-----------+-------------------+------------------+-----------------+
| client_id | client_first_name | client_last_name | portfolio_value |
+-----------+-------------------+------------------+-----------------+
|         5 | ABNER             | ROSSELLETT       |      1252115.50 |
|       500 | CANDICE           | BARTLETT         |      1384877.50 |
+-----------+-------------------+------------------+-----------------+
2 rows in set (4.01 sec)

mysql> set profiling=0;
Query OK, 0 rows affected (0.00 sec)

mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        0 | 0.00007300 | set profiling=1                               |
|        1 | 0.00044700 | select count(*) from client where broker_id=2 |
|        2 | 0.00003400 | set profiling=0                               |
|        3 | 0.00007400 | set profiling=1                               |
|        4 | 0.63789700 | alter table t engine=myisam                   |
|        5 | 0.00004000 | set profiling=0                               |
|        6 | 0.00007600 | set profiling=1                               |
|        7 | 4.01965600 | select * from v_client_portfolio_high         |
|        8 | 0.00003500 | set profiling=0                               |
+----------+------------+-----------------------------------------------+

mysql> select count(*) from information_schema.profiling where query_id=7;
+----------+
| count(*) |
+----------+
|    74734 |
+----------+

But when I'm doing query like select count(*) always shows 100, even when I'm set profiling_history_size=15;
[10 Mar 2014 12:15] Iza Stalo
Especially the problem is annoying when I want to do a corelatted subquery. SHOW PROFILE statment shows always 100 last sequence for my query. 

Is there any other way to get duration time, cpu system for select statments?
[18 Mar 2014 12:40] MySQL Verification Team
Hello Iza,

>>But when I'm doing query like select count(*) always shows 100, even when I'm set profiling_history_size=15;

The profiling_history_size controls how many statements are sent to server and it is not equal to the number of rows returns from INFORMATION_SCHEMA PROFILING Table.

>>Especially the problem is annoying when I want to do a corelatted subquery. SHOW PROFILE statment shows always 100 last sequence for my query.

Please could you provide the exact test(table, data and query - pls make it as private when you attach) case to reproduce this issue?

Thanks,
Umesh
[19 Apr 2014 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".