Bug #38611 Report spin waiting time used by Innodb
Submitted: 6 Aug 2008 19:04 Modified: 13 May 2010 16:12
Reporter: Mark Callaghan Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S4 (Feature request)
Version:5.0,5.1 OS:Any
Assigned to: CPU Architecture:Any
Tags: innodb, spinlock
Triage: Triaged: D5 (Feature request)

[6 Aug 2008 19:04] Mark Callaghan
Description:
Innodb uses a busy-wait loop in its mutex implementation. There is an assumption that the total wait time is 20 milliseconds. It should determine the wait time at startup and print it. It could also compute the best number of spins to get a 20 millisecond wait.

On my servers, the total busy wait time is 4 milliseconds, not 20.

How to repeat:
Read the source.

Suggested fix:
Code added to compute and print the spin wait time. This is also displayed in SHOW INNODB STATUS

static void time_spin_delay()
{
  struct timeval s, e;
  int i;

  srv_timed_spin_delay = 0;

  if (gettimeofday(&s, NULL))
    return;

  for (i = 0; i < SYNC_SPIN_ROUNDS; ++i)
    ut_delay(ut_rnd_interval(0, srv_spin_wait_delay));

  if (gettimeofday(&e, NULL))
    return;

  srv_timed_spin_delay = mics_diff(&e, &s);
}

/*************************************************************************
Prints counters for work done by srv_master_thread. */

static
void
srv_print_extra(
/*===================*/
        FILE  *file)    /* in: output stream */
{
        fprintf(file, "srv_master_thread loops: %lu 1_second, %lu sleeps, "
                "%lu 10_second, %lu background, %lu flush\n",
                srv_main_1_second_loops, srv_main_sleeps,
                srv_main_10_second_loops, srv_main_background_loops,
                srv_main_flush_loops);
        fprintf(file, "srv_master_thread log flush: %lu sync, %lu async\n",
                srv_sync_flush, srv_async_flush);
        fprintf(file, "srv_wait_thread_mics %lld microseconds, %.1f seconds\n",
                srv_thread_wait_mics,
                (double) srv_thread_wait_mics / 1000000.0);
        fprintf(file,
                "spinlock delay for %d delay %d rounds is %lld mics\n",
                srv_spin_wait_delay, SYNC_SPIN_ROUNDS, srv_timed_spin_delay);
}
[6 Aug 2008 19:31] Miguel Solorzano
Thank you for the bug report.