[MDEV-27238] Assertion `got_name == named_item_expected()' failed in Json_writer::on_start_object on JSON-less testcase using optimizer_trace Created: 2021-12-12  Updated: 2022-02-17  Resolved: 2021-12-23

Status: Closed
Project: MariaDB Server
Component/s: JSON, Optimizer
Affects Version/s: 10.4, 10.5, 10.6, 10.7, 10.8
Fix Version/s: 10.4.23, 10.5.14, 10.6.6, 10.7.2

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: regression

Issue Links:
Relates
relates to MDEV-27204 [ERROR] Json_writer: a member name wa... Closed
relates to MDEV-27878 Assertion `got_name == named_item_exp... Open

 Description   

Seems related to MDEV-27204, yet this testcase does not use JSON nor do versions affected match.

SET sql_mode='';
 
CREATE TABLE t (a INT KEY,b INT,KEY(b)) ENGINE=MEMORY;
 
SET optimizer_trace=1;
 
INSERT INTO t VALUES (0,0);
 
SELECT a FROM t WHERE (a,b) in (SELECT @c,@d);

Leads to:

10.7.2 979b23d5bfb11bb698ea65c9468b374978737ec0 (Debug)

 
mysqld: /test/10.7_dbg/sql/my_json_writer.cc:42: void Json_writer::on_start_object(): Assertion `got_name == named_item_expected()' failed.

10.7.2 979b23d5bfb11bb698ea65c9468b374978737ec0 (Debug)

 
Core was generated by `/test/MD121221-mariadb-10.7.2-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x14e8a0d6e700 (LWP 3592433))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x000014e8abfd2859 in __GI_abort () at abort.c:79
 
#2  0x000014e8abfd2729 in __assert_fail_base (fmt=0x14e8ac168588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5645bb249e18 "got_name == named_item_expected()", file=0x5645bb249d20 "/test/10.7_dbg/sql/my_json_writer.cc", line=42, function=<optimized out>) at assert.c:92
 
#3  0x000014e8abfe3f36 in __GI___assert_fail (assertion=assertion@entry=0x5645bb249e18 "got_name == named_item_expected()", file=file@entry=0x5645bb249d20 "/test/10.7_dbg/sql/my_json_writer.cc", line=line@entry=42, function=function@entry=0x5645bb249f18 "void Json_writer::on_start_object()") at assert.c:101
 
#4  0x00005645ba72ab95 in Json_writer::on_start_object (this=0x5645bcecb130) at /test/10.7_dbg/sql/my_json_writer.cc:42
 
#5  Json_writer::start_object (this=this@entry=0x5645bcecb130) at /test/10.7_dbg/sql/my_json_writer.cc:51
 
#6  0x00005645ba5c744d in Json_writer_object::Json_writer_object (str=0x0, writer=0x5645bcecb130, this=<synthetic pointer>) at /test/10.7_dbg/sql/my_json_writer.h:444
 
#7  Json_writer_object::Json_writer_object (str=0x0, thd=<optimized out>, this=<synthetic pointer>) at /test/10.7_dbg/sql/my_json_writer.h:449
 
#8  JOIN::optimize_inner (this=this@entry=0x14e7e0016fd8) at /test/10.7_dbg/sql/sql_select.cc:1986
 
#9  0x00005645ba5c8e3a in JOIN::optimize (this=0x14e7e0016fd8) at /test/10.7_dbg/sql/sql_select.cc:1809
 
#10 0x00005645ba9482be in subselect_single_select_engine::exec (this=0x14e7e0015fb0) at /test/10.7_dbg/sql/item_subselect.cc:4034
 
#11 0x00005645ba947ba6 in Item_subselect::exec (this=this@entry=0x14e7e0015ce0) at /test/10.7_dbg/sql/item_subselect.cc:853
 
#12 0x00005645ba94d3e9 in Item_in_subselect::exec (this=0x14e7e0015ce0) at /test/10.7_dbg/sql/item_subselect.cc:1035
 
#13 0x00005645ba946a75 in Item_in_subselect::val_bool (this=0x14e7e0015ce0) at /test/10.7_dbg/sql/item_subselect.cc:1965
 
#14 0x00005645ba3ecd77 in Item::val_bool_result (this=<optimized out>) at /test/10.7_dbg/sql/item.h:1783
 
#15 0x00005645ba88e738 in Item_in_optimizer::val_int (this=0x14e7e0017650) at /test/10.7_dbg/sql/item_cmpfunc.cc:1637
 
#16 0x00005645ba5a50ab in make_join_select (join=join@entry=0x14e7e00168e8, select=0x14e7e00cb820, cond=0x14e7e0017650) at /test/10.7_dbg/sql/sql_select.cc:11727
 
#17 0x00005645ba5c56dd in JOIN::optimize_stage2 (this=this@entry=0x14e7e00168e8) at /test/10.7_dbg/sql/sql_select.cc:2742
 
#18 0x00005645ba5c8b47 in JOIN::optimize_inner (this=this@entry=0x14e7e00168e8) at /test/10.7_dbg/sql/sql_select.cc:2479
 
#19 0x00005645ba5c8e3a in JOIN::optimize (this=this@entry=0x14e7e00168e8) at /test/10.7_dbg/sql/sql_select.cc:1809
 
#20 0x00005645ba5c94de in mysql_select (thd=thd@entry=0x14e7e0000db8, tables=0x14e7e0014468, fields=@0x14e7e0014128: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14e7e0014420, last = 0x14e7e0014420, elements = 1}, <No data fields>}, conds=0x14e7e0015ce0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x14e7e00168c0, unit=0x14e7e00051c0, select_lex=0x14e7e0013e88) at /test/10.7_dbg/sql/sql_select.cc:4979
 
#21 0x00005645ba5c97e2 in handle_select (thd=thd@entry=0x14e7e0000db8, lex=lex@entry=0x14e7e00050e8, result=result@entry=0x14e7e00168c0, setup_tables_done_option=setup_tables_done_option@entry=0) at /test/10.7_dbg/sql/sql_select.cc:545
 
#22 0x00005645ba528c1e in execute_sqlcom_select (thd=thd@entry=0x14e7e0000db8, all_tables=0x14e7e0014468) at /test/10.7_dbg/sql/sql_parse.cc:6253
 
#23 0x00005645ba535af1 in mysql_execute_command (thd=thd@entry=0x14e7e0000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.7_dbg/sql/sql_parse.cc:3944
 
#24 0x00005645ba521e0f in mysql_parse (thd=thd@entry=0x14e7e0000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14e8a0d6d400) at /test/10.7_dbg/sql/sql_parse.cc:8028
 
#25 0x00005645ba530aab in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14e7e0000db8, packet=packet@entry=0x14e7e000b879 "SELECT a FROM t WHERE (a,b) in (SELECT @c,@d)", packet_length=packet_length@entry=45, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_class.h:1360
 
#26 0x00005645ba533eea in do_command (thd=0x14e7e0000db8, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:1402
 
#27 0x00005645ba6ad902 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5645bceaae48, put_in_cache=put_in_cache@entry=true) at /test/10.7_dbg/sql/sql_connect.cc:1418
 
#28 0x00005645ba6adf07 in handle_one_connection (arg=arg@entry=0x5645bceaae48) at /test/10.7_dbg/sql/sql_connect.cc:1312
 
#29 0x00005645bab2e33e in pfs_spawn_thread (arg=0x5645bcdbe738) at /test/10.7_dbg/storage/perfschema/pfs.cc:2201
 
#30 0x000014e8ac4e1609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#31 0x000014e8ac0cf293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.23 (dbg), 10.5.14 (dbg), 10.6.6 (dbg), 10.7.2 (dbg), 10.8.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.42 (dbg), 10.2.42 (opt), 10.3.33 (dbg), 10.3.33 (opt), 10.4.23 (opt), 10.5.14 (opt), 10.6.6 (opt), 10.7.2 (opt), 10.8.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.36 (dbg), 5.7.36 (opt), 8.0.27 (dbg), 8.0.27 (opt)

 Comments   
Comment by Sergei Petrunia [ 2021-12-22 ]

The fix is kind of obvious.

What I find odd is this:

1. Optimization for select #1 reaches "plan refinement" stage in
make_join_select.
2. It tries to evaluate a constant subquery.
3. It finds out that the subquery has no query plan yet
4. It tries to compute a query plan.

The particularly odd is the combination of #2 and #3.

There are other places in the optimizer where it will evaluate "constant"
items. Does this mean that we need to make sure that for any of these places,
the calling side leaves the Optimizer Trace in the right state (that is, a
state where one can start tracing an optimization?)

Comment by Sergei Petrunia [ 2021-12-22 ]

There is optimize_constant_subqueries() call made from early phase of
JOIN::optimize()... but the subquery is not yet constant at that point.

The subquery should become constant when table t is found to be constant.
This call is made

conds->update_used_tables();

and it partially makes the subquery constant:

conds->used_tables()=0
 
conds->const_item()= false

const_item=false(), because Item_subselect::const_item_cache remains false...
which happens, because because engine->uncacheable()= UNCACHEABLE_EXPLAIN | UNCACHEABLE_SIDEEFFECT.

and this code doesn't make it non-constant:

void Item_subselect::update_used_tables()
 
{
 
  if (!forced_const)
 
  {
 
    recalc_used_tables(parent_select, FALSE);
 
    if (!(engine->uncacheable() & ~UNCACHEABLE_EXPLAIN))
 
    {
 
      // did all used tables become static?
 
      if (!(used_tables_cache & ~engine->upper_select_const_tables()) &&
 
          ! with_recursive_reference)
 
        const_item_cache= 1;
 
    }
 
  }
 
}

Comment by Sergei Petrunia [ 2021-12-22 ]

Trying a similar but non-degenerate subquery:

explain 
SELECT a FROM t 
WHERE t.a < (select max(a) from ten where ten.a+t.a<333);

It doesn't crash.

Reason:
make_join_select() doesn't try to evaluate it, because const_cond->is_expensive()=false.

Item_subselect::is_expensive() returns
1. FALSE for "degenerate" subqueries
2. TRUE when the subquery doesn't have a query plan, yet.

The original query takes path#1, this query takes path#2.

Comment by Sergei Petrunia [ 2021-12-22 ]

That is, this bug only applies to "degenerate" subqueries.
Other places in the optimizer that call item->val_int() for constant items are not affected because they check the
const_item()=true, or can_eval_in_optimize()=true which is even more restrictive than that.

Generated at Thu Feb 08 09:51:24 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.