mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> alter table sbtest2 import tablespace;
Query OK, 0 rows affected (13 min 8.99 sec)
mysql> show profile for query 1;
+--------------------------------+------------+
| Status                         | Duration   |
+--------------------------------+------------+
| starting                       |   0.000119 |
| Executing hook on transaction  |   0.000004 |
| starting                       |   0.000055 |
| checking permissions           |   0.000010 |
| discard_or_import_tablespace   |   0.000007 |
| Opening tables                 |   0.000156 |
| System lock                    | 788.966338 |
| end                            |   0.007391 |
| waiting for handler commit     |   0.000041 |
| waiting for handler commit     |   0.011179 |
| query end                      |   0.000022 |
| closing tables                 |   0.000019 |
| waiting for handler commit     |   0.000031 |
| freeing items                  |   0.000035 |
| cleaning up                    |   0.000043 |
+--------------------------------+------------+
15 rows in set, 1 warning (0.03 sec)

mysql> show processlist;
+----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+
| Id | User            | Host      | db     | Command | Time | State                  | Info                                  |
+----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+
|  5 | event_scheduler | localhost | NULL   | Daemon  |  818 | Waiting on empty queue | NULL                                  |
| 10 | root            | localhost | sbtest | Query   |  648 | System lock            | alter table sbtest2 import tablespace |
| 14 | root            | localhost | NULL   | Query   |    0 | init                   | show processlist                      |
+----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+
3 rows in set, 1 warning (0.00 sec)

# 開啟 Profiling
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
# 執(zhí)行需要分析的 SQL
mysql> select count(*) from slowtech.t1;
+----------+
| count(*) |
+----------+
|  1048576 |
+----------+
1 row in set (1.09 sec)
# 通過 show profiles 查看 SQL 對應(yīng)的 Query_ID
mysql> show profiles;
+----------+------------+----------------------------------+
| Query_ID | Duration   | Query                            |
+----------+------------+----------------------------------+
|        1 | 1.09378600 | select count(*) from slowtech.t1 |
+----------+------------+----------------------------------+
1 row in set, 1 warning (0.00 sec)
# 查看該 SQL 各個階段的執(zhí)行耗時情況，其中，1 是該 SQL 對應(yīng)的 Query_ID
mysql> show profile for query 1;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000157 |
| Executing hook on transaction  | 0.000009 |
| starting                       | 0.000020 |
| checking permissions           | 0.000012 |
| Opening tables                 | 0.000076 |
| init                           | 0.000011 |
| System lock                    | 0.000026 |
| optimizing                     | 0.000013 |
| statistics                     | 0.000033 |
| preparing                      | 0.000032 |
| executing                      | 1.093124 |
| end                            | 0.000025 |
| query end                      | 0.000013 |
| waiting for handler commit     | 0.000078 |
| closing tables                 | 0.000048 |
| freeing items                  | 0.000076 |
| cleaning up                    | 0.000037 |
+--------------------------------+----------+
17 rows in set, 1 warning (0.01 sec)

mysql> show profile all for query 1\G
...
*************************** 11. row ***************************
             Status: executing
           Duration: 0.825417
           CPU_user: 1.486951
         CPU_system: 0.007982
  Context_voluntary: 0
Context_involuntary: 553
       Block_ops_in: 0
      Block_ops_out: 0
      Messages_sent: 0
  Messages_received: 0
  Page_faults_major: 0
  Page_faults_minor: 24
              Swaps: 0
    Source_function: ExecuteIteratorQuery
        Source_file: sql_union.cc
        Source_line: 1678
...
17 rows in set, 1 warning (0.00 sec)

mysql> show profile source for query 1;
+--------------------------------+----------+-------------------------+----------------------+-------------+
| Status                         | Duration | Source_function         | Source_file          | Source_line |
+--------------------------------+----------+-------------------------+----------------------+-------------+
| starting                       | 0.000157 | NULL                    | NULL                 |        NULL |
| Executing hook on transaction  | 0.000009 | launch_hook_trans_begin | rpl_handler.cc       |        1484 |
| starting                       | 0.000020 | launch_hook_trans_begin | rpl_handler.cc       |        1486 |
| checking permissions           | 0.000012 | check_access            | sql_authorization.cc |        2173 |
| Opening tables                 | 0.000076 | open_tables             | sql_base.cc          |        5911 |
| init                           | 0.000011 | execute                 | sql_select.cc        |         760 |
| System lock                    | 0.000026 | mysql_lock_tables       | lock.cc              |         332 |
| optimizing                     | 0.000013 | optimize                | sql_optimizer.cc     |         379 |
| statistics                     | 0.000033 | optimize                | sql_optimizer.cc     |         721 |
| preparing                      | 0.000032 | optimize                | sql_optimizer.cc     |         806 |
| executing                      | 1.093124 | ExecuteIteratorQuery    | sql_union.cc         |        1677 |
| end                            | 0.000025 | execute                 | sql_select.cc        |         796 |
| query end                      | 0.000013 | mysql_execute_command   | sql_parse.cc         |        4896 |
| waiting for handler commit     | 0.000078 | ha_commit_trans         | handler.cc           |        1636 |
| closing tables                 | 0.000048 | mysql_execute_command   | sql_parse.cc         |        4960 |
| freeing items                  | 0.000076 | dispatch_sql_command    | sql_parse.cc         |        5434 |
| cleaning up                    | 0.000037 | dispatch_command        | sql_parse.cc         |        2478 |
+--------------------------------+----------+-------------------------+----------------------+-------------+
17 rows in set, 1 warning (0.00 sec)

  THD_STAGE_INFO(thd, stage_executing);

void QUERY_PROFILE::new_status(const char *status_arg, const char *function_arg,
                               const char *file_arg, unsigned int line_arg) {
  PROF_MEASUREMENT *prof;
  ...
  // 初始化 PROF_MEASUREMENT，初始化的過程中會采集數(shù)據(jù)。
  if ((function_arg != nullptr) && (file_arg != nullptr))
    prof = new PROF_MEASUREMENT(this, status_arg, function_arg,
                                base_name(file_arg), line_arg);
  else
    prof = new PROF_MEASUREMENT(this, status_arg);
  // m_seq 是階段的序號，對應(yīng) information_schema.profiling 中的 SEQ。
  prof->m_seq = m_seq_counter++; 
  // time_usecs 是采集到的系統(tǒng)當(dāng)前時間。
  m_end_time_usecs = prof->time_usecs; 
  // 將采集到的數(shù)據(jù)添加到隊列中，這個隊列在查詢時會用到。
  entries.push_back(prof); 
  ...
}

PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg,
                                   const char *status_arg,
                                   const char *function_arg,
                                   const char *file_arg, unsigned int line_arg)
    : profile(profile_arg) {
  collect();
  set_label(status_arg, function_arg, file_arg, line_arg);
}
void PROF_MEASUREMENT::collect() {
  time_usecs = (double)my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
#ifdef HAVE_GETRUSAGE
  getrusage(RUSAGE_SELF, &rusage);
#elif defined(_WIN32)
  ...
#endif
}

int PROFILING::fill_statistics_info(THD *thd_arg, Table_ref *tables) {
  DBUG_TRACE;
  TABLE *table = tables->table;
  ulonglong row_number = 0;
  QUERY_PROFILE *query;
  // 循環(huán) history 隊列，隊列中的元素是 QUERY_PROFILE，每一個查詢對應(yīng)一個 QUERY_PROFILE。
  // 隊列的大小由參數(shù) profiling_history_size 決定，默認(rèn)是 15。
  void *history_iterator;
  for (history_iterator = history.new_iterator(); history_iterator != nullptr;
       history_iterator = history.iterator_next(history_iterator)) {
    query = history.iterator_value(history_iterator);
    ulong seq;
    void *entry_iterator;
    PROF_MEASUREMENT *entry, *previous = nullptr;
    // 循環(huán)每個查詢中的 entries，entries 存儲了每個階段的系統(tǒng)當(dāng)前時間。
    for (entry_iterator = query->entries.new_iterator();
         entry_iterator != nullptr;
         entry_iterator = query->entries.iterator_next(entry_iterator),
        previous = entry, row_number++) {
      entry = query->entries.iterator_value(entry_iterator);
      seq = entry->m_seq;
      if (previous == nullptr) continue;
      if (thd_arg->lex->sql_command == SQLCOM_SHOW_PROFILE) {
        if (thd_arg->lex->show_profile_query_id ==
            0) /* 0 == show final query */
        {
          if (query != last) continue;
        } else {
          // 如果記錄中的 Query_ID 跟 show profile for query query_id 中的不一致，則繼續(xù)判斷下一條記錄
          if (thd_arg->lex->show_profile_query_id != query->profiling_query_id) 
            continue;
        }
      }
      restore_record(table, s->default_values);
      // query->profiling_query_id 用來填充 information_schema.profiling 中的 QUERY_ID
      table->field[0]->store((ulonglong)query->profiling_query_id, true);
      // seq 用來填充 information_schema.profiling 中的 SEQ
      table->field[1]->store((ulonglong)seq,
                             true); 
      // status 用來填充 information_schema.profiling 中的 STATE
      // 注意，這里是上一條記錄的 status，不是當(dāng)前記錄的 status
      table->field[2]->store(previous->status, strlen(previous->status),
                             system_charset_info);
      // 當(dāng)前記錄的 time_usecs 減去上一條記錄的 time_usecs 的值，換算成秒，用來填充 information_schema.profiling 中的 DURATION
      my_decimal duration_decimal;
      double2my_decimal(
          E_DEC_FATAL_ERROR,
          (entry->time_usecs - previous->time_usecs) / (1000.0 * 1000),
          &duration_decimal); 
      table->field[3]->store_decimal(&duration_decimal);
#ifdef HAVE_GETRUSAGE
      my_decimal cpu_utime_decimal, cpu_stime_decimal;
      // 當(dāng)前記錄的 ru_utime 減去上一條記錄的 ru_utime，用來填充 information_schema.profiling 中的 CPU_USER
      double2my_decimal(
          E_DEC_FATAL_ERROR,
          RUSAGE_DIFF_USEC(entry->rusage.ru_utime, previous->rusage.ru_utime) /
              (1000.0 * 1000),
          &cpu_utime_decimal);
      ...
      table->field[4]->store_decimal(&cpu_utime_decimal);
...
  return 0;
}

bool Sql_cmd_discard_import_tablespace::mysql_discard_or_import_tablespace(
    THD *thd, Table_ref *table_list) {
  ... 
  THD_STAGE_INFO(thd, stage_discard_or_import_tablespace);
  ...
  if (open_and_lock_tables(thd, table_list, 0, &alter_prelocking_strategy)) {
    return true;
  }
  ...
  const bool discard =
      (m_alter_info->flags & Alter_info::ALTER_DISCARD_TABLESPACE);
  error = table_list->table->file->ha_discard_or_import_tablespace(discard,
                                                                   table_def); 
  THD_STAGE_INFO(thd, stage_end);
  ...
  return true;
}