Archive

Archive for March, 2022

MySQL : events_waits_current – who is waiting and who is on CPU

March 25th, 2022

Anyone familiar with Oracle performance tuning knows about ASH , aka active session history. ASH saves a history of every session that is active every collection, which by default is once per second. Once per second is fast enough to give a clear view of database load.

The ASH data comes from v$session which is a structure that contains information on every connection and shows which connections are active, what SQL they are running (SQL_ID) and if they are runnable on CPU or waiting on a wait_event for some resource like an I/O to complete or a lock or latch. It’s a pretty simple select query on v$session to select who is active,  their wait_event and SQL_ID.

On Oracle that gives us a query like:

select sid||':'||serial# session_id,
       username,
       s.sql_id||':'||sql_child_number sqlid,
       decode(state, 'WAITING', wait_class||':'||event, 'CPU') event
from v$session s
where   (( s.wait_time != 0  /* on CPU  */ and s.status='ACTIVE'  /*ACTIVE */)
            or s.wait_class  != 'Idle' )

On MySQL it’s not so straight forward.  The view that shows who is connect to the instances is performance_schema.threads, but this view doesn’t have the wait event.

Example content of threads:

*************************** 1. row ***************************
          THREAD_ID: 469
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 357
   PROCESSLIST_USER: shopper_22
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: dbmorders_6
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 0
  PROCESSLIST_STATE: updating
   PROCESSLIST_INFO: UPDATE order_item SET sku=trim(sku) WHERE id < 553
   PARENT_THREAD_ID: NULL
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: TCP/IP
       THREAD_OS_ID: 246
     RESOURCE_GROUP: USR_default

Selecting out Active Session Data

SELECT
        threads.THREAD_ID,
    --  threads.PROCESSLIST_info sql_text,
        REPLACE(REPLACE(substr(threads.PROCESSLIST_info,1,40),'\r',''),'\n','') sql_text_short,
        threads.PROCESSLIST_USER,
        threads.PROCESSLIST_HOST,
        threads.PROCESSLIST_COMMAND,
        threads.PROCESSLIST_STATE
FROM
        performance_schema.threads AS threads 
 Where 
     threads.PROCESSLIST_STATE IS NOT NULL
 and threads.PROCESSLIST_COMMAND != 'Sleep'
 and threads.PROCESSLIST_COMMAND != 'Daemon'
 and threads.PROCESSLIST_ID != CONNECTION_ID()
;

-----------+------------------------------------------+------------------+------------------+---------------------+-------------------+
| THREAD_ID | sql_text_short                           | PROCESSLIST_USER | PROCESSLIST_HOST | PROCESSLIST_COMMAND | PROCESSLIST_STATE |
+-----------+------------------------------------------+------------------+------------------+---------------------+-------------------+
|       492 | SELECT * FROM order_item where sku LIKE  | shopper_11       | localhost        | Query               | executing         |
|       503 | SELECT * FROM order_item where sku LIKE  | shopper_1        | localhost        | Query               | executing         |
|       596 | SELECT * FROM order_item where sku LIKE  | shopper_7        | localhost        | Query               | executing         |
|       621 | INSERT INTO order_status_change (dbm_ord | shopper_6        | localhost        | Query               | executing         |
|       868 | INSERT INTO order_status_change (dbm_ord | shopper_2        | localhost        | Query               | executing         |
|       926 | INSERT INTO order_status_change (dbm_ord | shopper_13       | localhost        | Query               | executing         |
|     51380 | SELECT * FROM discount where description | shopper_7        | localhost        | Query               | executing         |
|    165954 | INSERT INTO order_status_change (dbm_ord | shopper_20       | localhost        | Query               | executing         |
|     98532 | SELECT * FROM discount where description | shopper_19       | localhost        | Query               | executing         |
|    843087 | select sleep(20)                         | dbmapp           | localhost        | Query               | User sleep        |
|    800275 | select sleep(20)                         | dbmapp           | localhost        | Query               | User sleep        |
|    932043 | select sleep(20)                         | dbmapp           | localhost        | Query               | User sleep        |
+-----------+------------------------------------------+------------------+------------------+---------------------+-------------------+

A few things:

  1. We get the SQL text directly from threads. Seems like this could be a bit inefficient if we collect and store this data frequently. Compare this to Oracle where we can just collect the SQL_ID each time and look up the SQL text just once per SQL_ID.  On MySQL we could has the text every collection and just store the text once per hash. TBD
  2. There is no WAIT_EVENT and no indication of who is waiting or who is runnable on CPU

 events_waits_current

To get wait events we should be able to look at performance_schema.events_waits_current and join threads using (THREAD_ID) .  Both views have the field THREAD_ID.

It sounds pretty simple as the documentation says there is one row per thread

https://dev.mysql.com/doc/refman/5.7/en/performance-schema-events-waits-current-table.html

The table stores one row per thread showing the current status of the thread’s most recent monitored wait event, so there is no system variable for configuring the table size.

Two problems:

  1. by default performance_schema.events_waits_current is empty
  2. there are cases where there are multiple lines in performance_schema.events_waits_current for the same thread_id

For the first issue where performance_schema.events_waits_current is empty, three things are required

  1. performance_schema enabled
  2. setup_consumers enabled
  3.  setup_instruments enabled

1. performance_schema enabled

Make sure

performance_schema  is set to ON:
SHOW VARIABLES LIKE 'performance_schema%';
+----------------------------------------------------------+-------+
| Variable_name                                            | Value |
+----------------------------------------------------------+-------+
| performance_schema                                       | ON    |
| performance_schema_accounts_size                         | -1    |
| performance_schema_digests_size                          | 10000 |
| performance_schema_error_size                            | 5018  |
| performance_schema_events_stages_history_long_size       | 10000 |
| performance_schema_events_stages_history_size            | 10    |
| performance_schema_events_statements_history_long_size   | 10000 |
| performance_schema_events_statements_history_size        | 10    |
| performance_schema_events_transactions_history_long_size | 10000 |
| performance_schema_events_transactions_history_size      | 10    |
| performance_schema_events_waits_history_long_size        | 10000 |
| performance_schema_events_waits_history_size             | 10    |
...

 

2. setup_consumers

https://dev.mysql.com/doc/mysql-perfschema-excerpt/5.6/en/performance-schema-wait-tables.html

The wait consumers are disabled by default:

mysql> SELECT *
       FROM performance_schema.setup_consumers
       WHERE NAME LIKE 'events_waits%';
+---------------------------+---------+
| NAME                      | ENABLED |
+---------------------------+---------+
| events_waits_current      | NO      |
| events_waits_history      | NO      |
| events_waits_history_long | NO      

To enable all the wait consumers :

      update performance_schema.setup_consumers set enabled="YES" where name like 'events_waits%';

3.setup_instruments

https://dev.mysql.com/doc/mysql-perfschema-excerpt/5.6/en/performance-schema-wait-tables.html

Some wait instruments are enabled by default; others are disabled. For example:

mysql> SELECT * FROM performance_schema.setup_instruments
       WHERE NAME LIKE 'wait/io/file/innodb%';
+--------------------------------------+---------+-------+
| NAME                                 | ENABLED | TIMED |
+--------------------------------------+---------+-------+
| wait/io/file/innodb/innodb_data_file | YES     | YES   |
| wait/io/file/innodb/innodb_log_file  | YES     | YES   |
| wait/io/file/innodb/innodb_temp_file | YES     | YES   |
+--------------------------------------+---------+-------+

mysql> SELECT * FROM performance_schema.setup_instruments
       WHERE NAME LIKE 'wait/io/socket/%';
+----------------------------------------+---------+-------+
| NAME                                   | ENABLED | TIMED |
+----------------------------------------+---------+-------+
| wait/io/socket/sql/server_tcpip_socket | NO      | NO    |
| wait/io/socket/sql/server_unix_socket  | NO      | NO    |
| wait/io/socket/sql/client_connection   | NO      | NO    |
+----------------------------------------+---------+-------+

There should be zero rows returned for

      SELECT * FROM performance_schema.setup_instruments WHERE NAME LIKE 'wait%' and ENABLED='NO';

To enable all the instruments :

      update performance_schema.setup_instruments set enabled='YES' , 
      timed='YES'where NAME LIKE 'wait/%';

Now we are ready to query events_waits_current to get wait_events for active thread_id values from performance_schema.threads

 select
     t.thread_id,
     t.PROCESSLIST_STATE,
     w.EVENT_ID,
     w.END_EVENT_ID,
     w.NESTING_EVENT_TYPE ,
     w.NESTING_EVENT_ID,
     w.SOURCE,
     COALESCE(
    IF ( t.PROCESSLIST_STATE ='User sleep','User sleep',  
        IF(w.EVENT_ID=w.END_EVENT_ID,'CPU',EVENT_NAME)  )
    ,'CPUbis')
       AS wait_event,
     REPLACE(REPLACE(substr(t.PROCESSLIST_info,1,40),'\r',''),'\n','') sql_text_short
 from
            performance_schema.threads t
  left join performance_schema.events_waits_current w on w.thread_id = t.thread_id              
 where 
         t.PROCESSLIST_STATE IS NOT NULL
   and   t.PROCESSLIST_COMMAND != 'Sleep' 
   and   t.PROCESSLIST_COMMAND != 'Daemon'
   and   t.PROCESSLIST_ID != CONNECTION_ID()
   order by t.thread_id
 ;


+-----------+-------------------+-----------+--------------+--------------------+------------------+---------------------------------------+------------------------------------------+
| thread_id | PROCESSLIST_STATE | EVENT_ID  | END_EVENT_ID | NESTING_EVENT_TYPE | NESTING_EVENT_ID | wait_event                            | sql_text                                 |
+-----------+-------------------+-----------+--------------+--------------------+------------------+---------------------------------------+------------------------------------------+
|       374 | Sending data      |  47464227 |         NULL | NULL               |             NULL | idle                                  | SELECT * FROM discount where description |
|       651 | Sending data      |  48306893 |         NULL | STATEMENT          |         48299933 | wait/io/table/sql/handler             | INSERT INTO order_status_change (dbm_ord |
|       651 | Sending data      |  48306901 |         NULL | WAIT               |         48306898 | wait/synch/mutex/innodb/lock_mutex    | INSERT INTO order_status_change (dbm_ord |
|       701 | Sending data      |  47680423 |         NULL | STATEMENT          |         47309200 | wait/io/table/sql/handler             | INSERT INTO order_status_change (dbm_ord |
|       701 | Sending data      |  47680425 |         NULL | WAIT               |         47680423 | wait/synch/mutex/innodb/trx_sys_mutex | INSERT INTO order_status_change (dbm_ord |
|       712 | Sending data      |  73823545 |         NULL | NULL               |             NULL | idle                                  | SELECT * FROM order_item where sku LIKE  |

Thread_id 651 and 701 both have two rows despite what the manual says about one row per thread!

Which row do we use? Or is there some bug?

Thanks to Mark Leith @MarkLeith who pointed out to me that the one to use is the one with the highest EVENT_ID

 select
     t.thread_id,
     t.PROCESSLIST_STATE,
     w.EVENT_ID,
     w.END_EVENT_ID,
     w.NESTING_EVENT_TYPE ,
     w.NESTING_EVENT_ID,
     w.SOURCE,
     COALESCE(
    IF ( t.PROCESSLIST_STATE ='User sleep','User sleep',  
        IF(w.EVENT_ID=w.END_EVENT_ID,'CPU',EVENT_NAME)  )
    ,'CPU')
       AS wait_event,
     REPLACE(REPLACE(substr(t.PROCESSLIST_info,1,40),'\r',''),'\n','') sql_text 
 from
            performance_schema.threads t
  left join performance_schema.events_waits_current w on w.thread_id = t.thread_id              
   and w.EVENT_ID in (
                           select max(w1.EVENT_ID)
                            from
                                performance_schema.threads t1
                     left join  performance_schema.events_waits_current w1
                     on w1.thread_id = t1.thread_id
                    where 
                            t1.PROCESSLIST_STATE IS NOT NULL
                      and   t1.PROCESSLIST_COMMAND != 'Sleep' 
                      and   t1.PROCESSLIST_COMMAND != 'Daemon'
                      and   t1.PROCESSLIST_ID != CONNECTION_ID()
                    group by t1.thread_id)
 where 
         t.PROCESSLIST_STATE IS NOT NULL
   and   t.PROCESSLIST_COMMAND != 'Sleep' 
   and   t.PROCESSLIST_COMMAND != 'Daemon'
   and   t.PROCESSLIST_ID != CONNECTION_ID()
   order by t.thread_id
 ;

+-----------+-------------------+-----------+--------------+--------------------+------------------+-------------------------------------------+------------------------------------------+
| thread_id | PROCESSLIST_STATE | EVENT_ID  | END_EVENT_ID | NESTING_EVENT_TYPE | NESTING_EVENT_ID | EVENT_NAME                                | sql_text                                 |
+-----------+-------------------+-----------+--------------+--------------------+------------------+-------------------------------------------+------------------------------------------+
|       672 | Sending data      |  47224916 |         NULL | STATEMENT          |         47224892 | wait/io/table/sql/handler                 | SELECT * FROM order_item where sku LIKE  |
|      1864 | User sleep        |  97625244 |         NULL | STATEMENT          |         97625228 | wait/synch/cond/sql/Item_func_sleep::cond | select sleep(20)                         |
|      1911 | updating          | 108506184 |         NULL | STATEMENT          |        108506129 | wait/io/table/sql/handler                 | update customer            set name=nam  |
|      2059 | User sleep        |  89344512 |         NULL | STATEMENT          |         89344496 | wait/synch/cond/sql/Item_func_sleep::cond | select sleep(20)                         |
+-----------+-------------------+-----------+--------------+--------------------+------------------+-------------------------------------------+------------------------------------------+

Now there are still a few problems. First how do we know who is on CPU and who is waiting?
If END_EVENT_ID has a value then the wait has finished and we should be on CPU.
Also what happens if there is not a corresponding row in events_waits_current for a thread_id that is active in performance_schema.threads? I imagine that means the thread is runnable on CPU as well. Putting this together we get

select
    t.thread_id,
    t.PROCESSLIST_COMMAND cmd,
    t.PROCESSLIST_STATE,
    w.EVENT_ID,
    w.END_EVENT_ID,
    w.NESTING_EVENT_TYPE ,
    w.NESTING_EVENT_ID,
    COALESCE( IF(w.EVENT_ID=w.END_EVENT_ID,'CPU',EVENT_NAME) ,'CPU') AS wait_event,
    REPLACE(REPLACE(substr(t.PROCESSLIST_info,1,40),'\r',''),'\n','') sql_text 
from
           performance_schema.threads t
 left join performance_schema.events_waits_current w on w.thread_id = t.thread_id  
  and w.EVENT_ID in (
                           select max(w1.EVENT_ID)
                            from
                                performance_schema.threads t1
                     left join  performance_schema.events_waits_current w1
                     on w1.thread_id = t1.thread_id
                    where 
                            t1.PROCESSLIST_STATE IS NOT NULL
                      and   t1.PROCESSLIST_COMMAND != 'Sleep' 
                      and   t1.PROCESSLIST_COMMAND != 'Daemon'
                      and   t1.PROCESSLIST_ID != CONNECTION_ID()
                    group by t1.thread_id)          
where 
        t.PROCESSLIST_STATE IS NOT NULL
  and   t.PROCESSLIST_COMMAND != 'Sleep' 
  and   t.PROCESSLIST_COMMAND != 'Daemon'
  and   t.PROCESSLIST_ID != CONNECTION_ID()
;

+-----------+-------------------+----------+--------------+--------------------+------------------+-------------------------------------------+------------------------------------------+
| thread_id | PROCESSLIST_STATE | EVENT_ID | END_EVENT_ID | NESTING_EVENT_TYPE | NESTING_EVENT_ID | wait_event                                | sql_text                                 |
+-----------+-------------------+----------+--------------+--------------------+------------------+-------------------------------------------+------------------------------------------+
|      1000 | Sending data      |  2101672 |         NULL | NULL               |             NULL | idle                                      | SELECT * FROM order_item where sku LIKE  |
|      1461 | User sleep        |   273962 |         NULL | NULL               |             NULL | wait/synch/cond/sql/Item_func_sleep::cond | select sleep(20)                         |
|      1466 | Sending data      |  1576483 |         NULL | NULL               |             NULL | idle                                      | SELECT * FROM discount where description |
|      1682 | Sending data      |  1037890 |         NULL | NULL               |             NULL | idle                                      | SELECT * FROM discount where description |
|      1888 | freeing items     |  1489102 |      1489102 | NULL               |             NULL | CPU                                       | COMMIT                                   |
+-----------+-------+-------------------+----------+--------------+--------------------+------------------+-------------------------------------------+------------------------------------------+

Now there are still strange things such as the “idle” wait_events? Why does performance_schema.threads say we are active but the corresponding row in events_waits_current say we are idle?
By the way, I only see these “idle” events on 5.6 and 5.7. On 8.0 they seem to be gone.
One nice thing is that this query runs on all three versions which is a bit surprising considering all the performance schema changes over those three versions.
Adding in performance_schema.events_statements_current & performance_schema.socket_instances

SELECT
    threads.thread_id, 
    threads.PROCESSLIST_ID,
    threads.PROCESSLIST_USER,
    threads.PROCESSLIST_HOST,
    threads.PROCESSLIST_DB,
    threads.PROCESSLIST_COMMAND,
    threads.PROCESSLIST_STATE ,
--  statement.TIMER_START AS event_timer_start,
--  statement.TIMER_END AS event_timer_end,
-- statement.LOCK_TIME,
    statement.CURRENT_SCHEMA,
--  threads.PROCESSLIST_info as SQL_TEXT,
    REPLACE(REPLACE(substr(threads.PROCESSLIST_info,1,40),'\r',''),'\n','') sql_text,
    COALESCE(
       IF ( threads.PROCESSLIST_STATE ='User sleep','User sleep',  
             IF(waits.EVENT_ID=waits.END_EVENT_ID,'CPU',waits.EVENT_NAME)  )
       ,'CPUbis') AS wait_event,
--  waits.TIMER_START AS wait_timer_start,
--  waits.TIMER_END AS wait_timer_end,
    waits.OBJECT_SCHEMA,
    waits.OBJECT_NAME,
    waits.INDEX_NAME,
    waits.OBJECT_TYPE,
    waits.SOURCE,
    socket.IP,
    socket.PORT
FROM
           performance_schema.threads                   AS threads
 LEFT JOIN performance_schema.events_waits_current      AS waits on waits.thread_id = threads.thread_id 
   and waits.EVENT_ID in (  select max(w1.EVENT_ID)
                           from   performance_schema.threads t1
                       left join  performance_schema.events_waits_current w1
                         on w1.thread_id = t1.thread_id
                   where 
                           t1.PROCESSLIST_STATE IS NOT NULL
                     and   t1.PROCESSLIST_COMMAND != 'Sleep' 
                     and   t1.PROCESSLIST_COMMAND != 'Daemon'
                     and   t1.PROCESSLIST_ID != CONNECTION_ID()
                   group by t1.thread_id)
 LEFT JOIN performance_schema.events_statements_current AS statement ON statement.thread_id = threads.thread_id
 LEFT JOIN performance_schema.socket_instances          AS socket  ON socket.thread_id = threads.thread_id
where 
        threads.PROCESSLIST_STATE IS NOT NULL
  and   threads.PROCESSLIST_COMMAND != 'Sleep' 
  and   threads.PROCESSLIST_COMMAND != 'Daemon'
  and   threads.PROCESSLIST_ID != CONNECTION_ID()
  order by threads.thread_id
;  
  

One thing that doesn’t make sense at all to me is that with the last line the SQL, the order by, the output includes lines with PROCESSLIST_COMMAND = Sleep even though there is an explicit threads.PROCESSLIST_COMMAND != ‘Sleep’. Anyone have an idea of what is happening? Is this a bug or is there an explanation?

-----------+----------------+------------------+------------------+----------------+---------------------+----------------------------+----------------+------------------------------------------+---------------------------+---------------+-------------+------------+-------------+--------------------+-----------+-------+
| thread_id | PROCESSLIST_ID | PROCESSLIST_USER | PROCESSLIST_HOST | PROCESSLIST_DB | PROCESSLIST_COMMAND | PROCESSLIST_STATE          | CURRENT_SCHEMA | sql_text                                 | wait_event                | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | OBJECT_TYPE | SOURCE             | IP        | PORT  |
+-----------+----------------+------------------+------------------+----------------+---------------------+----------------------------+----------------+------------------------------------------+---------------------------+---------------+-------------+------------+-------------+--------------------+-----------+-------+
|       557 |            445 | shopper_28       | localhost        | dbmorders_4    | Query               | executing                  | dbmorders_4    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL               | 127.0.0.1 | 42832 |
|       582 |            470 | shopper_12       | localhost        | dbmorders_5    | Query               | executing                  | dbmorders_5    | SELECT * FROM order_item where sku LIKE  | wait/io/table/sql/handler | dbmorders_5   | order_item  | NULL       | TABLE       | handler.cc:2991    | 127.0.0.1 | 42884 |
|       608 |            496 | shopper_11       | localhost        | dbmorders_1    | Query               | executing                  | dbmorders_1    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL               | 127.0.0.1 | 42940 |
|       750 |            638 | shopper_14       | localhost        | dbmorders_9    | Query               | waiting for handler commit | dbmorders_9    | INSERT INTO order_status_change (dbm_ord | CPU                       | NULL          | NULL        | NULL       | NULL        | sql_plugin.cc:2632 | 127.0.0.1 | 43240 |
|       789 |            677 | shopper_3        | localhost        | dbmorders_4    | Query               | executing                  | dbmorders_4    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL               | 127.0.0.1 | 43320 |
|       811 |            699 | shopper_7        | localhost        | dbmorders      | Sleep               | NULL                       | dbmorders      | NULL                                     | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL               | 127.0.0.1 | 43366 |
|       866 |            754 | shopper_4        | localhost        | dbmorders_8    | Sleep               | NULL                       | dbmorders_8    | NULL                                     | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL               | 127.0.0.1 | 43482 |
|       921 |            809 | dbmapp           | localhost        | dbm            | Query               | updating                   | dbm            | update customer            set name=nam  | wait/io/table/sql/handler | dbm           | customer    | PRIMARY    | TABLE       | handler.cc:3262    | 127.0.0.1 | 43598 |
|       938 |            826 | dbmapp           | localhost        | dbm            | Query               | User sleep                 | dbm            | select sleep(20)                         | User sleep                | NULL          | NULL        | NULL       | NULL        | item_func.cc:5301  | 127.0.0.1 | 43636 |


where as without the order by there are no threads.PROCESSLIST_COMMAND = ‘Sleep’

+-----------+----------------+------------------+------------------+----------------+---------------------+----------------------------+----------------+------------------------------------------+---------------------------+---------------+-------------+------------+-------------+-------------------+-----------+-------+
| thread_id | PROCESSLIST_ID | PROCESSLIST_USER | PROCESSLIST_HOST | PROCESSLIST_DB | PROCESSLIST_COMMAND | PROCESSLIST_STATE          | CURRENT_SCHEMA | sql_text                                 | wait_event                | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | OBJECT_TYPE | SOURCE            | IP        | PORT  |
+-----------+----------------+------------------+------------------+----------------+---------------------+----------------------------+----------------+------------------------------------------+---------------------------+---------------+-------------+------------+-------------+-------------------+-----------+-------+
|       657 |            545 | shopper_9        | localhost        | dbmorders_7    | Query               | executing                  | dbmorders_7    | SELECT * FROM dbm_user where username LI | wait/io/table/sql/handler | dbmorders_7   | dbm_user    | NULL       | TABLE       | handler.cc:2991   | 127.0.0.1 | 43046 |
|       485 |            373 | shopper_8        | localhost        | dbmorders_4    | Query               | executing                  | dbmorders_4    | SELECT * FROM dbm_user where username LI | wait/io/table/sql/handler | dbmorders_4   | dbm_user    | NULL       | TABLE       | handler.cc:2991   | 127.0.0.1 | 42666 |
|       561 |            448 | shopper_23       | localhost        | dbmorders_5    | Query               | executing                  | dbmorders_5    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL              | 127.0.0.1 | 42840 |
|       778 |            666 | shopper_5        | localhost        | dbmorders      | Query               | executing                  | dbmorders      | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL              | 127.0.0.1 | 43298 |
|     26965 |           1061 | shopper_17       | localhost        | dbmorders_2    | Query               | executing                  | dbmorders_2    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL              | 127.0.0.1 | 44132 |
|       720 |            608 | shopper_22       | localhost        | dbmorders_1    | Query               | executing                  | dbmorders_1    | SELECT * FROM discount where description | wait/io/table/sql/handler | dbmorders_1   | discount    | NULL       | TABLE       | handler.cc:2991   | 127.0.0.1 | 43176 |
|       726 |            614 | shopper_22       | localhost        | dbmorders_5    | Query               | executing                  | dbmorders_5    | SELECT * FROM discount where description | wait/io/table/sql/handler | dbmorders_5   | discount    | NULL       | TABLE       | handler.cc:2991   | 127.0.0.1 | 43188 |
|     10663 |            995 | shopper_25       | localhost        | dbmorders_2    | Query               | executing                  | dbmorders_2    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL              | 127.0.0.1 | 43988 |
|      8619 |            987 | shopper_24       | localhost        | dbmorders_9    | Query               | executing                  | dbmorders_9    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL              | 127.0.0.1 | 43970 |
|      1350 |            862 | shopper_27       | localhost        | dbmorders_5    | Query               | executing                  | dbmorders_5    | SELECT * FROM dbm_user where username LI | wait/io/table/sql/handler | dbmorders_5   | dbm_user    | NULL       | TABLE       | handler.cc:2991   | 127.0.0.1 | 43712 |
|    222821 |           1341 | dbmapp           | localhost        | dbm            | Query               | updating                   | dbm            | update customer            set name=nam  | wait/io/table/sql/handler | dbm           | customer    | PRIMARY    | TABLE       | handler.cc:3262   | 127.0.0.1 | 44734 |
|    108033 |           1233 | dbmapp           | localhost        | dbm            | Query               | User sleep                 | dbm            | select sleep(20)                         | User sleep                | NULL          | NULL        | NULL       | NULL        | item_func.cc:5301 | 127.0.0.1 | 44502 |
|     31247 |           1075 | dbmapp           | localhost        | dbm            | Query               | User sleep                 | dbm            | select sleep(20)                         | User sleep                | NULL          | NULL        | NULL       | NULL        | item_func.cc:5301 | 127.0.0.1 | 44164 |
|     58167 |           1143 | shopper_26       | localhost        | dbmorders_1    | Query               | executing                  | dbmorders_1    | INSERT INTO order_status_change (dbm_ord | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL              | 127.0.0.1 | 44306 |
|    550359 |           1871 | root             | localhost        | kyle           | Query               | updating                   | kyle           | update toto set id=4                     | wait/io/table/sql/handler | kyle          | toto        | NULL       | TABLE       | handler.cc:2991   | 127.0.0.1 | 45860 |
|    550417 |           1929 | dbm              | localhost        | sbtest         | Query               | waiting for handler commit | sbtest         | COMMIT                                   | CPUbis                    | NULL          | NULL        | NULL       | NULL        | NULL              | 127.0.0.1 | 45984 |
+-----------+----------------+------------------+------------------+----------------+---------------------+----------------------------+----------------+------------------------------------------+---------------------------+---------------+-------------+------------+-------------+-------------------+-----------+-------+

From Twitter, Øystein Grøvlen @ogrovlen, suggests
·
Regarding your last question, there is no concurrency control for performance schema tables, and the optimizer may choose to fetch column values after sorting. I suggest to try, ORDER BY threads.thread_id, threads.PROCESSLIST_COMMAND
 order by “threads.thread_id, threads.PROCESSLIST_COMMAND” didn’t work for me. Still getting sleep in the output but it gave me a idea  about adding a column from events_waits_current to the order by. That did work and now the sleeps are correctly filtered out
“order by t.thread_id , w.EVENT_NAME”

Uncategorized

MySQL -> what to do with NESTING_EVENT_ID

March 24th, 2022

How does one use  NESTING_EVENT_ID?

Below I’ve selected from  events_waits_history_long for a single thread, but none of the  NESTING_EVENT_ID values show up in EVENT_ID or END_EVENT_ID.

To simplify things , I’m just showing the data for one THREAD_ID listed in order of TIMER_START.

mysql>  select 
            THREAD_ID,
            EVENT_ID,
            END_EVENT_ID,
            NESTING_EVENT_ID,
            NESTING_EVENT_TYPE,
            EVENT_NAME,
            SOURCE,
            TIMER_WAIT,
            SPINS,
            OBJECT_SCHEMA,
            OBJECT_NAME,
            INDEX_NAME,
            OBJECT_TYPE,
            OBJECT_TYPE,
            OBJECT_INSTANCE_BEGIN,
            OPERATION,
            NUMBER_OF_BYTES,
            FLAGS 
 from 
           performance_schema.events_waits_history_long 
 where 
            THREAD_ID in ( select max(thread_id) from performance_schema.events_waits_history_long where NESTING_EVENT_ID is not NULL )
 order by 
           THREAD_ID, TIMER_START
 Limit 100;
+-----------+----------+--------------+------------------+--------------------+-------------------------------------------+---------------------------------+---------------+-------+---------------+----------------------------+------------+-------------+-------------+-----------------------+---------------+-----------------+-------+
| THREAD_ID | EVENT_ID | END_EVENT_ID | NESTING_EVENT_ID | NESTING_EVENT_TYPE | EVENT_NAME                                | SOURCE                          | TIMER_WAIT    | SPINS | OBJECT_SCHEMA | OBJECT_NAME                | INDEX_NAME | OBJECT_TYPE | OBJECT_TYPE | OBJECT_INSTANCE_BEGIN | OPERATION     | NUMBER_OF_BYTES | FLAGS |
+-----------+----------+--------------+------------------+--------------------+-------------------------------------------+---------------------------------+---------------+-------+---------------+----------------------------+------------+-------------+-------------+-----------------------+---------------+-----------------+-------+
| 518033674 |    92174 |        92174 |            92171 | WAIT               | wait/io/socket/sql/client_connection      | viosocket.cc:145                |          NULL |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | recv          |               4 |  NULL |
| 518033674 |    92232 |        92232 |            92231 | WAIT               | wait/io/socket/sql/client_connection      | viosocket.cc:145                |          NULL |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | recv          |               0 |  NULL |
| 518033674 |    92210 |        92210 |            92207 | WAIT               | wait/io/socket/sql/client_connection      | viosocket.cc:145                |          NULL |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | recv          |               4 |  NULL |
| 518033674 |    92209 |        92209 |            92207 | WAIT               | wait/io/socket/sql/client_connection      | viosocket.cc:813                |          NULL |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | select        |            NULL |  NULL |
| 518033674 |    92208 |        92208 |            92207 | WAIT               | wait/io/socket/sql/client_connection      | viosocket.cc:145                |          NULL |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | recv          |               0 |  NULL |
| 518033674 |    92173 |        92173 |            92171 | WAIT               | wait/io/socket/sql/client_connection      | viosocket.cc:813                |          NULL |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | select        |            NULL |  NULL |
| 518033674 |    92176 |        92176 |            92175 | STATEMENT          | wait/io/socket/sql/client_connection      | viosocket.cc:145                |       1612800 |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | recv          |              97 |  NULL |
| 518033674 |    92177 |        92177 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_data   | sql_class.h:3758                |        149600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541392 | lock          |            NULL |  NULL |
| 518033674 |    92178 |        92178 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |        512800 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92179 |        92179 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.cc:2152               |        232000 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92180 |        92180 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |         69600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92181 |        92181 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |         73600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92182 |        92182 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_query_plan | sql_class.h:1044                |        190400 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541584 | lock          |            NULL |  NULL |
| 518033674 |    92183 |        92183 |            92175 | STATEMENT          | wait/synch/mutex/sql/LOCK_table_cache     | table_cache.h:140               |        328000 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |              94768184 | lock          |            NULL |  NULL |
| 518033674 |    92184 |        92184 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_data   | sql_class.h:3769                |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541392 | lock          |            NULL |  NULL |
| 518033674 |    92185 |        92185 |            92175 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1355                  |        214400 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92186 |        92186 |            92175 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1383                  |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92187 |        92191 |            92175 | STATEMENT          | wait/lock/table/sql/handler               | handler.cc:7789                 |       2965600 |  NULL | dbm           | info                       | PRIMARY    | TABLE       | TABLE       |        47817989761064 | read external |            NULL |  NULL |
| 518033674 |    92188 |        92188 |            92187 | WAIT               | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1355                  |         33600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92189 |        92189 |            92187 | WAIT               | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1383                  |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92191 |        92191 |            92187 | WAIT               | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1355                  |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92192 |        92192 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_query_plan | sql_class.h:1044                |        114400 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541584 | lock          |            NULL |  NULL |
| 518033674 |    92193 |        92195 |            92175 | STATEMENT          | wait/io/table/sql/handler                 | handler.cc:3280                 |      18676800 |  NULL | dbm           | info                       | PRIMARY    | TABLE       | TABLE       |        47817989761064 | fetch         |               1 |  NULL |
| 518033674 |    92194 |        92194 |            92193 | WAIT               | wait/synch/mutex/innodb/trx_sys_mutex     | read0read.cc:544                |        123200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811968171800 | lock          |            NULL |  NULL |
| 518033674 |    92195 |        92195 |            92193 | WAIT               | wait/synch/sxlock/innodb/btr_search_latch | btr0sea.ic:122                  |        158400 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811987295224 | shared_lock   |            NULL |  NULL |
| 518033674 |    92196 |        92196 |            92175 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1383                  |         45600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92197 |        92197 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_query_plan | sql_class.h:1044                |         52000 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541584 | lock          |            NULL |  NULL |
| 518033674 |    92198 |        92198 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_query_plan | sql_class.h:1044                |         66400 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541584 | lock          |            NULL |  NULL |
| 518033674 |    92199 |        92199 |            92175 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1355                  |         45600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92200 |        92200 |            92175 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1383                  |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92201 |        92201 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_data   | sql_base.cc:1727                |         45600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541392 | lock          |            NULL |  NULL |
| 518033674 |    92202 |        92202 |            92175 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | ha_innodb.cc:17396              |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92203 |        92203 |            92175 | STATEMENT          | wait/synch/mutex/sql/LOCK_table_cache     | table_cache.h:140               |         45600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |              94768184 | lock          |            NULL |  NULL |
| 518033674 |    92204 |        92204 |            92175 | STATEMENT          | wait/io/socket/sql/client_connection      | viosocket.cc:220                |      20792800 |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | send          |              77 |  NULL |
| 518033674 |    92205 |        92205 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.cc:2152               |         75200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92206 |        92206 |            92175 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |         34400 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92212 |        92212 |            92211 | STATEMENT          | wait/io/socket/sql/client_connection      | viosocket.cc:145                |        454400 |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | recv          |               9 |  NULL |
| 518033674 |    92213 |        92213 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_data   | sql_class.h:3758                |         37600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541392 | lock          |            NULL |  NULL |
| 518033674 |    92214 |        92214 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |         32800 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92215 |        92215 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.cc:2152               |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92216 |        92216 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |         52800 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92217 |        92217 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |         47200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92218 |        92218 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_query_plan | sql_class.h:1044                |         44800 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541584 | lock          |            NULL |  NULL |
| 518033674 |    92219 |        92219 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1355                  |         44800 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92220 |        92220 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | lock0lock.cc:6386               |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92221 |        92221 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1331                  |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92222 |        92222 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.cc:1771                 |         28800 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92223 |        92223 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | lock0lock.cc:6406               |        121600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92224 |        92224 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | lock0lock.cc:6458               |         27200 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92225 |        92225 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.cc:1957                 |         44000 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92226 |        92226 |            92211 | STATEMENT          | wait/synch/mutex/innodb/trx_mutex         | trx0trx.h:1383                  |         28000 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47811978633272 | lock          |            NULL |  NULL |
| 518033674 |    92227 |        92227 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_query_plan | sql_class.h:1044                |         45600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541584 | lock          |            NULL |  NULL |
| 518033674 |    92228 |        92228 |            92211 | STATEMENT          | wait/io/socket/sql/client_connection      | viosocket.cc:220                |       4366400 |  NULL | NULL          | ::ffff:10.135.133.25:38102 | NULL       | SOCKET      | SOCKET      |        47811962370304 | send          |              11 |  NULL |
| 518033674 |    92229 |        92229 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.cc:2152               |         30400 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92230 |        92230 |            92211 | STATEMENT          | wait/synch/mutex/sql/THD::LOCK_thd_query  | sql_class.h:2970                |         37600 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |        47817989541440 | lock          |            NULL |  NULL |
| 518033674 |    92171 |        92174 |             NULL | NULL               | idle                                      | init_net_server_extension.cc:66 | 4024163774000 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |                     0 | idle          |            NULL |  NULL |
| 518033674 |    92207 |        92210 |             NULL | NULL               | idle                                      | init_net_server_extension.cc:66 |     761912000 |  NULL | NULL          | NULL                       | NULL       | NULL        | NULL        |                     0 | idle          |            NULL |  NULL |
+-----------+----------+--------------+------------------+--------------------+-------------------------------------------+---------------------------------+---------------+-------+---------------+----------------------------+------------+-------------+-------------+-----------------------+---------------+-----------------+-------+

mysql> select * from performance_schema.events_waits_history_long  
    where EVENT_ID in (
       select NESTING_EVENT_ID from performance_schema.events_waits_history_long  
        where
          THREAD_ID in ( select max(thread_id) from  performance_schema.events_waits_history_long where NESTING_EVENT_ID is not NULL )
    );
Empty set (0.17 sec)


mysql> select * from performance_schema.events_waits_history_long  
      where END_EVENT_ID in (
         select NESTING_EVENT_ID from performance_schema.events_waits_history_long  
         where
          THREAD_ID in ( select max(thread_id) from  performance_schema.events_waits_history_long where NESTING_EVENT_ID is not NULL )
      );
Empty set (0.14 sec)



Sometimes when selecting from performance_schema.events_waits_current I get two lines for the same thread:

 select
    t.thread_id,
    t.PROCESSLIST_COMMAND cmd,
    ww.EVENT_ID,
    ww.END_EVENT_ID,
    ww.NESTING_EVENT_TYPE ,
    ww.NESTING_EVENT_ID,
    ww.EVENT_NAME  wait_event,
    REPLACE(REPLACE(substr(t.PROCESSLIST_info,1,80),'\r',''),'\n','') sql_text 
from
                performance_schema.threads t
    left   join  performance_schema.events_waits_current ww on ww.thread_id = t.thread_id
where 
        t.PROCESSLIST_STATE IS NOT NULL
  and ( t.PROCESSLIST_COMMAND != 'Sleep' and t.PROCESSLIST_COMMAND != 'Daemon')
  and   t.PROCESSLIST_ID != CONNECTION_ID();

+-----------+-------+----------+--------------+--------------------+------------------+-------------------------------------------+----------------------------------------------------------------------------------+
| thread_id | cmd   | EVENT_ID | END_EVENT_ID | NESTING_EVENT_TYPE | NESTING_EVENT_ID | wait_event                                | sql_text                                                                         |
+-----------+-------+----------+--------------+--------------------+------------------+-------------------------------------------+----------------------------------------------------------------------------------+
| 518032847 | Query |    76405 |         NULL | STATEMENT          |            76347 | wait/io/table/sql/handler                 | SELECT customer.id_ AS customer_id_, customer.name AS customer_name, customer.de |
| 518032847 | Query |    91369 |         NULL | WAIT               |            76405 | wait/io/file/sql/hash_join                | SELECT customer.id_ AS customer_id_, customer.name AS customer_name, customer.de |

I see that  NESTING_EVENT_ID 76405  for  second row  where NESTING_EVENT_TYPE = WAIT is the same as the EVENT_ID for the first line where NESTING_EVENT_TYPE = STATEMENT, but what information does this communicate?

 

https://dev.mysql.com/doc/refman/5.7/en/performance-schema-events-statements-current-table.html

  • NESTING_EVENT_IDNESTING_EVENT_TYPENESTING_EVENT_LEVEL

    These three columns are used with other columns to provide information as follows for top-level (unnested) statements and nested statements (executed within a stored program).

    For top level statements:

    OBJECT_TYPE = NULL
    OBJECT_SCHEMA = NULL
    OBJECT_NAME = NULL
    NESTING_EVENT_ID = NULL
    NESTING_EVENT_TYPE = NULL
    NESTING_LEVEL = 0

    For nested statements:

    OBJECT_TYPE = the parent statement object type
    OBJECT_SCHEMA = the parent statement object schema
    OBJECT_NAME = the parent statement object name
    NESTING_EVENT_ID = the parent statement EVENT_ID
    NESTING_EVENT_TYPE = 'STATEMENT'
    NESTING_LEVEL = the parent statement NESTING_LEVEL plus one

Get the last statements for thread with blocking  transactions

select 
   t.thread_id, 
   s.EVENT_ID, 
   REPLACE(REPLACE(substr(s.SQL_TEXT,1,40),'\r',''),'\n','') thread_proc_info_short, 
   s.TIMER_WAIT/100000000000 time
from 
        performance_schema.events_transactions_current t
  join performance_schema.events_statements_history s on s.NESTING_EVENT_ID = t.EVENT_ID
where t.thread_id in ( select BLOCKING_THREAD_ID from performance_schema.data_lock_waits )
  and s.NESTING_EVENT_TYPE='TRANSACTION'
order by t.thread_id, s.EVENT_ID;

+-----------+----------+------------------------------------------+----------+
| thread_id | EVENT_ID | thread_proc_info_short                   | time     |
+-----------+----------+------------------------------------------+----------+
|    941942 |  1157846 | update toto set id=4                     |   0.0044 |
|    941942 |  1157944 | select    t.thread_id,    s.EVENT_ID,    |   2.1082 |
|    941942 |  1158151 | update toto set id=9                     |   0.2056 |
|    941942 |  1158259 | select    t.thread_id,    s.EVENT_ID,    |   1.1989 |
|    941942 |  1158433 | select BLOCKING_THREAD_ID from performan |   0.2601 |
|    942146 |     6245 | update titi set id=2                     |   0.0089 |
|    942146 |     6354 | update toto set id=999                   | 508.0915 |
|    942146 |     6455 | SET SESSION innodb_lock_wait_timeout =10 |   0.0032 |
|    949290 |     5682 | update tutu set id=3                     |   0.1975 |
+-----------+----------+------------------------------------------+----------+

NOt sure why this doesn’t work – would think INNODB_TRX has all the transactions but apparently not ?

select 
      t.thread_id,  
      s.EVENT_ID, 
      REPLACE(REPLACE(substr(s.SQL_TEXT,1,40),'\r',''),'\n','') thread_proc_info_short,    
      s.TIMER_WAIT/100000000000 time
from  
      performance_schema.events_transactions_current t
join  performance_schema.events_statements_history_long s on s.NESTING_EVENT_ID = t.EVENT_ID
where t.thread_id  in  ( select trx_mysql_thread_id  from  information_schema.INNODB_TRX )
  and s.NESTING_EVENT_TYPE='TRANSACTION'
order by  t.thread_id, s.EVENT_ID;
Empty set (2.00 sec)

This works

select 
      t.thread_id,  
      s.EVENT_ID, 
      REPLACE(REPLACE(substr(s.SQL_TEXT,1,40),'\r',''),'\n','') thread_proc_info_short,    
      s.TIMER_WAIT/100000000000 time
from  
      performance_schema.events_transactions_current t
join  performance_schema.events_statements_history s on s.NESTING_EVENT_ID = t.EVENT_ID
where t.thread_id  in  ( select   distinct THREAD_ID from performance_schema.data_locks)
  and s.NESTING_EVENT_TYPE='TRANSACTION'
order by  t.thread_id, s.EVENT_ID;

+-----------+----------+------------------------------------------+----------+
| thread_id | EVENT_ID | thread_proc_info_short                   | time     |
+-----------+----------+------------------------------------------+----------+
|    941942 |  1157846 | update toto set id=4                     |   0.0044 |
|    941942 |  1157944 | select    t.thread_id,    s.EVENT_ID,    |   2.1082 |
|    941942 |  1158151 | update toto set id=9                     |   0.2056 |
|    941942 |  1158259 | select    t.thread_id,    s.EVENT_ID,    |   1.1989 |
|    941942 |  1158433 | select BLOCKING_THREAD_ID from performan |   0.2601 |
|    941942 |  1158599 | select       t.thread_id,        s.EVE   |  57.5793 |
|    941942 |  2602390 | select       t.thread_id,        s.EVE   |  18.5984 |
|    942146 |     6245 | update titi set id=2                     |   0.0089 |
|    942146 |     6354 | update toto set id=999                   | 508.0915 |
|    942146 |     6455 | SET SESSION innodb_lock_wait_timeout =10 |   0.0032 |
|    949290 |     5682 | update tutu set id=3                     |   0.1975 |
+-----------+----------+------------------------------------------+----------+
11 rows in set (3.85 sec)


Could select by thread_id but that gives all the SQL and not just SQL in transaction

 select 
       s.thread_id,  
       s.EVENT_ID, 
       REPLACE(REPLACE(substr(s.SQL_TEXT,1,40),'\r',''),'\n','') thread_proc_info_short,    
       s.TIMER_WAIT/100000000000 time
 from 
 performance_schema.events_statements_history s where THREAD_ID=942146;

-----------+----------+------------------------------------------+---------+
| thread_id | EVENT_ID | thread_proc_info_short                   | time    |
+-----------+----------+------------------------------------------+---------+
|    941942 |  1158259 | select    t.thread_id,    s.EVENT_ID,    |  1.1989 |
|    941942 |  1158433 | select BLOCKING_THREAD_ID from performan |  0.2601 |
|    941942 |  1158599 | select       t.thread_id,        s.EVE   | 57.5793 |
|    941942 |  2602390 | select       t.thread_id,        s.EVE   | 18.5984 |
|    941942 |  2604424 | select       t.thread_id,        s.EVE   | 36.9560 |
|    941942 |  1157736 | SET SESSION innodb_lock_wait_timeout =10 |  0.0152 |
|    941942 |  1157755 | start transaction                        |  0.1609 |
|    941942 |  1157846 | update toto set id=4                     |  0.0044 |
|    941942 |  1157944 | select    t.thread_id,    s.EVENT_ID,    |  2.1082 |
|    941942 |  1158151 | update toto set id=9                     |  0.2056 |
+-----------+----------+------------------------------------------+---------+

 

reference:

https://www.bobbydurrettdba.com/2019/02/12/one-query-in-mysql-performance-schema/

Uncategorized

Protected: DataDog – the marriage of ASH, Query Stats and UI

March 23rd, 2022
Enter your password to view comments.

This content is password protected. To view it please enter your password below:

Uncategorized

MySQL waits and CPU

March 23rd, 2022

Question: how do I know that one user is waiting for a lock and another  user is burning CPU on MySQL?

i.e. how can I create active session history on MySQL like on Oracle?

Two simple cases I’m looking at
  1. session waiting on lock
    1. The wait event is ” wait/io/table/sql/handler” which happens for a number of potential reasons
    2. -> I can join to information_schema views INNODB_LOCK_WAITS & INNODB_TRX but this is heavy, and I’d rather only access those after I know there is a lock waiter.
  2. session burning CPU
    1. How do I know from performance schema views that the connection is active and burning CPU?
    2. It has a wait event that shows up wait/synch/mutex/sql/THD::LOCK_thd_data
    3. on Oracle to determine CPU, we just look at connections that are active and not waiting.
Also what is NESTING_EVENT_TYPE?  I see the same thread sometime twice in events_waits_current with NESTING_EVENT_TYPE STAGE and WAIT.
On some systems for the lock test below the NESTING_EVENT_TYPE shows up as NULL and others as STAGE.

 

I basically want to monitor user activity and collect who is active and if they are waiting for something or if they are on CPU.

Row Lock

First user
             start transaction;
             update toto set id=1;
Second user does
             update toto set id=4; -- hangs

How do I see second user is waiting for a row lock? Here is output from

  • performance_schema.threads
  • performance_schema.events_waits_current

For a connection waiting on a lock:

select * from performance_schema.threads  where thread_id=5329\G
           THREAD_ID: 5329
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 5223
   PROCESSLIST_USER: root
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: kyle
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 782
  PROCESSLIST_STATE: updating
   PROCESSLIST_INFO: update toto set id=4
   PARENT_THREAD_ID: NULL
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: SSL/TLS
       THREAD_OS_ID: 2088
     RESOURCE_GROUP: USR_default
     
select * from performance_schema.events_waits_current  where thread_id=5329\G
*************************** 1. row ***************************
            THREAD_ID: 5329
             EVENT_ID: 740239187
         END_EVENT_ID: NULL
           EVENT_NAME: wait/io/table/sql/handler
               SOURCE: handler.cc:2991
          TIMER_START: 45606173945401364
            TIMER_END: 46413477812683064
           TIMER_WAIT: 807303867281700
                SPINS: NULL
        OBJECT_SCHEMA: kyle
          OBJECT_NAME: toto
           INDEX_NAME: NULL
          OBJECT_TYPE: TABLE
OBJECT_INSTANCE_BEGIN: 139872327141152
     NESTING_EVENT_ID: 740239186
   NESTING_EVENT_TYPE: STAGE
            OPERATION: fetch
      NUMBER_OF_BYTES: 61

CPU

Have user running a procedure that just burns CPU running “call minute_rollup(100000000)”.  Here is output from
  • performance_schema.threads
  • performance_schema.events_waits_current
 select * from performance_schema.threads where thread_id= 6273  \G
 *************************** 1. row ***************************
          THREAD_ID: 6273
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 6167
   PROCESSLIST_USER: root
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: kyle
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 668
  PROCESSLIST_STATE: Opening tables
   PROCESSLIST_INFO: call minute_rollup(100000000)
   PARENT_THREAD_ID: NULL
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: SSL/TLS
       THREAD_OS_ID: 2087
     RESOURCE_GROUP: USR_default
     
    select * from performance_schema.events_waits_current  where thread_id=6273\G
             THREAD_ID: 6273
             EVENT_ID: 403685579
         END_EVENT_ID: 403685579
           EVENT_NAME: wait/synch/mutex/sql/THD::LOCK_thd_data
               SOURCE: sql_class.h:4142
          TIMER_START: 46300974764007954
            TIMER_END: 46300974764070510
           TIMER_WAIT: 62556
                SPINS: NULL
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
           INDEX_NAME: NULL
          OBJECT_TYPE: NULL
OBJECT_INSTANCE_BEGIN: 139871988613512
     NESTING_EVENT_ID: 403685578
   NESTING_EVENT_TYPE: STATEMENT
            OPERATION: lock
      NUMBER_OF_BYTES: NULL
                FLAGS: NULL

Procedure to burn CPU:

DELIMITER $$
DROP PROCEDURE IF EXISTS minute_rollup$$
CREATE PROCEDURE minute_rollup(input_number INT)
BEGIN
DECLARE counter int;
DECLARE out_number float;
set counter=0;
WHILE counter <= input_number DO
SET out_number=SQRT(rand());
SET counter = counter + 1;
END WHILE;
END$$
DELIMITER ;

call minute_rollup(100000000);

I think the trick to see if the connection is on CPU is performance_schema.events_waits_current.EVENT_ID= END_EVENT_ID then we are on CPU

 

select
       t.thread_id,
       IF(w.EVENT_ID=w.END_EVENT_ID,'CPU', w.EVENT_NAME) AS wait_event,
       REPLACE( REPLACE(substr(t.PROCESSLIST_info ,1,80), '\r', '') , '\n','') sql_text 
from
           performance_schema.threads t
 left join performance_schema.events_waits_current w on w.thread_id = t.thread_id
where 
        t.PROCESSLIST_STATE IS NOT NULL
 and ( t.PROCESSLIST_COMMAND != 'Sleep' and t.PROCESSLIST_COMMAND != 'Daemon')
 and t.PROCESSLIST_ID != CONNECTION_ID();

+-----------+-------------------------------------------+----------------------------------------------------------------------------------+
| thread_id | wait_event                                | sql_text                                                                         |
+-----------+-------------------------------------------+----------------------------------------------------------------------------------+
| 518002247 | CPU                                       | SELECT anon_1.anon_2_anon_3_customer_id_ AS anon_1_anon_2_anon_3_customer_id_, a |
| 518007382 | CPU                                       | COMMIT                                                                           |
| 518006817 | wait/io/table/sql/handler                 | SELECT anon_1.anon_2_customer_id_ AS anon_1_anon_2_customer_id_, anon_1.anon_2_c |
| 518007025 | wait/io/table/sql/handler                 | update customer            set name=name            where id_ in (2, 1);         |
| 518007027 | wait/synch/cond/sql/Item_func_sleep::cond | select sleep(20)                                                                 |
| 518007028 | wait/io/table/sql/handler                 | update customer            set name=name            where id_ in (8, 4);         |
| 518007029 | wait/io/table/sql/handler                 | update customer            set name=name            where id_ in (6, 3);         |
| 518007032 | wait/synch/cond/sql/Item_func_sleep::cond | select sleep(20)                                                                 |
| 518007034 | wait/io/table/sql/handler                 | SELECT anon_1.anon_2_customer_id_ AS anon_1_anon_2_customer_id_, anon_1.anon_2_c |
| 518007035 | wait/synch/cond/sql/Item_func_sleep::cond | select sleep(20)                                                                 |
| 518007039 | wait/io/table/sql/handler                 | update customer            set name=name            where id_ in (5, 3);         |
| 518005220 | wait/io/table/sql/handler                 | SELECT anon_1.customer_id_ AS anon_1_customer_id_, anon_1.customer_name AS anon_ |
| 518007058 | wait/io/table/sql/handler                 | update customer            set name=name            where id_ in (4, 2);         |
| 518004406 | wait/io/table/sql/handler                 | SELECT anon_1.anon_2_customer_id_ AS anon_1_anon_2_customer_id_, anon_1.anon_2_c |
| 518003240 | wait/io/table/sql/handler                 | update toto set id=4                                                             |
+-----------+-------------------------------------------+----------------------------------------------------------------------------------+
 

One unusual thing is that the thread can show up more than once in events_waits_current.

 select
    t.thread_id,
    w.NESTING_EVENT_TYPE,
    IF(w.EVENT_ID=w.END_EVENT_ID,'CPU', w.EVENT_NAME)  AS wait_event,
    REPLACE(    REPLACE(substr(t.PROCESSLIST_info ,1,80), '\r', '') , '\n','') sql_text 
from
               performance_schema.threads t
    left join  performance_schema.events_waits_current w on w.thread_id = t.thread_id
where 
        t.PROCESSLIST_STATE IS NOT NULL
  and ( t.PROCESSLIST_COMMAND != 'Sleep' and t.PROCESSLIST_COMMAND != 'Daemon')
  and   t.PROCESSLIST_ID != CONNECTION_ID()

+-----------+--------------------+-------------------------------------------+----------------------------------------------------------------------------------+
| thread_id | NESTING_EVENT_TYPE | wait_event                                | sql_text                                                                         |
+-----------+--------------------+-------------------------------------------+----------------------------------------------------------------------------------+
| 518010010 | STATEMENT          | wait/io/table/sql/handler                 | SELECT customer.id_ AS customer_id_, customer.name AS customer_name, customer.de |
| 518010010 | WAIT               | wait/io/file/sql/hash_join                | SELECT customer.id_ AS customer_id_, customer.name AS customer_name, customer.de |
| 518010011 | STATEMENT          | wait/io/table/sql/handler                 | SELECT customer.id_ AS customer_id_, customer.name AS customer_name, customer.de |
| 518010011 | WAIT               | wait/io/file/sql/hash_join                | SELECT customer.id_ AS customer_id_, customer.name AS customer_name, customer.de |

In the case of NESTING_EVENT_TYPE of type WAIT, I want that WAIT. IF there is no NESTING_EVENT_TYPE of type WAIT and only of type STATEMENT , then I want that wait (AFAICT) leading to a bit of a convoluted statement

select
    t.thread_id,
    COALESCE( ww.NESTING_EVENT_TYPE, ws.NESTING_EVENT_TYPE) NESTING_EVENT_TYPE,
    IF(ws.EVENT_ID=ws.END_EVENT_ID,'CPU',
       COALESCE( ww.EVENT_NAME, ws.EVENT_NAME) )  AS wait_event,
    REPLACE(REPLACE(substr(t.PROCESSLIST_info,1,80),'\r',''),'\n','') sql_text 
from
                performance_schema.threads t
    left   join  performance_schema.events_waits_current ww on ww.thread_id = t.thread_id
         and ww.NESTING_EVENT_TYPE = 'WAIT'
    left   join  performance_schema.events_waits_current ws on ws.thread_id = t.thread_id
            and ws.NESTING_EVENT_TYPE = 'STATEMENT'
where 
        t.PROCESSLIST_STATE IS NOT NULL
  and ( t.PROCESSLIST_COMMAND != 'Sleep' and t.PROCESSLIST_COMMAND != 'Daemon')
  and   t.PROCESSLIST_ID != CONNECTION_ID();
+-----------+--------------------+-------------------------------------------+----------------------------------------------------------------------------------+
| thread_id | NESTING_EVENT_TYPE | wait_event                                | sql_text                                                                         |
+-----------+--------------------+-------------------------------------------+----------------------------------------------------------------------------------+
| 518009610 | STATEMENT          | wait/io/table/sql/handler                 | SELECT anon_1.anon_2_anon_3_customer_id_ AS anon_1_anon_2_anon_3_customer_id_, a |
| 518010002 | STATEMENT          | CPU                                       | SELECT current_schema, sql_text, digest, digest_text, timer_start, @startup_time |
| 518003240 | STATEMENT          | wait/io/table/sql/handler                 | update toto set id=4                                                             |
| 518010412 | STATEMENT          | wait/io/table/sql/handler                 | SELECT anon_1.anon_2_customer_id_ AS anon_1_anon_2_customer_id_, anon_1.anon_2_c |
| 518010010 | WAIT               | wait/io/file/sql/hash_join                | SELECT customer.id_ AS customer_id_, customer.name AS customer_name, customer.de |
| 518010417 | WAIT               | wait/io/file/sql/hash_join                | SELECT anon_1.customer_id_ AS anon_1_customer_id_, anon_1.customer_name AS anon_ |
+-----------+--------------------+-------------------------------------------+----------------------------------------------------------------------------------+

It gets more confusing because in some cases there are multiple lines (only seen two, not more ) for the same thread with the same NESTING_EVENT_TYPE ( NULL in the below example)

SELECT
        threads.PROCESSLIST_ID,
         threads.PROCESSLIST_USER,
         threads.PROCESSLIST_HOST,
         threads.PROCESSLIST_COMMAND,
         threads.PROCESSLIST_STATE,
         current_events.TIMER_START,
         current_events.TIMER_END,
         current_events.TIMER_WAIT,
         current_events.NESTING_EVENT_TYPE,
         REPLACE(REPLACE(substr(current_events.SQL_TEXT,1,40),'\r',''),'\n','')  stmt_sql_text_short,
         REPLACE(REPLACE(substr(threads.PROCESSLIST_info,1,40),'\r',''),'\n','') thread_proc_info_short,
         current_events.CURRENT_SCHEMA,
         IF ( threads.PROCESSLIST_STATE ='User sleep','User sleep', (
            IF(current_waits.EVENT_ID=current_waits.END_EVENT_ID,'CPU', current_waits.EVENT_NAME)
          )) AS wait_event
 FROM
                    performance_schema.threads AS threads
         INNER JOIN performance_schema.events_statements_current AS current_events ON threads.THREAD_ID = current_events.THREAD_ID
         INNER JOIN performance_schema.events_waits_current AS current_waits ON threads.THREAD_ID = current_waits.THREAD_ID
  Where threads.PROCESSLIST_STATE is not NULL


+------+-----------+-------------+-----------------+--------------------+---------------------------------------------------------------------------------------------+
| PID  | PLIST_CMD | PLIST_STATE |  TIMER_WAIT     | NESTING_EVENT_TYPE |  thread_proc_info_short                   | wait_event                                       |
+------+-----------+-------------+-----------------+--------------------+---------------------------------------------------------------------------------------------+
| 8539 | Query     | executing   |    445524154000 | NULL               |  INSERT INTO order_status_change (dbm_ord | wait/io/table/sql/handler                        |
| 8539 | Query     | executing   |    445580677000 | NULL               |  INSERT INTO order_status_change (dbm_ord | CPU                                              |

| 8820 | Query     | init        |       170936000 | NULL               |  SELECT * from dbm_user WHERE id = 2404   | idle                                             |
| 8820 | Query     | init        |       170936000 | NULL               |  SELECT * from dbm_user WHERE id = 2404   | wait/io/socket/sql/client_connection             |

| 8730 | Query     | executing   |    595809657000 | NULL               |  INSERT INTO order_status_change (dbm_ord | wait/io/table/sql/handler                        |
| 8730 | Query     | executing   |    595869870000 | NULL               |  INSERT INTO order_status_change (dbm_ord | wait/synch/sxlock/innodb/lock_sys_global_rw_lock |


 

Uncategorized