Why Does MySQL SHOW PROFILE Show “System lock” for Tablespace Import?

Background

A recent case imported a 4 GB table using ALTER TABLE … IMPORT TABLESPACE, taking 13 minutes. Profiling revealed that the majority of the time was spent in the System lock stage.

Basic Usage of SHOW PROFILE

Enable profiling with SET profiling = 1;, run the target query, then view stages with SHOW PROFILE FOR QUERY 1;. The output lists each stage and its duration. Adding ALL shows CPU, context switches, I/O, and more, but the statistics apply to the whole process, not a single SQL statement.

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   |
| System lock                    | 788.966338 |
| ...                            | ...        |
+--------------------------------+------------+

The System lock status also appears in SHOW PROCESSLIST, which can be misleading.

Implementation Principle of SHOW PROFILE

SHOW PROFILE is implemented in sql_profile.cc and consists of two parts: data collection and data calculation.

1. Data Collection

Instrumentation points ("hooks") are inserted throughout the server code. Each hook calls THD_STAGE_INFO(thd, stage_name), which records the current system time and, if available, resource usage via getrusage.

void QUERY_PROFILE::new_status(const char *status_arg,
                               const char *function_arg,
                               const char *file_arg,
                               unsigned int line_arg) {
    PROF_MEASUREMENT *prof;
    if (function_arg && file_arg)
        prof = new PROF_MEASUREMENT(this, status_arg, function_arg,
                                    base_name(file_arg), line_arg);
    else
        prof = new PROF_MEASUREMENT(this, status_arg);
    prof->m_seq = m_seq_counter++;
    m_end_time_usecs = prof->time_usecs;
    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; // convert to microseconds
    #ifdef HAVE_GETRUSAGE
    getrusage(RUSAGE_SELF, &rusage);
    #endif
}

The collected timestamps are stored in a queue ( entries) for later processing.

2. Data Calculation

When SHOW PROFILE is executed, MySQL queries information_schema.profiling. The function PROFILING::fill_statistics_info iterates over the entries queue, computes the duration of each stage by subtracting the previous timestamp, and fills the corresponding columns (STATE, DURATION, CPU_USER, etc.).

int PROFILING::fill_statistics_info(THD *thd_arg, Table_ref *tables) {
    for (auto query : history) {
        for (auto entry : query->entries) {
            if (previous) {
                double duration = (entry->time_usecs - previous->time_usecs) / 1e6;
                // store STATE = previous->status, DURATION = duration, ...
            }
            previous = entry;
        }
    }
    return 0;
}

The STATE column actually stores the *previous* stage name, and the DURATION column is the time difference to the *next* stage.

Why the Tablespace Import Shows Most Time in System lock

The import operation is performed in mysql_discard_or_import_tablespace (in sql/handler.cc). The function calls THD_STAGE_INFO(thd, stage_discard_or_import_tablespace) and then open_and_lock_tables, which finally invokes THD_STAGE_INFO(thd, stage_system_lock). Consequently, the profiler records the stage as System lock even though the real work happens later.

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;
    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;
}

// open_and_lock_tables eventually calls
THD_STAGE_INFO(thd, stage_system_lock);

Profiling shows System lock lasting ~788 seconds, but the actual time‑consuming call is ha_discard_or_import_tablespace, which spends ~788.965 seconds checking and updating every page of the imported tablespace.

Conclusion

SHOW PROFILE reports each stage’s duration as the time difference to the next stage, and the STATE column reflects the previous stage name. This design can mislead when the visible stage (e.g., System lock) does not correspond to the real heavy‑weight operation (e.g., discard_or_import_tablespace). Understanding the underlying instrumentation and the code paths clarifies why the tablespace import appears as a System lock in profiling output.

https://dev.mysql.com/doc/refman/8.4/en/show-profile.html

https://dev.mysql.com/doc/refman/8.4/en/performance-schema-query-profiling.html

https://dev.mysql.com/worklog/task/?id=5522