What does 'system lock' mean in mysql profiling a LOAD DATA INFILE statement?

Question

2M rows inserted using LOAD DATA INFILE to innodb takes 7.5min, and profiling shows 99% of that time is in "System lock".

Does this tell me anything useful?

 mysql> set profiling=1;
 Query OK, 0 rows affected (0.00 sec)
 mysql> LOAD DATA CONCURRENT LOCAL INFILE '/tmp/item' REPLACE INTO TABLE item_load;
 Query OK, 1964807 rows affected, 8 warnings (7 min 27.35 sec)
 Records: 1964806 Deleted: 1 Skipped: 0 Warnings: 8
 mysql> show profile for query 1;
 +------------------------------+------------+
 | Status | Duration |
 +------------------------------+------------+
 | starting | 0.000206 |
 | checking permissions | 0.000015 |
 | Opening tables | 0.000034 |
 | System lock | 447.327523 |
 | Waiting for query cache lock | 0.000352 |
 | query end | 0.000011 |
 | closing tables | 0.000014 |
 | freeing items | 0.000033 |
 | logging slow query | 0.000007 |
 | logging slow query | 0.000006 |
 | cleaning up | 0.000006 |
 +------------------------------+------------+
 11 rows in set (0.02 sec)

Answer 1

According to the MySQL Documentation on General Thread States

The thread is going to request or is waiting for an internal or external system lock for the table. If this state is being caused by requests for external locks and you are not using multiple mysqld servers that are accessing the same MyISAM tables, you can disable external system locks with the --skip-external-locking option. However, external locking is disabled by default, so it is likely that this option will have no effect. For SHOW PROFILE, this state means the thread is requesting the lock (not waiting for it).

This should not be surprising since InnoDB does row-level locking. In addition, the gen_clust_index (a.k.a. Clustered Index) will experience Shared and Exclusive Locks on the Primary Key at some point.

• vidyadhar: What does the system lock means in sql thread state in replication. Is it same or any other reason ?

Answer 2

The mysql_load() function calls the open_and_lock_tables() function to lock the table mentioned in the LOAD DATA statement.

MySQL obtains an exclusive lock on the table so that it can very quickly load data into the table. There is very little overhead in the LOAD DATA process, just the bare minimum parsing is done to make it work.

The CONCURRENT option only affects MyISAM tables, if you are loading into an InnoDB table it does not permit concurrent access.

The reason why System lock took so long is that the actual data load was lumped into the timing for that step. The profiler works by measuring time between fenceposts, that is the entry time is logged for each instrumented user function. The mysql_lock_tables() function is called from inside mysql_load(), but mysql_load() is not instrumented, so the elapsed time starts at the system lock and ends at the next fencepost, which was the query cache lock.

Your data load of 1.96mn rows took about 447 seconds, there isn't any way to separate the actual lock time overhead from the loading time because the loading isn't instrumented.