[MDEV-17078] EXPLAIN in slow query log has wrong r_filtered for DELETE statement Created: 2018-08-27  Updated: 2020-08-25  Resolved: 2018-11-02

Status: Closed
Project: MariaDB Server
Component/s: Admin statements, Data Manipulation - Delete
Affects Version/s: 10.2.11
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Sergei Petrunia
Resolution: Cannot Reproduce Votes: 0
Labels: None


 Description   

A slow query log entry for a DELETE statement showed the following:

# User@Host: user[user] @ test.domain.com [10.6.184.141]
# Thread_id: 75816 Schema: db QC_hit: No
# Query_time: 420.906319 Lock_time: 0.086885 Rows_sent: 0 Rows_examined: 9734191
# Rows_affected: 0
#
# explain: id select_type table type possible_keys key key_len ref rows r_rows filtered r_filtered Extra
# explain: 1 SIMPLE tab ALL a_timestamp_indx NULL NULL NULL 9330481 9734191.00 100.00 55.55 Using where
#
SET timestamp=1535157447;
delete from tab where a_timestamp < (unix_timestamp(now())-14400)*1000000;

We can see that Rows_affected is 0. Supposedly, r_filtered is 55.55%.

The documentation has the following definition of r_filtered:

r_filtered is an observation-based counterpart of the filtered column. It shows which fraction of rows was left after applying the WHERE condition.

https://mariadb.com/kb/en/library/analyze-statement/

If 55.55% of rows were left after applying the WHERE clause, then how were 0 rows affected by the delete? It seems likely that either r_filtered is completely wrong or the definition of the column is wrong.



 Comments   
Comment by Sergei Petrunia [ 2018-11-02 ]

Indeed, Rows_affected should match r_rows *r_filtered.

When I try to reproduce, it does match for me:

# Time: 181102 15:06:26
# User@Host: root[root] @ localhost []
# Thread_id: 8  Schema: test  QC_hit: No
# Query_time: 0.013054  Lock_time: 0.000057  Rows_sent: 0  Rows_examined: 1000
# Rows_affected: 100
#
# explain: id   select_type     table   type    possible_keys   key     key_len ref     rows    r_rows  filtered        r_filtered      Extra
# explain: 1    SIMPLE  t10     ALL     NULL    NULL    NULL    NULL    1000    1000.00 100.00  10.00   Using where
#
SET timestamp=1541160386;
delete from t10 where a < 100;

Comment by Sergei Petrunia [ 2018-11-02 ]

So, I can't reproduce.

But if one looks into the support issue, one can see that they paste two slow query log entries from the same statement. The first time, Rows_affected!=0. The second time, Rows_affected=0.

So this bug doesn't happen all the time... and unfortunately, I have no clue what one should do to trigger it.

Comment by Sergei Petrunia [ 2018-11-02 ]

.. Tried both current 10.2 and 10.2.11 - didn't help

Comment by Sergei Petrunia [ 2018-11-02 ]

Feel free to re-open if there's a way to reproduce it.

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