MySQL Bugs: #69375: LOAD DATA INFILE claims to be holding 'System Lock' in processlist

Bug #69375	LOAD DATA INFILE claims to be holding 'System Lock' in processlist
Submitted:	1 Jun 2013 7:30	Modified:	5 Jun 2013 10:33
Reporter:	Justin Swanhart	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.6, 5.5, 5.1	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Execute a long running load data infile against an InnoDB table.

Examine 'SHOW PROCESSLIST'

Notice the status is 'System Lock'.

Execute a concurrent LDI.

It will also have the status 'System Lock'.

Both will complete because no real lock is being held.

How to repeat:
see above

Suggested fix:
Update the process list status to say 'loading data' instead of 'System Lock'

I filed this internally a while ago.
Bug 16189134 - "SYSTEM LOCK" THREAD STATE IS NONSENSE.

The "system lock" is set in mysql_lock_tables but not cleared before returning.  And most callers don't clear it immediately!

Somewhere between 5.6.12 and 5.6.21 this changed from 'System Lock' to 'checking permissions'

Posted by developer:
 
System lock still appears in 5.6.26 and 5.7.9 - the Performance Schema shows the same states:

mysql> SELECT VERSION();
+-------------------------------------------+
| VERSION()                                 |
+-------------------------------------------+
| 5.6.26-enterprise-commercial-advanced-log |
+-------------------------------------------+
1 row in set (0.00 sec)

mysql> UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME = 'events_stages_current';
Query OK, 1 row affected (0.00 sec)                                                                       
Rows matched: 1  Changed: 1  Warnings: 0                                                                  

mysql> UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME LIKE 'stage/%';
Query OK, 108 rows affected (0.00 sec)
Rows matched: 108  Changed: 108  Warnings: 0

mysql> SELECT * FROM performance_schema.threads WHERE THREAD_ID = 39\G
*************************** 1. row ***************************
          THREAD_ID: 39
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 2
   PROCESSLIST_USER: root
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: employees
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 47
  PROCESSLIST_STATE: System lock
   PROCESSLIST_INFO: LOAD DATA LOCAL INFILE '/tmp/salaries.txt' INTO TABLE salaries
   PARENT_THREAD_ID: NULL
               ROLE: NULL
       INSTRUMENTED: YES
1 row in set (0.00 sec)

mysql> SELECT * FROM performance_schema.events_stages_current WHERE THREAD_ID = 39\G
*************************** 1. row ***************************
         THREAD_ID: 39
          EVENT_ID: 52
      END_EVENT_ID: NULL
        EVENT_NAME: stage/sql/System lock
            SOURCE: lock.cc:304
       TIMER_START: 1198612097179000
         TIMER_END: 1246757084663000
        TIMER_WAIT: 48144987484000
  NESTING_EVENT_ID: 48
NESTING_EVENT_TYPE: STATEMENT
1 row in set (0.00 sec)

mysql> SELECT EVENT_NAME, sys.format_time(TIMER_WAIT) FROM performance_schema.events_stages_current WHERE THREAD_ID = 39;
+-----------------------+-----------------------------+
| EVENT_NAME            | sys.format_time(TIMER_WAIT) |
+-----------------------+-----------------------------+
| stage/sql/System lock | 49.54 s                     |
+-----------------------+-----------------------------+
1 row in set (0.00 sec)

mysql> SELECT VERSION();
+------------------------------------------+
| VERSION()                                |
+------------------------------------------+
| 5.7.9-enterprise-commercial-advanced-log |
+------------------------------------------+
1 row in set (0.00 sec)

mysql> SELECT * FROM performance_schema.threads WHERE THREAD_ID = 28\G
*************************** 1. row ***************************
          THREAD_ID: 28
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 2
   PROCESSLIST_USER: root
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: employees
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 24
  PROCESSLIST_STATE: System lock
   PROCESSLIST_INFO: LOAD DATA LOCAL INFILE '/tmp/salaries.txt' INTO TABLE salaries
   PARENT_THREAD_ID: 1
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: Socket
1 row in set (0.00 sec)

mysql> SELECT * FROM performance_schema.events_stages_current WHERE THREAD_ID = 28\G
*************************** 1. row ***************************
         THREAD_ID: 28
          EVENT_ID: 28
      END_EVENT_ID: NULL
        EVENT_NAME: stage/sql/System lock
            SOURCE: lock.cc:321
       TIMER_START: 157581299430000
         TIMER_END: 182860587295000
        TIMER_WAIT: 25279287865000
    WORK_COMPLETED: NULL
    WORK_ESTIMATED: NULL
  NESTING_EVENT_ID: 24
NESTING_EVENT_TYPE: STATEMENT
1 row in set (0.00 sec)

mysql> SELECT EVENT_NAME, sys.format_time(TIMER_WAIT) FROM performance_schema.events_stages_current WHERE THREAD_ID = 28;
+-----------------------+-----------------------------+
| EVENT_NAME            | sys.format_time(TIMER_WAIT) |
+-----------------------+-----------------------------+
| stage/sql/System lock | 26.14 s                     |
+-----------------------+-----------------------------+
1 row in set (0.00 sec)

Noted in 5.5.49, 5.6.30, 5.7.12, 5.8.0 changelogs.

Processlist state information was not updated correctly for LOAD DATA
INFILE and could show a state different from executing.