Are some MySQL wait events actually CPU time ?

June 29th, 2022

Sure, wait event times in any database will include some CPU time, though ideally it should be minimal. Waits should be instrumented as close to the off CPU wait event as possible, i.e. if I’m doing an IO, then I want the wait to cover just the read call:


start_wait('my_read_wait');
pread( ... );
end_wait('my_read_wait');

So my function that sets up the read will do some CPU that could get caught under the cover of the wait itself and the call to pread will use some CPU but most of the time should be waiting for the actual I/O if the I/O is coming from storage.

start_wait('my_lock');
semtimedop(...);
end_wait('my_lock');

On MySQL I’ve noticed that average active sessions on CPU are often well below what the host reports as CPU utilization. For example if I have one connection on CPU a 100% of the time on a 2 vCPU host then CPU Utilization should be around 50%.  There might be some other CPU activity by other processes but if the database is the only thing on the host and I only have one connection active then this is a pretty good approximation. One connection on CPU 100% of the time is the same a 1 average active session  (AAS) on CPU or 1 AAS on CPU.

On MySQL systems I’d often see AAS on CPU say at an average of 10% where as the CPU Utilization of the host is 50% or even 100%.

Finally I ran a test today where I had 2 sessions on a 2 vCPU host running a join using the same table 3 times and no index and no predicate filter. That basically makes the SQL have to do N * N * N lookups where N is the number of rows in the the table. In this case the table fit into memory so this should be a pure CPU operation and yes the host OS reported 100% CPU.  but low and behold in my case it came out ZERO AAS on CPU and 2 AAS on the wait ‘wait/io/table/sql/handler’.

On MySQL I am constantly seeing ‘wait/io/table/sql/handler’ in the top waits and happening when the SQL running should just be  reading buffers in memory. Here is an example:


CREATE TABLE seed ( id INT AUTO_INCREMENT PRIMARY KEY, val INT);
 insert into seed(val) values (1);
 insert into seed(val) select val from seed; /* 2 */
 insert into seed(val) select val from seed; /* 4 */
 insert into seed(val) select val from seed; /* 8 */
 insert into seed(val) select val from seed; /* 16 */
 insert into seed(val) select val from seed; /* 32 */
 insert into seed(val) select val from seed; /* 64 */
 insert into seed(val) select val from seed; /* 128 */
 insert into seed(val) select val from seed; /* 256 */
 insert into seed(val) select val from seed; /* 512 */
 insert into seed(val) select val from seed; /* 1024 */
 insert into seed(val) select val from seed; /* 2048 */
 insert into seed(val) select val from seed; /* 4096 */
 insert into seed(val) select val from seed; /* 8192 */
 insert into seed(val) select val from seed; /* 16384 */
create table seed1 as select * from seed;
create table seed2 as select * from seed;

Then run the following query by a couple of sessions.


select count(*) from seed a, seed1 b, seed2 c where a.id=b.id and a.id=c.id;

 

Here is the Performance Insights dashboard in Amazon RDS. CPU Utilizaiton goes from about 5% to 100% and DB Load goes from 0 to 2 with almost all load on ‘wait/io/table/sql/handler’

Screen Shot 2021-11-05 at 11.01.59 PM

Now if we track down the IO waits. we can see it’s wrapped around fetch row without actually seeing if the fetch is doing an I/O or reading from cache:

https://github.com/mysql/mysql-server/blob/5.7/sql/handler.cc#L3047

 MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result,
 { result= index_read_map(buf, key, keypart_map, find_flag); })
 if (!result && m_update_generated_read_fields)
 {
 result= update_generated_read_fields(buf, table, active_index);
 m_update_generated_read_fields= false;
 }
 DBUG_RETURN(result);
}
index_read_map:  https://github.com/mysql/mysql-server/blob/5.7/sql/handler.h#L2819
  virtual int index_read_map(uchar * buf, const uchar * key,
                             key_part_map keypart_map,
                             enum ha_rkey_function find_flag)
  {
    uint key_len= calculate_key_len(table, active_index, keypart_map);
    return  index_read(buf, key, key_len, find_flag);
  }
calculate_key_len:  https://github.com/mysql/mysql-server/blob/5.7/sql/handler.cc#L3047
uint calculate_key_len(TABLE *table, uint key,
                       key_part_map keypart_map)
{
  /* works only with key prefixes */
  assert(((keypart_map + 1) & keypart_map) == 0);

  KEY *key_info= table->key_info + key;
  KEY_PART_INFO *key_part= key_info->key_part;
  KEY_PART_INFO *end_key_part= key_part + actual_key_parts(key_info);
  uint length= 0;

  while (key_part < end_key_part && keypart_map)   {     length+= key_part->store_length;
    keypart_map >>= 1;
    key_part++;
  }
  return length;
}
IO Waits also are instrumented at
IO waits

MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, MAX_KEY, result, { result= rnd_pos(buf, pos); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result, { result= index_read_map(buf, key, keypart_map, find_flag); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, index, result, { result= index_read_idx_map(buf, index, key, keypart_map, find_flag); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result, { result= index_next(buf); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result, { result= index_prev(buf); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result, { result= index_first(buf); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result, { result= index_last(buf); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result, { result= index_next_same(buf, key, keylen); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_WRITE_ROW, MAX_KEY, error, { error= write_row(buf); }) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_UPDATE_ROW, active_index, error, { error= update_row(old_data, new_data);}) 
MYSQL_TABLE_IO_WAIT(PSI_TABLE_DELETE_ROW, active_index, error, { error= delete_row(buf);}) 

MYSQL_TABLE_IO_WAIT
https://github.com/mysql/mysql-server/blob/8d8c986e5716e38cb776b627a8eee9e92241b4ce/sql/handler.cc

#define MYSQL_TABLE_IO_WAIT(OP, INDEX, RESULT, PAYLOAD)
...
case PSI_BATCH_MODE_STARTING: {
m_psi_locker = PSI_TABLE_CALL(start_table_io_wait)

PSI_TABLE_CALL
include/mysql/psi/mysql_table.h

#define PSI_TABLE_CALL(M) psi_table_service->M
psi_table_service
https://github.com/mysql/mysql-server/blob/8d8c986e5716e38cb776b627a8eee9e92241b4ce/mysys/psi_noop.cc#L536

static struct PSI_table_locker *start_table_lock_wait_noop(
struct PSI_table_locker_state *, struct PSI_table *,
enum PSI_table_lock_operation, ulong, const char *, uint) {
return nullptr;
}

...
static PSI_table_service_t psi_table_noop = {
get_table_share_noop, release_table_share_noop,
drop_table_share_noop, open_table_noop,
unbind_table_noop, rebind_table_noop,
close_table_noop, start_table_io_wait_noop,
end_table_io_wait_noop, start_table_lock_wait_noop,
end_table_lock_wait_noop, unlock_table_noop};

PSI_table_service_t *psi_table_service = &psi_table_noop;

Reference https://fritshoogland.wordpress.com/2012/04/26/getting-to-know-oracle-wait-events-in-linux/


			


Uncategorized

  1. Trackbacks

  2. No trackbacks yet.
  1. Comments

  2. | #1

    wait/io/table/sql/handler events happen when the MySQL server is waiting for the storage engine. Hence, this does not distinguish between memory access or storage access. If the data is already in memory, most of this time will usually be CPU time. One exception is if there is lock conflicts.

  3. khailey
    | #2

    @Øystein Grøvlen
    Do you think the community edition of MySQL will ever break out the lock wait out. That would be extremely useful. Right now wait events seem of limited use considering that the top wait is wait/io/table/sql/handler and it could be CPU, Lock or I/O. It would be helpful as well if wait/io/table/sql/handler only covered the actual I/O calls and not the buffer reads. It’s confusing seeing runnable CPU much less than actual CPU reported by host

  4. | #3

    @khailey
    I think it is really the name of the event that confuses you. For I/O calls, you should look at the wait/io/file/ events.


seven + 1 =