Bug #278 After many queries LEFT JOIN returns incorrect results. SHOW INDEXES fixes it
Submitted: 11 Apr 2003 23:03 Modified: 8 Feb 2005 19:42
Reporter: Michael Shulman Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:4.0.12 OS:Microsoft Windows (WindowsXP)
Assigned to: Assigned Account CPU Architecture:Any

[11 Apr 2003 23:03] Michael Shulman
Description:
I'm using both MySQL 4.0.12 and MySQL 4.0.2-alpha.

My problem is that, after a while, LEFT JOINs start giving me the wrong answer. I have a repro case that involves running my server for quite a while, but I haven't extracted out the minimal case for the server.

In any case, this is the query that's causing trouble:

SELECT DISTINCT p.name, p.description, p.server_name, p.host_name, p.domain_name, cp.active, t.roles, c.name 
FROM peer p, community c, community_peer cp   
LEFT JOIN transport t ON (t.oid_sender = cp.oid)    
WHERE cp.oid_peer = p.oid 
AND cp.oid_community = c.oid 
AND c.name = 'zulu' order by 2

Early in a session, the t.roles column is filled in correctly with values. After the server has been running for a while, t.roles returns all NULLs. Restarting (but not reloading the data) causes the server to start working again. 

Here's the result late in the session:
mysql> select p.name, p.host_name, cp.active, t.roles, c.name
    -> FROM peer p, community c, community_peer cp
    -> LEFT JOIN transport t ON (t.oid_sender = cp.oid)
    -> where cp.oid_peer = p.oid and cp.oid_community = c.oid and c.name = 'zulu'
    -> ;
+-----------------+----------------+--------+-------+------+
| name            | host_name      | active | roles | name |
+-----------------+----------------+--------+-------+------+
| zulu pub        | zulu           |      0 |  NULL | zulu |
| zulu_cm         | mshulman-gx110 |      1 |  NULL | zulu |
| David           | david          |      0 |  NULL | zulu |
| mshulman_laptop | mshulman       |      0 |  NULL | zulu |
+-----------------+----------------+--------+-------+------+
4 rows in set (0.00 sec)

Note that all of the "roles" are NULL.

Then, I stop the MySQL Service and restart it, and re-issue the query.

+-----------------+----------------+--------+-------+------+
| name            | host_name      | active | roles | name |
+-----------------+----------------+--------+-------+------+
| David           | david          |      0 |     1 | zulu |
| mshulman_laptop | mshulman       |      0 |  NULL | zulu |
| zulu pub        | zulu           |      0 |     1 | zulu |
| zulu_cm         | mshulman-gx110 |      1 |     2 | zulu |
+-----------------+----------------+--------+-------+------+
4 rows in set (0.05 sec) 

The EXPLAINS tell the whole story. Sorry about the formatting. When the query gives me the wrong answer, EXPLAIN looks like this:

mysql> explain select p.name, p.host_name, cp.active, t.roles, c.name
    -> FROM peer p, community c, community_peer cp
    -> LEFT JOIN transport t ON (t.oid_sender = cp.oid)
    -> where cp.oid_peer = p.oid and cp.oid_community = c.oid and c.name = 'zulu';
+-------+--------+----------------------------+-----------------+---------+-
------------+------+-------------+
| table | type   | possible_keys              | key             | key_len |
ref         | rows | Extra       |
+-------+--------+----------------------------+-----------------+---------+-
------------+------+-------------+
| t     | system | sender_index               | NULL            |    NULL |
NULL        |    1 |             |
| c     | ALL    | PRIMARY                    | NULL            |    NULL |
NULL        |    1 | Using where |
| cp    | ref    | peer_index,community_index | community_index |      36 |
c.oid       |    1 |             |
| p     | eq_ref | PRIMARY                    | PRIMARY         |      36 |
cp.oid_peer |    1 |             |
+-------+--------+----------------------------+-----------------+---------+-
------------+------+-------------+
4 rows in set (0.00 sec)

Note that it thinks that "t" is a system (or const) table, and that it has to do a table scan of "c".

However, transport (or "t") has 3 rows, not just one.
mysql> select count(*) from transport;
+----------+
| count(*) |
+----------+
|        3 |
+----------+
1 row in set (0.00 sec)

Re-reading the index information fixes the problem:
mysql> show indexes from everserve.transport

Now it realizes that transport has an index.

Note that adding the "force index (sender index)" does not fix the problem.

mysql> explain select p.name, p.host_name, cp.active, t.roles, c.name
    -> FROM peer p, community c, community_peer cp
    -> LEFT JOIN transport t ON (t.oid_sender = cp.oid)
    -> where cp.oid_peer = p.oid and cp.oid_community = c.oid and c.name = 'zulu';
+-------+--------+----------------------------+--------------+---------+----
---------+------+-------------+
| table | type   | possible_keys              | key          | key_len | ref
| rows | Extra       |
+-------+--------+----------------------------+--------------+---------+----
---------+------+-------------+
| c     | ALL    | PRIMARY                    | NULL         |    NULL |
NULL        |    1 | Using where |
| cp    | ALL    | peer_index,community_index | NULL         |    NULL |
NULL        |    4 | Using where |
| p     | eq_ref | PRIMARY                    | PRIMARY      |      36 |
cp.oid_peer |    1 |             |
| t     | ref    | sender_index               | sender_index |      36 |
cp.oid      |    1 |             |
+-------+--------+----------------------------+--------------+---------+----
---------+------+-------------+
4 rows in set (0.00 sec)

How to repeat:
Unfortunately, this problem shows up only after the server has been running for a long time.

My scenario is:
1. Do the left join. My query is:
SELECT DISTINCT p.name, p.description, t.roles, c.name 
FROM peer p, community c, community_peer cp   
LEFT JOIN transport t ON (t.oid_sender = cp.oid)    
WHERE cp.oid_peer = p.oid 
AND cp.oid_community = c.oid 
AND c.name = 'zulu' order by 2

SEE: all values from the left-joined table (transport) are NULL
2. explain the left join
SEE: Explain shows no indexes on the transport table

3. SHOW INDEXES FROM db.transport

4. explain the left join again
SEE: All indexes on the transport table show up correctly

5. run the left join again
SEE: Correct answer. Proper values are returned from transport table.

If necessary, I can try to find a repro case and attach it to this report.

Suggested fix:
What does SHOW INDEXES FROM do to the index cache?

This problem occurs in both 4.0.2-alpha and 4.0.12-production.
[12 Apr 2003 6:35] Sinisa Milivojevic
We need a full repeatable test case.

In your case, what we are missing are dumps of the table,
plus a script that would run a query until the error occurs.
[12 Apr 2003 10:36] Michael Shulman
I will provide the full SQL script to create the situation. 

Is there a place to upload a long file?
[14 Apr 2003 4:59] Alexander Keremidarski
Michael,

Use our private upload area ftp://support.mysql.com/secret/
 and let us know file name or even best - use name like bug278.tar.gz so we can know which bug it is for.
[15 Apr 2003 10:47] Jason Burfield
I am having a very similar issue with 4.0.12 using MyISAM tables.

This query:
SELECT s.id, s.title, count(c.book_id) as total_comments,
ifnull(round(( sum(c.rating) / count(c.book_id) ),2), "n/a") as avg
FROM sponsor_books s
LEFT JOIN book_comments c on s.id=c.book_id ";
GROUP BY s.id 
ORDER BY avg desc, total_comments desc
limit 25";

worked properly on 3.23.47. However, since upgrading to 4.0.12 the 
'avg' is returned as 'n/a' (null) and 'total_comments' is returned as 0 for 
every record.

If I change ORDER BY avg desc, total_coments desc to: ORDER BY s.id 
everything works fine.

I tried Michael's suggestion of doing a SHOW INDEX from xxx before 
running the query, but it doesn't help anything.

I'm running 4.0.12-Max on Linux. (RedHat 8.0)
This was installed from the MySQL supplied RPM's.

Table structure for book_comments is:
mysql> desc book_comments;
+--------------
+------------------------------------------------+------
+-----+---------------------+----------------+
| Field        | Type                                           | Null | Key | Default             
| Extra          |
+--------------
+------------------------------------------------+------
+-----+---------------------+----------------+
| id           | bigint(20) unsigned                            |      | PRI | NULL                
| auto_increment |
| book_id      | int(10) unsigned                               |      |     | 0                   
|                |
| mem_id       | int(10) unsigned                               |      |     | 0                   
|                |
| mem_username | varchar(30)                                    |      |     |                     
|                |
| mem_name     | varchar(40)                                    |      |     |                     
|                |
| mem_city     | varchar(30)                                    |      |     |                     
|                |
| mem_state    | varchar(5)                                     |      |     |                     
|                |
| mem_country  | varchar(30)                                    |      |     |                     
|                |
| section1     | varchar(20)                                    |      |     |                     
|                |
| section2     | varchar(20)                                    |      |     |                     
|                |
| comments     | text                                           |      | MUL |                     
|                |
| rating       | enum('1','2','3','4','5','6','7','8','9','10') |      | MUL | 5                   
|                |
| date_added   | datetime                                       |      | MUL | 0000-
00-00 00:00:00 |                |
+--------------
+------------------------------------------------+------
+-----+---------------------+----------------+

Table structure for sponsor_books is:
mysql> desc sponsor_books;
+-----------------
+----------------------------------------------------------
+------+-----+---------------------+----------------+
| Field           | Type                                                     | Null | Key | 
Default             | Extra          |
+-----------------
+----------------------------------------------------------
+------+-----+---------------------+----------------+
| id              | int(10) unsigned                                         |      | PRI | 
NULL                | auto_increment |
| title           | varchar(100)                                             |      | MUL |                     
|                |
| author          | varchar(50)                                              |      | MUL |                     
|                |
| isbn            | varchar(20)                                              |      |     |                     
|                |
| link            | varchar(150)                                             |      |     |                     
|                |
| notes           | text                                                     |      | MUL |                     
|                |
| type            | enum('Book','Video','DVD','CD-ROM','AudioCD','Magazine') 
|      |     | Book                |                |
| student_reading | enum('no','yes')                                         |      |     | 
no                  |                |
| image           | varchar(20)                                              |      |     |                     
|                |
| date_added      | datetime                                                 |      |     | 
0000-00-00 00:00:00 |                |
+-----------------
+----------------------------------------------------------
+------+-----+---------------------+----------------+

Here is a sample output from the query:
+-----
+------------------------------------------------------------
-----------------------------+----------------+-----+
| id  | title                                                                                   | 
total_comments | avg |
+-----
+------------------------------------------------------------
-----------------------------+----------------+-----+
| 282 | North Dallas Forty                                                                      |              
0 | n/a |
| 347 | Prospects: A Portrait of Minor League Baseball                                          
|              0 | n/a |
| 412 | Communication Arts                                                                      
|              0 | n/a |
| 148 | The Big Picture: The Professional Photographer's Guide to Rights, 
Rates and Negotiation |              0 | n/a |
| 315 | Semi-Tough                                                                              |              
0 | n/a |
+-----
+------------------------------------------------------------
-----------------------------+----------------+-----+

If I find anything that helps, I will post it.

Thanks.

  --  Jason Burfield
[16 Apr 2003 12:15] Sinisa Milivojevic
bug properly reported as #298
[18 Apr 2003 9:24] Michael Shulman
Bug 298 turned out to not be a bug. This one is real... 

I put a workaround in our code that looks for all NULLs being returned from the left joined table. If I see that, I run the command "SHOW INDEXES FROM everserve.transport", rerun the LEFT JOIN, and then I get the right answer.

Unfortunately, the bug shows up only after running queries for approximately 20 minutes. I can send you a dump with the parameterized queries in it, but you can't reply that through MySQL. 

Is there an option in mm.MySQL (JDBC) or in the MySQL server to create a replay log by capturing all queries as they're executed?

-ms
[18 Apr 2003 9:37] Sinisa Milivojevic
It is possible that this is a bug, but we need a repeatable test case, id est a file that if run like this:

mysql < file

would produce a bug.

You can turn a general log in MySQL:

--log=filename

to help you produce such a test case.
[18 Apr 2003 10:31] Michael Shulman
Sinisa,

Unfortunately, the --log= option won't work, because the queries are generated dynamically using parameterized queries in JDBC.

Is there a JDBC option to dump the executed queries after the parameters are replaced?
Or is there an option in the my.cnf file to log database activity?

I suppose the third option is for us to send your our application and application-level script for debugging. 

Would any of these work for you?
-ms
[18 Apr 2003 10:40] Sinisa Milivojevic
Regarding JDBC, 	If you turn the query profiler on by adding 'profileSql=true' to the URL, yes...as long as you're not using MySQL-4.1.

for my.cnf 

log=... 
is ideal.
[18 Apr 2003 19:02] [ name withheld ]
I have added a .zip file containing the log from the session. I tried to use a binary file, but ran into a problem: when I piped the binary file back through mysql, the blob fields couldn't be parsed. After I removed the blob fields from the insert statements, the bug didn't show. 

It's either because the blobs are required, or because the intermingled SELECT statements aren't in the binary log file.

I uploaded a text file containing the session.

At the end, you'll see that the last line (#show indexes) is commented out. 

To repro the bug, 
1. run from the script (I hope this is possible)
2. See that the SELECT DISTINCT a few lines above gives the wrong answer. See that "t.roles" is NULL for all rows
3. run the line "SHOW INDEXES FROM EVERSERVE.TRANSPORT"
4. Repeat the SELECT DISTINCT. See that the t.roles is now correct.

If the SELECT DISTINCT does *not* give all NULLs for t.roles, it may be necessary to run the script another time or two.

Thank you for your patience with this problem.
[18 Apr 2003 19:09] [ name withheld ]
I just uploaded "bug278b.zip". This file has the result of the --bin-log, containing just the create tables, updates, inserts, and deletes, but without the selects.

When I tried to write this file back to the database, using 
   mysqlbinlog everserve.002 | mysql -u root -p 
it failed, likely because of the blob fields.

The everserve.002 file starts with a "drop database everserve", so you need to start with an empty database of that name.
I found that I couldn't replay the log because of the blob fields.
[19 Apr 2003 22:54] Alexander Keremidarski
I ran your query in simple script repeating it every second. After 16 hours it still returns correct result.

So far noone else reported it as repeatable so we don't have much choice, but to suspect somethign causes bug on your server(s) only.
[21 Apr 2003 11:08] Michael Shulman
Running the query by itself does not cause the bug to happen. The bug only happens when the server has been running for a long time. The attached script causes the DDL and DML statements that set up the bug scenario.

I can think of a couple of options. Is there a server at MySQL that I can point my product at? I can run my product using your server as the database server, and maybe get your server into the proper state to show the bug.

Another other option is to expose one of my servers in my lab and allow you to debug remotely. 

Can we do either of these?
-ms
[15 May 2003 14:10] Michael Widenius
I did find it very strange that you couldn't pipe things through the mysql
client from the binary log and decided to test this:

I unpacked the file bug278b.zip and did run the command:

mysqlbinlog everserve.002 | mysql --user=root

and it worked on my Linux machine without any problems.

At then noticed that you are running windows and this explains why you had
problems with pipes.

Windows can't handle the character ^Z / CHAR(24) in a pipe and will
abort the command if it encounters this (as ^Z meant end-of-file for
some very old programs)

The workaround to read the file on windows is to do:

dos> mysqlbinlog everserve.002 --result-file=/tmp/bin.out
dos> mysql --user=root -e "source /tmp/bin.out"

This way MySQL will directly create and read the input/output file and
can thus avoid problems with the ^Z / CHAR(24) character.

I have now updated the manual about this.

But back to the original problem.

We have on our side tried to repeat the problem with just the binary
log but not been able to do that (even while running with it for 16 +
hours).

As Sinisa pointed out, to be able to quickly solve this for you we
would need some way to repeat this problem.  If you could somehow
create a .sql or perl script that could repeat this behaviour we could
probably fix this very fast.

Having access to one of your servers wouldn't help that much as this
would not allow us to debug MySQL to check the status of variables
when this state happens.

On the other hand, I do have some good news:


In 4.0.4 we had a bug that a table could go into an 'index only' mode
in case of some very specific updates where the WHERE clause didn't
match any rows.  If this happens, you would get the behaviour you just
described.

If this is the case, you should get a different EXPLAIN when you get
the problem with LEFT JOIN than you would get when the queries are
working.  A 'flush tables table_name' should reset the problem until
you do the update again.

This bug is fixed in 4.0.13, which we are just building release binaries.

If 4.0.13 doesn't fix this problem, please open this bug report again.
If it fixes the problem, please close this bug.
[8 Feb 2005 19:42] Sergei Golubchik
No feedback was provided. The bug is being suspended because
we assume that you are no longer experiencing the problem.
If this is not the case and you are able to provide the
information that was requested earlier, please do so and
change the status of the bug back to "Open". Thank you.