Add more execution stages (commit, rollback, etc)

This was done to get more information about where time is spent.
Now we can get proper timing for time spent in commit, rollback,
binlog write etc.

Following stages was added:
- Commit
- Commit_implicit
- Rollback
- Rollback implicit
- Binlog write
- Init for update
  - This is used instead of "Init" for insert, update and delete.
- Staring cleanup

Following stages where changed:
- "Unlocking tables" stage reset stage to previous stage at end
- "binlog write" stage resets stage to previous stage at end
- "end" -> "end of update loop"
- "cleaning up" -> "Reset for next command"
- Added stage_searching_rows_for_update when searching for rows
  to be deleted.

Other things:
- Renamed all stages to start with big letter (before there was no
  consitency)
- Increased performance_schema_max_stage_classes from 150 to 160.
- Most of the test changes in performance schema comes from renaming of
  stages.
- Removed duplicate output of variables and inital state in a lot of
  performance schema tests.
  This was done to make it easier to change a default value for a
  performance variable without affecting all tests.
- Added start_server_variables.test to check configuration
- Removed some duplicate "closing tables" stages
- Updated position for "stage_init_update" and "stage_updating" for
  delete, insert and update to be just before update loop (for more
  exact timing).
- Don't set "Checking permissions" twice in a row.
- Remove stage_end stage from creating views (not done for create table
  either).
- Updated default performance history size from 10 to 20 because of new
  stages
- Ensure that ps_enabled is correct (to be used in a later patch)

17 files changed, 134 insertions, 92 deletions

diff --git a/sql/lock.cc b/sql/lock.cc
index 83a0896808f..c6dd3724eba 100644
--- a/sql/lock.cc
+++ b/sql/lock.cc
@@ -421,8 +421,11 @@ void mysql_unlock_tables(THD *thd, MYSQL_LOCK *sql_lock)
 
 void mysql_unlock_tables(THD *thd, MYSQL_LOCK *sql_lock, bool free_lock)
 {
-  DBUG_ENTER("mysql_unlock_tables");
   bool errors= thd->is_error();
+  PSI_stage_info org_stage;
+  DBUG_ENTER("mysql_unlock_tables");
+
+  thd->backup_stage(&org_stage);
   THD_STAGE_INFO(thd, stage_unlocking_tables);
 
   if (sql_lock->table_count)
@@ -433,6 +436,7 @@ void mysql_unlock_tables(THD *thd, MYSQL_LOCK *sql_lock, bool free_lock)
     my_free(sql_lock);
   if (!errors)
     thd->clear_error();
+  THD_STAGE_INFO(thd, org_stage);
   DBUG_VOID_RETURN;
 }
 
diff --git a/sql/log.cc b/sql/log.cc
index 02d83a89bef..540b7a256ce 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -2002,7 +2002,9 @@ static bool trans_cannot_safely_rollback(THD *thd, bool all)
 static int binlog_commit(handlerton *hton, THD *thd, bool all)
 {
   int error= 0;
+  PSI_stage_info org_stage;
   DBUG_ENTER("binlog_commit");
+
   binlog_cache_mngr *const cache_mngr=
     (binlog_cache_mngr*) thd_get_ha_data(thd, binlog_hton);
 
@@ -2019,6 +2021,9 @@ static int binlog_commit(handlerton *hton, THD *thd, bool all)
               YESNO(thd->transaction.all.modified_non_trans_table),
               YESNO(thd->transaction.stmt.modified_non_trans_table)));
 
+
+  thd->backup_stage(&org_stage);
+  THD_STAGE_INFO(thd, stage_binlog_write);
   if (!cache_mngr->stmt_cache.empty())
   {
     error= binlog_commit_flush_stmt_cache(thd, all, cache_mngr);
@@ -2030,6 +2035,7 @@ static int binlog_commit(handlerton *hton, THD *thd, bool all)
       we're here because cache_log was flushed in MYSQL_BIN_LOG::log_xid()
     */
     cache_mngr->reset(false, true);
+    THD_STAGE_INFO(thd, org_stage);
     DBUG_RETURN(error);
   }
 
@@ -2048,6 +2054,7 @@ static int binlog_commit(handlerton *hton, THD *thd, bool all)
   if (!all)
     cache_mngr->trx_cache.set_prev_position(MY_OFF_T_UNDEF);
 
+  THD_STAGE_INFO(thd, org_stage);
   DBUG_RETURN(error);
 }
 
diff --git a/sql/mysqld.cc b/sql/mysqld.cc
index cc94a7e7c79..c91529efb92 100644
--- a/sql/mysqld.cc
+++ b/sql/mysqld.cc
@@ -10100,104 +10100,110 @@ static PSI_file_info all_server_files[]=
 };
 #endif /* HAVE_PSI_INTERFACE */
 
-PSI_stage_info stage_after_apply_event= { 0, "after apply log event", 0};
+PSI_stage_info stage_after_apply_event= { 0, "After apply log event", 0};
 PSI_stage_info stage_after_create= { 0, "After create", 0};
 PSI_stage_info stage_after_opening_tables= { 0, "After opening tables", 0};
 PSI_stage_info stage_after_table_lock= { 0, "After table lock", 0};
-PSI_stage_info stage_allocating_local_table= { 0, "allocating local table", 0};
-PSI_stage_info stage_alter_inplace_prepare= { 0, "preparing for alter table", 0};
-PSI_stage_info stage_alter_inplace= { 0, "altering table", 0};
-PSI_stage_info stage_alter_inplace_commit= { 0, "committing alter table to storage engine", 0};
-PSI_stage_info stage_apply_event= { 0, "apply log event", 0};
+PSI_stage_info stage_allocating_local_table= { 0, "Allocating local table", 0};
+PSI_stage_info stage_alter_inplace_prepare= { 0, "Preparing for alter table", 0};
+PSI_stage_info stage_alter_inplace= { 0, "Altering table", 0};
+PSI_stage_info stage_alter_inplace_commit= { 0, "Committing alter table to storage engine", 0};
+PSI_stage_info stage_apply_event= { 0, "Apply log event", 0};
 PSI_stage_info stage_changing_master= { 0, "Changing master", 0};
 PSI_stage_info stage_checking_master_version= { 0, "Checking master version", 0};
-PSI_stage_info stage_checking_permissions= { 0, "checking permissions", 0};
-PSI_stage_info stage_checking_privileges_on_cached_query= { 0, "checking privileges on cached query", 0};
-PSI_stage_info stage_checking_query_cache_for_query= { 0, "checking query cache for query", 0};
-PSI_stage_info stage_cleaning_up= { 0, "cleaning up", 0};
-PSI_stage_info stage_closing_tables= { 0, "closing tables", 0};
+PSI_stage_info stage_checking_permissions= { 0, "Checking permissions", 0};
+PSI_stage_info stage_checking_privileges_on_cached_query= { 0, "Checking privileges on cached query", 0};
+PSI_stage_info stage_checking_query_cache_for_query= { 0, "Checking query cache for query", 0};
+PSI_stage_info stage_cleaning_up= { 0, "Reset for next command", 0};
+PSI_stage_info stage_closing_tables= { 0, "Closing tables", 0};
 PSI_stage_info stage_connecting_to_master= { 0, "Connecting to master", 0};
-PSI_stage_info stage_converting_heap_to_myisam= { 0, "converting HEAP to " TMP_ENGINE_NAME, 0};
+PSI_stage_info stage_converting_heap_to_myisam= { 0, "Converting HEAP to " TMP_ENGINE_NAME, 0};
 PSI_stage_info stage_copying_to_group_table= { 0, "Copying to group table", 0};
 PSI_stage_info stage_copying_to_tmp_table= { 0, "Copying to tmp table", 0};
-PSI_stage_info stage_copy_to_tmp_table= { 0, "copy to tmp table", 0};
+PSI_stage_info stage_copy_to_tmp_table= { 0, "Copy to tmp table", 0};
 PSI_stage_info stage_creating_delayed_handler= { 0, "Creating delayed handler", 0};
 PSI_stage_info stage_creating_sort_index= { 0, "Creating sort index", 0};
-PSI_stage_info stage_creating_table= { 0, "creating table", 0};
+PSI_stage_info stage_creating_table= { 0, "Creating table", 0};
 PSI_stage_info stage_creating_tmp_table= { 0, "Creating tmp table", 0};
-PSI_stage_info stage_deleting_from_main_table= { 0, "deleting from main table", 0};
-PSI_stage_info stage_deleting_from_reference_tables= { 0, "deleting from reference tables", 0};
-PSI_stage_info stage_discard_or_import_tablespace= { 0, "discard_or_import_tablespace", 0};
-PSI_stage_info stage_enabling_keys= { 0, "enabling keys", 0};
-PSI_stage_info stage_end= { 0, "end", 0};
-PSI_stage_info stage_executing= { 0, "executing", 0};
+PSI_stage_info stage_deleting_from_main_table= { 0, "Deleting from main table", 0};
+PSI_stage_info stage_deleting_from_reference_tables= { 0, "Deleting from reference tables", 0};
+PSI_stage_info stage_discard_or_import_tablespace= { 0, "Discard_or_import_tablespace", 0};
+PSI_stage_info stage_enabling_keys= { 0, "Enabling keys", 0};
+PSI_stage_info stage_end= { 0, "End of update loop", 0};
+PSI_stage_info stage_executing= { 0, "Executing", 0};
 PSI_stage_info stage_execution_of_init_command= { 0, "Execution of init_command", 0};
-PSI_stage_info stage_explaining= { 0, "explaining", 0};
+PSI_stage_info stage_explaining= { 0, "Explaining", 0};
 PSI_stage_info stage_finding_key_cache= { 0, "Finding key cache", 0};
 PSI_stage_info stage_finished_reading_one_binlog_switching_to_next_binlog= { 0, "Finished reading one binlog; switching to next binlog", 0};
 PSI_stage_info stage_flushing_relay_log_and_master_info_repository= { 0, "Flushing relay log and master info repository.", 0};
 PSI_stage_info stage_flushing_relay_log_info_file= { 0, "Flushing relay-log info file.", 0};
-PSI_stage_info stage_freeing_items= { 0, "freeing items", 0};
-PSI_stage_info stage_fulltext_initialization= { 0, "FULLTEXT initialization", 0};
-PSI_stage_info stage_got_handler_lock= { 0, "got handler lock", 0};
-PSI_stage_info stage_got_old_table= { 0, "got old table", 0};
-PSI_stage_info stage_init= { 0, "init", 0};
-PSI_stage_info stage_insert= { 0, "insert", 0};
-PSI_stage_info stage_invalidating_query_cache_entries_table= { 0, "invalidating query cache entries (table)", 0};
-PSI_stage_info stage_invalidating_query_cache_entries_table_list= { 0, "invalidating query cache entries (table list)", 0};
+PSI_stage_info stage_freeing_items= { 0, "Freeing items", 0};
+PSI_stage_info stage_fulltext_initialization= { 0, "Fulltext initialization", 0};
+PSI_stage_info stage_got_handler_lock= { 0, "Got handler lock", 0};
+PSI_stage_info stage_got_old_table= { 0, "Got old table", 0};
+PSI_stage_info stage_init= { 0, "Init", 0};
+PSI_stage_info stage_init_update= { 0, "Init for update", 0};
+PSI_stage_info stage_insert= { 0, "Insert", 0};
+PSI_stage_info stage_invalidating_query_cache_entries_table= { 0, "Invalidating query cache entries (table)", 0};
+PSI_stage_info stage_invalidating_query_cache_entries_table_list= { 0, "Invalidating query cache entries (table list)", 0};
 PSI_stage_info stage_killing_slave= { 0, "Killing slave", 0};
-PSI_stage_info stage_logging_slow_query= { 0, "logging slow query", 0};
+PSI_stage_info stage_logging_slow_query= { 0, "Logging slow query", 0};
 PSI_stage_info stage_making_temp_file_append_before_load_data= { 0, "Making temporary file (append) before replaying LOAD DATA INFILE.", 0};
 PSI_stage_info stage_making_temp_file_create_before_load_data= { 0, "Making temporary file (create) before replaying LOAD DATA INFILE.", 0};
-PSI_stage_info stage_manage_keys= { 0, "manage keys", 0};
+PSI_stage_info stage_manage_keys= { 0, "Manage keys", 0};
 PSI_stage_info stage_master_has_sent_all_binlog_to_slave= { 0, "Master has sent all binlog to slave; waiting for binlog to be updated", 0};
 PSI_stage_info stage_opening_tables= { 0, "Opening tables", 0};
-PSI_stage_info stage_optimizing= { 0, "optimizing", 0};
-PSI_stage_info stage_preparing= { 0, "preparing", 0};
+PSI_stage_info stage_optimizing= { 0, "Optimizing", 0};
+PSI_stage_info stage_preparing= { 0, "Preparing", 0};
 PSI_stage_info stage_purging_old_relay_logs= { 0, "Purging old relay logs", 0};
-PSI_stage_info stage_query_end= { 0, "query end", 0};
+PSI_stage_info stage_query_end= { 0, "Query end", 0};
+PSI_stage_info stage_starting_cleanup= { 0, "Starting cleanup", 0};
+PSI_stage_info stage_rollback= { 0, "Rollback", 0};
+PSI_stage_info stage_rollback_implicit= { 0, "Rollback_implicit", 0};
+PSI_stage_info stage_commit= { 0, "Commit", 0};
+PSI_stage_info stage_commit_implicit= { 0, "Commit_implicit", 0};
 PSI_stage_info stage_queueing_master_event_to_the_relay_log= { 0, "Queueing master event to the relay log", 0};
 PSI_stage_info stage_reading_event_from_the_relay_log= { 0, "Reading event from the relay log", 0};
-PSI_stage_info stage_recreating_table= { 0, "recreating table", 0};
+PSI_stage_info stage_recreating_table= { 0, "Recreating table", 0};
 PSI_stage_info stage_registering_slave_on_master= { 0, "Registering slave on master", 0};
 PSI_stage_info stage_removing_duplicates= { 0, "Removing duplicates", 0};
-PSI_stage_info stage_removing_tmp_table= { 0, "removing tmp table", 0};
-PSI_stage_info stage_rename= { 0, "rename", 0};
-PSI_stage_info stage_rename_result_table= { 0, "rename result table", 0};
+PSI_stage_info stage_removing_tmp_table= { 0, "Removing tmp table", 0};
+PSI_stage_info stage_rename= { 0, "Rename", 0};
+PSI_stage_info stage_rename_result_table= { 0, "Rename result table", 0};
 PSI_stage_info stage_requesting_binlog_dump= { 0, "Requesting binlog dump", 0};
-PSI_stage_info stage_reschedule= { 0, "reschedule", 0};
+PSI_stage_info stage_reschedule= { 0, "Reschedule", 0};
 PSI_stage_info stage_searching_rows_for_update= { 0, "Searching rows for update", 0};
 PSI_stage_info stage_sending_binlog_event_to_slave= { 0, "Sending binlog event to slave", 0};
-PSI_stage_info stage_sending_cached_result_to_client= { 0, "sending cached result to client", 0};
+PSI_stage_info stage_sending_cached_result_to_client= { 0, "Sending cached result to client", 0};
 PSI_stage_info stage_sending_data= { 0, "Sending data", 0};
-PSI_stage_info stage_setup= { 0, "setup", 0};
-PSI_stage_info stage_show_explain= { 0, "show explain", 0};
+PSI_stage_info stage_setup= { 0, "Setup", 0};
+PSI_stage_info stage_show_explain= { 0, "Show explain", 0};
 PSI_stage_info stage_slave_has_read_all_relay_log= { 0, "Slave has read all relay log; waiting for the slave I/O thread to update it", 0};
 PSI_stage_info stage_sorting= { 0, "Sorting", 0};
 PSI_stage_info stage_sorting_for_group= { 0, "Sorting for group", 0};
 PSI_stage_info stage_sorting_for_order= { 0, "Sorting for order", 0};
 PSI_stage_info stage_sorting_result= { 0, "Sorting result", 0};
-PSI_stage_info stage_statistics= { 0, "statistics", 0};
+PSI_stage_info stage_statistics= { 0, "Statistics", 0};
 PSI_stage_info stage_sql_thd_waiting_until_delay= { 0, "Waiting until MASTER_DELAY seconds after master executed event", 0 };
-PSI_stage_info stage_storing_result_in_query_cache= { 0, "storing result in query cache", 0};
-PSI_stage_info stage_storing_row_into_queue= { 0, "storing row into queue", 0};
+PSI_stage_info stage_storing_result_in_query_cache= { 0, "Storing result in query cache", 0};
+PSI_stage_info stage_storing_row_into_queue= { 0, "Storing row into queue", 0};
 PSI_stage_info stage_system_lock= { 0, "System lock", 0};
 PSI_stage_info stage_unlocking_tables= { 0, "Unlocking tables", 0};
 PSI_stage_info stage_table_lock= { 0, "Table lock", 0};
 PSI_stage_info stage_filling_schema_table= { 0, "Filling schema table", 0};
-PSI_stage_info stage_update= { 0, "update", 0};
-PSI_stage_info stage_updating= { 0, "updating", 0};
-PSI_stage_info stage_updating_main_table= { 0, "updating main table", 0};
-PSI_stage_info stage_updating_reference_tables= { 0, "updating reference tables", 0};
-PSI_stage_info stage_upgrading_lock= { 0, "upgrading lock", 0};
+PSI_stage_info stage_update= { 0, "Update", 0};
+PSI_stage_info stage_updating= { 0, "Updating", 0};
+PSI_stage_info stage_updating_main_table= { 0, "Updating main table", 0};
+PSI_stage_info stage_updating_reference_tables= { 0, "Updating reference tables", 0};
+PSI_stage_info stage_upgrading_lock= { 0, "Upgrading lock", 0};
 PSI_stage_info stage_user_lock= { 0, "User lock", 0};
 PSI_stage_info stage_user_sleep= { 0, "User sleep", 0};
-PSI_stage_info stage_verifying_table= { 0, "verifying table", 0};
-PSI_stage_info stage_waiting_for_delay_list= { 0, "waiting for delay_list", 0};
-PSI_stage_info stage_waiting_for_gtid_to_be_written_to_binary_log= { 0, "waiting for GTID to be written to binary log", 0};
-PSI_stage_info stage_waiting_for_handler_insert= { 0, "waiting for handler insert", 0};
-PSI_stage_info stage_waiting_for_handler_lock= { 0, "waiting for handler lock", 0};
-PSI_stage_info stage_waiting_for_handler_open= { 0, "waiting for handler open", 0};
+PSI_stage_info stage_verifying_table= { 0, "Verifying table", 0};
+PSI_stage_info stage_waiting_for_delay_list= { 0, "Waiting for delay_list", 0};
+PSI_stage_info stage_waiting_for_gtid_to_be_written_to_binary_log= { 0, "Waiting for GTID to be written to binary log", 0};
+PSI_stage_info stage_waiting_for_handler_insert= { 0, "Waiting for handler insert", 0};
+PSI_stage_info stage_waiting_for_handler_lock= { 0, "Waiting for handler lock", 0};
+PSI_stage_info stage_waiting_for_handler_open= { 0, "Waiting for handler open", 0};
 PSI_stage_info stage_waiting_for_insert= { 0, "Waiting for INSERT", 0};
 PSI_stage_info stage_waiting_for_master_to_send_event= { 0, "Waiting for master to send event", 0};
 PSI_stage_info stage_waiting_for_master_update= { 0, "Waiting for master update", 0};
@@ -10211,6 +10217,7 @@ PSI_stage_info stage_waiting_for_the_slave_thread_to_advance_position= { 0, "Wai
 PSI_stage_info stage_waiting_to_finalize_termination= { 0, "Waiting to finalize termination", 0};
 PSI_stage_info stage_waiting_to_get_readlock= { 0, "Waiting to get readlock", 0};
 PSI_stage_info stage_binlog_waiting_background_tasks= { 0, "Waiting for background binlog tasks", 0};
+PSI_stage_info stage_binlog_write= { 0, "Writing to binlog", 0};
 PSI_stage_info stage_binlog_processing_checkpoint_notify= { 0, "Processing binlog checkpoint notification", 0};
 PSI_stage_info stage_binlog_stopping_background_thread= { 0, "Stopping binlog background thread", 0};
 PSI_stage_info stage_waiting_for_work_from_sql_thread= { 0, "Waiting for work from SQL thread", 0};
@@ -10241,6 +10248,7 @@ PSI_stage_info *all_server_stages[]=
   & stage_alter_inplace_commit,
   & stage_alter_inplace_prepare,
   & stage_apply_event,
+  & stage_binlog_write,
   & stage_binlog_processing_checkpoint_notify,
   & stage_binlog_stopping_background_thread,
   & stage_binlog_waiting_background_tasks,
@@ -10251,6 +10259,8 @@ PSI_stage_info *all_server_stages[]=
   & stage_checking_query_cache_for_query,
   & stage_cleaning_up,
   & stage_closing_tables,
+  & stage_commit,
+  & stage_commit_implicit,
   & stage_connecting_to_master,
   & stage_converting_heap_to_myisam,
   & stage_copy_to_tmp_table,
@@ -10277,6 +10287,7 @@ PSI_stage_info *all_server_stages[]=
   & stage_got_handler_lock,
   & stage_got_old_table,
   & stage_init,
+  & stage_init_update,
   & stage_insert,
   & stage_invalidating_query_cache_entries_table,
   & stage_invalidating_query_cache_entries_table_list,
@@ -10290,6 +10301,7 @@ PSI_stage_info *all_server_stages[]=
   & stage_optimizing,
   & stage_preparing,
   & stage_purging_old_relay_logs,
+  & stage_starting_cleanup,
   & stage_query_end,
   & stage_queueing_master_event_to_the_relay_log,
   & stage_reading_event_from_the_relay_log,
@@ -10301,6 +10313,8 @@ PSI_stage_info *all_server_stages[]=
   & stage_rename_result_table,
   & stage_requesting_binlog_dump,
   & stage_reschedule,
+  & stage_rollback,
+  & stage_rollback_implicit,
   & stage_searching_rows_for_update,
   & stage_sending_binlog_event_to_slave,
   & stage_sending_cached_result_to_client,
diff --git a/sql/mysqld.h b/sql/mysqld.h
index aa08f77d468..ed6685828ba 100644
--- a/sql/mysqld.h
+++ b/sql/mysqld.h
@@ -411,6 +411,7 @@ extern PSI_stage_info stage_fulltext_initialization;
 extern PSI_stage_info stage_got_handler_lock;
 extern PSI_stage_info stage_got_old_table;
 extern PSI_stage_info stage_init;
+extern PSI_stage_info stage_init_update;
 extern PSI_stage_info stage_insert;
 extern PSI_stage_info stage_invalidating_query_cache_entries_table;
 extern PSI_stage_info stage_invalidating_query_cache_entries_table_list;
@@ -425,6 +426,11 @@ extern PSI_stage_info stage_optimizing;
 extern PSI_stage_info stage_preparing;
 extern PSI_stage_info stage_purging_old_relay_logs;
 extern PSI_stage_info stage_query_end;
+extern PSI_stage_info stage_starting_cleanup;
+extern PSI_stage_info stage_rollback;
+extern PSI_stage_info stage_rollback_implicit;
+extern PSI_stage_info stage_commit;
+extern PSI_stage_info stage_commit_implicit;
 extern PSI_stage_info stage_queueing_master_event_to_the_relay_log;
 extern PSI_stage_info stage_reading_event_from_the_relay_log;
 extern PSI_stage_info stage_recreating_table;
@@ -480,6 +486,7 @@ extern PSI_stage_info stage_waiting_for_the_slave_thread_to_advance_position;
 extern PSI_stage_info stage_waiting_to_finalize_termination;
 extern PSI_stage_info stage_waiting_to_get_readlock;
 extern PSI_stage_info stage_binlog_waiting_background_tasks;
+extern PSI_stage_info stage_binlog_write;
 extern PSI_stage_info stage_binlog_processing_checkpoint_notify;
 extern PSI_stage_info stage_binlog_stopping_background_thread;
 extern PSI_stage_info stage_waiting_for_work_from_sql_thread;
diff --git a/sql/sp_head.cc b/sql/sp_head.cc
index 73ce5403f38..0649ea2a4a3 100644
--- a/sql/sp_head.cc
+++ b/sql/sp_head.cc
@@ -2002,7 +2002,6 @@ sp_head::execute_procedure(THD *thd, List<Item> *args)
       thd->get_stmt_da()->set_overwrite_status(false);
     }
 
-    thd_proc_info(thd, "closing tables");
     close_thread_tables(thd);
     thd_proc_info(thd, 0);
 
@@ -3107,7 +3106,6 @@ sp_lex_keeper::reset_lex_and_exec_core(THD *thd, uint *nextp,
       thd->is_error() ? trans_rollback_stmt(thd) : trans_commit_stmt(thd);
       thd->get_stmt_da()->set_overwrite_status(false);
     }
-    thd_proc_info(thd, "closing tables");
     close_thread_tables(thd);
     thd_proc_info(thd, 0);
 
diff --git a/sql/sql_delete.cc b/sql/sql_delete.cc
index 9b1f755a02c..e7a0168fb48 100644
--- a/sql/sql_delete.cc
+++ b/sql/sql_delete.cc
@@ -273,6 +273,7 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
   if (open_and_lock_tables(thd, table_list, TRUE, 0))
     DBUG_RETURN(TRUE);
 
+  THD_STAGE_INFO(thd, stage_init_update);
   if (mysql_handle_list_of_derived(thd->lex, table_list, DT_MERGE_FOR_INSERT))
     DBUG_RETURN(TRUE);
   if (mysql_handle_list_of_derived(thd->lex, table_list, DT_PREPARE))
@@ -289,7 +290,6 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
 	       table_list->view_db.str, table_list->view_name.str);
     DBUG_RETURN(TRUE);
   }
-  THD_STAGE_INFO(thd, stage_init);
   table->map=1;
   query_plan.select_lex= &thd->lex->select_lex;
   query_plan.table= table;
@@ -556,7 +556,6 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
     goto got_error;
   
   init_ftfuncs(thd, select_lex, 1);
-  THD_STAGE_INFO(thd, stage_updating);
 
   if (table->prepare_triggers_for_delete_stmt_or_event())
   {
@@ -588,6 +587,8 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
     deltempfile= new (thd->mem_root) Unique (refpos_order_cmp, table->file,
                                              table->file->ref_length,
                                              MEM_STRIP_BUF_SIZE);
+
+    THD_STAGE_INFO(thd, stage_searching_rows_for_update);
     while (!(error=info.read_record(&info)) && !thd->killed &&
           ! thd->is_error())
     {
@@ -613,6 +614,7 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
     delete_record= true;
   }
 
+  THD_STAGE_INFO(thd, stage_updating);
   while (!(error=info.read_record(&info)) && !thd->killed &&
         ! thd->is_error())
   {
diff --git a/sql/sql_insert.cc b/sql/sql_insert.cc
index 98e0da1ddbe..698ff8246ed 100644
--- a/sql/sql_insert.cc
+++ b/sql/sql_insert.cc
@@ -761,9 +761,8 @@ bool mysql_insert(THD *thd,TABLE_LIST *table_list,
       DBUG_RETURN(TRUE);
   }
 
+  THD_STAGE_INFO(thd, stage_init_update);
   lock_type= table_list->lock_type;
-
-  THD_STAGE_INFO(thd, stage_init);
   thd->lex->used_tables=0;
   values= its++;
   if (bulk_parameters_set(thd))
@@ -860,7 +859,6 @@ bool mysql_insert(THD *thd,TABLE_LIST *table_list,
 #endif
 
   error=0;
-  THD_STAGE_INFO(thd, stage_update);
   if (duplic == DUP_REPLACE &&
       (!table->triggers || !table->triggers->has_delete_triggers()))
     table->file->extra(HA_EXTRA_WRITE_CAN_REPLACE);
@@ -940,6 +938,8 @@ bool mysql_insert(THD *thd,TABLE_LIST *table_list,
       goto values_loop_end;
     }
   }
+
+  THD_STAGE_INFO(thd, stage_update);
   do
   {
     DBUG_PRINT("info", ("iteration %llu", iteration));
@@ -3357,7 +3357,7 @@ bool Delayed_insert::handle_inserts(void)
   }
 
   if (WSREP((&thd)))
-    thd_proc_info(&thd, "insert done");
+    thd_proc_info(&thd, "Insert done");
   else
     thd_proc_info(&thd, 0);
   mysql_mutex_unlock(&mutex);
diff --git a/sql/sql_load.cc b/sql/sql_load.cc
index 5e11794f139..6e3396f0fcf 100644
--- a/sql/sql_load.cc
+++ b/sql/sql_load.cc
@@ -348,7 +348,7 @@ int mysql_load(THD *thd,sql_exchange *ex,TABLE_LIST *table_list,
   {
     DBUG_RETURN(TRUE);
   }
-  thd_proc_info(thd, "executing");
+  thd_proc_info(thd, "Executing");
   /*
     Let us emit an error if we are loading data to table which is used
     in subselect in SET clause like we do it for INSERT.
@@ -574,7 +574,7 @@ int mysql_load(THD *thd,sql_exchange *ex,TABLE_LIST *table_list,
     }
   }
 
-  thd_proc_info(thd, "reading file");
+  thd_proc_info(thd, "Reading file");
   if (!(error= MY_TEST(read_info.error)))
   {
     table->reset_default_fields();
diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc
index 738d59fd401..0132921ad1c 100644
--- a/sql/sql_parse.cc
+++ b/sql/sql_parse.cc
@@ -2370,7 +2370,7 @@ com_multi_end:
                (thd->open_tables == NULL ||
                (thd->locked_tables_mode == LTM_LOCK_TABLES)));
 
-    thd_proc_info(thd, "updating status");
+    thd_proc_info(thd, "Updating status");
     /* Finalize server status flags after executing a command. */
     thd->update_server_status();
     if (command != COM_MULTI)
@@ -6245,10 +6245,14 @@ finish:
       thd->reset_kill_query();
     }
     if (thd->is_error() || (thd->variables.option_bits & OPTION_MASTER_SQL_ERROR))
+    {
+      THD_STAGE_INFO(thd, stage_rollback);
       trans_rollback_stmt(thd);
+    }
     else
     {
       /* If commit fails, we should be able to reset the OK status. */
+      THD_STAGE_INFO(thd, stage_commit);
       thd->get_stmt_da()->set_overwrite_status(true);
       trans_commit_stmt(thd);
       thd->get_stmt_da()->set_overwrite_status(false);
@@ -6258,12 +6262,13 @@ finish:
 #endif
   }
 
-  /* Free tables */
+  /* Free tables. Set stage 'closing tables' */
   close_thread_tables(thd);
 #ifdef WITH_WSREP
   thd->wsrep_consistency_check= NO_CONSISTENCY_CHECK;
 #endif /* WITH_WSREP */
 
+
 #ifndef DBUG_OFF
   if (lex->sql_command != SQLCOM_SET_OPTION && ! thd->in_sub_stmt)
     DEBUG_SYNC(thd, "execute_command_after_close_tables");
@@ -6281,6 +6286,7 @@ finish:
       one of storage engines (e.g. due to deadlock). Rollback transaction in
       all storage engines including binary log.
     */
+    THD_STAGE_INFO(thd, stage_rollback_implicit);
     trans_rollback_implicit(thd);
     thd->mdl_context.release_transactional_locks();
   }
@@ -6290,6 +6296,7 @@ finish:
     DBUG_ASSERT(! thd->in_sub_stmt);
     if (!(thd->variables.option_bits & OPTION_GTID_BEGIN))
     {
+      THD_STAGE_INFO(thd, stage_commit_implicit);
       /* If commit fails, we should be able to reset the OK status. */
       thd->get_stmt_da()->set_overwrite_status(true);
       /* Commit the normal transaction if one is active. */
@@ -6317,6 +6324,8 @@ finish:
     thd->mdl_context.release_statement_locks();
   }
 
+  THD_STAGE_INFO(thd, stage_starting_cleanup);
+
   TRANSACT_TRACKER(add_trx_state_from_thd(thd));
 
   WSREP_TO_ISOLATION_END;
@@ -6585,7 +6594,9 @@ check_access(THD *thd, ulong want_access, const char *db, ulong *save_priv,
     dummy= 0;
   }
 
-  THD_STAGE_INFO(thd, stage_checking_permissions);
+  /* check access may be called twice in a row. Don't change to same stage */
+  if (thd->proc_info != stage_checking_permissions.m_name)
+    THD_STAGE_INFO(thd, stage_checking_permissions);
   if ((!db || !db[0]) && !thd->db && !dont_check_global_grants)
   {
     DBUG_PRINT("error",("No database"));
diff --git a/sql/sql_partition_admin.cc b/sql/sql_partition_admin.cc
index 61b026e5450..44dbd608875 100644
--- a/sql/sql_partition_admin.cc
+++ b/sql/sql_partition_admin.cc
@@ -595,7 +595,7 @@ bool Sql_cmd_alter_table_exchange_partition::
 
   /* Table and partition has same structure/options, OK to exchange */
 
-  thd_proc_info(thd, "verifying data with partition");
+  thd_proc_info(thd, "Verifying data with partition");
 
   if (verify_data_with_partition(swap_table, part_table, swap_part_id))
     DBUG_RETURN(TRUE);
diff --git a/sql/sql_profile.h b/sql/sql_profile.h
index 38682f3ddec..c96828fc678 100644
--- a/sql/sql_profile.h
+++ b/sql/sql_profile.h
@@ -287,7 +287,7 @@ public:
 
     @param  initial_state  (optional) name of period before first state change
   */
-  void start_new_query(const char *initial_state= "starting")
+  void start_new_query(const char *initial_state= "Starting")
   {
     DBUG_ASSERT(!current);
     if (unlikely(enabled))
diff --git a/sql/sql_table.cc b/sql/sql_table.cc
index c9057849ed5..a10c9fc1b1b 100644
--- a/sql/sql_table.cc
+++ b/sql/sql_table.cc
@@ -8591,7 +8591,7 @@ bool mysql_alter_table(THD *thd, const char *new_db, const char *new_name,
 #endif
   }
 
-  THD_STAGE_INFO(thd, stage_init);
+  THD_STAGE_INFO(thd, stage_init_update);
 
   /*
     Code below can handle only base tables so ensure that we won't open a view.
diff --git a/sql/sql_update.cc b/sql/sql_update.cc
index 9d69f8edcff..55be8723ab3 100644
--- a/sql/sql_update.cc
+++ b/sql/sql_update.cc
@@ -305,12 +305,12 @@ int mysql_update(THD *thd,
   if (lock_tables(thd, table_list, table_count, 0))
     DBUG_RETURN(1);
 
+  THD_STAGE_INFO(thd, stage_init_update);
   if (table_list->handle_derived(thd->lex, DT_MERGE_FOR_INSERT))
     DBUG_RETURN(1);
   if (table_list->handle_derived(thd->lex, DT_PREPARE))
     DBUG_RETURN(1);
 
-  THD_STAGE_INFO(thd, stage_init);
   table= table_list->table;
 
   if (!table_list->single_table_updatable())
@@ -707,7 +707,6 @@ int mysql_update(THD *thd,
   */
   thd->count_cuted_fields= CHECK_FIELD_WARN;
   thd->cuted_fields=0L;
-  THD_STAGE_INFO(thd, stage_updating);
 
   transactional_table= table->file->has_transactions();
   thd->abort_on_warning= !ignore && thd->is_strict_mode();
@@ -735,6 +734,7 @@ int mysql_update(THD *thd,
   can_compare_record= records_are_comparable(table);
   explain->tracker.on_scan_init();
 
+  THD_STAGE_INFO(thd, stage_updating);
   while (!(error=info.read_record(&info)) && !thd->killed)
   {
     explain->tracker.on_record_read();
diff --git a/sql/sql_view.cc b/sql/sql_view.cc
index 32fa481395e..e52ea0f7a39 100644
--- a/sql/sql_view.cc
+++ b/sql/sql_view.cc
@@ -706,7 +706,6 @@ bool mysql_create_view(THD *thd, TABLE_LIST *views,
   DBUG_RETURN(0);
 
 err:
-  THD_STAGE_INFO(thd, stage_end);
   lex->link_first_table_back(view, link_to_local);
   unit->cleanup();
   DBUG_RETURN(res || thd->is_error());
diff --git a/sql/wsrep_applier.cc b/sql/wsrep_applier.cc
index a299ddf074f..958add48b5a 100644
--- a/sql/wsrep_applier.cc
+++ b/sql/wsrep_applier.cc
@@ -234,11 +234,11 @@ wsrep_cb_status_t wsrep_apply_cb(void* const             ctx,
 
 #ifdef WSREP_PROC_INFO
   snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1,
-           "applying write set %lld: %p, %zu",
+           "Applying write set %lld: %p, %zu",
            (long long)wsrep_thd_trx_seqno(thd), buf, buf_len);
   thd_proc_info(thd, thd->wsrep_info);
 #else
-  thd_proc_info(thd, "applying write set");
+  thd_proc_info(thd, "Applying write set");
 #endif /* WSREP_PROC_INFO */
 
   /* tune FK and UK checking policy */
@@ -268,10 +268,10 @@ wsrep_cb_status_t wsrep_apply_cb(void* const             ctx,
 
 #ifdef WSREP_PROC_INFO
   snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1,
-           "applied write set %lld", (long long)wsrep_thd_trx_seqno(thd));
+           "Applied write set %lld", (long long)wsrep_thd_trx_seqno(thd));
   thd_proc_info(thd, thd->wsrep_info);
 #else
-  thd_proc_info(thd, "applied write set");
+  thd_proc_info(thd, "Applied write set");
 #endif /* WSREP_PROC_INFO */
 
   if (WSREP_CB_SUCCESS != rcode)
@@ -293,10 +293,10 @@ static wsrep_cb_status_t wsrep_commit(THD* const thd)
 {
 #ifdef WSREP_PROC_INFO
   snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1,
-           "committing %lld", (long long)wsrep_thd_trx_seqno(thd));
+           "Committing %lld", (long long)wsrep_thd_trx_seqno(thd));
   thd_proc_info(thd, thd->wsrep_info);
 #else
-  thd_proc_info(thd, "committing");
+  thd_proc_info(thd, "Committing");
 #endif /* WSREP_PROC_INFO */
 
   wsrep_cb_status_t const rcode(trans_commit(thd) ?
@@ -317,10 +317,10 @@ static wsrep_cb_status_t wsrep_commit(THD* const thd)
 
 #ifdef WSREP_PROC_INFO
   snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1,
-           "committed %lld", (long long) wsrep_thd_trx_seqno(thd));
+           "Committed %lld", (long long) wsrep_thd_trx_seqno(thd));
   thd_proc_info(thd, thd->wsrep_info);
 #else
-  thd_proc_info(thd, "committed");
+  thd_proc_info(thd, "Committed");
 #endif /* WSREP_PROC_INFO */
 
   return rcode;
@@ -330,10 +330,10 @@ static wsrep_cb_status_t wsrep_rollback(THD* const thd)
 {
 #ifdef WSREP_PROC_INFO
   snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1,
-           "rolling back %lld", (long long)wsrep_thd_trx_seqno(thd));
+           "Rolling back %lld", (long long)wsrep_thd_trx_seqno(thd));
   thd_proc_info(thd, thd->wsrep_info);
 #else
-  thd_proc_info(thd, "rolling back");
+  thd_proc_info(thd, "Rolling back");
 #endif /* WSREP_PROC_INFO */
 
   wsrep_cb_status_t const rcode(trans_rollback(thd) ?
@@ -341,10 +341,10 @@ static wsrep_cb_status_t wsrep_rollback(THD* const thd)
 
 #ifdef WSREP_PROC_INFO
   snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1,
-           "rolled back %lld", (long long)wsrep_thd_trx_seqno(thd));
+           "Rolled back %lld", (long long)wsrep_thd_trx_seqno(thd));
   thd_proc_info(thd, thd->wsrep_info);
 #else
-  thd_proc_info(thd, "rolled back");
+  thd_proc_info(thd, "Rolled back");
 #endif /* WSREP_PROC_INFO */
 
   return rcode;
diff --git a/sql/wsrep_hton.cc b/sql/wsrep_hton.cc
index d047c3580ef..32544a826e3 100644
--- a/sql/wsrep_hton.cc
+++ b/sql/wsrep_hton.cc
@@ -383,7 +383,7 @@ wsrep_run_wsrep_commit(THD *thd, bool all)
     mysql_mutex_unlock(&thd->LOCK_wsrep_thd);
 
     mysql_mutex_lock(&thd->mysys_var->mutex);
-    thd_proc_info(thd, "wsrep waiting on replaying");
+    thd_proc_info(thd, "WSREP waiting on replaying");
     thd->mysys_var->current_mutex= &LOCK_wsrep_replaying;
     thd->mysys_var->current_cond=  &COND_wsrep_replaying;
     mysql_mutex_unlock(&thd->mysys_var->mutex);
diff --git a/sql/wsrep_thd.cc b/sql/wsrep_thd.cc
index 5f29d28b19f..061ff795fc3 100644
--- a/sql/wsrep_thd.cc
+++ b/sql/wsrep_thd.cc
@@ -252,7 +252,7 @@ void wsrep_replay_transaction(THD *thd)
       MYSQL_END_STATEMENT(thd->m_statement_psi, thd->get_stmt_da());
       thd->m_statement_psi= NULL;
       thd->m_digest= NULL;
-      thd_proc_info(thd, "wsrep replaying trx");
+      thd_proc_info(thd, "WSREP replaying trx");
       WSREP_DEBUG("replay trx: %s %lld",
                   thd->query() ? thd->query() : "void",
                   (long long)wsrep_thd_trx_seqno(thd));
@@ -463,7 +463,7 @@ static void wsrep_rollback_process(THD *thd)
   wsrep_aborting_thd= NULL;
 
   while (thd->killed == NOT_KILLED) {
-    thd_proc_info(thd, "wsrep aborter idle");
+    thd_proc_info(thd, "WSREP aborter idle");
     thd->mysys_var->current_mutex= &LOCK_wsrep_rollback;
     thd->mysys_var->current_cond=  &COND_wsrep_rollback;
 
@@ -472,7 +472,7 @@ static void wsrep_rollback_process(THD *thd)
     WSREP_DEBUG("WSREP rollback thread wakes for signal");
 
     mysql_mutex_lock(&thd->mysys_var->mutex);
-    thd_proc_info(thd, "wsrep aborter active");
+    thd_proc_info(thd, "WSREP aborter active");
     thd->mysys_var->current_mutex= 0;
     thd->mysys_var->current_cond=  0;
     mysql_mutex_unlock(&thd->mysys_var->mutex);