top of page
  • Writer's picturekyle Hailey
    • Jun 29, 2022
    • 4 min read

MySQL wait events broken and are CPU time

Updated: Jun 29, 2023

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:

 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);
}

  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);
  }

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;
65 views0 comments

Recent Posts

See All
bottom of page