3

I am running a query that I expect to take a long time although I got no idea how long. I found out about SHOW ENGINE INNODB STATUS but I am not sure whether it is actually doing something or maybe it is stuck somewhere. Here's what I've tried to find out:

System monitor: By looking at the system monitor, I noticed the MySQL processes are not really using much memory nor CPU. However, I got 1 CPU at 100% continuously so some process is doing something although no progress on the list appears to be responsible for this. The db is 3GB and the query should be accessing pretty much all of it (24 million rows). Could it be that the resources are not shown on the mysql process but some sub-thread?

system monitor

SHOW ENGINE INNODB STATUS \G

This is the output.

SHOW ENGINE INNODB STATUS \G
 1. row 
  Type: InnoDB
  Name: 
Status: 
=====================================
2023-04-23 12:53:09 0x7ff1c440c700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 33 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 98 srv_active, 0 srv_shutdown, 5181 srv_idle
srv_master_thread log flush and writes: 5279
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2305
OS WAIT ARRAY INFO: signal count 2040
RW-shared spins 123, rounds 2059, OS waits 60
RW-excl spins 113, rounds 1833, OS waits 49
RW-sx spins 224, rounds 6342, OS waits 209
Spin rounds per wait: 16.74 RW-shared, 16.22 RW-excl, 28.31 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 9498291
Purge done for trxs n:o < 9498290 undo n:o < 0 state: running
History list length 58
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422151665308056, ACTIVE 1235 sec fetching rows
mysql tables in use 3, locked 3
209503 lock struct(s), heap size 26271864, 26067821 row lock(s)
MySQL thread id 39, OS thread handle 140676356118272, query id 127 localhost root Sending data
UPDATE events
INNER JOIN sessions_view_3
ON events.user_id = sessions_view_3.user_id
AND events.timestamp = sessions_view_3.timestamp
AND events.kind = sessions_view_3.kind
SET events.session_id_3 = sessions_view_3.global_session_id_3
---TRANSACTION 422151665303832, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
6622929 OS file reads, 239404 OS file writes, 8494 OS fsyncs
4944.03 reads/s, 16384 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 810, seg size 812, 1 merges
merged operations:
 insert 0, delete mark 1, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 468 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
143846.58 hash searches/s, 43181.66 non-hash searches/s
---
LOG
---
Log sequence number 43884780118
Log flushed up to   43884780118
Pages flushed up to 43884780118
Last checkpoint at  43884780109
0 pending log flushes, 0 pending chkp writes
2498 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 167772160
Dictionary memory allocated 41208
Buffer pool size   8027
Free buffers       1
Database pages     5955
Old database pages 2194
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2123, not young 529215348
0.00 youngs/s, 504929.52 non-youngs/s
Pages read 6593275, created 201671, written 202463
4944.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 992 / 1000, young-making rate 0 / 1000 not 772 / 1000
Pages read ahead 21.33/s, evicted without access 21.00/s, Random read ahead 0.00/s
LRU len: 5955, unzip_LRU len: 0
I/O sum[237723]:cur[2426], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=1131, Main thread ID=140676039636736, state: sleeping
Number of rows inserted 0, updated 0, deleted 0, read 261938483
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 187028.15 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

The query

The query is updating a whole table, based on the results of a view that also reads the whole table. I have not found a more optimized way to do so.

UPDATE events
INNER JOIN sessions_view_3
ON events.user_id = sessions_view_3.user_id
AND events.timestamp = sessions_view_3.timestamp
AND events.kind = sessions_view_3.kind
SET events.session_id_3 = sessions_view_3.global_session_id_3;


CREATE VIEW sessions_view_3 AS
SELECT user_id, `timestamp`,  kind,
    SUM(is_new_session) OVER (ORDER BY user_id, `timestamp`) AS global_session_id_3,
    SUM(is_new_session) OVER (PARTITION BY user_id ORDER BY `timestamp`) AS user_session_id_3
FROM (
    SELECT *,
    CASE WHEN
        last_event_timestamp IS NULL OR
        (page_type != 'theory' AND page_type != 'theory_section' AND exercise_id IS NOT NULL
        AND NOT EXISTS(SELECT 1 FROM events e2
                    WHERE (session_id = e2.session_id
                      AND exercise_id = e2.exercise_id
                      AND e2.timestamp < timestamp)
                      OR (session_id = e2.session_id
                      AND last_event_exercise_id = e2.exercise_id
                      AND e2.timestamp > last_event_timestamp)
                        )
        )
        THEN 1 ELSE 0 END AS is_new_session
    FROM (
        SELECT *,
        LAG(`timestamp`,1) OVER (PARTITION BY session_id ORDER BY `timestamp`) AS last_event_timestamp,
        LAG(`exercise_id`,1) OVER (PARTITION BY session_id ORDER BY `timestamp`) AS last_event_exercise_id
        FROM events
    ) e
) final
;

My conclusions

What seems good:

  • The transaction appears to be running and active
  • In ROW OPERATIONS, the total reads and reads/s keeps increasing / changing so it seems to be doing something

What seems odd:

  • In ROW OPERATIONS says state:sleeping
  • In ROW OPERATIONS says there are 0 queries in queue
  • All threads are waiting for completed aio requests, does this mean no thread is doing anything?
  • All tables and rows are locked. This is normal since the update, but I worry the update is locking the rows the view needs to read. Although I believe MySQL should first retrieve the data from the view, and then update.
  • The fact that no process is using much memory. My total memory usage is only 6GB, and around 3 of them are used by PyCharm

UPDATE: adding top output

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                                                 
   1131 mysql     20   0 2222320 389264  22700 S 100,0   1,2 422:15.44 mysqld
1
  • Also, is there any way of knowing how much it's got left? Apr 23, 2023 at 11:35

2 Answers 2

3

In ROW OPERATIONS says state:sleeping

The line about "state:sleeping" is referring to the InnoDB main thread, not the user threads that are running a query. The main thread runs a loop to do background tasks like flushing pages to disk. Sleeping is a normal state even if you have queries in progress on other threads.

Think of a bagpipe player, who must blow into the mouthpiece to keep the bag inflated, but this is asynchronous with respect to any notes he's playing on the pipe. There are times when the player can take a breath even during a note.

In ROW OPERATIONS says there are 0 queries in queue

It also shows zeroes in several other fields of that block.

You might be running SHOW ENGINE INNODB STATUS repeatedly? Keep in mind that some figures reported by this status are reset to 0 when you run the command. So if you run it in rapid succession, there isn't enough data since the last reset for it to recalculate rates and averages. So you get odd looking numbers sometimes. Look for the line near the top of the status output like "Per second averages calculated from the last 20 seconds". If the duration is like 0 or 1 seconds, I'd take the numbers with a grain of salt.

The InnoDB status monitor also resets itself every 20 seconds (IIRC) even if you're not querying the status, so the amount of status data can vary when you view it. The InnoDB monitor is not like a proper monitoring service like DataDog that keeps weeks of status values.

All threads are waiting for completed aio requests, does this mean no thread is doing anything?

It looks to like your system is quite busy. The string "waiting for completed aio requests" means it has aio requests in progress and it's waiting for one to complete.

The fact that you have many I/O threads occupied and waiting for I/O to complete tells me that it is indeed busy. If the threads were idle, they would say "waiting for i/o request".

I'm a bit surprised that your write threads are also occupied, although the line that shows the write I/O rate says "0.00 writes/s".

It make sense that you have low CPU activity, since the threads are waiting for I/O. Those two resources often have an inverse relationship. While waiting for I/O to complete, the CPU has nothing to do. And likewise if CPU is busy, it's likely that I/O is done.

You can use the top command (if your server is Linux) to view individual threads, and you can enable a column to show which CPU each thread is currently using. You can also open a display of individual CPU states. I'm not sure you're using Linux.

All tables and rows are locked. This is normal since the update, but I worry the update is locking the rows the view needs to read. Although I believe MySQL should first retrieve the data from the view, and then update.

The thread that acquired the lock can still read and write the row. You don't have a conflict if a subquery locked it. Stated another way, the thread owns the locks, not the query.

The fact that no process is using much memory. My total memory usage is only 6GB, and around 3 of them are used by PyCharm

It's probably creating large temp tables as a byproduct of the query. I'd guess multiple temp files for this query, because it's using a view, and also using window functions. If temp tables exceed tmp_table_size, they get spooled to disk. This could also account for the high rate of I/O.

4
  • Indeed, by looking at the top command output we can see mysql is responsible for the CPU being busy. We can also see it's taking disk space. However, I am pretty sure the waiting for completed aio requests part was like that even before running the command (for all threads). Is that normal? While this will still be useful to learn, I think I will look for a workaround since this is taking way too much Apr 23, 2023 at 17:31
  • I am also wondering if there is any way of checking in which part of the query it is currently working on (sub selects, etc) Apr 23, 2023 at 17:32
  • 1
    I don't think there's any way to tell what "part" of the query it's working on, because what you write in SQL has little to do with the way the engine executes it. The optimizer may rewrite the query, executing in a different order. Also the execution is split between the SQL layer and the storage engine layer (in your case, InnoDB). Apr 23, 2023 at 17:42
  • 1
    Also you asked if there's any way to know how much left it has to run. I don't think so. Percona Server is a branch of MySQL that adds a row count to the processlist, but since you don't know how many rows will be returned, this is hard to make any conclusion from until the end. Apr 23, 2023 at 17:44
2

I see this

UPDATE  events
    INNER JOIN  sessions_view_3  ON events.user_id = sessions_view_3.user_id
      AND  events.timestamp = sessions_view_3.timestamp
      AND  events.kind = sessions_view_3.kind
    SET events.session_id_3 = sessions_view_3.global_session_id_3

This index on events should help the UPDATE run faster:

INDEX(user_id,  timestamp, kind)

If you have no (or inadequate) indexes on the tables, this would explain the high CPU.

As for the SELECT in the VIEW...

I wonder if GROUP BY would be better than OVER.

These might help:

INDEX(exercise_id, timestamp, session_id)
INDEX(session_id, exercise_id, timestamp)

Do you need all columns (*)? If not, spell out the columns needed.

Please provide `SHOW CREATE TABLE events.

Because of how last_event_timestamp is computed and then used, it may be better to break the SELECT into two, then add the subtotals.

How long does it take to run the VIEW by itself? I have a hunch that it takes a long time. There may be a better write the Select in the Exists.

1
  • I did abandon this but: The view does take too much (I have never let it finish). I already got the indices. I don't think I have tried with group by, I did not know the LAG function works with group by as well , does it? Apr 25, 2023 at 16:07

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.