lock_timing.C

Go to the documentation of this file.

// Copyright (C) 2004, Kenneth C. Schalk
// 
// This file is part of Vesta.
// 
// Vesta is free software; you can redistribute it and/or
// modify it under the terms of the GNU Lesser General Public
// License as published by the Free Software Foundation; either
// version 2.1 of the License, or (at your option) any later version.
// 
// Vesta is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
// Lesser General Public License for more details.
// 
// You should have received a copy of the GNU Lesser General Public
// License along with Vesta; if not, write to the Free Software
// Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA

// lock_timing.C - Implementation of performance debug of StableLock
// and VolatileRootLock.

// Last modified on Tue Dec 13 16:28:30 EST 2005 by ken@xorian.net

#include <Basics.H>
#include <BufStream.H>
#include <FS.H>

#include <iomanip>

#include "logging.H"

#include "lock_timing.H"
#include "VRConcurrency.H"

#include <stdio.h> // FILE *
#include <sys/time.h> /* struct timeval */
#include <assert.h>

using std::setw;
using std::setfill;
using Basics::OBufStream;

// This is from AccessControl.C, but not declared in a header file.
extern ReadersWritersLock userGroup_lock;

#define TIMING_RECORDER_BUF_SIZE 32768

enum which_lock_t
  {
    stable,
    volatileRoot,
    userGroup
  };

class Lock_Timing_Recorder
{
private:
  // Global list of all timing recorders.
  static Basics::mutex list_mu;
  static Lock_Timing_Recorder *list_head;
  Lock_Timing_Recorder *list_next;

  // Mutex protecting the other fields of this class.  This is only
  // needed so that a background thread can
  Basics::mutex mu;

  // Integer that identifies the thread this object corresponds to.
  unsigned long my_thread_index;

  // File descriptor we're writing our data to.
  FILE *timing_record_stream;

  // The time at which we should switch to a new timing file.
  unsigned long file_end_time;

  // Buffer with data prepared to write out.
  char write_buffer[TIMING_RECORDER_BUF_SIZE];

  // Number of bytes in the buffer so far.
  unsigned int current_byte_count;

  // Does this thread have either or both of the locks?
  bool stable_locked, volatileRoot_locked, userGroup_locked;

  // Time of last record for each lock.  This gets set each time a
  // record is recorded for this lock.  The next record is recorded as
  // a delta from this time, so each record records the time since the
  // last record.
  struct timeval stable_time, volatileRoot_time, userGroup_time;

  // Record 6 bytes for a delta from the last time.
  void record_delta(struct timeval *last_time);

  // When we need to, start a new timing file.
  void start_new_file(struct timeval &current_time);

  // Pick data structures based on which lock we're dealing with
  void lock_data(which_lock_t lock,
                 /*OUT*/ struct timeval *&last_time_p,
                 /*OUT*/ bool *&locked_p,
                 /*OUT*/ char &lock_marker);

  void write_delta_record(char record_marker,
                          char lock_marker,
                          struct timeval *last_time_p);

public:
  Lock_Timing_Recorder();
  ~Lock_Timing_Recorder();

  void acquire_read_start(which_lock_t lock);

  void acquire_read_done(which_lock_t lock, bool failed = false);

  void acquire_write_start(which_lock_t lock);

  void acquire_write_done(which_lock_t lock, bool failed = false);

  void release_start(which_lock_t lock);

  void release_done(which_lock_t lock);

  void locked_reason(which_lock_t lock, const char *reason);

  // Thread that periodically checks to ensure that lock timing files
  // have been closed, even if some threads aren't acquiring or
  // releasing any locks.
  static void *new_file_check(void *arg);
};

Basics::mutex Lock_Timing_Recorder::list_mu;
Lock_Timing_Recorder *Lock_Timing_Recorder::list_head = 0;

static pthread_key_t lock_timing_key;
static pthread_once_t lock_timing_once = PTHREAD_ONCE_INIT;

// Should we be recording right now?  (Note: *not* protected by a
// mutex, which makes for a race condition.  We don't really care
// though.  A timing recorder should see its value on the next
// transaction anyway.)
static bool recording_timing = false;

extern Basics::mutex popen_mu;

static unsigned int timing_file_minutes = 60;

extern "C"
{
  static void lock_timing_cleanup(void *tsd) throw()
  {
    if(tsd != 0)
      {
        Lock_Timing_Recorder *recorder = (Lock_Timing_Recorder *) tsd;

        delete recorder;
      }
  }
}

#if !defined(__linux__)
// We can't have another thread close lock timing files on Linux due
// to the fact that only the forking thread can waitpid for a child
// process.
static Basics::thread new_file_check_thread;
#endif

extern "C"
{
  static void lock_timing_init() throw()
  {
    int err = pthread_key_create(&lock_timing_key, lock_timing_cleanup);
    assert(err == 0);

    try
      {
        Text unused;
        if(VestaConfig::get("Repository",
                            "timing_file_minutes", unused))
          timing_file_minutes = VestaConfig::get_int("Repository",
                                                     "timing_file_minutes");
      }
    catch (VestaConfig::failure f)
      {
        Repos::dprintf(DBG_ALWAYS,
                       "VestaConfig::failure in VestaSourceServerExport: %s\n",
                       f.msg.cchars());
        abort();
      }

#if !defined(__linux__)
    // We can't have another thread close lock timing files on Linux due
    // to the fact that only the forking thread can waitpid for a child
    // process.

    // Start a thread to periodically make idle threads close their lock
    // timing files.
    Basics::thread_attr new_file_check_attr;
#if defined (_POSIX_THREAD_PRIORITY_SCHEDULING) && !defined(__linux__)
    // Linux only allows the superuser to use SCHED_RR
    new_file_check_attr.set_schedpolicy(SCHED_RR);
    new_file_check_attr.set_inheritsched(PTHREAD_EXPLICIT_SCHED);
    new_file_check_attr.set_sched_priority(sched_get_priority_min(SCHED_RR));
#endif
    new_file_check_thread.fork_and_detach(Lock_Timing_Recorder::new_file_check,
                                          0,
                                          new_file_check_attr);
#endif
  }
}

static Lock_Timing_Recorder *find_recorder(bool create = false)
{
  // Make sure we've been initialized.
  pthread_once(&lock_timing_once, lock_timing_init);

  // Find/create the timing recorder for this thread
  Lock_Timing_Recorder *recorder =
    (Lock_Timing_Recorder *) pthread_getspecific(lock_timing_key);
  if((recorder == 0) && recording_timing && create)
    {
      // Create the recorder.  (Note: constructor calls
      // pthread_setspecific to register this recorder as the
      // recoreder for this thread.)
      recorder = NEW(Lock_Timing_Recorder);
    }

  return recorder;
}

static bool determine_which_lock(ReadersWritersLock *lock_p,
                                 /*OUT*/ which_lock_t &lock)
{
  // Figure out which lock this is.
  if(lock_p == &StableLock)
    {
      lock = stable;
      return true;
    }
  else if(lock_p == &VolatileRootLock)
    {
      lock = volatileRoot;
      return true;
    }
  else if(lock_p == &userGroup_lock)
    {
      lock = userGroup;
      return true;
    }

  // We only care about the big two.
  return false;
}

void rwlock_acquire_read_start(ReadersWritersLock *lock_p)
{
  // Figure out if we're interested in this lock, and which one it is.
  which_lock_t lock;
  if(!determine_which_lock(lock_p, /*OUT*/ lock))
    return;

  // Find/create the lock timing recorder for this thread
  Lock_Timing_Recorder *recorder = find_recorder(true);

  if(recorder != 0)
    {
      recorder->acquire_read_start(lock);
    }
}

void rwlock_acquire_read_done(ReadersWritersLock *lock_p, bool failed)
{
  // Figure out if we're interested in this lock, and which one it is.
  which_lock_t lock;
  if(!determine_which_lock(lock_p, /*OUT*/ lock))
    return;

  // Find the lock timing recorder for this thread
  Lock_Timing_Recorder *recorder = find_recorder();

  if(recorder != 0)
    {
      recorder->acquire_read_done(lock, failed);
    }
}

void rwlock_acquire_write_start(ReadersWritersLock *lock_p)
{
  // Figure out if we're interested in this lock, and which one it is.
  which_lock_t lock;
  if(!determine_which_lock(lock_p, /*OUT*/ lock))
    return;

  // Find/create the lock timing recorder for this thread
  Lock_Timing_Recorder *recorder = find_recorder(true);

  if(recorder != 0)
    {
      recorder->acquire_write_start(lock);
    }
}

void rwlock_acquire_write_done(ReadersWritersLock *lock_p,bool failed)
{
  // Figure out if we're interested in this lock, and which one it is.
  which_lock_t lock;
  if(!determine_which_lock(lock_p, /*OUT*/ lock))
    return;

  // Find the lock timing recorder for this thread
  Lock_Timing_Recorder *recorder = find_recorder();

  if(recorder != 0)
    {
      recorder->acquire_write_done(lock, failed);
    }
}

void rwlock_release_start(ReadersWritersLock *lock_p)
{
  // Figure out if we're interested in this lock, and which one it is.
  which_lock_t lock;
  if(!determine_which_lock(lock_p, /*OUT*/ lock))
    return;

  // Find the lock timing recorder for this thread
  Lock_Timing_Recorder *recorder = find_recorder();

  if(recorder != 0)
    {
      recorder->release_start(lock);
    }
}

void rwlock_release_done(ReadersWritersLock *lock_p)
{
  // Figure out if we're interested in this lock, and which one it is.
  which_lock_t lock;
  if(!determine_which_lock(lock_p, /*OUT*/ lock))
    return;

  // Find the lock timing recorder for this thread
  Lock_Timing_Recorder *recorder = find_recorder();

  if(recorder != 0)
    {
      recorder->release_done(lock);
    }
}

void rwlock_locked_reason(ReadersWritersLock *lock_p, const char *reason)
{
  // Figure out if we're interested in this lock, and which one it is.
  which_lock_t lock;
  if(!determine_which_lock(lock_p, /*OUT*/ lock))
    return;

  // Find the lock timing recorder for this thread
  Lock_Timing_Recorder *recorder = find_recorder();

  if(recorder != 0)
    {
      recorder->locked_reason(lock, reason);
    }
}

void rwlock_timing_control(bool enable)
{
  recording_timing = enable;
}

Lock_Timing_Recorder::Lock_Timing_Recorder()
  : current_byte_count(0), timing_record_stream(0),
    stable_locked(false), volatileRoot_locked(false), userGroup_locked(false),
    file_end_time(0), list_next(0)
{
  pthread_once(&lock_timing_once, lock_timing_init);

  stable_time.tv_sec = 0;
  stable_time.tv_usec = 0;
  volatileRoot_time.tv_sec = 0;
  volatileRoot_time.tv_usec = 0;
  userGroup_time.tv_sec = 0;
  userGroup_time.tv_usec = 0;

  // Remember our thread index.
#if defined(__linux__)
  my_thread_index = pthread_self()/1024;
#elif defined(__osf__)
  my_thread_index = pthread_getsequence_np(pthread_self());
#else
#error Need way to get thread index for this platform
#endif

  // Only one timing recorder per thread
  assert(pthread_getspecific(lock_timing_key) == 0);

  // This is the timing recorder for this thread.
  int err = pthread_setspecific(lock_timing_key, (void *) this);
  assert(err == 0);

  // Insert ourselves into the global list of lock timing recorders.
  Lock_Timing_Recorder::list_mu.lock();
  this->list_next = Lock_Timing_Recorder::list_head;
  Lock_Timing_Recorder::list_head = this;
  Lock_Timing_Recorder::list_mu.unlock();
}

void Lock_Timing_Recorder::start_new_file(struct timeval &current_time)
{
  // Close existing stream, if any.
  if(timing_record_stream != 0)
    {
      fflush(timing_record_stream);
      popen_mu.lock();
      pclose(timing_record_stream);
      popen_mu.unlock();
    }

  // Get the year/month/day/hour for use in the timing filename

  // If this is the first file we're opening, use the current time
  // rounded down to the specified number of minutes.
  struct tm time_detail;
  if(file_end_time == 0)
    {
      localtime_r(&(current_time.tv_sec), &time_detail);
      time_detail.tm_sec = 0;
      time_detail.tm_min -= (time_detail.tm_min%timing_file_minutes);
    }
  // Use the end time for the last file to label the next file
  else
    {
      time_t file_label_time = file_end_time;
      localtime_r(&file_label_time, &time_detail);
    }

  // Generate a name for a directory to put the timings into, and
  // create it if it doesn't exist.
  OBufStream l_dirname;
  l_dirname << "timings."
            << (time_detail.tm_year+1900) << "-"
            << setw(2) << setfill('0') << (time_detail.tm_mon + 1) << "-"
            << setw(2) << setfill('0') << time_detail.tm_mday;
  if(!FS::Exists(l_dirname.str()))
    {
      mkdir(l_dirname.str(), 0755);
    }

  // Open the stream we'll record our results into.  We start a gzip
  // process to compress them as we write them.
  OBufStream l_cmd;
  l_cmd << "exec gzip - > " << l_dirname.str()
        << "/rwlocks.pid_" << getpid()
        << ".thread_" << my_thread_index
        << "."
        << setw(2) << setfill('0') << time_detail.tm_hour << "_"
        << setw(2) << setfill('0') << time_detail.tm_min;
  popen_mu.lock();
  timing_record_stream = popen(l_cmd.str(), "w");
  popen_mu.unlock();
  assert(timing_record_stream != 0);

  // Compute the time at which we should start a new file (the
  // beginning of the next interval).
  file_end_time = mktime(&time_detail) + 60*timing_file_minutes;
}

Lock_Timing_Recorder::~Lock_Timing_Recorder()
{
  if(timing_record_stream != 0)
    {
      fflush(timing_record_stream);
      popen_mu.lock();
      pclose(timing_record_stream);
      popen_mu.unlock();
    }

  // Remove ourselves from the global list of lock timing recorders.
  Lock_Timing_Recorder::list_mu.lock();
  Lock_Timing_Recorder **points_to_me = &Lock_Timing_Recorder::list_head;
  while((*points_to_me != this) &&
        (*points_to_me != 0))
    {
      points_to_me = &((*points_to_me)->list_next);
    }
  if(*points_to_me == this)
    {
      *points_to_me = this->list_next;
    }
  Lock_Timing_Recorder::list_mu.unlock();

}

void Lock_Timing_Recorder::lock_data(which_lock_t lock,
                                     /*OUT*/ struct timeval *&last_time_p,
                                     /*OUT*/ bool *&locked_p,
                                     /*OUT*/ char &lock_marker)
{
  last_time_p = 0;
  locked_p = 0;
  lock_marker = 0;

  // Pick the data structures for the lock we're working with.
  switch(lock)
    {
    case stable:
      last_time_p = &(this->stable_time);
      locked_p = &(this->stable_locked);
      lock_marker = 1;
      break;
    case volatileRoot:
      last_time_p = &(this->volatileRoot_time);
      locked_p = &(this->volatileRoot_locked);
      lock_marker = 2;
      break;
    case userGroup:
      last_time_p = &(this->userGroup_time);
      locked_p = &(this->userGroup_locked);
      lock_marker = 3;
      break;
    }
  assert(last_time_p != 0);
  assert(locked_p != 0);
  assert(lock_marker != 0);
}

#define USECS_PER_SEC 1000000

static struct timeval delta_time(const struct timeval &time_a,
                                 const struct timeval &time_b)
{
  struct timeval result;

  if(time_a.tv_sec == time_b.tv_sec)
    {
      result.tv_sec = 0;
      // Need to handle time moving backwards thanks to ntp
      result.tv_usec = ((time_b.tv_usec >= time_a.tv_usec)
                        ? time_b.tv_usec - time_a.tv_usec
                        : 0);
    }
  else if(time_b.tv_sec > time_a.tv_sec)
    {
      result.tv_sec = (time_b.tv_sec - time_a.tv_sec) - 1;
      result.tv_usec = (time_b.tv_usec + USECS_PER_SEC) - time_a.tv_usec;
      if(result.tv_usec > USECS_PER_SEC)
        {
          result.tv_sec += result.tv_usec/USECS_PER_SEC;
          result.tv_usec %= USECS_PER_SEC;
        }
    }
  else
    {
      // Need to handle time moving backwards thanks to ntp
      result.tv_sec = 0;
      result.tv_usec = 0;
    }

  return result;
}

void Lock_Timing_Recorder::record_delta(struct timeval *last_time)
{
  // Get the current time
  struct timeval current_time;
  struct timezone unused_tz;
  int err = gettimeofday(&current_time, &unused_tz);
  assert(err == 0);

  // Find the time delta
  struct timeval delta = delta_time(*last_time, current_time);

  // Seconds delta from start
  unsigned short sec_delta = delta.tv_sec;
  assert(sec_delta == delta.tv_sec);
  memcpy(&(write_buffer[current_byte_count]),
         (void *) &sec_delta, sizeof(unsigned short));
  assert(sizeof(unsigned short) == 2);
  current_byte_count += sizeof(unsigned short);

  // Microseconds delta from start
  unsigned int usec_delta = delta.tv_usec;
  memcpy(&(write_buffer[current_byte_count]),
         (void *) &usec_delta, sizeof(unsigned int));
  assert(sizeof(unsigned int) == 4);
  current_byte_count += sizeof(unsigned int);

  // Change the last time to the current time so that he next delta
  // will be relative to this time.
  *last_time = current_time;
}

void Lock_Timing_Recorder::write_delta_record(char record_marker,
                                              char lock_marker,
                                              struct timeval *last_time_p)
{
  // Record which lock this is.
  write_buffer[current_byte_count++] = lock_marker;

  // Record the type of record (read lock acquired, start release,
  // release done, etc.)
  write_buffer[current_byte_count++] = record_marker;

  // Record the time since we started with this lock.
  record_delta(last_time_p);

  // Make sure we haven't run out of buffer space.
  assert(current_byte_count < TIMING_RECORDER_BUF_SIZE);
}

void Lock_Timing_Recorder::acquire_read_start(which_lock_t lock)
{
  this->mu.lock();

  struct timeval *last_time_p;
  bool *locked_p;
  char lock_marker;

  // If we're not supposed to be recording timing, do nothing.
  if(!recording_timing)
    {
      this->mu.unlock();
      return;
    }

  // Pick the data structures for the lock we're working with.
  lock_data(lock, last_time_p, locked_p, lock_marker);

  // It better not already be locked by this thread.
  assert(!(*locked_p));

  // Get the start time
  struct timezone unused_tz;
  int err = gettimeofday(last_time_p, &unused_tz);
  assert(err == 0);

  // Start a new timing file if we should
  if((timing_record_stream == 0) || (last_time_p->tv_sec >= file_end_time))
    {
      start_new_file(*last_time_p);

      // Get the time again to avoid counting the change of file for
      // this call.
      err = gettimeofday(last_time_p, &unused_tz);
      assert(err == 0);
    }

  // ------------------------------------------------------------
  // Place the acquireRead start record into the buffer
  // ------------------------------------------------------------

  // Which lock?
  write_buffer[current_byte_count++] = lock_marker;

  // acquireRead start marker byte
  write_buffer[current_byte_count++] = 1;

  // Start time seconds
  unsigned int start_sec = last_time_p->tv_sec;
  memcpy(&(write_buffer[current_byte_count]), (void *) &start_sec,
         sizeof(unsigned int));
  current_byte_count += sizeof(unsigned int);

  // Start time microseconds
  unsigned int start_usec = last_time_p->tv_usec;
  memcpy(&(write_buffer[current_byte_count]), (void *) &start_usec,
         sizeof(unsigned int));
  current_byte_count += sizeof(unsigned int);

  // Make sure we haven't run out of buffer space.
  assert(current_byte_count < TIMING_RECORDER_BUF_SIZE);

  this->mu.unlock();
}

void Lock_Timing_Recorder::acquire_read_done(which_lock_t lock,
                                             bool failed)
{
  this->mu.lock();

  // If we haven't recorded an earlier record for this thread, we've
  // got nothing to do.
  if(current_byte_count == 0)
    {
      this->mu.unlock();
      return;
    }

  struct timeval *last_time_p;
  bool *locked_p;
  char lock_marker;

  // Pick the data structures for the lock we're working with.
  lock_data(lock, last_time_p, locked_p, lock_marker);

  // If we don't have a start time forthis lock, we've got nothing to
  // do.
  if(last_time_p->tv_sec == 0)
    {
      this->mu.unlock();
      return;
    }

  // This thread now holds this lock.
  assert(!(*locked_p));
  *locked_p = true;

  // Write the record for this point.  (2 indicates a read lock was
  // acquired, 3 indicates a failed tryRead.)
  write_delta_record(failed ? 3 : 2,
                     lock_marker,
                     last_time_p);

  this->mu.unlock();
}

void Lock_Timing_Recorder::acquire_write_start(which_lock_t lock)
{
  this->mu.lock();

  struct timeval *last_time_p;
  bool *locked_p;
  char lock_marker;

  // If we're not supposed to be recording timing, do nothing.
  if(!recording_timing)
    {
      this->mu.unlock();
      return;
    }

  // Pick the data structures for the lock we're working with.
  lock_data(lock, last_time_p, locked_p, lock_marker);

  // It better not already be locked by this thread.
  assert(!(*locked_p));

  // Get the start time
  struct timezone unused_tz;
  int err = gettimeofday(last_time_p, &unused_tz);
  assert(err == 0);

  // Start a new timing file if we should
  if((timing_record_stream == 0) || (last_time_p->tv_sec >= file_end_time))
    {
      start_new_file(*last_time_p);

      // Get the time again to avoid counting the change of file for
      // this call.
      err = gettimeofday(last_time_p, &unused_tz);
      assert(err == 0);
    }

  // ------------------------------------------------------------
  // Place the acquireWrite start record into the buffer
  // ------------------------------------------------------------

  // Which lock?
  write_buffer[current_byte_count++] = lock_marker;

  // acquireWrite start marker byte
  write_buffer[current_byte_count++] = 4;

  // Start time seconds
  unsigned int start_sec = last_time_p->tv_sec;
  memcpy(&(write_buffer[current_byte_count]), (void *) &start_sec,
         sizeof(unsigned int));
  current_byte_count += sizeof(unsigned int);

  // Start time microseconds
  unsigned int start_usec = last_time_p->tv_usec;
  memcpy(&(write_buffer[current_byte_count]), (void *) &start_usec,
         sizeof(unsigned int));
  current_byte_count += sizeof(unsigned int);

  // Make sure we haven't run out of buffer space.
  assert(current_byte_count < TIMING_RECORDER_BUF_SIZE);

  this->mu.unlock();
}

void Lock_Timing_Recorder::acquire_write_done(which_lock_t lock,
                                              bool failed)
{
  this->mu.lock();

  // If we haven't recorded an earlier record for this thread, we've
  // got nothing to do.
  if(current_byte_count == 0)
    {
      this->mu.unlock();
      return;
    }

  struct timeval *last_time_p;
  bool *locked_p;
  char lock_marker;

  // Pick the data structures for the lock we're working with.
  lock_data(lock, last_time_p, locked_p, lock_marker);

  // If we don't have a start time forthis lock, we've got nothing to
  // do.
  if(last_time_p->tv_sec == 0)
    {
      this->mu.unlock();
      return;
    }

  // This thread now holds this lock.
  assert(!(*locked_p));
  *locked_p = true;

  // Write the record for this point.  (5 indicates a write lock was
  // acquired, 5 indicates a failed tryWrite.)
  write_delta_record(failed ? 6 : 5,
                     lock_marker,
                     last_time_p);

  this->mu.unlock();
}

void Lock_Timing_Recorder::release_start(which_lock_t lock)
{
  this->mu.lock();

  // If we haven't recorded an earlier record for this thread, we've
  // got nothing to do.
  if(current_byte_count == 0)
    {
      this->mu.unlock();
      return;
    }

  struct timeval *last_time_p;
  bool *locked_p;
  char lock_marker;

  // Pick the data structures for the lock we're working with.
  lock_data(lock, last_time_p, locked_p, lock_marker);

  // If we have no record of this thread holding this lock (which
  // can happen when lock timing is first turned on), do nothing.
  if(!*locked_p)
    {
      this->mu.unlock();
      return;
    }

  // Write the record for this point.
  write_delta_record(7,
                     lock_marker,
                     last_time_p);

  this->mu.unlock();
}

void Lock_Timing_Recorder::release_done(which_lock_t lock)
{
  this->mu.lock();

  // If we haven't recorded an earlier record for this thread, we've
  // got nothing to do.
  if(current_byte_count == 0)
    {
      this->mu.unlock();
      return;
    }

  struct timeval *last_time_p;
  bool *locked_p;
  char lock_marker;

  // Pick the data structures for the lock we're working with.
  lock_data(lock, last_time_p, locked_p, lock_marker);

  // If we have no record of this thread holding this lock (which
  // can happen when lock timing is first turned on), do nothing.
  if(!*locked_p)
    {
      this->mu.unlock();
      return;
    }

  // This thread is giving up this lock.
  *locked_p = false;

  // Write the record for this point.
  write_delta_record(8,
                     lock_marker,
                     last_time_p);

  // Reset the last time for this lock.
  last_time_p->tv_sec = 0;
  last_time_p->tv_usec = 0;

  // If neither lock is now held by this thread, it's time to flush
  // our write buffer.
  if(!stable_locked && !volatileRoot_locked && !userGroup_locked)
    {
      // Write the entire record for this call
      size_t written = fwrite(write_buffer, current_byte_count, 1,
                              timing_record_stream);
      assert(written == 1);
      fflush(timing_record_stream);

      // Reset the byte count
      current_byte_count = 0;
    }

  this->mu.unlock();
}

void Lock_Timing_Recorder::locked_reason(which_lock_t lock,
                                         const char *reason)
{
  this->mu.lock();

  // If we haven't recorded an earlier record for this thread, we've
  // got nothing to do.
  if(current_byte_count == 0)
    {
      this->mu.unlock();
      return;
    }

  struct timeval *last_time_p;
  bool *locked_p;
  char lock_marker;

  // Pick the data structures for the lock we're working with.
  lock_data(lock, last_time_p, locked_p, lock_marker);

  // If we have no record of this thread holding this lock (which
  // can happen when lock timing is first turned on), do nothing.
  if(!*locked_p)
    {
      this->mu.unlock();
      return;
    }

  // ------------------------------------------------------------
  // Place the locked reason record into the buffer
  // ------------------------------------------------------------

  // Which lock?
  write_buffer[current_byte_count++] = lock_marker;

  // Locked reason marker byte
  write_buffer[current_byte_count++] = 9;

  // Locked reason string
  strcpy(&(write_buffer[current_byte_count]), reason);
  current_byte_count += strlen(reason)+1;

  // Make sure we haven't run out of buffer space.
  assert(current_byte_count < TIMING_RECORDER_BUF_SIZE);

  this->mu.unlock();
}

void *Lock_Timing_Recorder::new_file_check(void *arg)
{
  // Sleep for one quarter the period of a lock timing file.  This
  // offsets us a bit to avoid falling exaqctly on the time when other
  // threads would be starting a new file anyway.
  unsigned int to_sleep = timing_file_minutes * 15;
  while(to_sleep > 0)
    to_sleep = sleep(to_sleep);

  while(1)
    {
      // Sleep for half the period of a lock timing file.  This gives
      // us two chances to close each lock timing file during the
      // period of the file.  We may need that if we hit one while it
      // happens to hold a lock.
      to_sleep = timing_file_minutes * 30;
      while(to_sleep > 0)
        to_sleep = sleep(to_sleep);

      // Get the current time.
      struct timeval current_time;
      struct timezone unused_tz;
      int err = gettimeofday(&current_time, &unused_tz);
      assert(err == 0);

      // Loop over the list of all lock timing recorders.
      Lock_Timing_Recorder::list_mu.lock();
      Lock_Timing_Recorder *cur = Lock_Timing_Recorder::list_head;
      while(cur != 0)
        {
          cur->mu.lock();
          // If this lock timing recorder has an open stream, and its
          // thread holds neither lock, and this lock timing file is
          // due to be closed, make it start a new one.
          if((cur->timing_record_stream != 0) &&
             !cur->stable_locked && !cur->volatileRoot_locked && !cur->userGroup_locked &&
             (current_time.tv_sec > cur->file_end_time))
            {
              cur->start_new_file(current_time);
            }
          cur->mu.unlock();

          // Move on to the next element in the list.
          cur = cur->list_next;
        }
      Lock_Timing_Recorder::list_mu.unlock();
    }

  // Unreachable.
  return 0;
}

---