Commit 766bae2b authored by Monty's avatar Monty Committed by Sergei Petrunia

Make trace.add() usage uniform

- Before any multiple add() calls, always use (if trace_started()).
- Add unlikely() around all tests of trace_started().
- Change trace.add(); trace.add(); to trace.add().add();
- When trace.add() goes over several line, use the following formating:
trace.
 add(xxx).
 add(yyy).
 add(zzz);

This format was choosen after a discussion between Sergei Petrunia and
me as it looks similar indepedent if 'trace' is an object or a
pointer. It also more suitable for an editors auto-indentation.

Other things:

Added DBUG_ASSERT(thd->trace_started()) to a few functions that should
only be called if trace is enabled.

"use_roworder_index_merge: true" changed to "use_sort_index_merge: false"
As the original output was often not correct.
Also fixed the related 'cause' to be correct.

In best_access_path() print the cost (and number of rows) before
checking if it the plan should be used. This removes the need to print
the cost in two places.

Changed a few "read_time" tags to "cost".
parent ec6aa282
......@@ -1117,6 +1117,7 @@ explain select * from t1,t2 where t1.a=t2.b+2 and t2.a= t1.b {
"rows": 1,
"cond_check_cost": 2.200585794,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 220.0585794,
"chosen": true
},
......@@ -1166,6 +1167,7 @@ explain select * from t1,t2 where t1.a=t2.b+2 and t2.a= t1.b {
"rows": 1,
"cond_check_cost": 2.200585794,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 220.0585794,
"chosen": true
},
......@@ -2265,6 +2267,7 @@ explain select * from t1 where a=1 and b=2 order by c limit 1 {
"rows": 180,
"cond_check_cost": 216.2743776,
"startup_cost": 0,
"rows_after_filter": 180,
"cost": 216.2743776,
"chosen": true
},
......@@ -2275,6 +2278,7 @@ explain select * from t1 where a=1 and b=2 order by c limit 1 {
"rows": 21,
"cond_check_cost": 25.34242739,
"startup_cost": 0,
"rows_after_filter": 21,
"cost": 25.34242739,
"chosen": true
},
......@@ -2724,6 +2728,7 @@ explain select * from t1 left join t2 on t2.a=t1.a {
"rows": 1,
"cond_check_cost": 1.2,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 4.8,
"chosen": true
},
......@@ -3253,7 +3258,7 @@ explain extended select * from t1 where a in (select pk from t10) {
{
"strategy": "SJ-Materialization",
"records": 3,
"read_time": 7.878564453
"cost": 7.878564453
},
{
"strategy": "DuplicateWeedout",
......@@ -3628,6 +3633,7 @@ explain select * from t1 where pk = 2 and a=5 and b=1 {
"rows": 1,
"cond_check_cost": 1.325585794,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 1.325585794,
"chosen": true
},
......@@ -3638,6 +3644,7 @@ explain select * from t1 where pk = 2 and a=5 and b=1 {
"rows": 1,
"cond_check_cost": 1.325829876,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 1.325829876,
"chosen": false,
"cause": "cost"
......@@ -3649,6 +3656,7 @@ explain select * from t1 where pk = 2 and a=5 and b=1 {
"rows": 1,
"cond_check_cost": 0.326073957,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 0.326073957,
"chosen": true
},
......@@ -4341,6 +4349,7 @@ explain delete t0,t1 from t0, t1 where t0.a=t1.a and t1.a<3 {
"rows": 1,
"cond_check_cost": 1.200585794,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 3.601757383,
"chosen": true
},
......@@ -4390,6 +4399,7 @@ explain delete t0,t1 from t0, t1 where t0.a=t1.a and t1.a<3 {
"rows": 2,
"cond_check_cost": 1.401171589,
"startup_cost": 0,
"rows_after_filter": 2,
"cost": 4.203514767,
"chosen": true
},
......@@ -5080,7 +5090,7 @@ explain select * from t1 where a in (select t_inner_1.a from t1 t_inner_1, t1 t_
{
"strategy": "SJ-Materialization",
"records": 3,
"read_time": 10.81538086
"cost": 10.81538086
},
{
"strategy": "DuplicateWeedout",
......@@ -7976,7 +7986,7 @@ t_outer_2.a in (select t_inner_3.a from t2 t_inner_3, t1 t_inner_4) {
{
"strategy": "SJ-Materialization",
"records": 27,
"read_time": 32.34101562
"cost": 32.34101562
},
{
"strategy": "DuplicateWeedout",
......@@ -8098,7 +8108,7 @@ t_outer_2.a in (select t_inner_3.a from t2 t_inner_3, t1 t_inner_4) {
{
"strategy": "SJ-Materialization",
"records": 27,
"read_time": 46.86152344
"cost": 46.86152344
},
{
"strategy": "DuplicateWeedout",
......@@ -8395,7 +8405,7 @@ t_outer_2.a in (select t_inner_3.a from t2 t_inner_3, t1 t_inner_4) {
{
"strategy": "SJ-Materialization",
"records": 3,
"read_time": 16.52563477
"cost": 16.52563477
},
{
"strategy": "DuplicateWeedout",
......@@ -9539,6 +9549,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 1,
"cond_check_cost": 2.200585794,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 22.00585794,
"chosen": true
},
......@@ -9769,6 +9780,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 1,
"cond_check_cost": 2.200585794,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 22.00585794,
"chosen": true
},
......@@ -10408,6 +10420,7 @@ json_detailed(json_extract(trace, '$**.choose_best_splitting'))
"rows": 1.8367,
"cond_check_cost": 2.367925794,
"startup_cost": 0,
"rows_after_filter": 1.8367,
"cost": 2.367925794,
"chosen": true
},
......
......@@ -214,6 +214,7 @@ explain select * from t1 where pk1 != 0 and key1 = 1 {
"rows": 1,
"cond_check_cost": 1.325146475,
"startup_cost": 0,
"rows_after_filter": 1,
"cost": 1.325146475,
"chosen": true
},
......
......@@ -51,6 +51,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 104,
"cond_check_cost": 124.96562,
"startup_cost": 0,
"rows_after_filter": 104,
"cost": 124.96562,
"chosen": true
},
......@@ -61,6 +62,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 340,
"cond_check_cost": 408.2577963,
"startup_cost": 0,
"rows_after_filter": 340,
"cost": 408.2577963,
"chosen": false,
"cause": "cost"
......@@ -72,6 +74,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 632,
"cond_check_cost": 758.7718449,
"startup_cost": 0,
"rows_after_filter": 632,
"cost": 758.7718449,
"chosen": false,
"cause": "cost"
......@@ -145,6 +148,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 6,
"cond_check_cost": 7.327343464,
"startup_cost": 0,
"rows_after_filter": 6,
"cost": 7.327343464,
"chosen": true
},
......@@ -155,6 +159,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 232,
"cond_check_cost": 278.6156139,
"startup_cost": 0,
"rows_after_filter": 232,
"cost": 278.6156139,
"chosen": false,
"cause": "cost"
......@@ -166,6 +171,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
"rows": 293,
"cond_check_cost": 351.8394392,
"startup_cost": 0,
"rows_after_filter": 293,
"cost": 351.8394392,
"chosen": false,
"cause": "cost"
......
This diff is collapsed.
......@@ -1014,11 +1014,12 @@ SplM_plan_info * JOIN_TAB::choose_best_splitting(double record_count,
{
Json_writer_object wrapper(thd);
Json_writer_object find_trace(thd, "best_splitting");
find_trace.add("table", best_table->alias.c_ptr());
find_trace.add("key", best_table->key_info[best_key].name);
find_trace.add("record_count", record_count);
find_trace.add("cost", spl_plan->cost);
find_trace.add("unsplit_cost", spl_opt_info->unsplit_cost);
find_trace.
add("table", best_table->alias.c_ptr()).
add("key", best_table->key_info[best_key].name).
add("record_count", record_count).
add("cost", spl_plan->cost).
add("unsplit_cost", spl_opt_info->unsplit_cost);
}
memcpy((char *) spl_plan->best_positions,
(char *) join->best_positions,
......@@ -1047,10 +1048,14 @@ SplM_plan_info * JOIN_TAB::choose_best_splitting(double record_count,
startup_cost= record_count * spl_plan->cost;
records= (ha_rows) (records * spl_plan->split_sel);
Json_writer_object trace(thd, "lateral_derived");
trace.add("startup_cost", startup_cost);
trace.add("splitting_cost", spl_plan->cost);
trace.add("records", records);
if (unlikely(thd->trace_started()))
{
Json_writer_object trace(thd, "lateral_derived");
trace.
add("startup_cost", startup_cost).
add("splitting_cost", spl_plan->cost).
add("records", records);
}
}
else
startup_cost= spl_opt_info->unsplit_cost;
......
......@@ -910,8 +910,10 @@ bool subquery_types_allow_materialization(THD* thd, Item_in_subselect *in_subs)
outer,
converted_from_in_predicate))
{
trace_transform.add("possible", false);
trace_transform.add("cause", "types mismatch");
if (unlikely(trace_transform.trace_started()))
trace_transform.
add("possible", false).
add("cause", "types mismatch");
DBUG_RETURN(FALSE);
}
}
......@@ -933,8 +935,10 @@ bool subquery_types_allow_materialization(THD* thd, Item_in_subselect *in_subs)
{
in_subs->types_allow_materialization= TRUE;
in_subs->sjm_scan_allowed= all_are_fields;
trace_transform.add("sjm_scan_allowed", all_are_fields)
.add("possible", true);
if (unlikely(trace_transform.trace_started()))
trace_transform.
add("sjm_scan_allowed", all_are_fields).
add("possible", true);
DBUG_PRINT("info",("subquery_types_allow_materialization: ok, allowed"));
DBUG_RETURN(TRUE);
}
......@@ -1294,8 +1298,10 @@ bool convert_join_subqueries_to_semijoins(JOIN *join)
OPT_TRACE_TRANSFORM(thd, trace_wrapper, trace_transform,
in_subq->get_select_lex()->select_number,
"IN (SELECT)", "semijoin");
trace_transform.add("converted_to_semi_join", false)
.add("cause", "subquery attached to the ON clause");
if (unlikely(trace_transform.trace_started()))
trace_transform.
add("converted_to_semi_join", false).
add("cause", "subquery attached to the ON clause");
break;
}
......@@ -1307,9 +1313,10 @@ bool convert_join_subqueries_to_semijoins(JOIN *join)
if (join->table_count +
in_subq->unit->first_select()->join->table_count >= MAX_TABLES)
{
trace_transform.add("converted_to_semi_join", false);
trace_transform.add("cause",
"table in parent join now exceeds MAX_TABLES");
if (unlikely(trace_transform.trace_started()))
trace_transform.
add("converted_to_semi_join", false).
add("cause", "table in parent join now exceeds MAX_TABLES");
break;
}
if (convert_subq_to_sj(join, in_subq))
......@@ -3147,8 +3154,9 @@ bool Sj_materialization_picker::check_qep(JOIN *join,
*strategy= SJ_OPT_MATERIALIZE;
if (unlikely(trace.trace_started()))
{
trace.add("records", *record_count);
trace.add("read_time", *read_time);
trace.
add("records", *record_count).
add("cost", *read_time);
}
return TRUE;
}
......@@ -3329,8 +3337,9 @@ bool LooseScan_picker::check_qep(JOIN *join,
*handled_fanout= first->table->emb_sj_nest->sj_inner_tables;
if (unlikely(trace.trace_started()))
{
trace.add("records", *record_count);
trace.add("read_time", *read_time);
trace.
add("records", *record_count).
add("read_time", *read_time);
}
return TRUE;
}
......
......@@ -149,7 +149,7 @@ void opt_trace_disable_if_no_security_context_access(THD *thd)
return;
}
Opt_trace_context *const trace= &thd->opt_trace;
if (!thd->trace_started())
if (unlikely(!thd->trace_started()))
{
/*
@@optimizer_trace has "enabled=on" but trace is not started.
......@@ -201,7 +201,7 @@ void opt_trace_disable_if_no_stored_proc_func_access(THD *thd, sp_head *sp)
if (likely(!(thd->variables.optimizer_trace &
Opt_trace_context::FLAG_ENABLED)) ||
thd->system_thread ||
!thd->trace_started())
likely(!thd->trace_started()))
return;
Opt_trace_context *const trace= &thd->opt_trace;
......@@ -235,7 +235,7 @@ void opt_trace_disable_if_no_tables_access(THD *thd, TABLE_LIST *tbl)
if (likely(!(thd->variables.optimizer_trace &
Opt_trace_context::FLAG_ENABLED)) ||
thd->system_thread ||
!thd->trace_started())
likely(!thd->trace_started()))
return;
Opt_trace_context *const trace= &thd->opt_trace;
......@@ -296,7 +296,7 @@ void opt_trace_disable_if_no_view_access(THD *thd, TABLE_LIST *view,
if (likely(!(thd->variables.optimizer_trace &
Opt_trace_context::FLAG_ENABLED)) ||
thd->system_thread ||
!thd->trace_started())
likely(!thd->trace_started()))
return;
Opt_trace_context *const trace= &thd->opt_trace;
......@@ -605,6 +605,7 @@ void Json_writer::add_table_name(const TABLE *table)
void trace_condition(THD * thd, const char *name, const char *transform_type,
Item *item, const char *table_name)
{
DBUG_ASSERT(thd->trace_started());
Json_writer_object trace_wrapper(thd);
Json_writer_object trace_cond(thd, transform_type);
trace_cond.add("condition", name);
......@@ -620,8 +621,9 @@ void add_table_scan_values_to_trace(THD *thd, JOIN_TAB *tab)
Json_writer_object table_records(thd);
table_records.add_table_name(tab);
Json_writer_object table_rec(thd, "table_scan");
table_rec.add("rows", tab->found_records)
.add("cost", tab->read_time);
table_rec.
add("rows", tab->found_records).
add("cost", tab->read_time);
}
......@@ -690,10 +692,11 @@ void print_best_access_for_table(THD *thd, POSITION *pos,
DBUG_ASSERT(thd->trace_started());
Json_writer_object obj(thd, "chosen_access_method");
obj.add("type", type == JT_ALL ? "scan" : join_type_str[type]);
obj.add("records", pos->records_read);
obj.add("cost", pos->read_time);
obj.add("uses_join_buffering", pos->use_join_buffer);
obj.
add("type", type == JT_ALL ? "scan" : join_type_str[type]).
add("records", pos->records_read).
add("cost", pos->read_time).
add("uses_join_buffering", pos->use_join_buffer);
if (pos->range_rowid_filter_info)
{
uint key_no= pos->range_rowid_filter_info->get_key_no();
......
......@@ -423,6 +423,7 @@ void TABLE::init_cost_info_for_usable_range_rowid_filters(THD *thd)
void TABLE::trace_range_rowid_filters(THD *thd) const
{
DBUG_ASSERT(thd->trace_started());
if (!range_rowid_filter_cost_info_elems)
return;
......@@ -440,10 +441,12 @@ void TABLE::trace_range_rowid_filters(THD *thd) const
void Range_rowid_filter_cost_info::trace_info(THD *thd)
{
DBUG_ASSERT(thd->trace_started());
Json_writer_object js_obj(thd);
js_obj.add("key", table->key_info[key_no].name);
js_obj.add("build_cost", cost_of_building_range_filter);
js_obj.add("rows", est_elements);
js_obj.
add("key", table->key_info[key_no].name).
add("build_cost", cost_of_building_range_filter).
add("rows", est_elements);
}
/**
......
This diff is collapsed.
......@@ -698,14 +698,15 @@ void print_keyuse_array_for_trace(THD *thd, DYNAMIC_ARRAY *keyuse_array)
{
keyuse_elem.add("index", keyuse->table->key_info[keyuse->key].name);
}
keyuse_elem.add("field", (keyuse->keypart == FT_KEYPART) ? "<fulltext>":
(keyuse->is_for_hash_join() ?
keyuse->table->field[keyuse->keypart]
->field_name.str :
keyuse->table->key_info[keyuse->key]
.key_part[keyuse->keypart]
.field->field_name.str));
keyuse_elem.add("equals",keyuse->val);
keyuse_elem.add("null_rejecting",keyuse->null_rejecting);
keyuse_elem.
add("field", (keyuse->keypart == FT_KEYPART) ? "<fulltext>":
(keyuse->is_for_hash_join() ?
keyuse->table->field[keyuse->keypart]
->field_name.str :
keyuse->table->key_info[keyuse->key]
.key_part[keyuse->keypart]
.field->field_name.str)).
add("equals",keyuse->val).
add("null_rejecting",keyuse->null_rejecting);
}
}
......@@ -953,8 +953,10 @@ Item *Item_func_in::in_predicate_to_in_subs_transformer(THD *thd,
if (!length || length > tmp_table_max_key_length() ||
args[0]->cols() > tmp_table_max_key_parts())
{
trace_conv.add("done", false);
trace_conv.add("reason", "key is too long");
if (unlikely(trace_conv.trace_started()))
trace_conv.
add("done", false).
add("reason", "key is too long");
return this;
}
......@@ -962,15 +964,19 @@ Item *Item_func_in::in_predicate_to_in_subs_transformer(THD *thd,
{
if (!args[i]->const_item())
{
trace_conv.add("done", false);
trace_conv.add("reason", "non-constant element in the IN-list");
if (unlikely(trace_conv.trace_started()))
trace_conv.
add("done", false).
add("reason", "non-constant element in the IN-list");
return this;
}
if (cmp_row_types(args[i], args[0]))
{
trace_conv.add("done", false);
trace_conv.add("reason", "type mismatch");
if (unlikely(trace_conv.trace_started()))
trace_conv.
add("done", false).
add("reason", "type mismatch");
return this;
}
}
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment