[MDEV-8864] Server crash #2 in Item_field::print on ANALYZE FORMAT=JSON Created: 2015-09-29  Updated: 2015-10-06  Resolved: 2015-10-06

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.1
Fix Version/s: 10.1.8

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: analyze-stmt, explain_json

Issue Links:
Relates
relates to MDEV-7267 Server crashes in Item_field::print o... Closed

 Description   

Note: Stack trace is different from MDEV-7267, and the tentative patch for MDEV-7267 does not fix it, so I'm filing it separately.

CREATE TABLE t1 (f1 INT) ENGINE=MyISAM;
 
INSERT INTO t1 VALUES (1),(2);
 
 
 
CREATE TABLE t2 (f2 INT) ENGINE=MyISAM;
 
INSERT INTO t2 VALUES (2),(3);
 
 
 
CREATE TABLE t3 (f3 INT) ENGINE=MyISAM;
 
INSERT INTO t3 VALUES (3),(4);
 
 
 
ANALYZE FORMAT=JSON 
SELECT GROUP_CONCAT(f3) AS gc, ( SELECT MAX(f1) FROM t1, t2 WHERE f2 = f3 ) sq
 
FROM t2, t3
 
WHERE f3 IN ( 1, 2 ) 
GROUP BY sq ORDER BY gc;

Stack trace from 10.1 + tentative patch for MDEV-7267

 
#3  <signal handler called>
 
#4  0x00007f19f4435d5e in Item_field::print (this=0x7f19e85a0050, str=0x7f19f3c70af0, query_type=QT_EXPLAIN) at /10.1-mdev7267/sql/item.cc:6624
 
#5  0x00007f19f44371b9 in Item_ref::print (this=0x7f19e867cd30, str=0x7f19f3c70af0, query_type=QT_EXPLAIN) at /10.1-mdev7267/sql/item.cc:7141
 
#6  0x00007f19f44371b9 in Item_ref::print (this=0x7f19e867cad8, str=0x7f19f3c70af0, query_type=QT_EXPLAIN) at /10.1-mdev7267/sql/item.cc:7141
 
#7  0x00007f19f4476632 in Item_func::print_op (this=0x7f19e867a2f0, str=0x7f19f3c70af0, query_type=QT_EXPLAIN) at /10.1-mdev7267/sql/item_func.cc:486
 
#8  0x00007f19f445a7b3 in Item_bool_rowready_func2::print (this=0x7f19e867a2f0, str=0x7f19f3c70af0, query_type=QT_EXPLAIN) at /10.1-mdev7267/sql/item_cmpfunc.h:389
 
#9  0x00007f19f4345545 in write_item (writer=0x7f19f3c70fb0, item=0x7f19e867a2f0) at /10.1-mdev7267/sql/sql_explain.cc:1351
 
#10 0x00007f19f434652e in Explain_table_access::print_explain_json (this=0x7f19e84e7bb0, query=0x7f19e84e73f0, writer=0x7f19f3c70fb0, is_analyze=true, fs_tracker=0x0, first_table_sort_used=false) at /10.1-mdev7267/sql/sql_explain.cc:1680
 
#11 0x00007f19f434432b in Explain_basic_join::print_explain_json_interns (this=0x7f19e84e7560, query=0x7f19e84e73f0, writer=0x7f19f3c70fb0, is_analyze=true, first_table_sort=0x0, first_table_sort_used=false) at /10.1-mdev7267/sql/sql_explain.cc:1002
 
#12 0x00007f19f4344193 in Explain_select::print_explain_json (this=0x7f19e84e7560, query=0x7f19e84e73f0, writer=0x7f19f3c70fb0, is_analyze=true) at /10.1-mdev7267/sql/sql_explain.cc:961
 
#13 0x00007f19f434349b in Explain_node::print_explain_json_for_children (this=0x7f19e859e208, query=0x7f19e84e73f0, writer=0x7f19f3c70fb0, is_analyze=true) at /10.1-mdev7267/sql/sql_explain.cc:662
 
#14 0x00007f19f4344394 in Explain_basic_join::print_explain_json_interns (this=0x7f19e859e208, query=0x7f19e84e73f0, writer=0x7f19f3c70fb0, is_analyze=true, first_table_sort=0x0, first_table_sort_used=false) at /10.1-mdev7267/sql/sql_explain.cc:1010
 
#15 0x00007f19f4344193 in Explain_select::print_explain_json (this=0x7f19e859e208, query=0x7f19e84e73f0, writer=0x7f19f3c70fb0, is_analyze=true) at /10.1-mdev7267/sql/sql_explain.cc:961
 
#16 0x00007f19f4341bc6 in Explain_query::print_explain_json (this=0x7f19e84e73f0, output=0x7f19e85a03a8, is_analyze=true) at /10.1-mdev7267/sql/sql_explain.cc:223
 
#17 0x00007f19f4341921 in Explain_query::send_explain (this=0x7f19e84e73f0, thd=0x7f19ea573070) at /10.1-mdev7267/sql/sql_explain.cc:166
 
#18 0x00007f19f41e2f19 in execute_sqlcom_select (thd=0x7f19ea573070, all_tables=0x7f19e867a628) at /10.1-mdev7267/sql/sql_parse.cc:5861
 
#19 0x00007f19f41d8fab in mysql_execute_command (thd=0x7f19ea573070) at /10.1-mdev7267/sql/sql_parse.cc:2962
 
#20 0x00007f19f41e63e2 in mysql_parse (thd=0x7f19ea573070, rawbuf=0x7f19e8678088 "ANALYZE FORMAT=JSON \nSELECT GROUP_CONCAT(f3) AS gc, ( SELECT MAX(f1) FROM t1, t2 WHERE f2 = f3 ) sq\nFROM t2, t3\nWHERE f3 IN ( 1, 2 ) \nGROUP BY sq ORDER BY gc", length=157, parser_state=0x7f19f3c721a0) at /10.1-mdev7267/sql/sql_parse.cc:7227
 
#21 0x00007f19f41d514a in dispatch_command (command=COM_QUERY, thd=0x7f19ea573070, packet=0x7f19ec135071 "", packet_length=157) at /10.1-mdev7267/sql/sql_parse.cc:1488
 
#22 0x00007f19f41d3e70 in do_command (thd=0x7f19ea573070) at /10.1-mdev7267/sql/sql_parse.cc:1110
 
#23 0x00007f19f4308fa5 in do_handle_one_connection (thd_arg=0x7f19ea573070) at /10.1-mdev7267/sql/sql_connect.cc:1350
 
#24 0x00007f19f4308cf6 in handle_one_connection (arg=0x7f19ea573070) at /10.1-mdev7267/sql/sql_connect.cc:1262
 
#25 0x00007f19f48d4837 in pfs_spawn_thread (arg=0x7f19f0c23d70) at /10.1-mdev7267/storage/perfschema/pfs.cc:1860
 
#26 0x00007f19f38adb50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#27 0x00007f19f173995d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112



 Comments   
Comment by Sergei Petrunia [ 2015-10-04 ]

It crashes when trying to print the WHERE clause for the subquery

( SELECT MAX(f1) FROM t1, t2 WHERE f2 = f3 )

"t2.f2" is printed sucessfully. We crash when printing "f3". "f3" refers to "t3.f3" from the parent query.

Upper query does a GROUP BY over the subquery value. I guess this means that the subquery is only evaluated in the pre-group-by context.

Comment by Sergei Petrunia [ 2015-10-04 ]

Changed the query's WHERE to be f3 IN ( 3,4 ) so that the upper query produces some rows.

Then, looking at the subquery WHERE while subquery is executed:

(gdb) p dbug_print_item(join_tab[1].select_cond)
 
  $161 = 0x555556cebec0 "(t2.f2 = t3.f3)"
 
 
 
(gdb) p ((Item*)(join_tab[1].select_cond))->args[0]
 
  $163 = (Item_field *) 0x7fff50009488
 
(gdb) p ((Item*)(join_tab[1].select_cond))->args[1]
 
  $164 = (Item_outer_ref *) 0x7fff5000be80
 
(gdb) p ((Item*)(join_tab[1].select_cond))->args[1]->ref[0]
 
  $166 = (Item_direct_ref *) 0x7fff5000c0d8
 
(gdb) p ((Item*)(join_tab[1].select_cond))->args[1]->ref[0]->ref[0]
 
  $167 = (Item_field *) 0x7fff50009580
 
 
 
(gdb) p ((Item*)(join_tab[1].select_cond))->args[1]->ref[0]->ref[0]->field
 
  $168 = (Field_long *) 0x7fff50020f48
 
(gdb) p ((Item*)(join_tab[1].select_cond))->args[1]->ref[0]->ref[0]->field->field_name
 
  $169 = 0x7fff5001de19 "f3"
 
(gdb) p ((Item*)(join_tab[1].select_cond))->args[1]->ref[0]->ref[0]->field->table->alias.Ptr
 
  $171 = 0x7fff5001dcb0 "t3"

Comment by Sergei Petrunia [ 2015-10-04 ]

That is, when subquery executes, we have:

Item_outer_ref(Item_direct_ref(Item_field(t3.f3)))

Watching this expression

(gdb) set $a2=& ((Item*)(join_tab[1].select_cond))->args[1]->ref[0]->ref[0]
 
(gdb) p *$a2
 
  $211 = (Item_field *) 0x7fff50009580
 
(gdb) watch *$a2
 
...
 
  Hardware watchpoint 10: *$a2
 
  Old value = (Item_field *) 0x7fff50009580
 
  New value = (Item_field *) 0x7fff5002d308

we see that it changes here:

  #0  __memcpy_ssse3_back () at ../sysdeps/x86_64/multiarch/memcpy-ssse3-back.S:1997
 
  #1  0x0000555555ab52c4 in JOIN::set_items_ref_array (this=0x7fff5000ad48, ptr=0x7fff5000b2f0) at /home/psergey/dev-git/10.1-dbg3/sql/sql_select.h:1431
 
  #2  0x0000555555a77926 in JOIN::exec_inner (this=0x7fff5000ad48) at /home/psergey/dev-git/10.1-dbg3/sql/sql_select.cc:2706
 
  #3  0x0000555555a7660f in JOIN::exec (this=0x7fff5000ad48) at /home/psergey/dev-git/10.1-dbg3/sql/sql_select.cc:2409
 
  #4  0x0000555555a79cf1 in mysql_select (thd=0x55555ac73a30, rref_pointer_array=0x55555ac77d98, tables=0x7fff500099a8, wild_num=0, fields=..., conds=0x7fff5000a830, og_num=2, order=0x7fff5000abb8, group=0x7fff5000aa70, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fff5000ad28, unit=0x55555ac77430, select_lex=0x55555ac77b20) at /home/psergey/dev-git/10.1-dbg3/sql/sql_select.cc:3346
 
  #5  0x0000555555a6fc57 in handle_select (thd=0x55555ac73a30, lex=0x55555ac77368, result=0x7fff5000ad28, setup_tables_done_option=0) at /home/psergey/dev-git/10.1-dbg3/sql/sql_select.cc:371
 
  #6  0x0000555555a40496 in execute_sqlcom_select (thd=0x55555ac73a30, all_tables=0x7fff500099a8) at /home/psergey/dev-git/10.1-dbg3/sql/sql_parse.cc:5849
 
  #7  0x0000555555a365b4 in mysql_execute_command (thd=0x55555ac73a30) at /home/psergey/dev-git/10.1-dbg3/sql/sql_parse.cc:2962
 
  #8  0x0000555555a439ed in mysql_parse (thd=0x55555ac73a30, rawbuf=0x7fff50007418 "ANALYZE FORMAT=JSON  SELECT GROUP_CONCAT(f3) AS gc, ( SELECT MAX(f1) FROM t1, t2 WHERE f2 = f3 ) sq FROM t2, t3 WHERE f3 IN ( 3,4 )  GROUP BY sq ORDER BY gc", length=156, parser_state=0x7fff6bffe100) at /home/psergey/dev-git/10.1-dbg3/sql/sql_parse.cc:7227

The change is from an Item_field("t3.f3") to Item_field(<temporary table>).

Comment by Sergei Petrunia [ 2015-10-04 ]

So if we have functions like JOIN::set_items_ref_array that change what Item_ref items point to, how can one try to print item trees that have been implicitly modified by set_items_ref_array?

  • Attempt to save and print the item that Item_ref originally pointed to. We'll need to distinguish between "early" (pre-set_items_ref_array) and "late" (post-set_items_ref_array) expressions. Considering that each subquery has its own set_items_ref_array call (or even several?), this may get very complex.
  • Make Item_field objects that point to temporary tables printable after the table is gone. Hope that printing these Item_field objects instead of what Item_ref was originally pointing at is acceptable.
Comment by Sergei Petrunia [ 2015-10-05 ]

elenst, Could you make a test run with this patch (combined for MDEV-8864 and MDEV-7267) http://lists.askmonty.org/pipermail/commits/2015-October/008482.html ?

Do you still observe other failures?

Comment by Sergei Petrunia [ 2015-10-05 ]

Found this comment at the end of JOIN::exec_inner :

  /* 
    With EXPLAIN EXTENDED we have to restore original ref_array
 
    for a derived table which is always materialized.
 
    We also need to do this when we have temp table(s).
 
    Otherwise we would not be able to print the query correctly.
 
  */

Generated at Thu Feb 08 07:30:21 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.