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".

11 files changed, 426 insertions, 251 deletions

diff --git a/mysql-test/main/opt_trace.result b/mysql-test/main/opt_trace.result
index 645b9f55589..f85feb3586b 100644
--- a/mysql-test/main/opt_trace.result
+++ b/mysql-test/main/opt_trace.result
@@ -1131,6 +1131,7 @@ explain select * from t1,t2 where t1.a=t2.b+2 and t2.a= t1.b	{
                               "rows": 1,
                               "found_matching_rows_cost": 2.200585794,
                               "startup_cost": 0,
+                              "rows_after_filter": 1,
                               "cost": 220.0585794,
                               "chosen": true
                             },
@@ -1180,6 +1181,7 @@ explain select * from t1,t2 where t1.a=t2.b+2 and t2.a= t1.b	{
                               "rows": 1,
                               "found_matching_rows_cost": 2.200585794,
                               "startup_cost": 0,
+                              "rows_after_filter": 1,
                               "cost": 220.0585794,
                               "chosen": true
                             },
@@ -2289,6 +2291,7 @@ explain  select * from t1 where a=1 and b=2 order by c limit 1	{
                           "rows": 180,
                           "found_matching_rows_cost": 216.2743776,
                           "startup_cost": 0,
+                          "rows_after_filter": 180,
                           "cost": 216.2743776,
                           "chosen": true
                         },
@@ -2299,6 +2302,7 @@ explain  select * from t1 where a=1 and b=2 order by c limit 1	{
                           "rows": 21,
                           "found_matching_rows_cost": 25.34242739,
                           "startup_cost": 0,
+                          "rows_after_filter": 21,
                           "cost": 25.34242739,
                           "chosen": true
                         },
@@ -2752,6 +2756,7 @@ explain select * from t1 left join t2 on t2.a=t1.a	{
                               "rows": 1,
                               "found_matching_rows_cost": 1.2,
                               "startup_cost": 0,
+                              "rows_after_filter": 1,
                               "cost": 4.8,
                               "chosen": true
                             },
@@ -3285,7 +3290,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",
@@ -3662,6 +3667,7 @@ explain select * from t1 where pk = 2 and a=5 and b=1	{
                           "rows": 1,
                           "found_matching_rows_cost": 1.325585794,
                           "startup_cost": 0,
+                          "rows_after_filter": 1,
                           "cost": 1.325585794,
                           "chosen": true
                         },
@@ -3672,6 +3678,7 @@ explain select * from t1 where pk = 2 and a=5 and b=1	{
                           "rows": 1,
                           "found_matching_rows_cost": 1.325829876,
                           "startup_cost": 0,
+                          "rows_after_filter": 1,
                           "cost": 1.325829876,
                           "chosen": false,
                           "cause": "cost"
@@ -3683,6 +3690,7 @@ explain select * from t1 where pk = 2 and a=5 and b=1	{
                           "rows": 1,
                           "found_matching_rows_cost": 0.326073957,
                           "startup_cost": 0,
+                          "rows_after_filter": 1,
                           "cost": 0.326073957,
                           "chosen": true
                         },
@@ -4381,6 +4389,7 @@ explain delete t0,t1 from t0, t1 where t0.a=t1.a and t1.a<3	{
                               "rows": 1,
                               "found_matching_rows_cost": 1.200585794,
                               "startup_cost": 0,
+                              "rows_after_filter": 1,
                               "cost": 3.601757383,
                               "chosen": true
                             },
@@ -4430,6 +4439,7 @@ explain delete t0,t1 from t0, t1 where t0.a=t1.a and t1.a<3	{
                               "rows": 2,
                               "found_matching_rows_cost": 1.401171589,
                               "startup_cost": 0,
+                              "rows_after_filter": 2,
                               "cost": 4.203514767,
                               "chosen": true
                             },
@@ -5126,7 +5136,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",
@@ -8026,7 +8036,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",
@@ -8148,7 +8158,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",
@@ -8445,7 +8455,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",
@@ -9689,6 +9699,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                         "rows": 1,
                                         "found_matching_rows_cost": 2.200585794,
                                         "startup_cost": 0,
+                                        "rows_after_filter": 1,
                                         "cost": 22.00585794,
                                         "chosen": true
                                     },
@@ -9949,6 +9960,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                         "rows": 1,
                                         "found_matching_rows_cost": 2.200585794,
                                         "startup_cost": 0,
+                                        "rows_after_filter": 1,
                                         "cost": 22.00585794,
                                         "chosen": true
                                     },
@@ -10638,6 +10650,7 @@ json_detailed(json_extract(trace, '$**.choose_best_splitting'))
                                         "rows": 1.8367,
                                         "found_matching_rows_cost": 2.367925794,
                                         "startup_cost": 0,
+                                        "rows_after_filter": 1.8367,
                                         "cost": 2.367925794,
                                         "chosen": true
                                     },
diff --git a/mysql-test/main/opt_trace_index_merge_innodb.result b/mysql-test/main/opt_trace_index_merge_innodb.result
index 4e7011eedc8..c766147d75c 100644
--- a/mysql-test/main/opt_trace_index_merge_innodb.result
+++ b/mysql-test/main/opt_trace_index_merge_innodb.result
@@ -214,6 +214,7 @@ explain select * from t1 where pk1 != 0  and key1 = 1	{
                           "rows": 1,
                           "found_matching_rows_cost": 1.325146475,
                           "startup_cost": 0,
+                          "rows_after_filter": 1,
                           "cost": 1.325146475,
                           "chosen": true
                         },
diff --git a/mysql-test/main/opt_trace_selectivity.result b/mysql-test/main/opt_trace_selectivity.result
index b2e35ed8574..982b2429221 100644
--- a/mysql-test/main/opt_trace_selectivity.result
+++ b/mysql-test/main/opt_trace_selectivity.result
@@ -56,6 +56,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                 "rows": 104,
                                 "found_matching_rows_cost": 124.96562,
                                 "startup_cost": 0,
+                                "rows_after_filter": 104,
                                 "cost": 124.96562,
                                 "chosen": true
                             },
@@ -67,6 +68,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                 "rows": 340,
                                 "found_matching_rows_cost": 408.2577963,
                                 "startup_cost": 0,
+                                "rows_after_filter": 340,
                                 "cost": 408.2577963,
                                 "chosen": false,
                                 "cause": "cost"
@@ -79,6 +81,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                 "rows": 632,
                                 "found_matching_rows_cost": 758.7718449,
                                 "startup_cost": 0,
+                                "rows_after_filter": 632,
                                 "cost": 758.7718449,
                                 "chosen": false,
                                 "cause": "cost"
@@ -164,6 +167,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                 "rows": 6,
                                 "found_matching_rows_cost": 7.327343464,
                                 "startup_cost": 0,
+                                "rows_after_filter": 6,
                                 "cost": 7.327343464,
                                 "chosen": true
                             },
@@ -175,6 +179,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                 "rows": 232,
                                 "found_matching_rows_cost": 278.6156139,
                                 "startup_cost": 0,
+                                "rows_after_filter": 232,
                                 "cost": 278.6156139,
                                 "chosen": false,
                                 "cause": "cost"
@@ -187,6 +192,7 @@ JSON_DETAILED(JSON_EXTRACT(trace, '$**.considered_execution_plans'))
                                 "rows": 293,
                                 "found_matching_rows_cost": 351.8394392,
                                 "startup_cost": 0,
+                                "rows_after_filter": 293,
                                 "cost": 351.8394392,
                                 "chosen": false,
                                 "cause": "cost"
diff --git a/sql/opt_range.cc b/sql/opt_range.cc
index dea8dae5f33..855d4d2a9ed 100644
--- a/sql/opt_range.cc
+++ b/sql/opt_range.cc
@@ -2294,9 +2294,11 @@ void TRP_RANGE::trace_basic_info(PARAM *param,
   const KEY &cur_key= param->table->key_info[keynr_in_table];
   const KEY_PART_INFO *key_part= cur_key.key_part;
 
-  trace_object->add("type", "range_scan")
-               .add("index", cur_key.name)
-               .add("rows", records);
+  if (unlikely(trace_object->trace_started()))
+    trace_object->
+      add("type", "range_scan").
+      add("index", cur_key.name).
+      add("rows", records);
 
   Json_writer_array trace_range(param->thd, "ranges");
 
@@ -2500,11 +2502,13 @@ void TRP_GROUP_MIN_MAX::trace_basic_info(PARAM *param,
   else
     trace_object->add_null("min_max_arg");
 
-  trace_object->add("min_aggregate", have_min)
-               .add("max_aggregate", have_max)
-               .add("distinct_aggregate", have_agg_distinct)
-               .add("rows", records)
-               .add("cost", read_cost);
+  if (unlikely(trace_object->trace_started()))
+    trace_object->
+      add("min_aggregate", have_min).
+      add("max_aggregate", have_max).
+      add("distinct_aggregate", have_agg_distinct).
+      add("rows", records).
+      add("cost", read_cost);
 
   const KEY_PART_INFO *key_part= index_info->key_part;
   {
@@ -2734,6 +2738,7 @@ int SQL_SELECT::test_quick_select(THD *thd, key_map keys_to_use,
   table_info.add_table_name(head);
 
   Json_writer_object trace_range(thd, "range_analysis");
+  if (unlikely(thd->trace_started()))
   {
     Json_writer_object table_rec(thd, "table_scan");
     table_rec.add("rows", records).add("cost", read_time);
@@ -2807,8 +2812,10 @@ int SQL_SELECT::test_quick_select(THD *thd, key_map keys_to_use,
 
       if (!keys_to_use.is_set(idx))
       {
-        trace_idx_details.add("usable", false)
-                         .add("cause", "not applicable");
+        if (unlikely(trace_idx_details.trace_started()))
+          trace_idx_details.
+            add("usable", false).
+            add("cause", "not applicable");
         continue;
       }
       if (key_info->flags & HA_FULLTEXT)
@@ -2873,10 +2880,14 @@ int SQL_SELECT::test_quick_select(THD *thd, key_map keys_to_use,
         read_time= key_read_time;
         chosen= TRUE;
       }
-      trace_cov.add("index", head->key_info[key_for_use].name)
-               .add("cost", key_read_time).add("chosen", chosen);
-      if (!chosen)
-        trace_cov.add("cause", "cost");
+      if (unlikely(trace_cov.trace_started()))
+      {
+        trace_cov.
+          add("index", head->key_info[key_for_use].name).
+          add("cost", key_read_time).add("chosen", chosen);
+        if (!chosen)
+          trace_cov.add("cause", "cost");
+      }
     }
 
     double best_read_time= read_time;
@@ -3091,9 +3102,10 @@ int SQL_SELECT::test_quick_select(THD *thd, key_map keys_to_use,
         Json_writer_object trace_range_plan(thd, "range_access_plan");
         best_trp->trace_basic_info(&param, &trace_range_plan);
       }
-      trace_range_summary.add("rows_for_plan", quick->records)
-                         .add("cost_for_plan", quick->read_time)
-                         .add("chosen", true);
+      trace_range_summary.
+        add("rows_for_plan", quick->records).
+        add("cost_for_plan", quick->read_time).
+        add("chosen", true);
     }
 
     free_root(&alloc,MYF(0));			// Return memory & allocator
@@ -3507,11 +3519,12 @@ bool calculate_cond_selectivity_for_table(THD *thd, TABLE *table, Item **cond)
     */
     table->multiply_cond_selectivity(quick_cond_selectivity);
 
+    if (unlikely(thd->trace_started()))
     {
       Json_writer_object selectivity_for_index(thd);
-      selectivity_for_index.add("index_name", key_info->name)
-        .add("selectivity_from_index",
-             quick_cond_selectivity);
+      selectivity_for_index.
+        add("index_name", key_info->name).
+        add("selectivity_from_index", quick_cond_selectivity);
     }
     /*
       We need to set selectivity for fields supported by indexes.
@@ -3549,10 +3562,13 @@ end_of_range_loop:
                  quick->get_type() == QUICK_SELECT_I::QS_TYPE_ROR_UNION ||
                  quick->get_type() == QUICK_SELECT_I::QS_TYPE_INDEX_MERGE ||
                  quick->get_type() == QUICK_SELECT_I::QS_TYPE_ROR_INTERSECT));
-    Json_writer_object selectivity_for_index(thd);
     table->cond_selectivity= original_selectivity;
-    selectivity_for_index.add("use_opt_range_condition_rows_selectivity",
-                              original_selectivity);
+    if (unlikely(thd->trace_started()))
+    {
+      Json_writer_object selectivity_for_index(thd);
+      selectivity_for_index.add("use_opt_range_condition_rows_selectivity",
+                                original_selectivity);
+    }
   }
   selectivity_for_indexes.end();
    
@@ -3625,8 +3641,10 @@ end_of_range_loop:
         {
           rows= 0;
           table->reginfo.impossible_range= 1;
-          selectivity_for_column.add("selectivity_from_histogram", rows);
-          selectivity_for_column.add("cause", "impossible range");
+          if (unlikely(selectivity_for_column.trace_started()))
+            selectivity_for_column.
+              add("selectivity_from_histogram", rows).
+              add("cause", "impossible range");
           goto free_alloc;
         }          
         else
@@ -5269,9 +5287,10 @@ TABLE_READ_PLAN *get_best_disjunct_quick(PARAM *param, SEL_IMERGE *imerge,
     }
     else
       non_cpk_scan_records += (*cur_child)->records;
-    trace_idx.add("index_to_merge",
-                  param->table->key_info[keynr_in_table].name)
-             .add("cumulated_cost", imerge_cost);
+    if (unlikely(trace_idx.trace_started()))
+      trace_idx.
+        add("index_to_merge", param->table->key_info[keynr_in_table].name).
+        add("cumulated_cost", imerge_cost);
   }
 
   to_merge.end();
@@ -5303,9 +5322,10 @@ TABLE_READ_PLAN *get_best_disjunct_quick(PARAM *param, SEL_IMERGE *imerge,
       optimizer_flag(param->thd, OPTIMIZER_SWITCH_INDEX_MERGE_UNION))
   {
     roru_read_plans= (TABLE_READ_PLAN**)range_scans;
-    trace_best_disjunct.add("use_roworder_union", true)
-                       .add("cause",
-                            "always cheaper than non roworder retrieval");
+    if (unlikely(trace_best_disjunct.trace_started()))
+      trace_best_disjunct.
+        add("use_roworder_union", true).
+        add("cause", "always cheaper than non roworder retrieval");
     goto skip_to_ror_scan;
   }
 
@@ -5326,16 +5346,21 @@ TABLE_READ_PLAN *get_best_disjunct_quick(PARAM *param, SEL_IMERGE *imerge,
   {
     double sweep_cost= get_sweep_read_cost(param, non_cpk_scan_records);
     imerge_cost+= sweep_cost;
-    trace_best_disjunct.add("cost_sort_rowid_and_read_disk", sweep_cost);
+    trace_best_disjunct.
+      add("records", non_cpk_scan_records).
+      add("cost_sort_rowid_and_read_disk", sweep_cost).
+      add("cost", imerge_cost);
   }
   DBUG_PRINT("info",("index_merge cost with rowid-to-row scan: %g",
                      imerge_cost));
   if (imerge_cost > read_time || 
       !optimizer_flag(param->thd, OPTIMIZER_SWITCH_INDEX_MERGE_SORT_UNION))
   {
-    trace_best_disjunct.add("use_roworder_index_merge", true);
-    trace_best_disjunct.add("cause", "cost");
-    goto build_ror_index_merge;
+    if (unlikely(trace_best_disjunct.trace_started()))
+      trace_best_disjunct.
+        add("use_sort_index_merge", false).
+        add("cause", imerge_cost > read_time ? "cost" : "disabled");
+    goto build_ror_index_merge;                 // Try roworder_index_merge
   }
 
   /* Add Unique operations cost */
@@ -5359,8 +5384,10 @@ TABLE_READ_PLAN *get_best_disjunct_quick(PARAM *param, SEL_IMERGE *imerge,
                            TIME_FOR_COMPARE_ROWID,
                            FALSE, NULL);
     imerge_cost+= dup_removal_cost;
-    trace_best_disjunct.add("cost_duplicate_removal", dup_removal_cost)
-                       .add("total_cost", imerge_cost);
+    if (unlikely(trace_best_disjunct.trace_started()))
+      trace_best_disjunct.
+        add("cost_duplicate_removal", dup_removal_cost).
+        add("total_cost", imerge_cost);
   }
 
   DBUG_PRINT("info",("index_merge total cost: %g (wanted: less then %g)",
@@ -5476,8 +5503,10 @@ skip_to_ror_scan:
 
   DBUG_PRINT("info", ("ROR-union: cost %g, %zu members",
                       roru_total_cost, n_child_scans));
-  trace_best_disjunct.add("index_roworder_union_cost", roru_total_cost)
-                     .add("members", n_child_scans);
+  if (unlikely(trace_best_disjunct.trace_started()))
+    trace_best_disjunct.
+      add("index_roworder_union_cost", roru_total_cost).
+      add("members", n_child_scans);
   TRP_ROR_UNION* roru;
   if (roru_total_cost < read_time)
   {
@@ -5880,15 +5909,19 @@ bool prepare_search_best_index_intersect(PARAM *param,
 
     if (*index_scan == cpk_scan)
     {
-      idx_scan.add("chosen", "false")
-              .add("cause", "clustered index used for filtering");
+      if (unlikely(idx_scan.trace_started()))
+        idx_scan.
+          add("chosen", "false").
+          add("cause", "clustered index used for filtering");
       continue;
     }
     if (cpk_scan && cpk_scan->used_key_parts >= used_key_parts &&
         same_index_prefix(cpk_scan->key_info, key_info, used_key_parts))
     {
-      idx_scan.add("chosen", "false")
-              .add("cause", "clustered index used for filtering");
+      if (unlikely(idx_scan.trace_started()))
+        idx_scan.
+          add("chosen", "false").
+          add("cause", "clustered index used for filtering");
       continue;
     }
 
@@ -5898,8 +5931,8 @@ bool prepare_search_best_index_intersect(PARAM *param,
 
     if (cost >= cutoff_cost)
     {
-      idx_scan.add("chosen", false);
-      idx_scan.add("cause", "cost");
+      if (unlikely(idx_scan.trace_started()))
+        idx_scan.add("chosen", false).add("cause", "cost");
       continue;
     }
    
@@ -5918,15 +5951,18 @@ bool prepare_search_best_index_intersect(PARAM *param,
     }
     if (!*scan_ptr || cost < (*scan_ptr)->index_read_cost)
     {
-      idx_scan.add("chosen", true);
-      if (!*scan_ptr)
-        idx_scan.add("cause", "first occurrence of index prefix");
-      else
-        idx_scan.add("cause", "better cost for same idx prefix");
+      if (unlikely(idx_scan.trace_started()))
+      {
+        idx_scan.add("chosen", true);
+        if (!*scan_ptr)
+          idx_scan.add("cause", "first occurrence of index prefix");
+        else
+          idx_scan.add("cause", "better cost for same idx prefix");
+      }
       *scan_ptr= *index_scan;
       (*scan_ptr)->index_read_cost= cost;
     }
-    else
+    else if (unlikely(idx_scan.trace_started()))
     {
       idx_scan.add("chosen", false).add("cause", "cost");
     }
@@ -5989,13 +6025,14 @@ bool prepare_search_best_index_intersect(PARAM *param,
       ha_rows records= records_in_index_intersect_extension(&curr, *scan_ptr);
       (*scan_ptr)->filtered_out= records >= scan_records ?
                                    0 : scan_records-records;
-      if (thd->trace_started())
+      if (unlikely(thd->trace_started()))
       {
         Json_writer_object selected_idx(thd);
         selected_idx.add("index", key_info->name);
         print_keyparts(thd, key_info, (*scan_ptr)->used_key_parts);
-        selected_idx.add("records", (*scan_ptr)->records)
-                    .add("filtered_records", (*scan_ptr)->filtered_out);
+        selected_idx.
+          add("records", (*scan_ptr)->records).
+          add("filtered_records", (*scan_ptr)->filtered_out);
       }
     }
   } 
@@ -6005,13 +6042,14 @@ bool prepare_search_best_index_intersect(PARAM *param,
     {
       KEY *key_info= (*scan_ptr)->key_info;
       (*scan_ptr)->filtered_out= 0;
-      if (thd->trace_started())
+      if (unlikely(thd->trace_started()))
       {
         Json_writer_object selected_idx(thd);
         selected_idx.add("index", key_info->name);
         print_keyparts(thd, key_info, (*scan_ptr)->used_key_parts);
-        selected_idx.add("records", (*scan_ptr)->records)
-                    .add("filtered_records", (*scan_ptr)->filtered_out);
+        selected_idx.
+          add("records", (*scan_ptr)->records).
+          add("filtered_records", (*scan_ptr)->filtered_out);
       }
     }
   }
@@ -6544,9 +6582,11 @@ TRP_INDEX_INTERSECT *get_best_index_intersect(PARAM *param, SEL_TREE *tree,
     intersect_trp->range_scans= range_scans;
     intersect_trp->range_scans_end= cur_range;
     intersect_trp->filtered_scans= common.filtered_scans;
-    trace_idx_interect.add("rows", intersect_trp->records)
-                      .add("cost", intersect_trp->read_cost)
-                      .add("chosen",true);
+    if (unlikely(trace_idx_interect.trace_started()))
+      trace_idx_interect.
+        add("rows", intersect_trp->records).
+        add("cost", intersect_trp->read_cost).
+        add("chosen",true);
   }
   DBUG_RETURN(intersect_trp);
 }
@@ -6562,11 +6602,12 @@ void TRP_ROR_INTERSECT::trace_basic_info(PARAM *param,
   THD *thd= param->thd;
   DBUG_ASSERT(trace_object->trace_started());
 
-  trace_object->add("type", "index_roworder_intersect");
-  trace_object->add("rows", records);
-  trace_object->add("cost", read_cost);
-  trace_object->add("covering", is_covering);
-  trace_object->add("clustered_pk_scan", cpk_scan != NULL);
+  trace_object->
+    add("type", "index_roworder_intersect").
+    add("rows", records).
+    add("cost", read_cost).
+    add("covering", is_covering).
+    add("clustered_pk_scan", cpk_scan != NULL);
 
   Json_writer_array smth_trace(thd, "intersect_of");
   for (ROR_SCAN_INFO **cur_scan= first_scan; cur_scan != last_scan;
@@ -6576,9 +6617,10 @@ void TRP_ROR_INTERSECT::trace_basic_info(PARAM *param,
     const KEY_PART_INFO *key_part= cur_key.key_part;
 
     Json_writer_object trace_isect_idx(thd);
-    trace_isect_idx.add("type", "range_scan");
-    trace_isect_idx.add("index", cur_key.name);
-    trace_isect_idx.add("rows", (*cur_scan)->records);
+    trace_isect_idx.
+      add("type", "range_scan").
+      add("index", cur_key.name).
+      add("rows", (*cur_scan)->records);
 
     Json_writer_array trace_range(thd, "ranges");
 
@@ -7217,16 +7259,18 @@ TRP_ROR_INTERSECT *get_best_ror_intersect(const PARAM *param, SEL_TREE *tree,
     /* S= S + first(R);  R= R - first(R); */
     if (!ror_intersect_add(intersect, *cur_ror_scan, &trace_idx, FALSE))
     {
-      trace_idx.add("usable", false)
-               .add("cause", "does not reduce cost of intersect");
+      trace_idx.
+        add("usable", false).
+        add("cause", "does not reduce cost of intersect");
       cur_ror_scan++;
       continue;
     }
     
-    trace_idx.add("cumulative_total_cost", intersect->total_cost)
-             .add("usable", true)
-             .add("matching_rows_now", intersect->out_rows)
-             .add("intersect_covering_with_this_index", intersect->is_covering);
+    trace_idx.
+      add("cumulative_total_cost", intersect->total_cost).
+      add("usable", true).
+      add("matching_rows_now", intersect->out_rows).
+      add("intersect_covering_with_this_index", intersect->is_covering);
 
     *(intersect_scans_end++)= *(cur_ror_scan++);
 
@@ -7240,8 +7284,9 @@ TRP_ROR_INTERSECT *get_best_ror_intersect(const PARAM *param, SEL_TREE *tree,
     }
     else
     {
-      trace_idx.add("chosen", false)
-               .add("cause", "does not reduce cost");
+      trace_idx.
+        add("chosen", false).
+        add("cause", "does not reduce cost");
     }
   }
   trace_isect_idx.end();
@@ -7249,8 +7294,9 @@ TRP_ROR_INTERSECT *get_best_ror_intersect(const PARAM *param, SEL_TREE *tree,
   if (intersect_scans_best == intersect_scans)
   {
     DBUG_PRINT("info", ("None of scans increase selectivity"));
-    trace_ror.add("chosen", false)
-             .add("cause","does not increase selectivity");
+    trace_ror.
+      add("chosen", false).
+      add("cause","does not increase selectivity");
     DBUG_RETURN(NULL);
   }
     
@@ -7274,22 +7320,27 @@ TRP_ROR_INTERSECT *get_best_ror_intersect(const PARAM *param, SEL_TREE *tree,
     if (ror_intersect_add(intersect, cpk_scan, &trace_cpk, TRUE) &&
         (intersect->total_cost < min_cost))
     {
-      trace_cpk.add("clustered_pk_scan_added_to_intersect", true)
-               .add("cumulated_cost", intersect->total_cost);
+      if (trace_cpk.trace_started())
+      trace_cpk.
+        add("clustered_pk_scan_added_to_intersect", true).
+        add("cumulated_cost", intersect->total_cost);
       intersect_best= intersect; //just set pointer here
     }
     else
     {
-      trace_cpk.add("clustered_pk_added_to_intersect", false)
-               .add("cause", "cost");
+      if (trace_cpk.trace_started())
+        trace_cpk.
+          add("clustered_pk_added_to_intersect", false).
+          add("cause", "cost");
       cpk_scan= 0; // Don't use cpk_scan
     }
   }
   else
   {
-    trace_cpk.add("clustered_pk_added_to_intersect", false)
-             .add("cause", cpk_scan ? "roworder is covering"
-                                    : "no clustered pk index");
+    trace_cpk.
+      add("clustered_pk_added_to_intersect", false).
+      add("cause", cpk_scan ? "roworder is covering"
+          : "no clustered pk index");
     cpk_scan= 0;                                // Don't use cpk_scan
   }
   trace_cpk.end();
@@ -7319,17 +7370,20 @@ TRP_ROR_INTERSECT *get_best_ror_intersect(const PARAM *param, SEL_TREE *tree,
     DBUG_PRINT("info", ("Returning non-covering ROR-intersect plan:"
                         "cost %g, records %lu",
                         trp->read_cost, (ulong) trp->records));
-    trace_ror.add("rows", trp->records)
-             .add("cost", trp->read_cost)
-             .add("covering", trp->is_covering)
-             .add("chosen", true);
+    if (unlikely(trace_ror.trace_started()))
+      trace_ror.
+        add("rows",      trp->records).
+        add("cost",     trp->read_cost).
+        add("covering", trp->is_covering).
+        add("chosen",   true);
   }
   else
   {
-    trace_ror.add("chosen", false)
-             .add("cause", (read_time > min_cost)
-                            ? "too few indexes to merge"
-                            : "cost");
+    trace_ror.
+      add("chosen", false).
+      add("cause", (read_time >= min_cost)
+          ? "too few indexes to merge"
+          : "cost");
   }
   DBUG_PRINT("enter", ("opt_range_condition_rows: %llu",
                        (ulonglong) param->table->opt_range_condition_rows));
@@ -7597,11 +7651,13 @@ static TRP_RANGE *get_key_scans_params(PARAM *param, SEL_TREE *tree,
           trace_ranges(&trace_range, param, idx, key, key_part);
         trace_range.end();
 
-        trace_idx.add("rowid_ordered", is_ror_scan)
-                 .add("using_mrr", !(mrr_flags & HA_MRR_USE_DEFAULT_IMPL))
-                 .add("index_only", read_index_only)
-                 .add("rows", found_records)
-                 .add("cost", cost.total_cost());
+        if (unlikely(trace_idx.trace_started()))
+          trace_idx.
+            add("rowid_ordered", is_ror_scan).
+            add("using_mrr", !(mrr_flags & HA_MRR_USE_DEFAULT_IMPL)).
+            add("index_only", read_index_only).
+            add("rows", found_records).
+            add("cost", cost.total_cost());
       }
       if ((found_records != HA_POS_ERROR) && is_ror_scan)
       {
@@ -7619,7 +7675,7 @@ static TRP_RANGE *get_key_scans_params(PARAM *param, SEL_TREE *tree,
         best_buf_size=  buf_size;
         trace_idx.add("chosen", true);
       }
-      else
+      else if (unlikely(trace_idx.trace_started()))
       {
         trace_idx.add("chosen", false);
         if (found_records == HA_POS_ERROR)
@@ -11038,7 +11094,7 @@ SEL_ARG *enforce_sel_arg_weight_limit(RANGE_OPT_PARAM *param, uint keyno,
 
   uint weight2= sel_arg? sel_arg->weight : 0;
 
-  if (weight2 != weight1)
+  if (unlikely(weight2 != weight1 && param->thd->trace_started()))
   {
     Json_writer_object wrapper(param->thd);
     Json_writer_object obj(param->thd, "enforce_sel_arg_weight_limit");
@@ -11047,8 +11103,9 @@ SEL_ARG *enforce_sel_arg_weight_limit(RANGE_OPT_PARAM *param, uint keyno,
     else
       obj.add("pseudo_index", field->field_name);
 
-    obj.add("old_weight", (longlong)weight1);
-    obj.add("new_weight", (longlong)weight2);
+    obj.
+      add("old_weight", (longlong)weight1).
+      add("new_weight", (longlong)weight2);
   }
   return sel_arg;
 }
@@ -11072,12 +11129,16 @@ bool sel_arg_and_weight_heuristic(RANGE_OPT_PARAM *param, SEL_ARG *key1,
   ulong max_weight= param->thd->variables.optimizer_max_sel_arg_weight;
   if (max_weight && key1->weight + key1->elements*key2->weight > max_weight)
   {
-    Json_writer_object wrapper(param->thd);
-    Json_writer_object obj(param->thd, "sel_arg_weight_heuristic");
-    obj.add("key1_field", key1->field->field_name);
-    obj.add("key2_field", key2->field->field_name);
-    obj.add("key1_weight", (longlong)key1->weight);
-    obj.add("key2_weight", (longlong)key2->weight);
+    if (unlikely(param->thd->trace_started()))
+    {
+      Json_writer_object wrapper(param->thd);
+      Json_writer_object obj(param->thd, "sel_arg_weight_heuristic");
+      obj.
+        add("key1_field", key1->field->field_name).
+        add("key2_field", key2->field->field_name).
+        add("key1_weight", (longlong)key1->weight).
+        add("key2_weight", (longlong)key2->weight);
+    }
     return true; // Discard key2
   }
   return false;
@@ -13805,7 +13866,8 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
       (!join->select_distinct) &&
       !is_agg_distinct)
   {
-    trace_group.add("chosen", false).add("cause","no group by or distinct");
+    if (unlikely(trace_group.trace_started()))
+      trace_group.add("chosen", false).add("cause","no group by or distinct");
     DBUG_RETURN(NULL);
   }
   /* Analyze the query in more detail. */
@@ -13830,8 +13892,10 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
         continue;
       else
       {
-        trace_group.add("chosen", false)
-                   .add("cause", "not applicable aggregate function");
+        if (unlikely(trace_group.trace_started()))
+          trace_group.
+            add("chosen", false).
+            add("cause", "not applicable aggregate function");
         DBUG_RETURN(NULL);
       }
 
@@ -13843,15 +13907,19 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
           min_max_arg_item= (Item_field*) expr;
         else if (! min_max_arg_item->eq(expr, 1))
         {
-          trace_group.add("chosen", false)
-                     .add("cause", "arguments different in min max function");
+          if (unlikely(trace_group.trace_started()))
+            trace_group.
+              add("chosen", false).
+              add("cause", "arguments different in min max function");
           DBUG_RETURN(NULL);
         }
       }
       else
       {
-        trace_group.add("chosen", false)
-                   .add("cause", "no field item in min max function");
+        if (unlikely(trace_group.trace_started()))
+          trace_group.
+            add("chosen", false).
+            add("cause", "no field item in min max function");
         DBUG_RETURN(NULL);
       }
     }
@@ -13860,8 +13928,10 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
   /* Check (SA7). */
   if (is_agg_distinct && (have_max || have_min))
   {
-    trace_group.add("chosen", false)
-               .add("cause", "have both agg distinct and min max");
+    if (unlikely(trace_group.trace_started()))
+      trace_group.
+        add("chosen", false).
+        add("cause", "have both agg distinct and min max");
     DBUG_RETURN(NULL);
   }
 
@@ -13873,8 +13943,10 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
     {
       if (item->real_item()->type() != Item::FIELD_ITEM)
       {
-        trace_group.add("chosen", false)
-                   .add("cause", "distinct field is expression");
+        if (unlikely(trace_group.trace_started()))
+          trace_group.
+            add("chosen", false).
+            add("cause", "distinct field is expression");
         DBUG_RETURN(NULL);
       }
     }
@@ -13886,8 +13958,10 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
   {
     if ((*tmp_group->item)->real_item()->type() != Item::FIELD_ITEM)
     {
-      trace_group.add("chosen", false)
-                 .add("cause", "group field is expression");
+      if (unlikely(trace_group.trace_started()))
+      trace_group.
+        add("chosen", false).
+        add("cause", "group field is expression");
       DBUG_RETURN(NULL);
     }
     elements_in_group++;
@@ -14313,8 +14387,10 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
                                       Field::itMBR : Field::itRAW,
                                       &has_min_max_fld, &has_other_fld))
   {
-    trace_group.add("usable", false)
-               .add("cause", "unsupported predicate on agg attribute");
+    if (unlikely(trace_group.trace_started()))
+      trace_group.
+        add("usable", false).
+        add("cause", "unsupported predicate on agg attribute");
     DBUG_RETURN(NULL);
   }
 
@@ -14323,8 +14399,10 @@ get_best_group_min_max(PARAM *param, SEL_TREE *tree, double read_time)
   */
   if (is_agg_distinct && table->file->is_clustering_key(index))
   {
-    trace_group.add("usable", false)
-               .add("cause", "index is clustered");
+    if (unlikely(trace_group.trace_started()))
+      trace_group.
+        add("usable", false).
+        add("cause", "index is clustered");
     DBUG_RETURN(NULL);
   }
 
diff --git a/sql/opt_split.cc b/sql/opt_split.cc
index 86ed442814c..74e9d2c65b5 100644
--- a/sql/opt_split.cc
+++ b/sql/opt_split.cc
@@ -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;
diff --git a/sql/opt_subselect.cc b/sql/opt_subselect.cc
index 4a53559f408..99800b1fa37 100644
--- a/sql/opt_subselect.cc
+++ b/sql/opt_subselect.cc
@@ -895,8 +895,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);
     }
   }
@@ -918,8 +920,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);
   }
@@ -1279,8 +1283,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;
     }
 
@@ -1292,9 +1298,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))
@@ -3132,8 +3139,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;
     }
@@ -3314,8 +3322,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;
   }
diff --git a/sql/opt_trace.cc b/sql/opt_trace.cc
index ed2e2927687..4c1465001b8 100644
--- a/sql/opt_trace.cc
+++ b/sql/opt_trace.cc
@@ -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);
 }
 
 
@@ -691,10 +693,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();
diff --git a/sql/rowid_filter.cc b/sql/rowid_filter.cc
index 8cd2a5aeddb..3ed9a989345 100644
--- a/sql/rowid_filter.cc
+++ b/sql/rowid_filter.cc
@@ -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);
 }
 
 /**
diff --git a/sql/sql_select.cc b/sql/sql_select.cc
index c8420d8679c..d482de59110 100644
--- a/sql/sql_select.cc
+++ b/sql/sql_select.cc
@@ -539,9 +539,10 @@ static void trace_table_dependencies(THD *thd,
   {
     TABLE_LIST *table_ref= join_tabs[i].tab_list;
     Json_writer_object trace_one_table(thd);
-    trace_one_table.add_table_name(&join_tabs[i]);
-    trace_one_table.add("row_may_be_null",
-                       (bool)table_ref->table->maybe_null);
+    trace_one_table.
+      add_table_name(&join_tabs[i]).
+      add("row_may_be_null",
+          (bool)table_ref->table->maybe_null);
     const table_map map= table_ref->get_map();
     DBUG_ASSERT(map < (1ULL << table_count));
     for (uint j= 0; j < table_count; j++)
@@ -1735,7 +1736,7 @@ JOIN::prepare(TABLE_LIST *tables_init, COND *conds_init, uint og_num,
     }
   }
 
-  if (thd->trace_started())
+  if (unlikely(thd->trace_started()))
   {
     Json_writer_object trace_wrapper(thd);
     opt_trace_print_expanded_query(thd, select_lex, &trace_wrapper);
@@ -5478,7 +5479,7 @@ make_join_statistics(JOIN *join, List<TABLE_LIST> &tables_list,
     }
   }
 
-  if (thd->trace_started())
+  if (unlikely(thd->trace_started()))
     trace_table_dependencies(thd, stat, join->table_count);
 
   if (join->conds || outer_join)
@@ -5499,7 +5500,7 @@ make_join_statistics(JOIN *join, List<TABLE_LIST> &tables_list,
                                skip_unprefixed_keyparts))
       goto error;
     DBUG_EXECUTE("opt", print_keyuse_array(keyuse_array););
-    if (thd->trace_started())
+    if (unlikely(thd->trace_started()))
       print_keyuse_array_for_trace(thd, keyuse_array);
   }
 
@@ -5948,13 +5949,13 @@ make_join_statistics(JOIN *join, List<TABLE_LIST> &tables_list,
           delete select;
         else
         {
-          if (thd->trace_started())
+          if (unlikely(thd->trace_started()))
             add_table_scan_values_to_trace(thd, s);
         }
       }
       else
       {
-        if (thd->trace_started())
+        if (unlikely(thd->trace_started()))
           add_table_scan_values_to_trace(thd, s);
       }
     }
@@ -8073,8 +8074,10 @@ best_access_path(JOIN      *join,
         */
         records= 1.0;
         type= JT_FT;
-        trace_access_idx.add("access_type", join_type_str[type])
-                        .add("full-text index", keyinfo->name);
+        if (unlikely(trace_access_idx.trace_started()))
+          trace_access_idx.
+            add("access_type", join_type_str[type]).
+            add("full-text index", keyinfo->name);
       }
       else
       {
@@ -8099,8 +8102,10 @@ best_access_path(JOIN      *join,
             DBUG_ASSERT(join->eq_ref_tables & table->map);
             /* TODO: Adjust cost for covering and clustering key */
             type= JT_EQ_REF;
-            trace_access_idx.add("access_type", join_type_str[type])
-                            .add("index", keyinfo->name);
+            if (unlikely(trace_access_idx.trace_started()))
+              trace_access_idx.
+                add("access_type", join_type_str[type]).
+                add("index", keyinfo->name);
             if (!found_ref && table->opt_range_keys.is_set(key))
               tmp= adjust_quick_cost(table->opt_range[key].cost, 1);
             else
@@ -8116,8 +8121,10 @@ best_access_path(JOIN      *join,
           else
           {
             type= JT_REF;
-            trace_access_idx.add("access_type", join_type_str[type])
-                            .add("index", keyinfo->name);
+            if (unlikely(trace_access_idx.trace_started()))
+              trace_access_idx.
+                add("access_type", join_type_str[type]).
+                add("index", keyinfo->name);
             if (!found_ref)
             {                                     /* We found a const key */
               /*
@@ -8147,8 +8154,10 @@ best_access_path(JOIN      *join,
               }
               /* quick_range couldn't use key! */
               records= (double) s->records/rec;
-              trace_access_idx.add("used_range_estimates", false)
-                .add("reason", "not available");
+              if (unlikely(trace_access_idx.trace_started()))
+                trace_access_idx.
+                  add("used_range_estimates", false).
+                  add("reason", "not available");
             }
             else
             {
@@ -8183,17 +8192,13 @@ best_access_path(JOIN      *join,
                 records= (double) table->opt_range[key].rows;
                 trace_access_idx.add("used_range_estimates", "clipped down");
               }
-              else
+              else if (unlikely(trace_access_idx.trace_started()))
               {
                 trace_access_idx.add("used_range_estimates", false);
                 if (table->opt_range_keys.is_set(key))
-                {
                   trace_access_idx.add("reason", "not better than ref estimates");
-                }
                 else
-                {
                   trace_access_idx.add("reason", "not available");
-                }
               }
             }
             /* Limit the number of matched rows */
@@ -8204,8 +8209,10 @@ best_access_path(JOIN      *join,
         else
         {
           type = ref_or_null_part ? JT_REF_OR_NULL : JT_REF;
-          trace_access_idx.add("access_type", join_type_str[type])
-                          .add("index", keyinfo->name);
+          if (unlikely(trace_access_idx.trace_started()))
+            trace_access_idx.
+              add("access_type", join_type_str[type]).
+              add("index", keyinfo->name);
           /*
             Use as much key-parts as possible and a uniq key is better
             than a not unique key
@@ -8450,15 +8457,23 @@ best_access_path(JOIN      *join,
         }
       }
       tmp= COST_ADD(tmp, records_after_filter/TIME_FOR_COMPARE);
-      trace_access_idx.add("rows", records).
-        add("found_matching_rows_cost",tmp).
-        add("startup_cost", startup_cost);
+      if (unlikely(trace_access_idx.trace_started()))
+          trace_access_idx.
+          add("rows", records).
+          add("found_matching_rows_cost",tmp).
+          add("startup_cost", startup_cost);
 
       tmp= COST_MULT(tmp, record_count);
       tmp= COST_ADD(tmp, startup_cost);
+
+      if (unlikely(trace_access_idx.trace_started()))
+        trace_access_idx.
+          add("rows_after_filter", records_after_filter).
+          add("cost", tmp);
+
       if (tmp + 0.0001 < best_cost)
       {
-        trace_access_idx.add("cost", tmp).add("chosen", true);
+        trace_access_idx.add("chosen", true);
         best_cost= tmp;
         best_records= records;
         best_key= start_key;
@@ -8467,10 +8482,11 @@ best_access_path(JOIN      *join,
         best_filter= filter;
         best_type= type;
       }
-      else if (thd->trace_started())
+      else if (unlikely(thd->trace_started()))
       {
-        trace_access_idx.add("cost",tmp).add("chosen", false)
-                        .add("cause", cause ? cause : "cost");
+        trace_access_idx.
+          add("chosen", false).
+          add("cause", cause ? cause : "cost");
       }
     } /* for each key */
     records= best_records;
@@ -8518,6 +8534,7 @@ best_access_path(JOIN      *join,
       (!(s->table->map & join->outer_join) ||
        join->allowed_outer_join_with_cache))    // (2)
   {
+    Json_writer_object trace_access_hash(thd);
     double refills, cmp_time;
     /* Estimate the cost of the hash join access to the table */
     double rnd_records= matching_candidates_in_table(s, found_constraint,
@@ -8566,12 +8583,14 @@ best_access_path(JOIN      *join,
     best_uses_jbuf= TRUE;
     best_filter= 0;
     best_type= JT_HASH;
-    Json_writer_object trace_access_hash(thd);
-    trace_access_hash.add("type", "hash");
-    trace_access_hash.add("index", "hj-key");
-    trace_access_hash.add("rows", rnd_records);
-    trace_access_hash.add("cost", best_cost);
-    trace_access_hash.add("chosen", true);
+    if (unlikely(trace_access_hash.trace_started()))
+      trace_access_hash.
+        add("type", "hash").
+        add("index", "hj-key").
+        add("rows", rnd_records).
+        add("refills", refills).
+        add("cost", best_cost).
+        add("chosen", true);
   }
 
   /*
@@ -8747,8 +8766,10 @@ best_access_path(JOIN      *join,
     best_filter_cmp_gain= (best_filter ?
                            best_filter->get_cmp_gain(record_count * records) :
                            0);
-    trace_access_scan.add("resulting_rows", rnd_records);
-    trace_access_scan.add("cost", tmp);
+    if (unlikely(trace_access_scan.trace_started()))
+      trace_access_scan.
+        add("resulting_rows", rnd_records).
+        add("cost", tmp);
 
     /* TODO: Document the following if */
     if (best_cost == DBL_MAX ||
@@ -8779,9 +8800,11 @@ best_access_path(JOIN      *join,
   }
   else
   {
-    trace_access_scan.add("type", "scan");
-    trace_access_scan.add("chosen", false);
-    trace_access_scan.add("cause", "cost");
+    if (unlikely(trace_access_scan.trace_started()))
+      trace_access_scan.
+        add("type", "scan").
+        add("chosen", false).
+        add("cause", "cost");
   }
 
   /* Update the cost information for the current partial plan */
@@ -10533,10 +10556,11 @@ best_extension_by_limited_search(JOIN      *join,
                                            current_record_count /
                                            TIME_FOR_COMPARE));
 
-      if (unlikely(thd->trace_started()))
+      if (unlikely(trace_one_table.trace_started()))
       {
-        trace_one_table.add("rows_for_plan", current_record_count);
-        trace_one_table.add("cost_for_plan", current_read_time);
+        trace_one_table.
+          add("rows_for_plan", current_record_count).
+          add("cost_for_plan", current_read_time);
       }
       optimize_semi_joins(join, remaining_tables, idx, &current_record_count,
                           &current_read_time, loose_scan_pos);
@@ -12442,8 +12466,10 @@ make_join_select(JOIN *join,SQL_SELECT *select,COND *cond)
           trace_const_cond.add("condition_on_constant_tables", const_cond);
           if (const_cond->is_expensive())
           {
-            trace_const_cond.add("evaluated", "false")
-                            .add("cause", "expensive cond");
+            if (unlikely(trace_const_cond.trace_started()))
+              trace_const_cond.
+                add("evalualted", "false").
+                add("cause", "expensive cond");
           }
           else
           {
@@ -12455,8 +12481,10 @@ make_join_select(JOIN *join,SQL_SELECT *select,COND *cond)
             if (!const_cond_result)
             {
               DBUG_PRINT("info",("Found impossible WHERE condition"));
-              trace_const_cond.add("evaluated", "true")
-                              .add("found", "impossible where");
+              if (unlikely(trace_const_cond.trace_started()))
+                trace_const_cond.
+                  add("evalualted", "true").
+                  add("found", "impossible where");
               join->exec_const_cond= NULL;
               DBUG_RETURN(1);
             }
@@ -12559,9 +12587,13 @@ make_join_select(JOIN *join,SQL_SELECT *select,COND *cond)
             tab->table->intersect_keys.is_set(tab->ref.key))))
       {
         /* Range uses longer key;  Use this instead of ref on key */
-        Json_writer_object ref_to_range(thd);
-        ref_to_range.add("ref_to_range", true);
-        ref_to_range.add("cause", "range uses longer key");
+        if (unlikely(thd->trace_started()))
+        {
+          Json_writer_object ref_to_range(thd);
+          ref_to_range.
+            add("ref_to_range", true).
+            add("cause", "range uses longer key");
+        }
         tab->type=JT_ALL;
         use_quick_range=1;
         tab->use_quick=1;
@@ -13072,8 +13104,9 @@ make_join_select(JOIN *join,SQL_SELECT *select,COND *cond)
           continue;
         Item *const cond = tab->select_cond;
         Json_writer_object trace_one_table(thd);
-        trace_one_table.add_table_name(tab);
-        trace_one_table.add("attached", cond);
+        trace_one_table.
+          add_table_name(tab).
+          add("attached", cond);
       }
     }
   }
@@ -18295,8 +18328,11 @@ optimize_cond(JOIN *join, COND *conds,
 
     Json_writer_object trace_wrapper(thd);
     Json_writer_object trace_cond(thd, "condition_processing");
-    trace_cond.add("condition", join->conds == conds ? "WHERE" : "HAVING")
-              .add("original_condition", conds);
+
+    if (unlikely(trace_cond.trace_started()))
+      trace_cond.
+        add("condition", join->conds == conds ? "WHERE" : "HAVING").
+        add("original_condition", conds);
 
     Json_writer_array trace_steps(thd, "steps");
     DBUG_EXECUTE("where", print_where(conds, "original", QT_ORDINARY););
@@ -18304,10 +18340,13 @@ optimize_cond(JOIN *join, COND *conds,
                              ignore_on_conds, cond_equal,
                              MY_TEST(flags & OPT_LINK_EQUAL_FIELDS));
     DBUG_EXECUTE("where",print_where(conds,"after equal_items", QT_ORDINARY););
+
+    if (unlikely(thd->trace_started()))
     {
       Json_writer_object equal_prop_wrapper(thd);
-      equal_prop_wrapper.add("transformation", "equality_propagation")
-                        .add("resulting_condition", conds);
+      equal_prop_wrapper.
+        add("transformation", "equality_propagation").
+        add("resulting_condition", conds);
     }
 
     /* change field = field to field = const for each found field = const */
@@ -18317,20 +18356,24 @@ optimize_cond(JOIN *join, COND *conds,
       Remove all and-levels where CONST item != CONST item
     */
     DBUG_EXECUTE("where",print_where(conds,"after const change", QT_ORDINARY););
+    if (unlikely(thd->trace_started()))
     {
       Json_writer_object const_prop_wrapper(thd);
-      const_prop_wrapper.add("transformation", "constant_propagation")
-                        .add("resulting_condition", conds);
+      const_prop_wrapper.
+        add("transformation", "constant_propagation").
+        add("resulting_condition", conds);
     }
     conds= conds->remove_eq_conds(thd, cond_value, true);
     if (conds && conds->type() == Item::COND_ITEM &&
         ((Item_cond*) conds)->functype() == Item_func::COND_AND_FUNC)
       *cond_equal= &((Item_cond_and*) conds)->m_cond_equal;
 
+    if (unlikely(thd->trace_started()))
     {
       Json_writer_object cond_removal_wrapper(thd);
-      cond_removal_wrapper.add("transformation", "trivial_condition_removal")
-                          .add("resulting_condition", conds);
+      cond_removal_wrapper.
+        add("transformation", "trivial_condition_removal").
+        add("resulting_condition", conds);
     }
     DBUG_EXECUTE("info",print_where(conds,"after remove", QT_ORDINARY););
   }
@@ -30008,15 +30051,19 @@ test_if_cheaper_ordering(const JOIN_TAB *tab, ORDER *order, TABLE *table,
                                         HA_POS_ERROR;
           if (is_best_covering && !is_covering)
           {
-            possible_key.add("chosen", false);
-            possible_key.add("cause", "covering index already found");
+            if (unlikely(possible_key.trace_started()))
+              possible_key.
+                add("chosen", false).
+                add("cause", "covering index already found");
             continue;
           }
 
           if (is_covering && refkey_select_limit < select_limit)
           {
-            possible_key.add("chosen", false);
-            possible_key.add("cause", "ref estimates better");
+            if (unlikely(possible_key.trace_started()))
+              possible_key.
+                add("chosen", false).
+                add("cause", "ref estimates better");
             continue;
           }
           if (table->opt_range_keys.is_set(nr))
@@ -30056,8 +30103,9 @@ test_if_cheaper_ordering(const JOIN_TAB *tab, ORDER *order, TABLE *table,
         }
         else
         {
-          possible_key.add("usable", false);
-          possible_key.add("cause", "cost");
+          possible_key.
+            add("usable", false).
+            add("cause", "cost");
         }
       }
       else
@@ -30071,13 +30119,15 @@ test_if_cheaper_ordering(const JOIN_TAB *tab, ORDER *order, TABLE *table,
     {
       if (keys.is_set(nr))
       {
-        possible_key.add("can_resolve_order", false);
-        possible_key.add("cause", "order can not be resolved by key");
+        possible_key.
+          add("can_resolve_order", false).
+          add("cause", "order can not be resolved by key");
       }
       else
       {
-        possible_key.add("can_resolve_order", false);
-        possible_key.add("cause", "not usable index for the query");
+        possible_key.
+          add("can_resolve_order", false).
+          add("cause", "not usable index for the query");
       }
     }
   }
diff --git a/sql/sql_test.cc b/sql/sql_test.cc
index b85b37b1726..f50452a9d6c 100644
--- a/sql/sql_test.cc
+++ b/sql/sql_test.cc
@@ -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);
   }
 }
diff --git a/sql/sql_tvc.cc b/sql/sql_tvc.cc
index d80342a8395..176a1610a15 100644
--- a/sql/sql_tvc.cc
+++ b/sql/sql_tvc.cc
@@ -954,8 +954,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;
   }
 
@@ -963,15 +965,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;
     }
   }