Times::utime_after_lock (lock time) is wrong

[Daniel Nichter]

In Times.cc:

void Times::set_time()
{
  _end_timer= _start_timer= boost::posix_time::microsec_clock::universal_time();
  utime_after_lock= (_start_timer - _epoch).total_microseconds();
}

void Times::set_time_after_lock()
{
  utime_after_lock= (boost::posix_time::microsec_clock::universal_time() - _epoch).total_microseconds();
}

The first assignment to utime_after_lock in set_time() seems wrong because it results in the number of microseconds since epoch when it should be set to zero because this is when query execution begins. Furthermore, the second assignment in set_time_after_lock(), which is called in locking/global.cc, overwrites the first assignment and again sets the value to the number of microseconds since epoch.

To fix this and make lock time correct, I propose adding to class Times:

  boost::posix_time::ptime _lock_end_timer;

Then initialize _lock_end_timer in set_time() like the other timers, and in set_time_after_lock() assign _lock_end_timer= boost::posix_time::microsec_clock::universal_time(). Finally, add an accessor function getElapsedLockTime() which returns (_lock_end_timer - _start_timer).total_microseconds().

There's a further consideration: plugin/innobase/handler/ha_innodb.cc

/******************************************************************//**
Set the time waited for the lock for the current query. */
UNIV_INTERN
void
thd_set_lock_wait_time(
/*===================*/
  drizzled::Session* in_session, /*!< in: thread handle (THD*) */
  ulint value) /*!< in: time waited for the lock */
{
  if (in_session)
    in_session->times.utime_after_lock+= value;
}

I don't know the code well enough to know if there's an interaction between locking/global.cc and that Innobase code. In any case, it's confusing because utime_after_lock is being accessed two different ways; which one is correct? Is one interfering with the other?

If I have understood the code correctly and you agree that this is a problem, I can branch and fix class Times.

[Olaf van der Spek (olafvdspek)]

All code touching utime_after_lock assumes it's usecs since epoch, except the bit in thd_set_lock_wait_time.
I'm not sure why it's doing all those tricks. Init 0 seems fine.